Andy-H Posted February 21, 2012 Share Posted February 21, 2012 Is there any simple way I can log the execution time of each mysql query that is executed on a page, maybe with a register shutdown function, I have been trying to profile and reduce execution time of the CRM / tracking system at work and have used a register shutdown function to log page execution time. We were unsure of wither it was the internet connection, browsers having a hard time rendering nested tables(the code is OLD), or mysql queries taking too long to execute. Yesterday I started re-coding a script and I got to a query, it returned one row/field and had a limit 1, but it searched for an md5 has in the where clause, as soon as I added this query in my re-code it took execution time from 1s to 13s, I ran the query in phpmyadmin and the execution time was 0.5s, this was running in a loop which returned about 20 rows, I added an index on the md5 hash field and the query then took 0.0005s to load, I now want to do this for all scripts on the system. Any ideas? Thanks // EDIT, please note that I don't have shell access, I only have access to the scripts, plesk panel and PHPmyadmin Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/ Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 Tried: rename_function('mysql_query', 'debug_mysql_query'); override_function('mysql_query', '$query, $link = NULL', '$start = microtime(true);debug_mysql_query($query, $link);'. '$end = microtime(true);'. 'if ( stristr($query, \'SELECT\') )'. '{'. '$query = "INSERT INTO query_execution_time ( query, time ) VALUES ( \'". mysql_real_escape_string($query) ."\', ($end-$start) ) ";'. 'debug_mysql_query($query, $link);'. '}'); but we don't have PECL Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319494 Share on other sites More sharing options...
kicken Posted February 21, 2012 Share Posted February 21, 2012 If you don't already have some central function you run all your queries through, you'll just have to scatter your code with some calls to a timing function. I use this function to help to timing of my code when I find something is slow: function markTime($finish=false, $lbl=null){ static $startTime=null; static $points=array(); if ($finish){ if ($startTime==null){ $startTime = microtime(); trigger_error('Timer not initiated. Call with no arguments to start timer.'); } $endTime = microtime(1); if ($lbl == null){ $lbl = count($points); } $points[] = array($lbl, $endTime); $tally = array(); $lastPoint = $startTime; foreach ($points as $point){ $fromStart = number_format($point[1]-$startTime, 3); $fromPrev = number_format($point[1]-$lastPoint, 3); $tally[] = array($point[0], $fromStart, $fromPrev); $lastPoint = $point[1]; } $totalTime = number_format($endTime-$startTime, 3); echo '<pre> Total time: '.$totalTime.'; tracked '.count($points).' points Time track:'; foreach ($tally as $pointInfo){ echo ' Point: '.$pointInfo[0].' From start: '.$pointInfo[1].' From prev: '.$pointInfo[2]; } echo '</pre>'; $startTime = null; } else if ($startTime == null){ $startTime = microtime(1); $points = array(); } else { if ($lbl == null){ $lbl = count($points); } $points[] = array($lbl, microtime(1)); } } As an example usage: <?php markTime(false, 'Begin loop'); foreach (range(1, 1000) as $i){ //... } markTime(true, 'End Loop'); Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319527 Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 Thanks, but there are literally thousands of mysql queries, it's just not feasible to do it that way, I will have to ask my boss to install apd one night when he gets back in. Cheers though. Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319536 Share on other sites More sharing options...
PFMaBiSmAd Posted February 21, 2012 Share Posted February 21, 2012 Why not do a search and replace using your programming editor, on either just the files for one offending page or on all the files in the application, to change mysql_query statements to your debug_mysql_query function call? this was running in a loop which returned about 20 rows ^^^ I hope you are actually correcting the logic that is doing things like that, so that you have one query that gets all the rows you want, then you simply iterate over those rows? please note that I don't have shell access, I only have access to the scripts, plesk panel and PHPmyadmin Edit: Why aren't you working with an off-line copy of the application code and database to test and prove the changes you are making? You shouldn't actually be using the online active application and data for making changes and testing. Prove each change on a development system, then make that change to the actual application. Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319538 Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 Oh the logic was OK, perhaps I could have used a join but the code is so messy I would have to waste time getting to understand it, at the moment I'm just trying to speed up execution with temporary patches as we are planning on building a new system soon. What I meant by that was: $query = "SELECT rows FROM table"; $result = mysql_query($query); while ( $row = mysql_fetch_assoc($result) ) { // select LIMIT 1 use data. } I don't have FTP access, or privileges to create ftp accounts, so I am working in plesk :s (give me CPanel any day), the server is only running 5.1.6 (so I can't even namespace) so it needs updating anyway, might ask my boss to install 5.3 with APD.Also, the site consists of 176 files, as I said, I have a slow page execution log with register shutdown function, so I might go for a search & replace on the slowest few. Cheers Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319546 Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 SELECT MAX(load_time), AVG(load_time), page, request_url FROM page_loads WHERE MONTH(time) = 2 GROUP BY page ORDER BY MAX(load_time) DESC See attachment 8| Wish me luck lol Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319558 Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 Looking at the statistics do you think this is an internet connection problem? I have just loaded a page to a url that took 381 seconds to load on feb 9th, and it loaded instantaneously?? Also, it can't be down to session locking as the only session present is one I set to log the usernames in slow execution logs. It uses cookies though? Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319561 Share on other sites More sharing options...
PFMaBiSmAd Posted February 21, 2012 Share Posted February 21, 2012 There are too many different things that could cause page generation times to vary - server disk spin-up time on drives not configured to run continuously, disk errors occurring, disk caching problems, php bytecode cache problems, backup programs running and locking database tables or code files, replication running and locking data/files, concurrent usage exceeding the available server processing/memory resources, DOS attacks, applications intentionally locking database tables and not releasing them, available memory/memory allocation/memory page file/disk swapping, poorly written code, code that loads a huge number of files and they are not already present in the disk cache, lack of database table indexes, ... You need to find the actual cause. However, once you have optimized the code, you can at least eliminate the code as being the source of the problem. If your page generation time is solely being calculated in the php code, then the issue is likely on the server and not an Internet connection problem. A page taking 381 seconds to generate would indicate a fundamental problem, such as an operating system problem, disk problem, web server problem, php bug/code bug, mysql server problem. MONTH(time) = 2 ^^^ You do realize that term in your query will match data for all years. If/once you have more than one year of data, that query will give you combined results for the selected month for all years. Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319573 Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 OK so it's definitely a problem on the server, yeah I know, but I only ave like 4 months worth of data. Thanks Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319574 Share on other sites More sharing options...
PFMaBiSmAd Posted February 21, 2012 Share Posted February 21, 2012 I forgot to ask, but what is the max_execution_time setting and are there any set_time_limit statements in the code? Php should be stopping execution on a page request after the max_execution_time/set_time_limit has been reached (edit: assuming that the web server has actually passed control to the php language engine.) Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319580 Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 Max exec time is 60 seconds :S Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319591 Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 Can anyone please tell me why this is happening? function debug_mysql_query($query, $link = false) { $start = microtime(true); if ( is_resource($link) ) { mysql_query($query, $link); } else { mysql_query($query); } $end = microtime(true); if ( stristr($query, 'SELECT') ) { $res = mysql_connect('localhost','*******','*******'); mysql_select_db('slow_execution', $res); $query = "INSERT INTO query_execution_time ( query, time, page ) VALUES ( '". mysql_real_escape_string($query, $res) ."', ". number_format($end - $start, 19) .", '". mysql_real_escape_string($_SERVER['PHP_SELF'], $res) ."' ) "; mysql_query($query, $res); mysql_close($res); } } And when I replace all occurrences of mysql_query I get: E_WARNING: mysql_num_rows(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 235 E_WARNING: mysql_query(): 5 is not a valid MySQL-Link resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_top.php on line: 620 E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_top.php on line: 621 E_WARNING: mysql_query(): 5 is not a valid MySQL-Link resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_top.php on line: 947 E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_top.php on line: 948 E_WARNING: mysql_query(): 5 is not a valid MySQL-Link resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_top.php on line: 985 E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_top.php on line: 986 E_WARNING: mysql_query(): 5 is not a valid MySQL-Link resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_bottom.php on line: 9 E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_bottom.php on line: 10 E_WARNING: mysql_query(): 5 is not a valid MySQL-Link resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_bottom.php on line: 16 E_WARNING: mysql_num_rows(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_bottom.php on line: 17 E_WARNING: mysql_query(): 5 is not a valid MySQL-Link resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_bottom.php on line: 35 E_WARNING: mysql_num_rows(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_bottom.php on line: 35 Whenever a link resource is used in a query. I originally had function debug_mysql_query($query, $link = null) { $start = microtime(true); mysql_query($query, $link); $end = microtime(true); if ( stristr($query, 'SELECT') ) { $res = mysql_connect('localhost','*******','*******'); mysql_select_db('slow_execution', $res); $query = "INSERT INTO query_execution_time ( query, time, page ) VALUES ( '". mysql_real_escape_string($query, $res) ."', ". number_format($end - $start, 19) .", '". mysql_real_escape_string($_SERVER['PHP_SELF'], $res) ."' ) "; mysql_query($query, $res); } } Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319620 Share on other sites More sharing options...
PFMaBiSmAd Posted February 21, 2012 Share Posted February 21, 2012 Your function needs to return the value from the mysql_query() statement so that the calling code will get the result-resource/true/false value back. Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319622 Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 OMFG how stupid do I fell lol Thanks for the help again Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319623 Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 Still no luck :S function debug_mysql_query($query, $link = null) { $start = microtime(true); $data = mysql_query($query, $link); $end = microtime(true); if ( stristr($query, 'SELECT') ) { $res = mysql_connect('localhost','****','****'); mysql_select_db('slow_execution', $res); $query = "INSERT INTO query_execution_time ( query, time, page ) VALUES ( '". mysql_real_escape_string($query, $res) ."', ". number_format($end - $start, 19) .", '". mysql_real_escape_string($_SERVER['PHP_SELF'], $res) ."' ) "; mysql_query($query, $res); } return $data; } E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 223 E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_top.php on line: 621 E_WARNING: mysql_fetch_assoc(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_top.php on line: 907 E_WARNING: mysql_num_rows(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_top.php on line: 921 E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_top.php on line: 948 E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_top.php on line: 986 E_WARNING: mysql_num_rows(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 314 E_WARNING: mysql_num_rows(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 342 E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/functions.php on line: 6 E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 437 E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 460 E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 491 E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 684 E_NOTICE: Undefined index: MobilePhone in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 902 E_NOTICE: Undefined index: phone3 in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 903 E_NOTICE: Undefined index: Phone in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 949 E_NOTICE: Undefined index: MobilePhone in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 955 E_NOTICE: Undefined index: phone3 in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 961 E_NOTICE: Undefined index: Phone in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 1038 E_NOTICE: Undefined index: MobilePhone in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 1039 E_NOTICE: Undefined index: phone3 in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 1040 E_NOTICE: Undefined index: tel1 in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 1061 E_NOTICE: Undefined index: tel2 in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 1064 E_NOTICE: Undefined index: tel3 in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 1066 E_NOTICE: Undefined index: password in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 1071 E_NOTICE: Undefined index: Email in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/device.php on line: 1073 E_WARNING: mysql_fetch_array(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_bottom.php on line: 10 E_WARNING: mysql_num_rows(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_bottom.php on line: 17 E_WARNING: mysql_num_rows(): supplied argument is not a valid MySQL result resource in file: /var/www/vhosts/eros.phantomsystems.co.uk/httpdocs/template_bottom.php on line: 35 Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319628 Share on other sites More sharing options...
PFMaBiSmAd Posted February 21, 2012 Share Posted February 21, 2012 Are the database connection details you are using in that code the same as for the main database connection? Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319630 Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 NO they're for a different database, got you, that's why I put the mysql_close, to avoid it using the lastt connectiion, does this not work? Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319633 Share on other sites More sharing options...
PFMaBiSmAd Posted February 21, 2012 Share Posted February 21, 2012 They might be for a different database, but are they the same hostname, username, and password as the main database connection? Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319638 Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 Ahh yes they are, thanks Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319650 Share on other sites More sharing options...
PFMaBiSmAd Posted February 21, 2012 Share Posted February 21, 2012 The mysql_connect statement, inside that function, the way it is coded now, is reusing the existing main database connection because the hostname,username, and password are the same. When you use mysql_close inside that function, you are actually closing the main connection. You would need to set the 4th parameter of the mysql_connect statment to true to form a new connection that you could separately select the slow_execution database without interfering with the main database connection and the currently selected database on the main connection. Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319651 Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 Ok thanks, I was just re-selecting the old database, but that sounds better. Mind you, won't that be slower as it's re-connecting every time the query is called? Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319656 Share on other sites More sharing options...
kicken Posted February 21, 2012 Share Posted February 21, 2012 You could not change the DB at all and just specify it in the query. Table names can be prefixed with the DB name allowing you to work across multiple DB's at once. INSERT INTO slow_execution.query_execution_time ... Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319666 Share on other sites More sharing options...
Andy-H Posted February 21, 2012 Author Share Posted February 21, 2012 Oh yeah, I'll do that then, thanks. Quote Link to comment https://forums.phpfreaks.com/topic/257449-mysql-query-execution-time/#findComment-1319677 Share on other sites More sharing options...
Recommended Posts
Join the conversation
You can post now and register later. If you have an account, sign in now to post with your account.