3scale/apisonator

Total job process time logged is not correct

davidor opened this issue · 0 comments

For each processed job, the workers log some information like the process time, the total time (process time + time in the queue), etc.

The second is not correct. The reason is that the enqueue time is stored in Redis by a listener when it enqueues a job:

Resque.enqueue(ReportJob, service_id, data, Time.now.getutc.to_f, context_info)

Whereas the total time is calculated by the worker when it finished processing a job:

" #{(end_time.to_f - enqueue_time).round(5)}"+

That's the reason why sometimes we get inconsistent numbers in the logs. For example, sometimes we see that the process time is greater than the process time plus the time in the queue. In many deployments, those two timestamps always come from different machines (listeners vs background workers) so comparing them is not reliable.