Seeing some strange behavior in profiling

[cooljacob204]

Hey all,

I'm seeing some strange behavior in some of our threads with them spending a lot of time this sleep call: https://github.com/jeremyevans/sequel/blob/master/lib/sequel/connection_pool/threaded.rb#L297

This is a job within sidekiq.

My first though is that we have a cpu issue. But in the profiling at least it doesn't seem to be indicate that sleep is using the most across all threads in various jobs. We do have some high CPU usage in some workers but not all of them.

Wouldn't high CPU usage make threads want to swap faster therefor spend less time sleeping?
Actually maybe that makes sense. It's sleeping longer because another thread grabbed context causing this one to stay sleeping. Does that sound right? It still doesn't explain to me though why most of the profiling time is sleeping.

Any idea what could cause our threads to spend a lot of time in the sleep method?

[jeremyevans]

This is a sleep(0) call, used to pass control to another thread. If you are using a sampling profiler, this is likely due to the sampling. Can you try a tracing profiler and see how much time is actually spent in the sleep(0) call? I would guess it is insignificant.

If this is causing an actual issue, I'm OK with making the sleep(0) optional. It appears to be added to work around issues when using the async library.

Also, you may want to try using the timed_queue connection pool (SEQUEL_DEFAULT_CONNECTION_POOL=timed_queue environment variable, or :pool_class=>:timed_queue database option). That is the default connection pool in Ruby 3.4+, but should work in Ruby 3.2+ (it may become the default connection pool in Ruby 3.2 and 3.3).

[cooljacob204]

So it looks like this fixed our problem completely. I'm sorta baffled, I don't really understand why this would fix it.

Our time spend processing the problematic job:

Our 1 hour queue latency where the job lived:

New profile:

Going to verify this by going back to the old pool setting and see if it spikes.

[jeremyevans]

Please do. I had a hunch that timed_queue was better, but I had no idea the difference was that dramatic.

[cooljacob204]

Yeah, turning it back off dramatically increased the amount of time my jobs took, I turned it off at 17 utc and back on at 18 utc.

Our sidekiq queue latency:

Time spent performing the job:

For additional context we are on Ruby 3.3.3, Rails 7.1.3.2, Sidekiq 6.5.12, Sequel 5.77.0

[cooljacob204]

Our workers have a db_pool size of 10 and a sidekiq concurrency of 10.

Even when I reduced the sidekiq concurrency to 5 we still saw this issue.

[jeremyevans]

Thank you very much for that information. I'll accelerate my plans to make timed_queue the default connection pool on Ruby 3.2+.