Search code examples
phptimemicrotime

Can you figure out this PHP timing issue?


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.


Solution

  • 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:


    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.