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).

Answer 3

You're relying on connection_aborted() to be true the moment you hit the 'Stop' button in your browser, but have shown no evidence that you have verified that this is the case. In fact, it is not.

You've forgotten how "connection aborted" checking happens in networking. An application (php in this case) doesn't know what's happened until it tries to write to the pipe.

The first comment on the documentation for connection_abort() says: "In order to detect a disconnection inside the script we need to flush the buffer (it is only when the the server tries to send the buffer content that it will see that the connection is broken)."

So I do not believe that you could reliably use connection_abort() in this way.

Rest assured, microtime() works properly.

Answer 4

connection_aborted() can only detect disconnection when the buffer is sent. But flush() does not necessarily sent the buffer. So the loop keeps iterating until the buffer is filled and indeed flushed.

For more details please refer to the manual pages of the named functions.

Answer 5

Using your script out of the box, does not work properly on Ubuntu, using Chrome to access the page. The loop just continues, had to restart Apache. On the other end, adding ob_end_flush() at the top, resolves that issue, plus the timer is actually correct.

ob_end_flush();
ignore_user_abort(true); 
set_time_limit(0);

$begin_time = microtime(true);

$elapsed_time = 0;

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

$elapsed_time = microtime(true) - $begin_time;

$timer_seconds = $elapsed_time; 
error_log(var_export($timer_seconds, true));


$timer_seconds = $elapsed_time / 2; 
error_log(var_export($timer_seconds, true));

If you run this and look at the error log, you'll see that $elpased_time is correct on the first run, no need to divide by too. As per why your code behaves like that, i don't know as it doesn't even work on my machine.

Answer 6

This is not an "Issue" so much as "by design"

It is a function of the way http works.

When sending a web page to a client (browser) the server 'MUST' send a content-length header. Now it cannot know the length of the content until it has got it all from the script.

So servers will buffer the script output until the script finishes.

This is where the vagaries come in. depending upon the server and even different versions of the same server, it may or may not check whether the client has disconnected on a regular basis and if it does, those checks can be at differing time intervals. which may even change depending on how busy the server is.

PHP has no control over the connection to the client, it can only ask the server if the connection still exists. The server may or may not tell it the truth. So the script continues to run (at the time the server may not know).

So why did Mikushi's work after adding the ob_end_flush() at the START of the script?

Well thats because it turned on another feature of http called chunk transfer. This allows data to be sent in chunks each with a special version of the content-length header (it doesn't actually say that, it just sends the next chunk length)

Try Mikushi's script with Wireshark and you will see the encoding, an example is shown here

HTTP/1.1 200 OK
Date: Tue, 01 Feb 2011 11:52:35 GMT
Server: Apache/2.2.3 (CentOS)
X-Powered-By: PHP/5.1.6
Connection: close
Transfer-Encoding: chunked
Content-Type: text/html; charset=UTF-8


7 <== this is the content-length 
<pre>0

2 <== this is the content-length 
1

2 ditto ...
2

2
3

2
4

2
5

So this means its impossible (yes Tomalak you got me :) ) to know when the server is going to terminate the connection and therefore return true for connection_aborted() until you test the actual server involved. Because each one is different. Even the web browser may do some stuff that delays the actual close, which may further muddy the issue.

DC