DtcQueueBundle icon indicating copy to clipboard operation
DtcQueueBundle copied to clipboard

Published 20 hours ago • verified publisher icon mmucklo

Running even though there are no jobs available?

Open klodoma opened this issue 5 years ago • 2 comments

I am not sure since when this is happening, but I think it has something to do with the latest upgrade.

If I run

 php bin/console dtc:queue:run -d 120

then I get the following logs, although there no jobs in queue or whatsoever. dtc_queue_job, dtc_queue_run tables are empty.

Does this make sense?

Dec  3 20:56:09 |DEBUG| DOCTRI "START TRANSACTION"
Dec  3 20:56:09 |DEBUG| DOCTRI UPDATE dtc_queue_run SET elapsed = ?, last_heartbeat_at = ? WHERE id = ? 0=45.01664113998413 1="2019-12-03 19:56:09" 2="8"
Dec  3 20:56:09 |DEBUG| DOCTRI "COMMIT"
Dec  3 20:56:09 |DEBUG| DOCTRI SELECT d0_.id AS id_0 FROM dtc_queue_job d0_ WHERE d0_.status = ? AND (d0_.when_us IS NULL OR d0_.when_us <= ?) AND (d0_.expires_at IS NULL OR d0_.expires_at > ?) ORDER BY d0_.priority DESC, d0_.when_us ASC LIMIT 100 0="new" 1="157540296946011300" 2="2019-12-03 19:56:09"
Dec  3 20:56:09 |DEBUG| DOCTRI "START TRANSACTION"
Dec  3 20:56:09 |DEBUG| DOCTRI UPDATE dtc_queue_run SET elapsed = ?, last_heartbeat_at = ? WHERE id = ? 0=45.26295495033264 1="2019-12-03 19:56:09" 2="8"
Dec  3 20:56:09 |DEBUG| DOCTRI "COMMIT"
Dec  3 20:56:09 |DEBUG| DOCTRI SELECT d0_.id AS id_0 FROM dtc_queue_job d0_ WHERE d0_.status = ? AND (d0_.when_us IS NULL OR d0_.when_us <= ?) AND (d0_.expires_at IS NULL OR d0_.expires_at > ?) ORDER BY d0_.priority DESC, d0_.when_us ASC LIMIT 100 0="new" 1="157540296996991200" 2="2019-12-03 19:56:09"
Dec  3 20:56:09 |DEBUG| DOCTRI "START TRANSACTION"
Dec  3 20:56:09 |DEBUG| DOCTRI UPDATE dtc_queue_run SET elapsed = ?, last_heartbeat_at = ? WHERE id = ? 0=45.77183294296265 1="2019-12-03 19:56:09" 2="8"
Dec  3 20:56:09 |DEBUG| DOCTRI "COMMIT"
Dec  3 20:56:10 |DEBUG| DOCTRI SELECT d0_.id AS id_0 FROM dtc_queue_job d0_ WHERE d0_.status = ? AND (d0_.when_us IS NULL OR d0_.when_us <= ?) AND (d0_.expires_at IS NULL OR d0_.expires_at > ?) ORDER BY d0_.priority DESC, d0_.when_us ASC LIMIT 100 0="new" 1="157540297030901300" 2="2019-12-03 19:56:10"
Dec  3 20:56:10 |DEBUG| DOCTRI "START TRANSACTION"
Dec  3 20:56:10 |DEBUG| DOCTRI UPDATE dtc_queue_run SET elapsed = ?, last_heartbeat_at = ? WHERE id = ? 0=46.10707402229309 1="2019-12-03 19:56:10" 2="8"
Dec  3 20:56:10 |DEBUG| DOCTRI "COMMIT"
Dec  3 20:56:10 |DEBUG| DOCTRI SELECT d0_.id AS id_0 FROM dtc_queue_job d0_ WHERE d0_.status = ? AND (d0_.when_us IS NULL OR d0_.when_us <= ?) AND (d0_.expires_at IS NULL OR d0_.expires_at > ?) ORDER BY d0_.priority DESC, d0_.when_us ASC LIMIT 100 0="new" 1="157540297077936900" 2="2019-12-03 19:56:10"
Dec  3 20:56:10 |DEBUG| DOCTRI "START TRANSACTION"
Dec  3 20:56:10 |DEBUG| DOCTRI UPDATE dtc_queue_run SET elapsed = ?, last_heartbeat_at = ? WHERE id = ? 0=46.579270124435425 1="2019-12-03 19:56:10" 2="8"
Dec  3 20:56:10 |DEBUG| DOCTRI "COMMIT"
Dec  3 20:56:10 |DEBUG| DOCTRI SELECT d0_.id AS id_0 FROM dtc_queue_job d0_ WHERE d0_.status = ? AND (d0_.when_us IS NULL OR d0_.when_us <= ?) AND (d0_.expires_at IS NULL OR d0_.expires_at > ?) ORDER BY d0_.priority DESC, d0_.when_us ASC LIMIT 100 0="new" 1="157540297095925000" 2="2019-12-03 19:56:10"
Dec  3 20:56:10 |DEBUG| DOCTRI "START TRANSACTION"
Dec  3 20:56:10 |DEBUG| DOCTRI UPDATE dtc_queue_run SET elapsed = ?, last_heartbeat_at = ? WHERE id = ? 0=46.75971603393555 1="2019-12-03 19:56:10" 2="8"
Dec  3 20:56:10 |DEBUG| DOCTRI "COMMIT"
Dec  3 20:56:11 |DEBUG| DOCTRI SELECT d0_.id AS id_0 FROM dtc_queue_job d0_ WHERE d0_.status = ? AND (d0_.when_us IS NULL OR d0_.when_us <= ?) AND (d0_.expires_at IS NULL OR d0_.expires_at > ?) ORDER BY d0_.priority DESC, d0_.when_us ASC LIMIT 100 0="new" 1="157540297117920100" 2="2019-12-03 19:56:11"
Dec  3 20:56:11 |DEBUG| DOCTRI "START TRANSACTION"
Dec  3 20:56:11 |DEBUG| DOCTRI UPDATE dtc_queue_run SET elapsed = ?, last_heartbeat_at = ? WHERE id = ? 0=46.979125022888184 1="2019-12-03 19:56:11" 2="8"
Dec  3 20:56:11 |DEBUG| DOCTRI "COMMIT"
Dec  3 20:56:11 |DEBUG| DOCTRI SELECT d0_.id AS id_0 FROM dtc_queue_job d0_ WHERE d0_.status = ? AND (d0_.when_us IS NULL OR d0_.when_us <= ?) AND (d0_.expires_at IS NULL OR d0_.expires_at > ?) ORDER BY d0_.priority DESC, d0_.when_us ASC LIMIT 100 0="new" 1="157540297160951100" 2="2019-12-03 19:56:11"
Dec  3 20:56:11 |DEBUG| DOCTRI "START TRANSACTION"
Dec  3 20:56:11 |DEBUG| DOCTRI UPDATE dtc_queue_run SET elapsed = ?, last_heartbeat_at = ? WHERE id = ? 0=47.40811014175415 1="2019-12-03 19:56:11" 2="8"
Dec  3 20:56:11 |DEBUG| DOCTRI "COMMIT"
Dec  3 20:56:11 |DEBUG| DOCTRI SELECT d0_.id AS id_0 FROM dtc_queue_job d0_ WHERE d0_.status = ? AND (d0_.when_us IS NULL OR d0_.when_us <= ?) AND (d0_.expires_at IS NULL OR d0_.expires_at > ?) ORDER BY d0_.priority DESC, d0_.when_us ASC LIMIT 100 0="new" 1="157540297162913300" 2="2019-12-03 19:56:11"
Dec  3 20:56:11 |DEBUG| DOCTRI "START TRANSACTION"
Dec  3 20:56:11 |DEBUG| DOCTRI UPDATE dtc_queue_run SET elapsed = ?, last_heartbeat_at = ? WHERE id = ? 0=47.42810893058777 1="2019-12-03 19:56:11" 2="8"
Dec  3 20:56:11 |DEBUG| DOCTRI "COMMIT"
Dec  3 20:56:11 |DEBUG| DOCTRI SELECT d0_.id AS id_0 FROM dtc_queue_job d0_ WHERE d0_.status = ? AND (d0_.when_us IS NULL OR d0_.when_us <= ?) AND (d0_.expires_at IS NULL OR d0_.expires_at > ?) ORDER BY d0_.priority DESC, d0_.when_us ASC LIMIT 100 0="new" 1="157540297194920100" 2="2019-12-03 19:56:11"
Dec  3 20:56:11 |DEBUG| DOCTRI "START TRANSACTION"
Dec  3 20:56:11 |DEBUG| DOCTRI UPDATE dtc_queue_run SET elapsed = ?, last_heartbeat_at = ? WHERE id = ? 0=47.74859094619751 1="2019-12-03 19:56:11" 2="8"
Dec  3 20:56:11 |DEBUG| DOCTRI "COMMIT"
Dec  3 20:56:12 |DEBUG| DOCTRI SELECT d0_.id AS id_0 FROM dtc_queue_job d0_ WHERE d0_.status = ? AND (d0_.when_us IS NULL OR d0_.when_us <= ?) AND (d0_.expires_at IS NULL OR d0_.expires_at > ?) ORDER BY d0_.priority DESC, d0_.when_us ASC LIMIT 100 0="new" 1="157540297228917800" 2="2019-12-03 19:56:12"
Dec  3 20:56:12 |DEBUG| DOCTRI "START TRANSACTION"
Dec  3 20:56:12 |DEBUG| DOCTRI UPDATE dtc_queue_run SET elapsed = ?, last_heartbeat_at = ? WHERE id = ? 0=48.08786702156067 1="2019-12-03 19:56:12" 2="8"
Dec  3 20:56:12 |DEBUG| DOCTRI "COMMIT"
Dec  3 20:56:12 |DEBUG| DOCTRI SELECT d0_.id AS id_0 FROM dtc_queue_job d0_ WHERE d0_.status = ? AND (d0_.when_us IS NULL OR d0_.when_us <= ?) AND (d0_.expires_at IS NULL OR d0_.expires_at > ?) ORDER BY d0_.priority DESC, d0_.when_us ASC LIMIT 100 0="new" 1="157540297234912800" 2="2019-12-03 19:56:12"
Dec  3 20:56:12 |DEBUG| DOCTRI "START TRANSACTION"
Dec  3 20:56:12 |DEBUG| DOCTRI UPDATE dtc_queue_run SET elapsed = ?, last_heartbeat_at = ? WHERE id = ? 0=48.14727997779846 1="2019-12-03 19:56:12" 2="8"
Dec  3 20:56:12 |DEBUG| DOCTRI "COMMIT"

klodoma avatar Dec 03 '19 20:12 klodoma

@klodoma It looks like it's lost it's handle to an entry in the dtc_queue_run table.

Every time run is called it's supposed to create an entry in dtc_queue_run. It then is supposed to update that entry with a heartbeat while the job cycles (that's the UPDATE you're being).

Then it will continually poll the database for new jobs (that's the SELECT... you're seeing).

These debug messages are correct, but the missing entry in dtc_queue_run is more concerning (there should be an entry that shows up with ID 8).

Is there anything from the beginning of the log?

mmucklo avatar Dec 04 '19 08:12 mmucklo

These debug messages are correct, but the missing entry in dtc_queue_run is more concerning (there should be an entry that shows up with ID 8). dtc_queue_run has the entry, sorry I overseen that.

Ok, I had a look at the code and how it runs. So far it all makes sense.

Are there so many real-life use-cases are there in order to run this loop so often(a frw times / second), especially the sleep time if no jobs are available, especially, running a database query to see if it needs to run?

time_nanosleep(0, $nanoSleepTime);

Practically, this solves the "watch or monitor" problem, like, watching for new jobs, if I need to execute smth etc...

=============================================== I am a bit critical, about executing select queries for monitoring; here is an idea I have:

Did you considered using a local file for monitoring instead if executing database queries?

Like save all these executions?

SELECT d0_.id AS id_0 FROM dtc_queue_job d0_ WHERE d0_.status = ? AND (d0_.when_us IS NULL OR d0_.when_us <= ?) AND (d0_.expires_at IS NULL OR d0_.expires_at > ?) ORDER BY d0_.priority DESC, d0_.when_us ASC LIMIT 100 1="157553494010532200" 2="2019-12-05 08:35:40"

For example, every time a dtc_queue_job change occurs, new job created, timed etc... you put the execution time in a file, or you put just the "next-run-timestamp" in that file and monitor in the loop only that file. (no database queries, no nothing needs to be executed); from time-to-time you re-read the database and update there the heart-beat but that can occur every now and then... The problem I see with the file-monitoring is on a multi-server load-balanced environment.

klodoma avatar Dec 05 '19 08:12 klodoma