Mosquito does not display job timing accurately, clarification needed

[anapsix]

Please clarify what finished and took ... log output measures.
It looks like it does not actually reflect how long the job took to complete.

Crystal version: 0.35.1
Mosquito Shard version: 0.4.4

Example code:

require "mosquito"

Mosquito::Redis.instance.flushall

class PutsJob < Mosquito::QueuedJob
  params seconds : Int32
  def perform
    puts "sleeping for #{seconds} seconds.."
    sleep seconds
  end
end

PutsJob.new(seconds: 1).enqueue
PutsJob.new(seconds: 2).enqueue
PutsJob.new(seconds: 3).enqueue
PutsJob.new(seconds: 4).enqueue
PutsJob.new(seconds: 5).enqueue

spawn do
  Mosquito::Runner.start
end

sleep 20

Output:

2020-12-11T14:03:29.342249Z   INFO - mosquito: Mosquito is buzzing...
2020-12-11T14:03:29.343754Z   INFO - mosquito: Running task puts_job<1607695409338:670> from puts_job
sleeping for 1 seconds..
2020-12-11T14:03:30.349457Z   INFO - mosquito: Success: task puts_job<1607695409338:670> finished and took 36.0µs
2020-12-11T14:03:30.350865Z   INFO - mosquito: Running task puts_job<1607695409338:521> from puts_job
sleeping for 2 seconds..
2020-12-11T14:03:32.355791Z   INFO - mosquito: Success: task puts_job<1607695409338:521> finished and took 28.0µs
2020-12-11T14:03:32.357121Z   INFO - mosquito: Running task puts_job<1607695409339:896> from puts_job
sleeping for 3 seconds..
2020-12-11T14:03:35.359185Z   INFO - mosquito: Success: task puts_job<1607695409339:896> finished and took 21.0µs
2020-12-11T14:03:35.360249Z   INFO - mosquito: Running task puts_job<1607695409340:325> from puts_job
sleeping for 4 seconds..
2020-12-11T14:03:39.363053Z   INFO - mosquito: Success: task puts_job<1607695409340:325> finished and took 43.0µs
2020-12-11T14:03:39.364571Z   INFO - mosquito: Running task puts_job<1607695409340:586> from puts_job
sleeping for 5 seconds..
2020-12-11T14:03:44.365458Z   INFO - mosquito: Success: task puts_job<1607695409340:586> finished and took 40.0µs

[robacarp]

@anapsix thank you for reporting this. I actually ran into the same bug recently and haven't had time to document it. I haven't dug in, but I believe that this benchmark needs to be swapped out for a Time.measure call.

[anapsix]

I was wondering if that's what causing it. I'll look into making PR tomorrow, unless you get around it before then.

[robacarp]

Yes, I suspect the reason is that Benchmark purposely ignores time while a thread is sleeping. When I added that, Time did not have a #measure method yet.

[anapsix]

created #56 and #57

[robacarp]

closed by #57