Can you figure out this PHP timing issue?

Question

Can anyone tell me why when I ran a script with the below contents and then stop it after 5 seconds that I need to divide the elapsed time by 2 to get the correct script execution time?

ignore_user_abort(true); set_time_limit(0); 

$begin_time = microtime(true);

$elapsed_time = 0;

while(!connection_aborted()) {
    echo ' ';
    flush();
    usleep(1000000);
}

$elapsed_time = microtime(true) - $begin_time;

$timer_seconds = $elapsed_time; //10 seconds

$timer_seconds = $elapsed_time / 2; //5 seconds


/*I am writing to a DB - but you can use this to test */
$fp = fopen('times.txt', 'w');
fwrite($fp, 'Time Elapsed: '.$timer_seconds);
fclose($fp);

Feel free to try the code as it has baffled me on why the $elapsed_time needs to be divided by two. Maybe I have misunderstood something?

Thanks all for any help

Update

I have updated the code so that anyone can try this out and it will write to a text file to view the output.

Answer 1

Experiment:

Significant changes from original code:

1) Using implicit_flush and all buffers are flushed before doing anything.
2) Instead of outputting just a space, the code outputs the iteration number and 1023 bytes of other data to tell the browser that we have good amount of output to display. A normal known trick.
3) Along with saving the time in the output text file, it also saves the total iterations that the code ran.

The code used:

<?php
// Tricks to allow instant output
@ini_set('implicit_flush', 1);
for ($i = 0; $i < ob_get_level(); $i++)
    ob_end_flush();
ob_implicit_flush(1);

//Your Code starts here
ignore_user_abort(true);
set_time_limit(0); 

$begin_time = microtime(true);
$elapsed_time = 0;

while(!connection_aborted())
{
    //this I changed, so that a looooong string is outputted
    echo $i++.str_repeat(' ',1020).'<br/>';
    flush();
    usleep(1000000);
}

$elapsed_time = microtime(true) - $begin_time;
$timer_seconds = $elapsed_time; //10 seconds

//Writes to file the number of ITERATIONS too along with time
$fp = fopen('4765107.txt', 'w');
fwrite($fp, 'Time Elapsed: '.$timer_seconds);
fwrite($fp, "\nIterations: ".$i);
fclose($fp);
?>

Live Demo:

• Now, here is the code to run: http://work.sktnetwork.com/so/4765107.php

• And here is the .TXT file it generates: http://work.sktnetwork.com/so/4765107.txt

---

What I got:

1) When code is run for 10 iterations and STOP button on browser is clicked, the output file shows 13 iterations with ~ 13.01 seconds taken.

2) When code is run for 20 iterations and STOP button on browser is clicked, the output file shows 23 iterations with ~ 23.01 seconds taken.

---

Inferences & Conclusion:

1) The script actually does NOT stops when the STOP button is clicked but after 2-4 seconds of clicking it. So, there are more iterations that what appears in the browser.

2) The number of iterations is SAME as the number of seconds it takes to execute, as shown in output file.

Therefore, there is no error and apparently no bugs, it's just the latency time between clicking the STOP button and the script actually stopping.

---

Notes:

1) Server: A Linux VPS.
2) Clients tested: Firefox and Chrome.
3) As the script ends 2-4 seconds after STOP is clicked, it takes around 3-4 seconds for the output file to be updated for the current test.

Answer 2

Summary: (this post became epic as I tested various avenues)

PHP takes -typically two- while-loop iterations to detect a disconnect or to deliver output. This delay could come from the web server software, host computer, client computer, and client browser but then it should vary depending on the sleep per iteration. More likely the delay is coming from internal execution or output process of PHP (perhaps from a small internal buffer or the interrupt handling process).

Epic Post:

Counting your execution time from [Refresh] or URL-submit isn't exactly an accurate starting point - any number of steps may be required first and could add to the delay:

1. DNS lookup required (with TCP overhead)
2. TCP connection established with server
3. Web Server creates a thread or child
4. Web Server decides how to deal with the request
5. PHP may need to start up
6. PHP may need to convert your source into opcode

So rather than measuring [Refresh] -> [Stop] time and comparing it to the number recorded by PHP, I measured displayed output to recorded output - which reduces the delay measurement to mostly just within PHP (although Server/Browser will effect). The modified script can't run away (it terminates after a fixed number of iterations), clears the default php.ini buffering, and reports an iteration count on screen and in the timing file. I ran the script with various $sleep periods to see the effects. The final script:

<?php
date_default_timezone_set('America/Los_Angeles'); //Used by ob apparently
ignore_user_abort(true); //Don't terminate script because user leaves
set_time_limit(0); //Allow runaway script !danger !danger
while (@ob_end_flush()) {}; //By default set on/4K in php.ini

$start=microtime(true);

$n=1000;
$i=0;
$sleep=100000;// 0.1s
while(!connection_aborted() && $i<$n) {
    echo "\n[".++$i."]";flush();
    usleep($sleep);
}

$end=microtime(true);

file_put_contents("timing.txt",
    "#\$sleep=".($sleep/1000000).
      "s\n/ s=$start / e=$end ($i) / d=".($end-$start)."\n",
    FILE_APPEND);
?>

Results: (multiple runs concatenated, run in Firefox)

# On-screen $i / start utime / end utime (current $i) / delta utime

#$sleep=1s
2 / s=1296251342.5729 / e=1296251346.5721 (4) / d=3.999242067337
3 / s=1296251352.9094 / e=1296251357.91 (5) / d=5.000559091568
#$sleep=0.1s
11 / s=1296251157.982 / e=1296251159.2896 (13) / d=1.3075668811798
8 / s=1296251167.5659 / e=1296251168.5709 (10) / d=1.0050280094147
16 / s=1296251190.0493 / e=1296251191.8599 (18) / d=1.810576915741
4 / s=1296251202.7471 / e=1296251203.3505 (6) / d=0.60339689254761
16 / s=1296251724.5782 / e=1296251726.3882 (18) / d=1.8099851608276
#$sleep=0.01s
42 / s=1296251233.0498 / e=1296251233.5217 (44) / d=0.47195816040039
62 / s=1296251260.4463 / e=1296251261.1336 (64) / d=0.68735003471375
150 / s=1296251279.2656 / e=1296251280.901 (152) / d=1.6353850364685
379 / s=1296252444.7587 / e=1296252449.0108 (394) / d=4.2521529197693
#$sleep=0.001s
337 / s=1296251293.4823 / e=1296251294.1515 (341) / d=0.66925406455994
207 / s=1296251313.7312 / e=1296251314.1445 (211) / d=0.41328597068787
792 / s=1296251324.5233 / e=1296251326.0915 (795) / d=1.5682451725006

(Opera doesn't display numbers during, but displays final numbers which roughly match)
(Chrome doesn't display anything during/after the test)
(Safari doesn't display anything during/after the test)
(IE doesn't display anything during/after the test)

The first number on each line indicates the number displayed on screen once [stop] was pressed (manually recorded).

A few points:

• Your stop point is quantized to the nearest $sleep period (1/10s in the above script) because the script only checks at the beginning of each while iteration, there's some variation because the usleep method isn't a perfect delay.
• The browser and server you're using makes a difference. The flush manual page notes "may not be able to override the buffering scheme of your web server, and has no effect on any client-side buffering in the browser." Then goes into more detail about both server and client issues. [Server: WinXPsp3 / Apache 2.2.17 / PHP 5.3.3 Client: WinXPsp3 / FireFox 3.6.13]

Analysis:

In all but the 0.001s delay we're seeing a 2 iteration delay between [stop] and PHP catching it (or Firefox or Apache reporting). With a 0.001s delay it varies a bit, the average being ~4 iterations or 0.004s - this is probably getting close to detection speed threshold.

When the delay time is 0.1s or above we're seeing an execution time closely matching $sleep * {recorded iterations}.

When the delay time is below 0.1s we're seeing execution delays greater than the sleep time. This is likely from the cost of checking client-connection, incrementing $i, outputting text, and flushing the buffer per iteration. The discrepancy between the execution time and $i*$sleep is pretty linear suggesting it takes ~0.001s/iteration to complete these tasks (with a 0.01s sleep it's 0.0008, while a 0.001s sleep works out to 0.0010 - probably a result of increased MALLOC/output).