PHP5 getrusage() returning incorrect information?

Question

I'm trying to determine CPU usage of my PHP scripts. I just found this article which details how to find system and user CPU usage time (Section 4).

However, when I tried out the examples, I received completely different results.

The first example:

sleep(3);

$data = getrusage();
echo "User time: ".
    ($data['ru_utime.tv_sec'] +
    $data['ru_utime.tv_usec'] / 1000000);
echo "System time: ".
    ($data['ru_stime.tv_sec'] +
    $data['ru_stime.tv_usec'] / 1000000);

Results in:

User time: 29.53
System time: 2.71

Example 2:

for($i=0;$i<10000000;$i++) {

}

// Same echo statements

Results:

User time: 16.69
System time: 2.1

Example 3:

$start = microtime(true);  
while(microtime(true) - $start < 3) {  

}  

// Same echo statements

Results:

User time: 34.94
System time: 3.14

Obviously, none of the information is correct except maybe the system time in the third example. So what am I doing wrong? I'd really like to be able to use this information, but it needs to be reliable.

I'm using Ubuntu Server 8.04 LTS (32-bit) and this is the output of php -v:

PHP 5.2.4-2ubuntu5.10 with Suhosin-Patch 0.9.6.2 (cli) (built: Jan  6 2010 22:01:14)
Copyright (c) 1997-2007 The PHP Group
Zend Engine v2.2.0, Copyright (c) 1998-2007 Zend Technologies

Answer 1

You can use the system 'time' command to verify this information externally:

/usr/bin/time php script.php

which will print something like:

0.03user 0.00system 0:03.04elapsed 0%CPU (0avgtext+0avgdata 32752maxresident)k
0inputs+0outputs (0major+2234minor)pagefaults 0swaps

Of course, dont't forget that the getrusage() information is CPU time used and microtime() is wall clock time. The program may run for 10 minutes according to the clock on the wall, but internally may only use a few seconds of CPU time. Then there's contending for CPU time with all the background programs running on the system, resource contention, plus regular housekeeping.

There's far too many factors involved to be able to get an accurate timing for such short periods. Doing three runs of the while(microtime()) version of your loop, I got the following timings:

user: 0.98, 0.09, 0.90 sys: 0.12, 0.05, 0.94

Obviously quite the variance. Even just a simple <? print_r(getrusage()) ?> has utime/stimes ranging from 0 to 0.03.

Try running your loops for longer periods, and do something within them to increase cpu usage. Right now your numbers are too small to accurately measure.

Answer 2

Thanks to Marc B's advice, I was able to figure out that the ridiculously short times were causing errors in getrusage()'s calculations.

I have created a work-around to discard these inaccurate numbers. Here's the code:

define('SCRIPT_START', microtime(1));

register_shutdown_function('record_activity');

/* Do work here */

function record_activity()
{
    $data = getrusage();
    $cpuu = ($data['ru_utime.tv_sec'] + $data['ru_utime.tv_usec'] / 1000000);
    $cpus = ($data['ru_stime.tv_sec'] + $data['ru_stime.tv_usec'] / 1000000);
    $renderedtime = round(microtime(1) - SCRIPT_START, 6);

    // Have some log function to put this info somewhere
    insert_record($renderedtime,
        //Only pass user CPU time if it's less than or equal to rendered time
        ($renderedtime >= $cpuu ? $cpuu : NULL ),
        //Only pass system CPU time if it's less than or equal to rendered time
        ($renderedtime >= $cpus ? $cpus : NULL ));
}

Hopefully, this will be helpful to anyone else experiencing the same issue.