[nick2price]

Hi guys, I want to see how long all the sql statements take in our current system, so I can make changes and then see if I have managed to speed them up. So where I have something like

$result = mysql_query("SELECT `id`,`loginstatus` FROM `users` WHERE `username`='".$login_username."' AND `password`='".$encpassword."'");

Is it just a case of changing it to

$start = microtime(true);
$result = mysql_query("SELECT `id`,`loginstatus` FROM `users` WHERE `username`='".$login_username."' AND `password`='".$encpassword."'");
echo microtime(true) - $start;

And should I be ending the timer there, or should I do it once checks have been carried out? e.g.

if(mysql_num_rows($result)==1){
echo microtime(true) - $start;
..

Lastly, instead of echoing, is there anyway I can write it to a log file or something instead?

Cheers

[e_i_pi]

Your method is probably good enough for what you're doing, but if you want the numbers to come from MySQL (and therefore be as accurate as possible), you need to do one of two things, both of which use PROFILING.

The first is to get the overall execution time:

SET PROFILING = 1;
SELECT * FROM MyTable; -- this is your query
SHOW PROFILES;
SET PROFILING = 0;

Using PHP, you will have to fire off separate queries. I won't go into the pro's and con's of PDOs, I'm sure you're aware and this is likely legacy code you are working with:

mysql_query("SET PROFILING = 1");
$dataResult = mysql_query("SELECT * FROM MyTable");
$metricsResult = mysql_query("SHOW PROFILES");
mysql_query("SET PROFILING = 0");

There is another command you can run instead of SHOW PROFILES, which gives you more details:

SET PROFILING = 1;
SELECT * FROM MyTable; -- this is your query
SHOW PROFILE FOR QUERY 1;
SET PROFILING = 0;

This will give you a full breakdown of the entire execution time, something like this:

Spoiler

Status 	Duration
starting 	0.000029
checking permissions 	0.000006
Opening tables 	0.000034
System lock 	0.000009
init 	0.000017
optimizing 	0.000006
statistics 	0.000013
preparing 	0.000009
executing 	0.000004
Sending data 	0.000052
end 	0.000007
query end 	0.000005
closing tables 	0.000008
freeing items 	0.000033
logging slow query 	0.000004
cleaning up 	0.000004

Depends how deep you want to go into your query performance tuning.

This post has been edited by e_i_pi: 10 September 2012 - 04:40 PM

[nick2price]

Wow, didnt know you could receive that much information back. I think profiling is the way to go then, as it should cover more than I need. As I will be doing this in about a million different places, I intend to write the data to a file. Does php have a logger type system, or will I write directly to a file myself?

Cheers

[e_i_pi]

I think you'll have to write to a file yourself. Keep in mind that logging every single query could be a massive performance killer.

[nick2price]

Kool, I was actually thinking about performance. So, if it could cause a performance issue, whats the common way of doing something like this. As it stands, I have a php system which makes a lot of database calls. I want to in essense do a before and after check. I do a speed check on every query and log the data (before), I go in and make changes, and then I do the same speed test on my ammended version (after). If I have to contemplate that doing this could have an issue on speed, would this be a fair test? I want to make this as accurate as possible for obvious reasons.

p.s. Once everything is done and tested, I would remove the speed test code. This is just something I want to do for testing purposes.

Cheers

This post has been edited by nick2price: 11 September 2012 - 01:26 AM

[Atli]

You could turn the profiling on right after you connect to MySQL, and then register a function to be executed when the script is about to end (see register_shutdown_function) to collect the profile data and write it to a file.

For example, in whatever code you use to connect to MySQL, right after you've made the connection, do something like:

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 = __DIR__ . "/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');
}

You can set the ENABLE_SQL_PROFILER constant at any point before that, to turn the profiling on or off.

You could also log each query, to see which individual queries need optimizing, by making small changes to the log function. Although, personally I'd be inclined to write logs like that do a database table, to make them easier to work with.

[nick2price]

Hi Atli, I am just trying to implement your suggestion and wanted to make sure I am doing everything correct. So, at the top of my page, I have

mysql_connect("$sqlhost", "$sqluser", "$sqlpass") or die(mysql_error());
mysql_select_db("$sqldb") or die(mysql_error());

Then underneath this, I add the code you showed? And then further down my code I have something like

$result = mysql_query("SELECT `id` FROM `users` WHERE `username`='".$login_username."'");

So how does it know to do the profilling on this query? Do I need to put something before or after it? Or are the queries automatically registered?

Cheers

Nick

[Atli]

Doing SET PROFILING = 1 after connecting tells MySQL to start profiling all queries it receives during that session. You don't need to change your mysql_query calls at all. Just execute them as you normally would.

You can find more detailed info on this in the manual:
- 13.7.5.31. SHOW PROFILE Syntax


By the way, don't do: "$sqlhost". Putting quotes around variables is pointless, unless the variable is supposed to be a part of a string. Just do: $sqlhost.

[nick2price]

Kool, just to clarify. I have a config file with things like this set

$sqlhost = "localhost";

So that means I dont need the quotes when I use them in my files?

[calebjonasson]

I'm just going to throw this out there. Whenever you are trying to get an accurate set of results from profiling a query it is important to turn off mysql cache. Note that doing this in production will severely slow down your queries and it should only be done when actually attempting to get a performance gain from the queries.

[nick2price]

Kool, I have just researched that and people do make that suggestion. They also say other caches could also be running, so not sure if I need to handle these aswell?
In terms of the code Atli provided, would it just be a case of placing this underneath where profiling is set to one?

SET SESSION query_cache_type=0;

I know that resets the cache for the current session, not to sure if this is good enough though?

Cheers

Nick