Profiling Database Load

Profiling database load is as simple as counting the number of times that a query is run on the database. Last week we added memory reporting to our profiler. This week we will update it to handle database queries and find places where the database is doing more work than it needs to. First, here is the code:

<?php
class Profiler{
o
oconst PROFILER_START_GLOBAL = 'profiler_start';
o
oconst DB_TYPE_READ = 'db_read';
oconst DB_TYPE_EDIT = 'db_edit';
oconst DB_TYPE_CREATE = 'db_create';
oconst DB_TYPE_DELETE = 'db_delete';
o
ostatic protected $all_profilers;
o
ostatic protected $current_index = 0;
oprotected $index;
oprotected $name;
oprotected $start_time;
oprotected $start_memory;
oprotected $db_read = 0;
oprotected $db_edit = 0;
oprotected $db_create = 0;
oprotected $db_delete = 0;
oprotected $checkpoints;
o
ofunction __construct(){
o++self::$current_index;
o$this->set_index(self::$current_index);
oself::$all_profilers[self::$current_index] = &$this;
o}
o
ostatic function init_profiler($name='Main'){
o$prof = new Profiler();
o$prof->set_start_time(microtime(true));
o$prof->set_start_memory(memory_get_usage());
oif($prof->get_index() == 0 && self::global_start_exists()){//check for the start time global since this is the main profiler
o$prof->set_global_start();
o$prof->set_start_memory(0);
o}
o$prof->set_name($name);
o
oreturn $prof;
o}
o
ofunction get_index(){return $this->index;}
oprivate function set_index($index){$this->index = $index;}
o
oprivate function get_start_time(){
oreturn $this->start_time;
o}
oprivate function set_start_time($time){$this->start_time = $time;}
o
oprivate function get_start_memory(){
oreturn $this->start_memory;
o}
o
oprivate function set_start_memory($memory){$this->start_memory = $memory;}
o
ostatic private function global_start_exists(){
oreturn ($GLOBALS[self::PROFILER_START_GLOBAL]);
o}
ofunction set_global_start(){
oif(self::global_start_exists()){
o$this->set_start_time($GLOBALS[self::PROFILER_START_GLOBAL]);
o}
o}
o
ofunction get_name(){return $this->name;}
ofunction set_name($name){$this->name = $name;}
o
oprivate function get_db_read(){
oreturn $this->db_read;
o}
oprivate function get_db_edit(){
oreturn $this->db_edit;
o}
oprivate function get_db_create(){
oreturn $this->db_create;
o}
oprivate function get_db_delete(){
oreturn $this->db_delete;
o}
ostatic function add_db_read(){
oforeach(self::$all_profilers as &$profiler){
o++$profiler->db_read;
o}
o}
ostatic function add_db_edit(){
oforeach(self::$all_profilers as &$profiler){
o++$profiler->db_edit;
o}
o}
ostatic function add_db_create(){
oforeach(self::$all_profilers as &$profiler){
o++$profiler->db_create;
o}
o}
ostatic function add_db_delete(){
oforeach(self::$all_profilers as &$profiler){
o++$profiler->db_delete;
o}
o}
o
ofunction get_elapsed_time(){
o$current_time = microtime(true);
o$elapsed = $current_time - $this->get_start_time();
oreturn $elapsed;
o}
o
ofunction get_elapsed_memory(){
o$current_mem = memory_get_usage();
o$elapsed = $current_mem - $this->get_start_memory();
oreturn $elapsed;
o}

o
ostatic function add_profiler_checkpoint($checkpoint_name,$index=1){
o$profiler = self::$all_profilers[$index];
oif(!$profiler){
o$profiler = Profiler::init_profiler($checkpoint_name.'_profiler');
o}
o$profiler->add_checkpoint($checkpoint_name);
o}
o
ofunction add_checkpoint($checkpoint_name){
o$checkpoint = array();
o$checkpoint['name'] = $checkpoint_name;
o$checkpoint['time'] = $this->get_elapsed_time();
o$checkpoint['memory'] = $this->get_elapsed_memory();
o$checkpoint[self::DB_TYPE_READ] = $this->get_db_read();
o$checkpoint[self::DB_TYPE_EDIT] = $this->get_db_edit();
o$checkpoint[self::DB_TYPE_CREATE] = $this->get_db_create();
o$checkpoint[self::DB_TYPE_DELETE] = $this->get_db_delete();
o$this->checkpoints[] = $checkpoint;
o}
ofunction get_checkpoints(){return $this->checkpoints;}
o
ofunction get_result($newline='<br>'){
o$total_time = $this->get_elapsed_time();
o$total_memory = $this->get_elapsed_memory();
o$total_db_read = $this->get_db_read();
o$total_db_edit = $this->get_db_edit();
o$total_db_create = $this->get_db_create();
o$total_db_delete = $this->get_db_delete();
o$profiler_text = '';
o$profiler_text .= 'Profiler '.$this->get_index().': '.$this->get_name().$newline;
oif(count($this->get_checkpoints()) > 0){
o$profiler_text .= 'Checkpoints: '.count($this->get_checkpoints()).$newline;
o$profiler_text .= '--Checkpoint Name-- --Time-- --Memory-- --Read-- --Edit-- --Create-- --Delete--'.$newline;
o$prev_checkpoint = array('time'=>0,'memory'=>0,self::DB_TYPE_READ=>0,self::DB_TYPE_EDIT=>0,self::DB_TYPE_CREATE=>0,self::DB_TYPE_DELETE=>0);
oforeach($this->get_checkpoints() as $checkpoint){
o$time = round($checkpoint['time']-$prev_checkpoint['time'],4);
o$memory = round($checkpoint['memory']-$prev_checkpoint['memory'],4);
o$db_read = round($checkpoint[self::DB_TYPE_READ]-$prev_checkpoint[self::DB_TYPE_READ],4);
o$db_edit = round($checkpoint[self::DB_TYPE_EDIT]-$prev_checkpoint[self::DB_TYPE_EDIT],4);
o$db_create = round($checkpoint[self::DB_TYPE_CREATE]-$prev_checkpoint[self::DB_TYPE_CREATE],4);
o$db_delete = round($checkpoint[self::DB_TYPE_DELETE]-$prev_checkpoint[self::DB_TYPE_DELETE],4);
o$timepercent = self::get_percent($prev_checkpoint['time'],$checkpoint['time'],$total_time);
o$mempercent = self::get_percent($prev_checkpoint['memory'],$checkpoint['memory'],$total_memory);
o$db_read_percent = self::get_percent($prev_checkpoint[self::DB_TYPE_READ],$checkpoint[self::DB_TYPE_READ],$total_db_read);
o$db_edit_percent = self::get_percent($prev_checkpoint[self::DB_TYPE_EDIT],$checkpoint[self::DB_TYPE_EDIT],$total_db_edit);
o$db_create_percent = self::get_percent($prev_checkpoint[self::DB_TYPE_CREATE],$checkpoint[self::DB_TYPE_CREATE],$total_db_create);
o$db_delete_percent = self::get_percent($prev_checkpoint[self::DB_TYPE_DELETE],$checkpoint[self::DB_TYPE_DELETE],$total_db_delete);
o$profiler_text .= $checkpoint['name'];
o$profiler_text .= ' ';
o$profiler_text .= $time.'('.round($timepercent,2).'%)';
o$profiler_text .= ' ';
o$profiler_text .= $memory.'('.round($mempercent,2).'%)';
o$profiler_text .= ' ';
o$profiler_text .= $db_read.'('.round($db_read_percent,2).'%)';
o$profiler_text .= ' ';
o$profiler_text .= $db_edit.'('.round($db_edit_percent,2).'%)';
o$profiler_text .= ' ';
o$profiler_text .= $db_create.'('.round($db_create_percent,2).'%)';
o$profiler_text .= ' ';
o$profiler_text .= $db_delete.'('.round($db_delete_percent,2).'%)';
o$profiler_text .= $newline;
o$prev_checkpoint = $checkpoint;
o}
o}
o$final_time = round($total_time-$prev_checkpoint['time'],4);
o$final_memory = round($total_memory-$prev_checkpoint['memory'],4);
o$final_db_read = $total_db_read-$prev_checkpoint[self::DB_TYPE_READ];
o$final_db_edit = $total_db_edit-$prev_checkpoint[self::DB_TYPE_EDIT];
o$final_db_create = $total_db_create-$prev_checkpoint[self::DB_TYPE_CREATE];
o$final_db_delete = $total_db_delete-$prev_checkpoint[self::DB_TYPE_DELETE];
o$final_time = $total_time-$prev_checkpoint['time'];
o$final_percent_time = self::get_percent($prev_checkpoint['time'],$total_time,$total_time);
o$final_percent_memory = self::get_percent($prev_checkpoint['memory'],$total_memory,$total_memory);
o$final_percent_db_read = self::get_percent($prev_checkpoint[self::DB_TYPE_READ],$total_db_read,$total_db_read);
o$final_percent_db_edit = self::get_percent($prev_checkpoint[self::DB_TYPE_EDIT],$total_db_edit,$total_db_edit);
o$final_percent_db_create = self::get_percent($prev_checkpoint[self::DB_TYPE_CREATE],$total_db_create,$total_db_create);
o$final_percent_db_delete = self::get_percent($prev_checkpoint[self::DB_TYPE_DELETE],$total_db_delete,$total_db_delete);
o$profiler_text .= 'Final ';
o$profiler_text .= $final_time.'('.round($final_percent_time,2).'%)';
o$profiler_text .= ' ';
o$profiler_text .= $final_memory.'('.round($final_percent_memory,2).'%)';
o$profiler_text .= ' ';
o$profiler_text .= $final_db_read.'('.round($final_percent_db_read,2).'%)';
o$profiler_text .= ' ';
o$profiler_text .= $final_db_edit.'('.round($final_percent_db_edit,2).'%)';
o$profiler_text .= ' ';
o$profiler_text .= $final_db_create.'('.round($final_percent_db_create,2).'%)';
o$profiler_text .= ' ';
o$profiler_text .= $final_db_delete.'('.round($final_percent_db_delete,2).'%)';
o$profiler_text .= $newline;
o
o$profiler_text .= '-------';
o$profiler_text .= $newline;
o
o$profiler_text .= 'Total ';
o$profiler_text .= round($total_time,4);
o$profiler_text .= ' ';
o$profiler_text .= round($total_memory,4);
o$profiler_text .= ' ';
o$profiler_text .= $total_db_read;
o$profiler_text .= ' ';
o$profiler_text .= $total_db_edit;
o$profiler_text .= ' ';
o$profiler_text .= $total_db_create;
o$profiler_text .= ' ';
o$profiler_text .= $total_db_delete;
o$profiler_text .= $newline;
o
oreturn $profiler_text;
o}
o
ofunction get_percent($prev_checkpoint_value,$this_checkpoint_value,$total_value){
o$checkpoint_value = $this_checkpoint_value - $prev_checkpoint_value;
o$percent = $checkpoint_value / $total_value;
oreturn $percent*100;
o}
o
ostatic function get_all_results($newline='<br>'){
o$text = 'Profilers'.$newline;
oforeach(self::$all_profilers as $profiler){
o$text .= $profiler->get_result($newline);
o}
o$text .= '----------'.$newline;
oreturn $text;
o}
}

Note that I broke my queries up into 4 types, read, edit, create and delete, but you can use others as desired.

Usage

The database queries are incremented through the add functions (line 81). Simply use Profiler::add_db_read();  wherever the database is read. Use the other 3 add functions for their respective query types. For any large application it is worthwhile to have some sort of data interface class that can take care of connecting to the database and building queries for you. I use one and I only need to add a few lines of code to it to get it to count every query. What about custom queries? My data interface has a custom function which builds the connection for me and acts as a wrapper allowing me to add in profiler statements like this one. In my case I added a parameter to my custom query function. This parameter expects one of the DB_TYPE constants and uses it to decide which add function to call.

 Output

This week I made a major change to the output. I split the “final” section which represented the total into 2 sections, “Final” and “Total”. “Final” represents any time, memory or database queries that occurred between the last checkpoint and the output of the profile. As you would expect, “Total” represents to full total count for everything.

For more usage details see Profiler 1 and 2.