Optimizing slow web pages with mk-query-digest
I don’t use many tools in my consulting practice but for the ones I do, I try to know them as best as I can. I’ve been using mk-query-digest for almost as long as it exists but it continues to surprise me in ways I couldn’t imagine it would. This time I’d like to share a quick tip on how mk-query-digest allows you to slice your data in a completely different way than it otherwise would by default.
Disclaimer: this only works when persistent connections or connection pools aren’t used and is only accurate when single mysql connection is used during execution of a request.
If you are seeking to reduce the load on the database server and [as a result] increase response time for some random user requests, you are usually interested in queries that are consuming most MySQL time and that’s how mk-query-digest groups and orders data by default. Fixing top 10 queries on the list indeed will most likely reduce the load and improve response time for some requests. What if some pages are still slow to load because of the time spent in database and you either can’t or don’t want to profile or debug the application to figure out what’s happening under the hood?
That sounds like something I was working on today – I had a slow query log (captured with long_query_time=0 and all the eXtra benefits from Percona slow query log patch), I knew some particular pages were taking minutes to load and that’s exactly what the customer asked me to focus on. So instead of using mk-query-digest to list me top slowest queries, I asked it to list me top slowest sessions:
|
1 |
mk-query-digest --group-by=Thread_id --order-by=Query_time:sum in > out |
Spot on, the session I needed to focus on was right at the top. And what do you know, 519 queries were run during that session which took 148s seconds overall:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 |
# ######################################################################## # Report grouped by Thread_id # ######################################################################## # Item 1: 3.41 QPS, 0.97x concurrency, ID 0xABCE5AD2A2DD1BA1 at byte 288124661 # This item is included in the report because it matches --limit. # Scores: Apdex = 0.97 [1.0], V/M = 19.02 # Query_time sparkline: | ^______| # Time range: 2011-04-05 16:12:13 to 16:14:45 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 0 519 # Exec time 2 148s 11us 33s 285ms 53ms 2s 26us # Lock time 0 5ms 0 334us 9us 66us 32us 0 # Rows sent 0 41 0 1 0.08 0.99 0.27 0 # Rows examine 1 4.97M 0 445.49k 9.80k 5.73k 49.33k 0 # Rows affecte 0 2 0 1 0.00 0 0.06 0 # Rows read 1 2.01M 0 250.47k 3.96k 1.96 27.94k 0.99 # Bytes sent 0 241.20k 11 8.01k 475.89 918.49 689.98 258.32 # Merge passes 0 0 0 0 0 0 0 0 # Tmp tables 0 15 0 1 0.03 0 0.17 0 # Tmp disk tbl 0 3 0 1 0.01 0 0.08 0 # Tmp tbl size 0 4.78k 0 4.78k 9.43 0 211.60 0 # Query size 0 100.95k 19 2.71k 199.17 363.48 206.60 151.03 # InnoDB: # IO r bytes 0 0 0 0 0 0 0 0 # IO r ops 0 0 0 0 0 0 0 0 # IO r wait 0 0 0 0 0 0 0 0 # pages distin 1 67.99k 0 10.64k 1.26k 3.88k 2.47k 31.70 # queue wait 0 0 0 0 0 0 0 0 # rec lock wai 0 0 0 0 0 0 0 0 # Boolean: # Filesort 0% yes, 99% no # Full scan 7% yes, 92% no # QC Hit 78% yes, 21% no # Tmp table 2% yes, 97% no # Tmp table on 0% yes, 99% no # String: # Databases prod_db # Hosts localhost # InnoDB trxID 1153145C (2/0%), 11531626 (2/0%)... 43 more # Last errno 0 # Users prod # Query_time distribution # 1us # 10us ################################################################ # 100us ######### # 1ms # # 10ms # # 100ms # # 1s ### # 10s+ # 160847 |
The stats here are aggregated per all queries which is great, but I still need to figure out what queries were run. I could use mk-log-player and split all sessions that way, unfortunately mk-log-player will not have all the other useful information, not even query timing. Instead, I’ve used mk-query-digest:
|
1 |
mk-query-digest --filter='$event->{Thread_id} == 160847' in > out |
Now I know exactly what needs to be fixed first to make the greatest impact to this page response time. I can also convert that into a slow query log that lists all the queries that were executed during this session in the order they were executed:
|
1 |
mk-query-digest --filter='$event->{Thread_id} == 160847' --no-report --print in > out |
Pretty cool, isn’t it? Sure, it would be even better if mk-query-digest would do a nested group-by and order-by within a group so I would avoid the extra step, but then even better than that would be if it would optimize the queries all together! Unfortunately mk-query-digest won’t do that for you, but then there’s mk-query-advisor 😉
Comments (14)
Mike, I just looked at the source files and (the src.rpm) and they indeed contain separate patches that you can apply. The patch you want here is microslow_innodb.patch. I would however recommend to use a more recent version of MySQL and in fact without modifications, the patch that’s available in mysql-5.0.92 src.rpm file will fail at two hunks against mysql-5.0.77. On vanilla mysql-5.0.92 it applies cleanly. Mind that if you want to apply few patches (which I highly recommend if you’re using InnoDB, especially the IO patch, split_buf_pool_mutex and recovery patch) you must apply them in a certain order which you can find in percona-sql-50.spec file. Hope this helps.
Thanks for the reply Aurimas. We would need it separately, yes — we are running MySQL 5.0.77, not Percona Server. Our server hosts won’t support Percona Server (even though it’s identical to MySQL for their purposes), so we have to use “vanilla” MySQL. But they would be okay with this patch I think. I found some old documentation that said the patch could be applied to non-Percona MySQL, but I understand if that’s no longer the case.
Mike, sorry if I have confused you. The functionality you need is available in any version of the Percona Server. Some older version may not have Thread_id yet, but I can’t tell you which version exactly does not have it. If you upgrade to Percona Server 5.0.92-b23, you should definitely have the functionality you need. If you need the slow query patch only, I can take a look to see how it can be extracted if it’s still all available separately.
Err… slow query log, not sow query log. Accursed fingers!
You mention the sow log query patch which allows for logging in microseconds, but I can only find a version of that from 2006. We are running MySQL 5.0.77 — do you have a version of the patch that’s compatible with that, and can you link me to it if so?
Thanks, Justin. Indeed you can overcome the shortcomings of the approach I used in that case. The good thing about grouping by thread_id though is that you get a fairly good picture of how long certain page requests are spending in MySQL without the need to modify or even look at the application. If you’re serious about instrumenting your app, then you can’t really rely on that as there’s a lot more than just MySQL calls you’re interested in and this is when Instrumentation-for-PHP becomes irreplaceable.
mqd is awesome. Here is another trick that you can use if you can modify the SQL app:
You can use a query wrapper in your application that appends SQL comments to your SQL statements. These comments can include the file/function/line that the SQL was called in. If you construct this in a regular way, then you can use mqd’s –embedded-attributes option to parse those comments and aggregate by page or page function.
My reference instrumentation project (Instrumentation-for-PHP) adds those comments to SQL statements. It also assigns a unique ‘request_id’ to every web request, and places this into the comments too. So you can extract the SQL for a single session, even if connection pooling or a load balancer is used. Finally, it also stuffs the session_id into the SQL as well.
Both of these are useful using –filter because embedded attributes are processed before filters are applied:
The query comment consists of key value pairs:
SELECT 1;
– File: index.php Line: 118 Function: fullCachePage request_id: ABC session_id: XYZ
mk-query-digest can then filter by web page:
mk-query-digest /var/lib/mysql/slow –embedded-attributes ‘^– [^n]+’,'(w+): ([^t]+)’ –filter
‘$event->{File} && $event->{File} =~ m/index/’
mqd is awesome. Here is another trick that you can use if you can modify the SQL app:
You can use a query wrapper in your application that appends SQL comments to your SQL statements. These comments can include the file/function/line that the SQL was called in. If you construct this in a regular way, then you can use mqd’s –embedded-attributes option to parse those comments and aggregate by page or page function.
My reference instrumentation project (Instrumentation-for-PHP) adds those comments to SQL statements. It also assigns a unique ‘request_id’ to every web request, and places this into the comments too. So you can extract the SQL for a single session, even if connection pooling or a load balancer is used. Finally, it also stuffs the session_id into the SQL as well.
Both of these are useful using –filter because embedded attributes are processed before filters are applied:
The query comment consists of key value pairs:
SELECT 1;
— File: index.php Line: 118 Function: fullCachePage request_id: ABC session_id: XYZ
mk-query-digest can then filter by web page:
mk-query-digest /var/lib/mysql/slow –embedded-attributes ‘^– [^\n]+’,'(\w+): ([^\t]+)’ –filter
‘$event->{File} && $event->{File} =~ m/index/’
Thanks, Justin. Indeed you can overcome the shortcomings of the approach I used in that case. The good thing about grouping by thread_id though is that you get a fairly good picture of how long certain page requests are spending in MySQL without the need to modify or even look at the application. If you’re serious about instrumenting your app, then you can’t really rely on that as there’s a lot more than just MySQL calls you’re interested in and this is when Instrumentation-for-PHP becomes irreplaceable.
You mention the sow log query patch which allows for logging in microseconds, but I can only find a version of that from 2006. We are running MySQL 5.0.77 — do you have a version of the patch that’s compatible with that, and can you link me to it if so?
Err… slow query log, not sow query log. Accursed fingers! 🙂
Mike, sorry if I have confused you. The functionality you need is available in any version of the Percona Server. Some older version may not have Thread_id yet, but I can’t tell you which version exactly does not have it. If you upgrade to Percona Server 5.0.92-b23, you should definitely have the functionality you need. If you need the slow query patch only, I can take a look to see how it can be extracted if it’s still all available separately.
Thanks for the reply Aurimas. We would need it separately, yes — we are running MySQL 5.0.77, not Percona Server. Our server hosts won’t support Percona Server (even though it’s identical to MySQL for their purposes), so we have to use “vanilla” MySQL. But they would be okay with this patch I think. I found some old documentation that said the patch could be applied to non-Percona MySQL, but I understand if that’s no longer the case.
Mike, I just looked at the source files and (the src.rpm) and they indeed contain separate patches that you can apply. The patch you want here is microslow_innodb.patch. I would however recommend to use a more recent version of MySQL and in fact without modifications, the patch that’s available in mysql-5.0.92 src.rpm file will fail at two hunks against mysql-5.0.77. On vanilla mysql-5.0.92 it applies cleanly. Mind that if you want to apply few patches (which I highly recommend if you’re using InnoDB, especially the IO patch, split_buf_pool_mutex and recovery patch) you must apply them in a certain order which you can find in percona-sql-50.spec file. Hope this helps.