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.

Lifegiving

Don't use that microtime_float function. Use the true paramter to microtime(true); which was introduced in PHP 5.0.0... Also, how are you counting the 5 seconds? – Fishmonger

@Pekka - I am using Linux hosting to test this. – Lifegiving

@Fishmonger - Ah ok. I have used that but its still the same issue where elapsed time is twice as much as the correct time that has passed. Edited question to make use of microtime(true); – Lifegiving

How do you "stop" your script ? – Diogenes

Also note that echo and flush are not free. So don't expect 5 loop iterations to take exactly 5 seconds. I'm not saying it should be much more than that (I'd be very surprised at anything more than 5.25 seconds or so), but it won't be 5 flat... – Fishmonger

@Diogenes - I hit the stop button on my browser and then the connection_aborted() should indicate that I am not at the other end due to the echo ' '; flush();. – Lifegiving

@Fishmonger - you are right, I am expecting a degree of error but its double what I am timing. In fact, I would be happy if it was off by a second or two but its much more than that! – Lifegiving

Try bringing the usleep time up. The cost of flush and echo should be pretty constant per iteration. So if you make the sleep time 5 seconds (for a total sleep time of 25 seconds), that would cause 5 iterations. So if your output is 30 seconds, you know echo and flush combine for 1 second per iteration (ludicrous, I know)... – Fishmonger

@Fishmonger - you won't believe this. I did what you said but the actual recorded time was 50.000932!? What the hell. – Lifegiving

I did another test. Kept it at 1 second, the usleep above the echo and flush. For actual 10 seconds it gave 15. For actual 15 seconds it gave 20. For actual 20 it gave 25. Its becoming more random and random.Has anyone tried this and what where your findings? Is it just me? – Lifegiving

@Abs: The first comment on php.net/manual/en/function.connection-aborted.php 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)." – Halfwitted

@Tomalak - that is why I have the echo and flush. I have also made use of ob_implicit_flush(); but that made no difference either. Is that what you meant? – Lifegiving

What is the purpose of this? What are you trying to accomplish? Maybe there is an easier way to get to where you want instead of trying to figure out how its working. – Prewar

@Abs: From your 10, 15, 20 test it alway seems to delay 5 seconds. What are the results of stopping after 7, 17, 201, 501 seconds? Graph that. A problem between php and the browser should tend to be about the same number of seconds for each trial. – Stunsail

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.

Saarinen

Thank you for your answer and length post, I've learnt a lot! – Lifegiving

@Abs, I am happy to note that it helped you learning. Please consider accepting the answer, if you like it. – Saarinen

To be consistent you should have used ++$i on your echo line in the code - it makes the output iteration value 1 based the same way your stored value is. Your "what I got" section should read 11/13 and 21/23 (if you're using 1 based counting) or 10/12 and 20/22 (if you're using zero based). – Jealous

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

Jealous

+1 Thank you for your answer and length post, I've learnt a lot! – Lifegiving

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.

Halfwitted

Granted when I press it is unlikely for connection_aborted() to pick up on this straight away but the next iteration (a second later) it does. So my timing can be wrong by a second or two but not more than twice as much as it really takes. – Lifegiving

@Tomalak - can you explain please, why it does not? – Lifegiving

@Abs: Because your timing is out by a factor of two from what you expect, hence the original question. – Halfwitted

My timing is out but I meant can you explain why you think connection_aborted is the problem? I have read the docs and that same line and it says as long as you flush output then connection_aborted will check if user is still connected. So my loop can only been wrong by a second since the flush needs to be accounted for. – Lifegiving

@Abs: Logical deduction. You have a problem with code in which everything but connection_aborted is trivial; thus, the problem likely lies with connection_aborted either misbehaving or being misunderstood. – Halfwitted

@Tomalak connection_aborted can be fast. if you tell the browser to stop it 'Should' do a graceful close. this advises the network layer the connection is no good. the next read or write by php will return an error indicating such. connection_abort can take many minutes if the connection failed, such as someone pulled the plug on the remote pc. – Shool

@DeveloperChris: "can" and "should" are all well and good, but -- as I tried to explain to the OP -- that is clearly not happening here by virtue of the question existing. – Halfwitted

@Tomalak you are correct. A little more thought on my behalf would have been wise. – Shool

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.

Extranuclear

Nope, I have tested the output flushing by using my browser to see a character being outputted every second. So it is actually flushing. – Lifegiving

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.

Virtue

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

Shool