Mutex sleep is taking a lot of CPU

Question

I profiled my event-machine based application with ruby-prof and found the following interesting:

                  5.28    0.00    5.28    0.00          4/4     Mutex#synchronize
90.72%   0.00%    5.28    0.00    5.28    0.00            4     Mutex#sleep

I think ruby-prof counts only CPU ticks, and hence I'm unable to figure out why mutex sleep might take CPU time. I'd assume it sleeps on the kernel level not counting towards the fiber time. Any ideas? Even better, I'd want the Mutex#sleep to release control to the event machine, so it can do other stuff.

Answer 1

If ruby-prof --mode=cpu is really only accounting CPU time, then Mutex#sleep is a spinlock:

http://en.wikipedia.org/wiki/Spinlock

That would make sense, because you're only supposed to wrap very short assignments in mutex locks. Setting up a signal alarm would be insane overhead.

So the challenge you face is to determine the mutexes you're sleeping on, and what they wrap. Then, you'll either discover avoidable mutex abuse, or unavoidable wait times.

Answer 2

that 90% may mean that you're "sleeping" 90% of the time [?] in general with EM you don't need to sleep, you just respond to events, and the majority of cpu will show up as EM's "run" method

Answer 3

As far as I know, if you are stuck waiting for a lock to release, that thread is stuck in sleep mode. The only way to keep Eventmachine running is to ensure that your locks occur in a separate thread.

Answer 4

Usually, if one thread is doing something and the second one is waiting for it to finish, then it will be seen as sleeping. So your sleeping time can be either (depending on your thread): - your thread is waiting for a event (idle) - your theread is waiting for another thread to finish something (other thread busy)

Answer 5

There is far too little information here to give an accurate answer, however, I would suggest looking at a few other aspects, such as whether or not ruby-prof is even picking up time spent in the reactor?

Disregarding what percentages ruby-prof gives you, how long does your profile actually run for, and how long is actually spent in the mutex? It's likely this is only showing #defer threads or something similar, and entirely ignoring the C++ runtime in another thread.