drush_invoke_process uses 100% CPU

Problem/Motivation

When running a command that includes a call to drush_invoke_process CPU usage becomes crazy high, and basically consumes an entire CPU core until the command completes.

Run a simple drush make command and watch CPU usage for a simple demonstration, or set up a more artificial, but more useful, test as follows:

I've created a few Drush commands that show this issue very clearly:

Install my sandbox commands: http://drupal.org/sandbox/darthsteven/1553722

This will give you four new commands for Drush 5:

• drush-process-test-sleep - sleeps for the given amount of time in seconds, using PHP's sleep function..
• drush-process-test-sleep-wrapper - calls the above command with drush_invoke_process
• drush-process-test-pi - computes pi using a given number of iterations, CPU heavy Drush command!
• drush-process-test-pi-wrapper - calls the above command with drush_invoke_process

So, some empirical testing, on a mid 2011 macbook pro with 2.7Ghz Core i7:

$ time drush drush-process-test-sleep 15                             
drush drush-process-test-sleep 15  0.18s user 0.11s system 1% cpu 15.558 total

This is what we expect, Drush basically consumes no real resources, and takes 15 seconds to run.

So now, the wrapper Drush command:

$ time drush drush-process-test-sleep-wrapper 15
drush drush-process-test-sleep-wrapper 15  14.85s user 0.88s system 100% cpu 15.606 total

So we took 1/10 second longer to complete, but averaged 100% CPU (out of 400%). Ouch.

With the CPU intensive task:

$ time drush drush-process-test-pi 200          
drush drush-process-test-pi 200  14.50s user 0.10s system 99% cpu 14.660 total

and then that command, wrapped:

$ time drush drush-process-test-pi-wrapper 200
drush drush-process-test-pi-wrapper 200  33.11s user 0.93s system 195% cpu 17.388 total

So we actually took three seconds longer (wall time), just by being in a subcommand, and actually used twice as much CPU time!

We're saved here, because I'm running these tests on a multi-core machine, if one ran them in a VM with a single core say, I'd expect them to be awful. Either way, what we see here, is that the parent process is stealing resources from the children. By default, Drush will invoke four children processes to get through the invoked commands, with means that for my system for example, there will be more threads than CPU cores, and one of those cores with be being maxed out at 100% needlessly.

So, why is this happening?

_drush_backend_proc_open is the key function here, it is responsible for opening the child processes and polling them for changes, to see if they have written output data, or indeed, completed. It does the polling in a loop, but that loop just executes as often as possible. This does make the parent process as responsive as possible, but doesn't really reflect what the child process is doing. If the child process is going to sit and output nothing for 15 seconds, the parent doesn't need to check for output thousands of times a second, people aren't going to notice it it takes 15 seconds or 15.1 seconds.

Proposed resolution

Use the PHP stream_select function to block until there is data to be read, this won't work on Windows, so as a workaround introduce the notion of 'nap time' to _drush_backend_proc_open which will mean that it won't poll the sub-processes as fast as possible, but will sensibly back off its polling when it hasn't received any updates from them in its run loop.

Basically at the start of the function, we set $nap_time to 0, then at the start of each iteration of the run loop we increase this by 1. During the course of the loop, if there is any output from any of the children, or if one of them finishes etc. then we reset $nap_time back to 0. At the end of the run loop we sleep for a period of time determined by the $nap_time variable. Slightly arbitrarily, I've suggested we sleep for increments of half a millisecond, up to a maximum of 1/10 of a second. So, basically, if you have lots of child processes that exit really quickly, then it should still be responsive, but if you have a process that doesn't really do much for a long time, it should get to polling it every 0.1 seconds relatively quickly. On Unix like systems it should basically poll the streams as often as it needs to automatically, by using stream_select.

Testing of the proposed fix in #7

So, using the same tests as above, here's how the timings look:

$ time drush drush-process-test-sleep 15        
drush drush-process-test-sleep 15  0.17s user 0.04s system 1% cpu 15.295 total

And now the wrapper:

$ time drush drush-process-test-sleep-wrapper 15
drush drush-process-test-sleep-wrapper 15  0.41s user 0.08s system 3% cpu 15.648 total

And the pi test:

$ time drush drush-process-test-pi 200          
drush drush-process-test-pi 200  14.66s user 0.07s system 98% cpu 14.928 total

And the wrapper of that:

$ time drush drush-process-test-pi-wrapper 200  
drush drush-process-test-pi-wrapper 200  14.65s user 0.10s system 98% cpu 15.010 total

So you can see that the wrapper hasn't added a crazy amount of overhead this time.

Remaining tasks

None.

User interface changes

In rare circumstances Drush commands may execute more slowly, but in general they should be much, much faster.

API changes

None!