One of the tools of the toolsuite, pt-query-digest, allows to process and profile queries that run through the server, either by processing logs (general log, slow query log, etc...), or by processing wire protocol gathered by tcpdump.
P6Spy (sourceforge.net/projects/p6spy) is an open source driver that works as a 'proxy' driver, which allows to log every query that passes through it, while delegating query execution to 'real' drivers, the ones that would actually be used to communicate with the DB. Even though it is quite old, it does the job.
The patch is hosted on github gist and available here : add-p6spy-parser-3.0.13.patch . Therefore to be able to parse and digest a p6spy query log using pt-query-digest after having downloaded and uncompressed the toolkit in e.g. /opt/percona/toolkit/3.0.13' , you'll need to do e.g. :
The SHA1 digest for this patch is : b4c9473f8be2a50837f0b9a833ec00a1ccdc4b7a). This patch is not required to simply use the patched tool.
allows to determine query performance, from the app server 'point of view', for each type of query, with great statistical detail (avg response time per query type , std dev, variance to mean, ... see examples below) without having direct access to the actual DB or involving a DBA (helpful when on short engagements).
allows (mostly) to use pt-query-digest to parse response times of any database accessed through jdbc, without knowledge of that database's particular protocol. It has maximum compatibility with MySQL, but works with other databases too since the queries passing through the driver should have mostly consistent syntax, and not much DB-specific syntax. Sufficiently enough at least to get a precise idea of the query type performance for a particular test run.
If using a DB whose wire protocol is already supported by Maatkit (such as MySQL and PostgreSQL), it is then easier to determine for example the network overhead, as the DB side profiling can be easily compared with the driver-side profiling using p6spy.
To gather a query log, 3 steps are required :
Download a copy of p6spy.jar and place it in the classpath. I usually use tomcat/shared/lib. I have tested/updated the config as of December 2018 to work against the latest release of p6spy, 3.8.1.
Create a spy.properties and place it on the classpath. I usually use tomcat/shared/classes/spy.properties. This file will contain the driver configuration. A simple working example is included below :
The custom log format is in fact the "old" log format, so that it can be backwards compatible. At some point, p6spy interverted the connection ID and category. This format ensures both old and new logs can be parsed without changing the parser itself.
You only need to change the 'realdriver' property if you are not using MySQL (replace by your actual driver).
In alfresco-global.properties, Change the DB driver and URL to use the p6spy driver, which in the case above, will delegate to the MySQL driver, e.g :
Upon startup, you should see a /tmp/spy.log being created, filling up with queries and associated response time among other things. This is the log that will be parsed (as in the examples below) with pt-query-digest. Note that for better accuracy and richer information, you can use percona toolkit directly against MySQL, but this gives you somewhat DB independence, network time to the driver, and some nice statistics if for some reason you don't have access to the actual DB.
As is the case for the other parsers, there are 2 output 'modes' that can be used :
This is a summary output for a limited number of query types (sorted by impact). Example :
By default the top 10 queries in terms of impact (# of times executed * avg response time) are shown, but this may be changed with the '--limit' parameter. For each aggregated query type (queries that differ only by the values), the column fields are as follows :
Query ID : an assigned query ID. this can be used to store these results in a database, and do some trending over time, or more generally to compare a specific query fingerprint performance over time
Response time : the overall response time for this query, in terms of elasped seconds and percentage of the total query time for all queries
Calls : the number of times this particular query was parsed out of the log
Item : a summarized description of the query, also called query fingerprint, which is the abstracted form of a query, which makes it possible to group similar queries together. Abstracting a query removes literal values, normalizes whitespace, and so on. See the output documentation for more details.
Note : on a local fast/dev laptop many of the queries will report sub 1ms and therefore 0 in the p6spy log file. p6spy has apparently added an option to report the timings using the JVM's nanotime but last i tested it didn't work. you would have to adjust the parser itself to adjust the current conversion from milliseconds to seconds. I doubt this would be the most accurate though. The tool is better suited to profile queries in a production / pre-production scenario where the queries would go over the network and therefore usually report over 1ms when you factor in the network's round trip time.
This a detailed output for each query type. This is the default output if none is specified.
$ pt-query-digest --type=p6spy /tmp/spy.log
Below is shown the detailed output for the query #1 :
# Query 1: 0 QPS, 0x concurrency, ID 0x631DB93E5642CADF at byte 13096045 _ # Scores: V/M = 0.00 # Time range: 1295101185998 to 1299596773258 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 22 2575 # Exec time 21 778ms 0 28ms 302us 972us 1ms 0 # Query_time distribution # 1us # 10us # 100us # 1ms ################################################################ # 10ms # # 100ms # 1s # 10s+ # Tables # SHOW TABLE STATUS LIKE 'alf_node_aspects'\G # SHOW CREATE TABLE `alf_node_aspects`\G # insert into alf_node_aspects (node_id, qname_id) values (162299, 31)\G
In this mode, only the top 5 queries are detailed by default. The other 4 are not printed here. More statistical details are available for this query in this mode (min,max, 95%, stddev, median), including a sample query of that type for reference. Can be used to be copy/pasted to get the query plan for example.
Even though more information is available when using the wire protocol (for example concurrency, rows examined, query plan, query plan warnings, ...), this data allows to have a good overview of this particular query's performance. See percona documentation for more details about the histogram. Note : Sparklines are no longer available as of the 2.2 release.
Note that it is not necessary to use pt-query-digest on the actual server where the log has been collected. The log can be transferred to another machine for processing, for example if the machine doesn't have Perl installed. pt-query-digest is written in Perl, and has fairly minimal dependencies, only some core packages that ought to be installed in any reasonably new version of Perl.
Percona documentation for the tool itself is available here.