[nick2price]

Hi guys, just wanted to start a fresh thread on this topic so it is easier for people to search. So, I am starting the profiling of our system. Our entry file to the system is index.php, and using your suggestions from before, its starts like

// init sessions
session_start() or die("Failure Starting Session");

// includes
require("inc/config.php");
require("inc/functions.php");

// prevent browser cacheing
header("Cache-Control: no-cache");

// connect to database
mysql_connect($sqlhost, $sqluser, $sqlpass) or die(mysql_error());
mysql_select_db($sqldb) or die(mysql_error());

if (ENABLE_SQL_PROFILER) {
    mysql_query("SET PROFILING = 1");
    
    /**
     * A function to collect and write the profiling info to
     * a log file. It'll be executed when the script execution
     * ends. (See below the function.)
     */
    function write_to_log()
    {
        $profilingResult = mysql_query("SHOW PROFILES");
        if ($profilingResult) {
            // Collect the duration info
            $queryCount = 0;
            $totalDuration = 0.0;
            while ($row = mysql_fetch_assoc($profilingResult)) {
                ++$queryCount;
                $totalDuration += (double)$row["Duration"];
            }
            
            // Stop profiling
            mysql_query("SET PROFILING = 0");
            
            // Write the profiler data to the log file.
            // Note that the CWD of a shutdown function is not
            // reliable. Use an absolute path to the log file.
            $filePath = "inc" . "/mysql_profiler.log";
            $line = sprintf("Count: %d, duration: %.9f\n", $queryCount, $totalDuration);
            if (!file_put_contents($filePath, $line, FILE_APPEND)) {
                trigger_error("Failed to write to log file. Check permissions!", E_USER_ERROR);
            }
        }
        else {
            trigger_error("SHOW PROFILES query failed: " . mysql_error(), E_USER_ERROR);
        }
    }
    
    // Register the write_to_log function up to be executed when the
    // PHP script execution is about to end. All queries your code
    // will execute should be done at this time, so the profiling
    // info will be complete.
    register_shutdown_function('write_to_log');
}

After this, I pretty much go straight into logging into the system

if($_POST['login_username']){
	// get posted details
	$login_username = mysql_real_escape_string($_POST['login_username']);
	$login_password = mysql_real_escape_string($_POST['login_password']);
	

	// query database for matching active user
	$result = mysql_query("SELECT `id`,`loginstatus` FROM `users` WHERE `username`='".$login_username."' AND `password`='".$login_password."'");

...

Then, it pretty much gives the user a session and loads a lot more php files and other things. Now, I dont know if what I done at the top is enough to profile all queries in every php file, or if I need more. At the moment, I do get data written to my file, but its pretty much

Quote

Count: 0, duration: 0.000000000
Count: 15, duration: 0.000881000
Count: 15, duration: 0.000162000
Count: 15, duration: 0.000184000
Count: 15, duration: 0.000186000
Count: 15, duration: 0.000921000
Count: 15, duration: 0.000896000
Count: 15, duration: 0.001320000
Count: 15, duration: 0.000193000
Count: 15, duration: 0.000180000
Count: 4, duration: 0.015574000
Count: 0, duration: 0.000000000

Also, when I look for examples online, they all use the command line to set profiling to 1, but everything I am doing is on a live server, so I dont think I can or need to do this. Does it look like I am getting the right results and is there anyway to get the name of the query being profiled? Any advise appreciated

Cheers

[CTphpnwb]

Why would you define a function inside an if statement? Call it or don't, I'd put the definition at the top or the bottom of the file or I'd make it an include at the top.

[Atli]

That part of the code is actually based of an example I gave him. The reason I defined the log function inside the if statement is that the entire profiling code should have as little an effect on the code as possible when not enabled. When defined inside the if clause it will be completely ignored when that is the case. It's a minor concern, granted, but I'd still prefer it to not exist when it's not needed.

[Atli]

nick2price said:

and is there anyway to get the name of the query being profiled?

Sure if you look at the while loop of the log_to_file function, you'll see that it's handling the result set from the SHOW PROFILES call. It only uses the Duration value, but each row also contains the query that was being profiled as well. Look up the SHOW PROFILES syntax in the MySQL manual for full details on that.

[nick2price]

Kool, wicked. So just to clarify, where I have the code at the moment, it will continue running and profiling whenever a query is made (even queries in different classes), until the session is finished which I presume is when the user logs out. I am trying to go through the code slowly so I understand everything, and there are a couple of things which confuse me. I have tried an online search but cant seem to find anything. At the moment, it will only enter the if statement if the following is true

if (ENABLE_SQL_PROFILER) {

So what sets that to true?

Also, once in the if statement, does it stay in there until the session is finished? The reason I ask this is because of this code

register_shutdown_function('write_to_log');

I cant work out if on shuting down the function, it is recalling the function to open again (basically recursion), or if its just shut down once everything is completed?


Nick

[Atli]

Quote

So what sets that to true?

It's a constant, defined using the define() function. It's just a convenient way to allow you to turn the profiling on or off in a confit file somewhere, rather than having to edit the code directly.

Quote

I cant work out if on shuting down the function, it is recalling the function to open again (basically recursion), or if its just shut down once everything is completed

The register_shutdown_function function makes PHP call the given function just before the script execution ends. In this case I want the log_to_file function to execute after all your MySQL queries have completed, to sum up the duration and print it to the file.

[nick2price]

Quote

It's a constant, defined using the define() function. It's just a convenient way to allow you to turn the profiling on or off in a confit file somewhere, rather than having to edit the code directly.

Sorry, stupid question here, so do I need to actually set this to true in a config file or something or is it true by default? Should I be adding something like the following to my config file?

define(ENABLE_SQL_PROFILER, true);

And one last silly question before I call it a night and start a fresh tomorrow. I have checked out the syntax here
http://dev.mysql.com...w-profiles.html

That shows me nothing so I checked out the SHOW PROFILE syntax instead, which has several types, but I dont see one called duration. So where did you get the duration row from as I am trying to see what I could use to get the query names.

cheers

[Atli]

Quote

so do I need to actually set this to true in a config file or something or is it true by default?

Yes, you set this in your config file. By default PHP assumes unset constants are strings that were accidentally left unquoted, so I suppose it will default to true. It should produce a notice in that case though. You should just set it yourself, to avoid anything like that.

Quote

That shows me nothing so I checked out the SHOW PROFILE syntax instead, which has several types, but I dont see one called duration. So where did you get the duration row from as I am trying to see what I could use to get the query names.

Look closer at that manual page. About half way down there is a long example of various uses of the syntax and their result sets. The simplest use of it, the one I used, is the first one. The third column in the result set has the query that it's profiling.

This post has been edited by Atli: 14 September 2012 - 06:22 PM
Reason for edit:: Accidental double post.

[nick2price]

Hey, I am still having a bit of problem getting the query name printed. From what I can see, I could use query or status. So in the while loop, I have added

$queryName += $row["Status"];

I am assuming it returns a String so I dont need to cast it. Then in the sprintf, I have just added it

$line = sprintf("Count: %d, duration: %.9f\n", $queryCount, $totalDuration, $queryName);

I dont seem to be getting any output for the name though, and when I mess about with it to only print out the status, it seems to print out 0.0000.

Obviously I am doing something wrong, am I even close here?

Cheers

[Atli]

The code I wrote jus calculated the sum of all the queries and printed that as one line. If you want to print the results for each individual query you need to change that. It's not enough to just add a couple of lines to that code, you need to rewrite the loop so it adds a new line each time it iterates over the result .

You may want to read more thoroughly the docs for the sprintf function. You are not using it correctly there. It's basically just a complex string replacement function, where you add type specific placeholders, like %s for strings, or %f for floating point numbers, and then you list the variables that replace them after the string in the function parameter list. It's a very useful function. Well worth learning properly.

Quote

$queryName += $row["Status"];

In this scenario you want to be using the Query field, not the Status field. That field belongs to another version of the syntax than I was using. However adding the strings into one big string doesn't make much sense for yor purposes. You should be handling them individually.

Also, The += operator adds numbers. If you want to concat strings you need to do .=.

[nick2price]

Just out of interest, if I want to get a lot more detail from the test, would it be better to just use something like XDebug or Zend Studio? Whenever I try to find some example code for what I am doing here, everyone seems to just mention these tools.

[Atli]

I'm not exactly sure how far those go when dealing with database performance. The code we have been dealing with so far has been profiling MySQL queries only, using MySQLs own profiling tools. XDebug, at far as I am aware, just profiles PHP code. Of course that can give you a good idea which of your queries are running slow, by observing the PHP code that executes them.

You should probably be starting with that in any case, and optimizing the biggest bottleneck first, whether that is a database query or not.

[CTphpnwb]

Atli, on 14 September 2012 - 07:41 PM, said:

That part of the code is actually based of an example I gave him. The reason I defined the log function inside the if statement is that the entire profiling code should have as little an effect on the code as possible when not enabled. When defined inside the if clause it will be completely ignored when that is the case. It's a minor concern, granted, but I'd still prefer it to not exist when it's not needed.

In that case I'd do something like this:

<?php
if($sometest) {
	include "something.php";
}

something.php:

<?php
//other code here...

foo();
// other code here...

function foo() {
	//Do something
}

This way nothing gets included unless the $sometest is true, but it's clear that foo() does get called when that happens.