Home

Your premium source for custom modification services for phpBB

  logo

HomeForumsBlogMOD ManagerFAQSearchRegisterLogin

Comments February 29, 2008

Timing Queries in phpBB2

Filed under: Performance Tuning, phpBB — Dave Rathbun @ 5:16 pm Comments Off 

In the first post in this series I talked about the fact that phpBB2 already provides a mechanism for counting queries that are used to generate a page. Now I am going to take that a step further. For optimization purposes, I want to know how long the query processing took.

The changes I made were only to the includes/mysql4.php code. I did not bother making them for other database drivers since this is the only one I use. The first step is to set up another template variable to go along with the $num_queries value, and I called it $sql_time. It’s added at the top of the code so that it looks like this:

        var $db_connect_id;
        var $query_result;
        var $row = array();
        var $rowset = array();
        var $num_queries = 0;
        var $sql_time = 0.0;
        var $in_transaction = 0;

Once that value is set, I need to use it. There are a few things about the query process that I don’t really care about, such as the connection and so on. What I do care about is the time it takes to prepare, execute, and fetch rows from my query handle. The function that prepares the query (and executes it in the case of anything other than a SELECT query) is $db->sql_query(), then the fetching process (if needed) takes place in the $db->sql_fetchrow() or $db->sql_fetchrowset() functions.

sql_query()

I set up a variable at the beginning of this function to capture the time. I also set up a variable used to capture the microtime() result just before the query starts. And I wrote a custom function called microtime_duration() that calculates the difference between two microtime array values. So here is the code for the sql_query() function now:

        function sql_query($query = "", $transaction = FALSE)
        {
                //
                // Remove any pre-existing queries
                //
                unset($this->query_result);

                $my_sql_time = 0.0;
                $start = microtime();

                if( $query != "" )
                {
                        $this->num_queries++;
                        if( $transaction == BEGIN_TRANSACTION && !$this->in_transaction )
                        {
                                $result = mysql_query("BEGIN", $this->db_connect_id);
                                if(!$result)
                                {
                                        return false;
                                }
                                $this->in_transaction = TRUE;
                        }

                        $this->query_result = mysql_query($query, $this->db_connect_id);
                }
                else
                {
                        if( $transaction == END_TRANSACTION && $this->in_transaction )
                        {
                                $result = mysql_query("COMMIT", $this->db_connect_id);
                        }
                }

                $stop = microtime();
                $my_sql_time = microtime_duration($start, $stop);
                $this->sql_time = $this->sql_time + $my_sql_time;
                ...

There is more after that, but nothing that is different. What this does is capture the $start time before the query is processed, and the duration once the query is done. The total is added to the $sql_time variable defined earlier.

$sql_fetchrow() and $sql_fetchrowset()

I use the same technique for the next two functions. There is a new variable defined at the beginning of the function used to calculate the time before storing it, a $start value to capture the start time, and the call to the microtime_duration() function to do the calculation.

        function sql_fetchrow($query_id = 0)
        {
                $my_sql_time = 0;
                if( !$query_id )
                {
                        $query_id = $this->query_result;
                }

                if( $query_id )
                {
                        $start = microtime();
                        $this->row[$query_id] = mysql_fetch_array($query_id, MYSQL_ASSOC);
                        $my_sql_time = microtime_duration($start, microtime());
                        $this->sql_time = $this->sql_time + $my_sql_time;
                        return $this->row[$query_id];
                }
                else
                {
                        return false;
                }
        }
        function sql_fetchrowset($query_id = 0)
        {
                $my_sql_time = 0;
                if( !$query_id )
                {
                        $query_id = $this->query_result;
                }

                if( $query_id )
                {
                        unset($this->rowset[$query_id]);
                        unset($this->row[$query_id]);

                        $start = microtime();
                        while($this->rowset[$query_id] = mysql_fetch_array($query_id, MYSQL_ASSOC))
                        {
                                $result[] = $this->rowset[$query_id];
                        }
                        $my_sql_time = microtime_duration($start, microtime());
                        $this->sql_time = $this->sql_time + $my_sql_time;

                        return $result;
                }
                else
                {
                        return false;
                }
        }

Finishing Things Off

Now, just like my prior post where I echo the number of queries in the footer, I can echo the total SQL time in the footer. I can reference the class variable using $db->sql_time, retrieve it, format it as desired, and echo it using a standard template variable. I have the following line in the footer of my board:

Generated in 0.1582 seconds using 11 queries. (SQL 0.0060 Parse 0.1151 Other 0.0371)

The total page time is calculated by setting a start timer in the very first bit of code that is executed (in common.php to be precise) and the timer stops in includes/page_tail.php, just before I have to create the footer values. The SQL time is generated as described in this post. The Parse time is calculated by setting a timer just before and after the pparse() function, and the “Other” time is generated by subtracting the total parse and total SQL time from the overall page generation time.

Why am I focused on the parse time? If you look at that line, you will see that parsing takes more time by far (on a percentage basis) than either of the other two values. Since I am interested in making my system faster, the best place to look isn’t where things are already fast (my SQL time for 11 queries is only six thousandths of a second) but where things are currently slow. So that’s the next step I took in this investigation: what can I do about the slow parse times?

Stay tuned for more. I have numbers. I have statistics. I have some interesting conclusions to share. 8)

Supporting Information

Here is the code for the microtime_duration() function that I use to avoid having to write the same code over and over.

function microtime_duration($start, $end)
{
        list($usec, $sec) = explode(' ', $start);
        $starttime = floatval($usec + $sec);
        list($usec, $sec) = explode(' ', $end);
        $endtime = floatval($usec + $sec);
        $duration = $endtime - $starttime;

        return $duration;
}

No Comments

No comments yet.

RSS feed for comments on this post.

Sorry, the comment form is closed at this time.

Powered by WordPress