search

vajda-lab / scc-api

RESTful API for high performance computing centers
0 stars 1 forks source link

Task timing #75

Closed kojoidrissa closed 3 years ago

kojoidrissa commented 3 years ago

The timer for scheduled_allocate_job is showing up in the logs, but not the ones for scheduled_poll_job or update_jobs. I may be using the timer method wrong. I'm gonna let it run a bit more while I do some stuff here at home, then I'll look at it again tomorrow.

scheduler_1  | [2021-07-21 22:26:00,048: INFO/MainProcess] Scheduler: Sending due task poll-job (jobs.tasks.scheduled_poll_job)
worker_1     | [2021-07-21 22:26:00,065: INFO/MainProcess] Received task: jobs.tasks.scheduled_poll_job[c093f21f-4647-4bc1-bd29-697a4c923bb3]  
django_1     | [21/Jul/2021 22:26:39] "POST /apis/jobs/ HTTP/1.1" 201 260
django_1     | [21/Jul/2021 22:26:42] "POST /apis/jobs/ HTTP/1.1" 201 260
django_1     | [21/Jul/2021 22:26:45] "POST /apis/jobs/ HTTP/1.1" 201 260
django_1     | [21/Jul/2021 22:26:47] "POST /apis/jobs/ HTTP/1.1" 201 260
scheduler_1  | [2021-07-21 22:27:00,047: INFO/MainProcess] Scheduler: Sending due task allocate-job (jobs.tasks.scheduled_allocate_job)
worker_1     | [2021-07-21 22:27:00,050: INFO/MainProcess] Received task: jobs.tasks.scheduled_allocate_job[2ec00d41-e4a8-40e3-8a62-b26265e513ba]  
worker_1     | [2021-07-21 22:27:00,421: INFO/ForkPoolWorker-1] SCHEDULED_ALLOCATE_JOB took 0.4 seconds
worker_1     | [2021-07-21 22:27:00,421: INFO/ForkPoolWorker-1] Task jobs.tasks.scheduled_allocate_job[2ec00d41-e4a8-40e3-8a62-b26265e513ba] succeeded in 0.3691929969936609s: None
scheduler_1  | [2021-07-21 22:28:00,047: INFO/MainProcess] Scheduler: Sending due task poll-job (jobs.tasks.scheduled_poll_job)
worker_1     | [2021-07-21 22:28:00,051: INFO/MainProcess] Received task: jobs.tasks.scheduled_poll_job[07ece01e-7f78-4cb9-937f-689ecde05482]  
scheduler_1  | [2021-07-21 22:29:00,049: INFO/MainProcess] Scheduler: Sending due task allocate-job (jobs.tasks.scheduled_allocate_job)
worker_1     | [2021-07-21 22:29:00,054: INFO/MainProcess] Received task: jobs.tasks.scheduled_allocate_job[e9b064ff-8d34-46be-a89b-ce02433fb868]  
scheduler_1  | [2021-07-21 22:30:00,050: INFO/MainProcess] Scheduler: Sending due task poll-job (jobs.tasks.scheduled_poll_job)
worker_1     | [2021-07-21 22:30:00,053: INFO/MainProcess] Received task: jobs.tasks.scheduled_poll_job[86a269c8-e074-4c66-8037-0aa6acc9d6a3]  
scheduler_1  | [2021-07-21 22:31:00,050: INFO/MainProcess] Scheduler: Sending due task allocate-job (jobs.tasks.scheduled_allocate_job)
worker_1     | [2021-07-21 22:31:00,054: INFO/MainProcess] Received task: jobs.tasks.scheduled_allocate_job[2b7d4e5d-b2f5-4473-bf95-4da8c9f0dd9c]
kojoidrissa commented 3 years ago

@jefftriplett Looks like update_jobs is the culprit:

worker_1     | [2021-07-22 00:43:51,547: INFO/ForkPoolWorker-1] UPDATE_JOBS took 6830 seconds
worker_1     | [2021-07-22 00:43:51,548: INFO/ForkPoolWorker-1] SCHEDULED_POLL_JOB took 6831 seconds
worker_1     | [2021-07-22 00:43:51,553: INFO/ForkPoolWorker-1] Task jobs.tasks.scheduled_poll_job[0b2ea9a6-26ec-4870-8aed-f784fed896ca] succeeded in 6831.520618705079s: None
worker_1     | [2021-07-22 00:43:51,969: INFO/ForkPoolWorker-1] SCHEDULED_ALLOCATE_JOB took 0 seconds
worker_1     | [2021-07-22 00:43:51,970: INFO/ForkPoolWorker-1] Task jobs.tasks.scheduled_allocate_job[3c698603-a553-44a2-8a02-78a7d2c351b1] succeeded in 0.41223010793328285s: None
worker_1     | [2021-07-22 00:43:51,975: INFO/MainProcess] Received task: jobs.tasks.scheduled_poll_job[5ff353c5-174e-493e-bab0-85fa56b317fc]  
worker_1     | [2021-07-22 00:43:51,978: INFO/MainProcess] Received task: jobs.tasks.scheduled_poll_job[983c73df-fb19-46ba-a465-b1ddf524a52f]  
worker_1     | [2021-07-22 00:43:51,980: INFO/MainProcess] Received task: jobs.tasks.scheduled_allocate_job[86356d59-36d3-498b-9ee1-d7be3e37d105]  
worker_1     | [2021-07-22 00:43:51,982: INFO/MainProcess] Received task: jobs.tasks.scheduled_poll_job[18b4280c-f51f-4501-ad9f-76645c024dd2]  
worker_1     | [2021-07-22 00:43:51,983: INFO/MainProcess] Received task: jobs.tasks.scheduled_allocate_job[84bf3252-0a9e-4af7-9f2e-1e0fd89f18cd]  
worker_1     | [2021-07-22 00:43:51,984: INFO/MainProcess] Received task: jobs.tasks.scheduled_allocate_job[54367575-3bd0-44b9-beec-7576a670752b]  
worker_1     | [2021-07-22 00:43:51,986: INFO/MainProcess] Received task: jobs.tasks.scheduled_allocate_job[3c698603-a553-44a2-8a02-78a7d2c351b1]  
worker_1     | [2021-07-22 00:43:51,988: INFO/MainProcess] Received task: jobs.tasks.scheduled_poll_job[ac118ea2-17b8-4d6e-8d7b-51c8f1bfa8c4]  
scheduler_1  | [2021-07-22 00:44:00,000: INFO/MainProcess] Scheduler: Sending due task poll-job (jobs.tasks.scheduled_poll_job)
worker_1     | [2021-07-22 00:44:37,360: INFO/ForkPoolWorker-2] UPDATE_JOBS took 6996 seconds
worker_1     | [2021-07-22 00:44:37,361: INFO/ForkPoolWorker-2] SCHEDULED_POLL_JOB took 6997 seconds
worker_1     | [2021-07-22 00:44:37,367: INFO/ForkPoolWorker-2] Task jobs.tasks.scheduled_poll_job[9b59e35d-af9d-431d-8f7d-11d16b6a9598] succeeded in 6997.314644107129s: None
worker_1     | [2021-07-22 00:44:37,728: INFO/ForkPoolWorker-2] SCHEDULED_ALLOCATE_JOB took 0 seconds
worker_1     | [2021-07-22 00:44:37,729: INFO/ForkPoolWorker-2] Task jobs.tasks.scheduled_allocate_job[54367575-3bd0-44b9-beec-7576a670752b] succeeded in 0.35962291108444333s: None
worker_1     | [2021-07-22 00:44:37,732: INFO/MainProcess] Received task: jobs.tasks.scheduled_allocate_job[33a9e57b-204a-4aeb-8d25-3450e2736622]  
worker_1     | [2021-07-22 00:44:39,353: INFO/MainProcess] Received task: jobs.tasks.scheduled_poll_job[75051411-8aad-4b98-b1c1-f6f70e3e97d3]