strange php timing issue that makes no sense.

Discussion in 'OT Technology' started by crotchfruit, Nov 23, 2003.

  1. crotchfruit

    crotchfruit Guest

    brief background: i'm writing a php+mysql website. one of my util php files declares a global $START_TIME as a float using this function:

    Code:
    function getmicrotime()
    { 
        list($usec, $sec) = explode(" ",microtime()); 
        $sec = ((int)$sec) % 10000; //reduces precision error 
        return ((float)$usec + (float)$sec); 
    } 
    $START_TIME = getmicrotime();
    
    then at the end of each page's skeleton i print out the new getmicrotime() - $START_TIME so i can see how long each page takes to complete. this was working great.. the pages were being generated in about 0.01 - 0.02 seconds.

    so i started writing one of the DB admin pages (to add/delete elements in the DB.) it was working great too. the thing is, once i added more than 3 elements into a specific table, my pages jumped from 0.015 seconds to 0.250 seconds!

    i've spent awhile debugging, and all of my experimental data points to a coding problem, but i wanted to isolate which exact function call is adding all this extra execution time..

    so i went through and started echoing the getmicrotime()-$START_TIME at various places in my code. i eventually narrowed it down to this:

    Code:
    global $START_TIME;
    $ttaken = getmicrotime() - $START_TIME;
    echo sprintf('TAG1- Page generated in %5.3f seconds<br>', $ttaken);
    
    echo $this->body;
            
    $ttaken = getmicrotime() - $START_TIME;
    echo sprintf('TAG2- Page generated in %5.3f seconds<br>', $ttaken);
    
    all my other tag intervals show almost zero incremental time. but sure enough the output i see between this interval is:

    Code:
    TAG1- Page generated in 0.019 seconds
    ...body is echo'd...
    TAG2- Page generated in 0.233 seconds
    
    i don't understand why an echo would take so long. the $this->body is maybe 1-2 Kb (just displaying the DB data in simple HTML.)

    the weird thing is that when i drop my table elements down to 3, the TAG2 line reads 0.02X (quick) instead of 0.2XX (slow).. and when i go back up to 4+ elements the delay goes back to slow... even though the extra elements are maybe 100bytes more of HTML to display.

    argh! what's going on?
     
  2. Astro

    Astro Code Monkey

    Joined:
    Mar 18, 2000
    Messages:
    2,047
    Likes Received:
    0
    Location:
    Cleveland Ohio
    Have you tried creating a bare-bones script minus the class? Have you tried a query with just the 4th field?

    I don't see anything wrong with the code. You either have some some more code that is acting funky or you hit a quirk in PHP.
     
  3. crotchfruit

    crotchfruit Guest

    ok, now i'm convinced that this is a php quirk of some sort. i took the original code:

    Code:
    global $START_TIME;
    $ttaken = getmicrotime() - $START_TIME;
    echo sprintf('TAG1- Page generated in %5.3f seconds<br>', $ttaken);
    
    echo $this->body;
            
    $ttaken = getmicrotime() - $START_TIME;
    echo sprintf('TAG2- Page generated in %5.3f seconds<br>', $ttaken);
    

    where, when the number of elements i was displaying was 3 or less, would execute with near-instant time (i.e. the TAG2 line would read TAG1+0.001 seconds), and added a second echo to it:

    Code:
    global $START_TIME;
    $ttaken = getmicrotime() - $START_TIME;
    echo sprintf('TAG1- Page generated in %5.3f seconds<br>', $ttaken);
    
    echo $this->body;
    echo $this->body;
            
    $ttaken = getmicrotime() - $START_TIME;
    echo sprintf('TAG2- Page generated in %5.3f seconds<br>', $ttaken);
    
    now it jacks up to 0.25 seconds instead of 0.001 seconds doing the exact same output as the previous version! argh! i then added more duplicate echos, and i can see that the time goes up by about 0.2 seconds per echo! i tried replacing echo with print, same results. this shouldn't be happening speed-wise (i'm on dsl, server is fat pipe, and obviously the page is capable of loading in 0.02 seconds.

    more data i just got:

    the strlen of $this-body, when it takes 0.001 seconds, is 7.5K. the strlen when it takes 0.2 seconds is 9K.

    then i tried this: i took the 0.001 text (0.001 second to echo) and did this:

    Code:
    global $START_TIME;
    $ttaken = getmicrotime() - $START_TIME;
    echo sprintf('TAG1- Page generated in %5.3f seconds<br>', $ttaken);
    
    echo $this->body;
            
    $ttaken = getmicrotime() - $START_TIME;
    echo sprintf('TAG2- Page generated in %5.3f seconds<br>', $ttaken);
    
    echo $this->body;
            
    $ttaken = getmicrotime() - $START_TIME;
    echo sprintf('TAG3- Page generated in %5.3f seconds<br>', $ttaken);
    
    now TAG1->TAG2 takes 0.001 seconds, but TAG2->TAG3 takes 0.2+ seconds. ARGH!#KLJUF)@*(J@)$FJ)WERFJDEFDFKLJ!!!(_$$@($(@
     
  4. crotchfruit

    crotchfruit Guest

    ok.. problem solved (i think..)

    looks like it was an output bufferring issue, and that my connection is not as quick as i thought.

    i'm guessing from my experimental data that my default php state had set the output buffer to 8K (?).. so that when i went over 8K it sent the actual HTML to the client, which was causing the time delay.

    i added ob_start() to the beginning of my skeleton, and only flush it at the end (after adding the final timestamp to the buffer.) looks like this overrides the default buffer flush level of 8K (which must exist because echoing code less than that did not produce a time delay) and lets me "echo" everything into a memory buffer to be transmit at once.

    the end result is that the time-to-client is the same, but now i get accurate page-generation timestamps.

    hope this helps anyone else who hits the same problem :eek3:
     

Share This Page