How to Read and Interpret pt-query-digest Slow Query Log Analysis Output

Understanding pt-query-digest Output

After analyzing a MySQL slow query log with pt-query-digest mysql-slow.log, a detailed report is generated. This guide explains each section of that report.

Report Header

The header contains metadata about the tool's execution environment and the log file:

# A software update is available:
#   * The current version for Percona::Toolkit is 2.2.9.

# 170ms user time, 10ms system time, 26.00M rss, 213.39M vsz
# Current date: Mon Jul 28 09:55:34 2014
# Hostname: lump.group.com
# Files: mysql-slow.log
# Overall: 5 total, 4 unique, 0.02 QPS, 0.04x concurrency ________________
# Time range: 2014-07-28 09:50:30 to 09:54:50

• user time / system time / rss / vsz: CPU time, physical memory (RSS), and virtual memory (VSZ) used by the analysis tool.
• Current date / Hostname: System time and hostname where the analysis was run (this may differ from the database server).
• Files: Name of the analyzed log file.
• Overall: Total queries, unique queries, average Queries Per Second (QPS), and estimated concurrency.
• Time range: Time period covered by the log.

Overall Statistics Summary

This section provides aggregated metrics for all queries:

# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            10s      1s      3s      2s      3s   753ms      1s
# Lock time          196us       0    79us    39us    76us    33us    42us
# Rows sent          1.40k       0     716     287  685.39  335.14    3.89
# Rows examine      15.32k       0  11.13k   3.06k  10.80k   4.02k   2.06k
# Rows affecte           0       0       0       0       0       0       0
# Bytes sent        72.42k      11  38.85k  14.48k  38.40k  17.57k  234.30
# Query size           807       6     342  161.40  329.68  146.53  112.70

• Exec time: Query execution time.
• Lock time: Time spent waiting for locks.
• Rows sent: Rows returned to the client.
• Rows examine: Rows examined (scanned), primarily for SELECTs.
• Rows affecte: Rows affected by INSERT, UPDATE, DELETE.
• Bytes sent: Size of the returned result set in bytes.
• Query size: Length of the query statement in characters.

Column meanings: total (sum), min (minimum), max (maximum), avg (average), 95% (95th percentile), stddev (standard deviation), median (median).

Query Performance Profile

This section ranks queries by their cumulative response time:

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ===============
#    1 0x4A9CF4735A0490F2  3.1898 31.9%     1 3.1898  0.00 SELECT history_uint
#    2 0x2B0044BDE0960A2F  2.6991 27.0%     1 2.6991  0.00 SELECT history
#    3 0x813031B8BBC3B329  2.5755 25.7%     2 1.2877  0.00 COMMIT
#    4 0x469563A79E581DDB  1.5380 15.4%     1 1.5380  0.00 SELECT sessions

• Rank: Query ranking, sorted by total response time (descending).
• Query ID: Query fingerprint (a unique identifier generated by normalizing the query, removing spaces and literal values).
• Response time: Total response time and its percentage of the overall time.
• Calls: Number of times this query was executed.
• R/Call: Average response time per call.
• V/M: Variance-to-mean ratio (index of dispersion), indicating response time variability.
• Item: Simplified representation of the query.

Detailed Query Analysis

The report provides a detailed breakdown for each unique Query ID. For the top query:

# Query 1: 0 QPS, 0x concurrency, ID 0x4A9CF4735A0490F2 at byte 591 ______

• QPS: Queries per second for this specific query pattern.
• concurrency: Estimated concurrency.
• ID: Hexadecimal query fingerprint. For filtering with --filter, remove the 0x prefix.
• at byte 591: Byte offset in the log file for quick location.

This is followed by a detailed statistics table for that query:

# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         20       1
# Exec time     31      3s      3s      3s      3s      3s       0      3s
# Lock time     40    79us    79us    79us    79us    79us       0    79us
# Rows sent     49     715     715     715     715     715       0     715
# Rows examine  13   2.09k   2.09k   2.09k   2.09k   2.09k       0   2.09k
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent    45  33.31k  33.31k  33.31k  33.31k  33.31k       0  33.31k
# Query size    42     342     342     342     342     342       0     342

The pct column shows the percentage this query contributes to the total for each metric. For example, Count 20 means this query represents 20% of all query executions.

Additional context is provided:

• String: Context like database, user, and host.
• Query_time distribution: A histogram showing the distribution of execution times.
• Tables: Provides SQL statements to get table status and structure (e.g., SHOW TABLE STATUS, SHOW CREATE TABLE).
• EXPLAIN: The tool generates (or converts) a SELECT statement suitable for use with EXPLAIN to analyze the query execution plan.

This guide is based on public documentation to help understand pt-query-digest output. Actual output may vary slightly depending on the tool version and options used.