Practical Performance Tuning 
using Digested SQL Logs	

Bob Burgess
Salesforce Marketing Cloud
Who?	

!   Database Architect	

!   Salesforce Marketing Cloud (Radian6  Buddy Media stack)
Why?	

!   I can’t be the only one
Talking about today…	

!   Slow database: the problem  the solution	

!   What is the MySQL “Slow Log”?	

!   Making sense of log contents	

!   Interpreting the digested log	

!   Tuning examples
Slow Database: the problem  the solution
The Problem	

!   Slow database. Why?	

!   Long-running queries	

!   Small “fast” queries (numerous  not tuned)	

!   Small “fast” queries (tuned but extremely numerous)
The Solution	

!   Watch everything then analyze	

!   Catch all queries, even the “fast” queries	

!   Look at total time spent on each query	

!   Attack them from the top, down
Capture Everything	

!   “Slow” Log	

!   Detailed	

!   Too detailed?
What is the MySQL “Slow Log”?
Slow Log: Purpose	

!   Log all queries	

!   Time threshold	

!   Capture information about each query	

• Execution time	

• Row counts	

• User  Host	

• Others
Slow Log: Contents	

# Time: 150329 9:52:13
# User@Host: root[root] @ localhost [] Id: 1
# Schema: sakila Last_errno: 0 Killed: 0
# Query_time: 0.019128 Lock_time: 0.009394 Rows_sent: 1 Rows_examined: 200 Rows_affected: 0
# Bytes_sent: 267
SET timestamp=1427633533;
select * from actor where first_name='JOHN';
Slow Log: Contents	

# Time: 150329 9:52:13
# User@Host: root[root] @ localhost [] Id: 1
# Schema: sakila Last_errno: 0 Killed: 0
# Query_time: 0.019128 Lock_time: 0.009394 Rows_sent: 1 Rows_examined: 200 Rows_affected: 0
# Bytes_sent: 267
SET timestamp=1427633533;
select * from actor where first_name='JOHN';
Slow Log: Contents	

# Time: 150329 9:52:13
# User@Host: root[root] @ localhost [] Id: 1
# Schema: sakila Last_errno: 0 Killed: 0
# Query_time: 0.019128 Lock_time: 0.009394 Rows_sent: 1 Rows_examined: 200 Rows_affected: 0
# Bytes_sent: 267
SET timestamp=1427633533;
select * from actor where first_name='JOHN';
Slow Log: Contents	

# Time: 150329 9:52:13
# User@Host: root[root] @ localhost [] Id: 1
# Schema: sakila Last_errno: 0 Killed: 0
# Query_time: 0.019128 Lock_time: 0.009394 Rows_sent: 1 Rows_examined: 200 Rows_affected: 0
# Bytes_sent: 267
SET timestamp=1427633533;
select * from actor where first_name='JOHN';
Slow Log: Contents	

# Time: 150329 9:52:13
# User@Host: root[root] @ localhost [] Id: 1
# Schema: sakila Last_errno: 0 Killed: 0
# Query_time: 0.019128 Lock_time: 0.009394 Rows_sent: 1 Rows_examined: 200 Rows_affected: 0
# Bytes_sent: 267
SET timestamp=1427633533;
select * from actor where first_name='JOHN';
Slow Log: Contents	

# Time: 150329 9:52:13
# User@Host: root[root] @ localhost [] Id: 1
# Schema: sakila Last_errno: 0 Killed: 0
# Query_time: 0.019128 Lock_time: 0.009394 Rows_sent: 1 Rows_examined: 200 Rows_affected: 0
# Bytes_sent: 267
SET timestamp=1427633533;
select * from actor where first_name='JOHN';
Slow Log: Contents	

# Time: 150329 9:52:13
# User@Host: root[root] @ localhost [] Id: 1
# Schema: sakila Last_errno: 0 Killed: 0
# Query_time: 0.019128 Lock_time: 0.009394 Rows_sent: 1 Rows_examined: 200 Rows_affected: 0
# Bytes_sent: 267
SET timestamp=1427633533;
select * from actor where first_name='JOHN';
Slow Log: Contents	

# Time: 150329 9:52:13
# User@Host: root[root] @ localhost [] Id: 1
# Schema: sakila Last_errno: 0 Killed: 0
# Query_time: 0.019128 Lock_time: 0.009394 Rows_sent: 1 Rows_examined: 200 Rows_affected: 0
# Bytes_sent: 267
SET timestamp=1427633533;
select * from actor where first_name='JOHN';
Slow Log: Configuration	

!   set global long_query_time = 0;
!   threshold execution time for inclusion in slow log
Slow Log: Configuration	

!   set global slow_query_log_file = '/path/to/slow.log';
!   location of the slow log file
Slow Log: Configuration	

!   set global log_slow_verbosity = 'microtime';
!   what to include in the slow log file	

!   microtime	

!   innodb	

!   query_plan	

!   profiling
Slow Log: Configuration	

!   set global slow_query_log_use_global_control =
'long_query_time, log_slow_verbosity';
!   make slow log configuration changes apply to all sessions, 
including open sessions
Slow Log: Configuration	

!   set global log_slow_slave_statements = 1;
!   include replicated SQL in the slow log
Slow Log: Configuration	

!   set global slow_query_log = 1;
!   turn on the slow log!	

!   High activity / slow disk	

!   General overhead
Slow Log with different MySQL versions
Slow-Log in Stock 5.1 / 5.5 / 5.6	

!   set global slow_query_log_file = '/path/to/slow.log';
set global long_query_time=0;
set global slow_query_log=1;
!   Logs only for sessions created after logging starts
Slow-Log in Percona 5.1 / 5.5 / 5.6	

!   set global slow_query_log_file = '/path/to/slow.log';
set global long_query_time=0;
set global slow_query_log=1;
!   Logs only for sessions created after logging starts
Slow-Log in Percona 5.1	

!   set global slow_query_log_file = '/path/to/slow.log';
set global long_query_time=0;
set global log_slow_verbosity='microtime,innodb';
set global use_global_log_slow_control=1;
set global log_slow_slave_statements=1;
set global slow_query_log=1;
!   Logs all sessions (and include innodb info  slave SQL)
Slow-Log in Percona 5.5 / 5.6	

!   set global slow_query_log_file = '/path/to/slow.log';
set global long_query_time=0;
set global log_slow_verbosity='microtime,innodb';
set global slow_query_log_use_global_control=1;
set global log_slow_slave_statements=1;
set global slow_query_log=1;
!   Logs all sessions (and include innodb info  slave SQL)
5.1 / 5.5 / 5.6
Stock	

5.1
Percona	

5.5 / 5.6
Percona	

long_query_time	

 yes	

 yes	

 yes	

slow_query_log_file	

 yes	

 yes	

 yes	

log_slow_verbosity	

 no: “microtime” only	

 yes	

 yes	

slow_query_log
_use_global_control	

no: session only	

“use_global_log
_slow_control”	

yes	

log_slow_slave
_statements	

no	

 yes	

 yes
5.1 / 5.5 / 5.6
Stock	

5.1
Percona	

5.5 / 5.6
Percona	

long_query_time	

 yes	

 yes	

 yes	

slow_query_log_file	

 yes	

 yes	

 yes	

log_slow_verbosity	

 no: “microtime” only	

 yes	

 yes	

slow_query_log
_use_global_control	

no: session only	

“use_global_log
_slow_control”	

yes	

log_slow_slave
_statements	

no	

 yes	

 yes
5.1 / 5.5 / 5.6
Stock	

5.1
Percona	

5.5 / 5.6
Percona	

long_query_time	

 yes	

 yes	

 yes	

slow_query_log_file	

 yes	

 yes	

 yes	

log_slow_verbosity	

 no: “microtime” only	

 yes	

 yes	

slow_query_log
_use_global_control	

no: session only	

“use_global_log
_slow_control”	

yes	

log_slow_slave
_statements	

no	

 yes	

 yes
5.1 / 5.5 / 5.6
Stock	

5.1
Percona	

5.5 / 5.6
Percona	

long_query_time	

 yes	

 yes	

 yes	

slow_query_log_file	

 yes	

 yes	

 yes	

log_slow_verbosity	

 no: “microtime” only	

 yes	

 yes	

slow_query_log
_use_global_control	

no: session only	

“use_global_log
_slow_control”	

yes	

log_slow_slave
_statements	

no	

 yes	

 yes
Making Sense of Log Contents	

!   Millions of pieces of data	

!   grep | awk | sort | uniq -c
!   pt-query-digest	

!   created by Baron Schwartz	

!   primarily developed by him and Daniel Nichter
pt-query-digest	

!   Aggregates log entry data by query fingerprint	

!   Sorts output by whatever’s important to you
pt-query-digest: query fingerprint	

select * from actor where first_name='JOHN';
SELECT /* my query */ last_name From actor where first_name = 'Bob';
select * from actor where first_name=?

select 50, last_name from actor 

where first_name='JOHN' and last_name in ('SMITH', 'JONES');
select ?, last_name from actor where first_name=? and last_name in(?+)
pt-query-digest: Output	

# 1825.5s user time, 19.6s system time, 526.79M rss, 677.20M vsz
# Current date: Tue Mar 10 12:16:58 2015
# Hostname: db1234
# Files: slow.log.db5678
# Overall: 6.36M total, 775 unique, 10.90k QPS, 5.54x concurrency
pt-query-digest: Output	

# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 3228s 1us 79s 507us 657us 52ms 131us
# Lock time 303s 0 2s 47us 125us 1ms 30us
# Rows sent 173.14M 0 7.27M 28.56 20.43 8.25k 0.99
# Rows examine 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Rows affecte 128.30k 0 77 0.02 0 0.17 0
# Rows read 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Bytes sent 11.60G 0 414.78M 1.91k 2.62k 358.51k 537.02
# Query size 1.48G 6 121.50k 250.43 719.66 363.95 166.51
pt-query-digest: Output	

# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 3228s 1us 79s 507us 657us 52ms 131us
# Lock time 303s 0 2s 47us 125us 1ms 30us
# Rows sent 173.14M 0 7.27M 28.56 20.43 8.25k 0.99
# Rows examine 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Rows affecte 128.30k 0 77 0.02 0 0.17 0
# Rows read 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Bytes sent 11.60G 0 414.78M 1.91k 2.62k 358.51k 537.02
# Query size 1.48G 6 121.50k 250.43 719.66 363.95 166.51
Query
execution time
pt-query-digest: Output	

# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 3228s 1us 79s 507us 657us 52ms 131us
# Lock time 303s 0 2s 47us 125us 1ms 30us
# Rows sent 173.14M 0 7.27M 28.56 20.43 8.25k 0.99
# Rows examine 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Rows affecte 128.30k 0 77 0.02 0 0.17 0
# Rows read 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Bytes sent 11.60G 0 414.78M 1.91k 2.62k 358.51k 537.02
# Query size 1.48G 6 121.50k 250.43 719.66 363.95 166.51
Time before
query executes
pt-query-digest: Output	

# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 3228s 1us 79s 507us 657us 52ms 131us
# Lock time 303s 0 2s 47us 125us 1ms 30us
# Rows sent 173.14M 0 7.27M 28.56 20.43 8.25k 0.99
# Rows examine 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Rows affecte 128.30k 0 77 0.02 0 0.17 0
# Rows read 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Bytes sent 11.60G 0 414.78M 1.91k 2.62k 358.51k 537.02
# Query size 1.48G 6 121.50k 250.43 719.66 363.95 166.51
Rows returned
to the client
pt-query-digest: Output	

# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 3228s 1us 79s 507us 657us 52ms 131us
# Lock time 303s 0 2s 47us 125us 1ms 30us
# Rows sent 173.14M 0 7.27M 28.56 20.43 8.25k 0.99
# Rows examine 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Rows affecte 128.30k 0 77 0.02 0 0.17 0
# Rows read 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Bytes sent 11.60G 0 414.78M 1.91k 2.62k 358.51k 537.02
# Query size 1.48G 6 121.50k 250.43 719.66 363.95 166.51
Rows scanned
for selects
pt-query-digest: Output	

# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 3228s 1us 79s 507us 657us 52ms 131us
# Lock time 303s 0 2s 47us 125us 1ms 30us
# Rows sent 173.14M 0 7.27M 28.56 20.43 8.25k 0.99
# Rows examine 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Rows affecte 128.30k 0 77 0.02 0 0.17 0
# Rows read 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Bytes sent 11.60G 0 414.78M 1.91k 2.62k 358.51k 537.02
# Query size 1.48G 6 121.50k 250.43 719.66 363.95 166.51
Rows changed
by ins/upd/del
pt-query-digest: Output	

# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 3228s 1us 79s 507us 657us 52ms 131us
# Lock time 303s 0 2s 47us 125us 1ms 30us
# Rows sent 173.14M 0 7.27M 28.56 20.43 8.25k 0.99
# Rows examine 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Rows affecte 128.30k 0 77 0.02 0 0.17 0
# Rows read 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Bytes sent 11.60G 0 414.78M 1.91k 2.62k 358.51k 537.02
# Query size 1.48G 6 121.50k 250.43 719.66 363.95 166.51
Rows read to
process ins/upd/
del
pt-query-digest: Output	

# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 3228s 1us 79s 507us 657us 52ms 131us
# Lock time 303s 0 2s 47us 125us 1ms 30us
# Rows sent 173.14M 0 7.27M 28.56 20.43 8.25k 0.99
# Rows examine 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Rows affecte 128.30k 0 77 0.02 0 0.17 0
# Rows read 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Bytes sent 11.60G 0 414.78M 1.91k 2.62k 358.51k 537.02
# Query size 1.48G 6 121.50k 250.43 719.66 363.95 166.51
Size of result
set
pt-query-digest: Output	

# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 3228s 1us 79s 507us 657us 52ms 131us
# Lock time 303s 0 2s 47us 125us 1ms 30us
# Rows sent 173.14M 0 7.27M 28.56 20.43 8.25k 0.99
# Rows examine 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Rows affecte 128.30k 0 77 0.02 0 0.17 0
# Rows read 781.43M 0 11.46M 128.90 59.77 15.43k 0.99
# Bytes sent 11.60G 0 414.78M 1.91k 2.62k 358.51k 537.02
# Query size 1.48G 6 121.50k 250.43 719.66 363.95 166.51
Size of incoming
SQL
pt-query-digest: Output	

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== =============== ======= ====== ====== ====================================================
# 1 0x2AEA6C2B72904C1E 431.5703 13.4% 1578 0.2735 0.30 SELECT UNION Roles RoleGrants DefaultRolePermissions
# 2 0x97C874BC88FDB2E3 226.4475 7.0% 48 4.7177 49.80 SELECT Event EventAttribute
# 3 0x4A106EF2450AEAC1 119.0458 3.7% 547909 0.0002 0.03 SELECT ApplicationUser Client
# 4 0x00694E9F0A0CD23D 113.0377 3.5% 313 0.3611 0.05 SELECT ExtendedMediaTypeAttribute TopicFilter
# 5 0x813031B8BBC3B329 110.2512 3.4% 206088 0.0005 1.80 COMMIT
# MISC 0xMISC 2218.8264 68.7% 5600850 0.0004 0.0 769 ITEMS
pt-query-digest: Output	

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== =============== ======= ====== ====== ====================================================
# 1 0x2AEA6C2B72904C1E 431.5703 13.4% 1578 0.2735 0.30 SELECT UNION Roles RoleGrants DefaultRolePermissions
# 2 0x97C874BC88FDB2E3 226.4475 7.0% 48 4.7177 49.80 SELECT Event EventAttribute
# 3 0x4A106EF2450AEAC1 119.0458 3.7% 547909 0.0002 0.03 SELECT ApplicationUser Client
# 4 0x00694E9F0A0CD23D 113.0377 3.5% 313 0.3611 0.05 SELECT ExtendedMediaTypeAttribute TopicFilter
# 5 0x813031B8BBC3B329 110.2512 3.4% 206088 0.0005 1.80 COMMIT
# MISC 0xMISC 2218.8264 68.7% 5600850 0.0004 0.0 769 ITEMS
Rank in
specified sort
order
pt-query-digest: Output	

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== =============== ======= ====== ====== ====================================================
# 1 0x2AEA6C2B72904C1E 431.5703 13.4% 1578 0.2735 0.30 SELECT UNION Roles RoleGrants DefaultRolePermissions
# 2 0x97C874BC88FDB2E3 226.4475 7.0% 48 4.7177 49.80 SELECT Event EventAttribute
# 3 0x4A106EF2450AEAC1 119.0458 3.7% 547909 0.0002 0.03 SELECT ApplicationUser Client
# 4 0x00694E9F0A0CD23D 113.0377 3.5% 313 0.3611 0.05 SELECT ExtendedMediaTypeAttribute TopicFilter
# 5 0x813031B8BBC3B329 110.2512 3.4% 206088 0.0005 1.80 COMMIT
# MISC 0xMISC 2218.8264 68.7% 5600850 0.0004 0.0 769 ITEMS
Hash of query
fingerprint
pt-query-digest: Output	

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== =============== ======= ====== ====== ====================================================
# 1 0x2AEA6C2B72904C1E 431.5703 13.4% 1578 0.2735 0.30 SELECT UNION Roles RoleGrants DefaultRolePermissions
# 2 0x97C874BC88FDB2E3 226.4475 7.0% 48 4.7177 49.80 SELECT Event EventAttribute
# 3 0x4A106EF2450AEAC1 119.0458 3.7% 547909 0.0002 0.03 SELECT ApplicationUser Client
# 4 0x00694E9F0A0CD23D 113.0377 3.5% 313 0.3611 0.05 SELECT ExtendedMediaTypeAttribute TopicFilter
# 5 0x813031B8BBC3B329 110.2512 3.4% 206088 0.0005 1.80 COMMIT
# MISC 0xMISC 2218.8264 68.7% 5600850 0.0004 0.0 769 ITEMS
Total time
spent
pt-query-digest: Output	

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== =============== ======= ====== ====== ====================================================
# 1 0x2AEA6C2B72904C1E 431.5703 13.4% 1578 0.2735 0.30 SELECT UNION Roles RoleGrants DefaultRolePermissions
# 2 0x97C874BC88FDB2E3 226.4475 7.0% 48 4.7177 49.80 SELECT Event EventAttribute
# 3 0x4A106EF2450AEAC1 119.0458 3.7% 547909 0.0002 0.03 SELECT ApplicationUser Client
# 4 0x00694E9F0A0CD23D 113.0377 3.5% 313 0.3611 0.05 SELECT ExtendedMediaTypeAttribute TopicFilter
# 5 0x813031B8BBC3B329 110.2512 3.4% 206088 0.0005 1.80 COMMIT
# MISC 0xMISC 2218.8264 68.7% 5600850 0.0004 0.0 769 ITEMS
How many
times this SQL
ran
pt-query-digest: Output	

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== =============== ======= ====== ====== ====================================================
# 1 0x2AEA6C2B72904C1E 431.5703 13.4% 1578 0.2735 0.30 SELECT UNION Roles RoleGrants DefaultRolePermissions
# 2 0x97C874BC88FDB2E3 226.4475 7.0% 48 4.7177 49.80 SELECT Event EventAttribute
# 3 0x4A106EF2450AEAC1 119.0458 3.7% 547909 0.0002 0.03 SELECT ApplicationUser Client
# 4 0x00694E9F0A0CD23D 113.0377 3.5% 313 0.3611 0.05 SELECT ExtendedMediaTypeAttribute TopicFilter
# 5 0x813031B8BBC3B329 110.2512 3.4% 206088 0.0005 1.80 COMMIT
# MISC 0xMISC 2218.8264 68.7% 5600850 0.0004 0.0 769 ITEMS
Mean response
time per call
pt-query-digest: Output	

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== =============== ======= ====== ====== ====================================================
# 1 0x2AEA6C2B72904C1E 431.5703 13.4% 1578 0.2735 0.30 SELECT UNION Roles RoleGrants DefaultRolePermissions
# 2 0x97C874BC88FDB2E3 226.4475 7.0% 48 4.7177 49.80 SELECT Event EventAttribute
# 3 0x4A106EF2450AEAC1 119.0458 3.7% 547909 0.0002 0.03 SELECT ApplicationUser Client
# 4 0x00694E9F0A0CD23D 113.0377 3.5% 313 0.3611 0.05 SELECT ExtendedMediaTypeAttribute TopicFilter
# 5 0x813031B8BBC3B329 110.2512 3.4% 206088 0.0005 1.80 COMMIT
# MISC 0xMISC 2218.8264 68.7% 5600850 0.0004 0.0 769 ITEMS
Variance to Mean ratio
(indicates spread of values)
pt-query-digest: Output	

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== =============== ======= ====== ====== ====================================================
# 1 0x2AEA6C2B72904C1E 431.5703 13.4% 1578 0.2735 0.30 SELECT UNION Roles RoleGrants DefaultRolePermissions
# 2 0x97C874BC88FDB2E3 226.4475 7.0% 48 4.7177 49.80 SELECT Event EventAttribute
# 3 0x4A106EF2450AEAC1 119.0458 3.7% 547909 0.0002 0.03 SELECT ApplicationUser Client
# 4 0x00694E9F0A0CD23D 113.0377 3.5% 313 0.3611 0.05 SELECT ExtendedMediaTypeAttribute TopicFilter
# 5 0x813031B8BBC3B329 110.2512 3.4% 206088 0.0005 1.80 COMMIT
# MISC 0xMISC 2218.8264 68.7% 5600850 0.0004 0.0 769 ITEMS
Command
and tables
pt-query-digest: Output per Query	

# Query 3: 939.81 QPS, 0.20x concurrency, ID 0x4A106EF2450AEAC1 at byte 2946778373
# Scores: V/M = 0.03
# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 8 547909
# Exec time 3 119s 100us 922ms 217us 424us 2ms 159us
# Lock time 10 31s 18us 10ms 56us 131us 97us 36us
# Rows sent 0 535.07k 1 1 1 1 0 1
# Rows examine 0 535.07k 1 1 1 1 0 1
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 0 535.07k 1 1 1 1 0 1
# Bytes sent 12 1.41G 2.62k 2.89k 2.71k 2.62k 6.83 2.62k
# Query size 5 78.87M 148 176 150.94 151.03 2.37 143.84
pt-query-digest: Output per Query	

# Query 3: 939.81 QPS, 0.20x concurrency, ID 0x4A106EF2450AEAC1 at byte 2946778373
# Scores: V/M = 0.03
# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 8 547909
# Exec time 3 119s 100us 922ms 217us 424us 2ms 159us
# Lock time 10 31s 18us 10ms 56us 131us 97us 36us
# Rows sent 0 535.07k 1 1 1 1 0 1
# Rows examine 0 535.07k 1 1 1 1 0 1
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 0 535.07k 1 1 1 1 0 1
# Bytes sent 12 1.41G 2.62k 2.89k 2.71k 2.62k 6.83 2.62k
# Query size 5 78.87M 148 176 150.94 151.03 2.37 143.84
Rank in sort
order
pt-query-digest: Output per Query	

# Query 3: 939.81 QPS, 0.20x concurrency, ID 0x4A106EF2450AEAC1 at byte 2946778373
# Scores: V/M = 0.03
# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 8 547909
# Exec time 3 119s 100us 922ms 217us 424us 2ms 159us
# Lock time 10 31s 18us 10ms 56us 131us 97us 36us
# Rows sent 0 535.07k 1 1 1 1 0 1
# Rows examine 0 535.07k 1 1 1 1 0 1
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 0 535.07k 1 1 1 1 0 1
# Bytes sent 12 1.41G 2.62k 2.89k 2.71k 2.62k 6.83 2.62k
# Query size 5 78.87M 148 176 150.94 151.03 2.37 143.84
How many
per second
pt-query-digest: Output per Query	

# Query 3: 939.81 QPS, 0.20x concurrency, ID 0x4A106EF2450AEAC1 at byte 2946778373
# Scores: V/M = 0.03
# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 8 547909
# Exec time 3 119s 100us 922ms 217us 424us 2ms 159us
# Lock time 10 31s 18us 10ms 56us 131us 97us 36us
# Rows sent 0 535.07k 1 1 1 1 0 1
# Rows examine 0 535.07k 1 1 1 1 0 1
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 0 535.07k 1 1 1 1 0 1
# Bytes sent 12 1.41G 2.62k 2.89k 2.71k 2.62k 6.83 2.62k
# Query size 5 78.87M 148 176 150.94 151.03 2.37 143.84
Query ID
pt-query-digest: Output per Query	

# Query 3: 939.81 QPS, 0.20x concurrency, ID 0x4A106EF2450AEAC1 at byte 2946778373
# Scores: V/M = 0.03
# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 8 547909
# Exec time 3 119s 100us 922ms 217us 424us 2ms 159us
# Lock time 10 31s 18us 10ms 56us 131us 97us 36us
# Rows sent 0 535.07k 1 1 1 1 0 1
# Rows examine 0 535.07k 1 1 1 1 0 1
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 0 535.07k 1 1 1 1 0 1
# Bytes sent 12 1.41G 2.62k 2.89k 2.71k 2.62k 6.83 2.62k
# Query size 5 78.87M 148 176 150.94 151.03 2.37 143.84
Percent of
Total
pt-query-digest: Output per Query	

# Query 3: 939.81 QPS, 0.20x concurrency, ID 0x4A106EF2450AEAC1 at byte 2946778373
# Scores: V/M = 0.03
# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 8 547909
# Exec time 3 119s 100us 922ms 217us 424us 2ms 159us
# Lock time 10 31s 18us 10ms 56us 131us 97us 36us
# Rows sent 0 535.07k 1 1 1 1 0 1
# Rows examine 0 535.07k 1 1 1 1 0 1
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 0 535.07k 1 1 1 1 0 1
# Bytes sent 12 1.41G 2.62k 2.89k 2.71k 2.62k 6.83 2.62k
# Query size 5 78.87M 148 176 150.94 151.03 2.37 143.84
Total this
query
pt-query-digest: Output per Query	

# Query 3: 939.81 QPS, 0.20x concurrency, ID 0x4A106EF2450AEAC1 at byte 2946778373
# Scores: V/M = 0.03
# Time range: 2015-03-10 11:34:01 to 11:43:44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 8 547909
# Exec time 3 119s 100us 922ms 217us 424us 2ms 159us
# Lock time 10 31s 18us 10ms 56us 131us 97us 36us
# Rows sent 0 535.07k 1 1 1 1 0 1
# Rows examine 0 535.07k 1 1 1 1 0 1
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 0 535.07k 1 1 1 1 0 1
# Bytes sent 12 1.41G 2.62k 2.89k 2.71k 2.62k 6.83 2.62k
# Query size 5 78.87M 148 176 150.94 151.03 2.37 143.84
Stats
pt-query-digest: Output per Query	

# String:
# Databases sphere
# Hosts dm1234 (90486/36%), dm2345 (79213/24%), ap3456 (77959/23%)
# Last errno 0
# Users appuser01 (478323/87%), appuser02 (64465/11%), appuser03(5049/0%)
pt-query-digest: Output per Query	

# Query_time distribution
# 1us
# 10us ##
# 100us ################################################################
# 1ms ####
# 10ms #
# 100ms #
# 1s
# 10s+
pt-query-digest: Output per Query	

# Tables
# SHOW TABLE STATUS FROM `sphere` LIKE 'ApplicationUser'G
# SHOW CREATE TABLE `sphere`.`ApplicationUser`G
# SHOW TABLE STATUS FROM `sphere` LIKE 'Client'G
# SHOW CREATE TABLE `sphere`.`Client`G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT au.*, c.active, c.clientEndDate FROM ApplicationUser au JOIN Client c ON
au.clientId = c.clientId WHERE userId = 48954G
pt-query-digest: Useful Switches	

!   --limit	

!   “Top-n” limit	

!   Percent and/or number of results	

!   --limit 95%:20
!   --limit 5
!   --limit 10%
pt-query-digest: Useful Switches	

!   --show-all	

!   Show all values in lists, not just what fits on one line
pt-query-digest: Useful Switches	

!   --order-by	

!   Specify how to sort the output	

!   Parameter is {metric}:{function}	

!   --order-by Query_time:sum (default)
!   --order-by Bytes_sent:sum (interface saturation?)
!   --order-by Rows_examined:sum (Find table scans)
!   --order-by Query-time:cnt (find high QPS)
pt-query-digest: Useful Switches	

!   --explain	

!   Explain each query	

!   Specify where to connect for the Explain Plan queries	

!   --explain h=myServer,P=3306,u=myUser,p=secret
Generating Log Digests	

First: Get pt-query-digest	

	

wget percona.com/get/pt-query-digest
chmod +x pt-query-digest
Generating Log Digests	

Then: Enable the slow log for a limited time	

	

mysql –e'set global {all the settings from earlier}'
mysql –e'set global slow_query_log=1'
sleep 60
mysql –e'set global slow_query_log=0'
Generating Log Digests	

Digest the resulting log…	

	

./pt-query-digest /path/to/slow.log digest.txt
Generating Log Digests (Periodic)	

For 10 minutes:	

•  Enable the slow log	

•  Wait 30 seconds	

•  Disable the slow log	

•  Wait 30 seconds	

	

Then…	

pt-query-digest --limit 5 --explain h=…,P=…
/path/to/slow.log digest.txt
Generating Log Digests (Emergency)	

•  Enable the slow log	

•  Wait 30 seconds	

•  Disable the slow log	

	

Then…	

pt-query-digest --show-all /path/to/slow.log digest.txt
Interpreting Digested Logs	

!   Most important metric: total execution time	

4 s	

 100 ms
Interpreting Digested Logs	

!   Most important metric: total execution time	

4 s	

 8 s
pt-query-digest: Output	

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== =============== ======= ====== ====== ====================================================
# 1 0x2AEA6C2B72904C1E 431.5703 13.4% 1578 0.2735 0.30 SELECT UNION Roles RoleGrants DefaultRolePermissions
# 2 0x97C874BC88FDB2E3 226.4475 7.0% 48 4.7177 49.80 SELECT Event EventAttribute
# 3 0x4A106EF2450AEAC1 119.0458 3.7% 547909 0.0002 0.03 SELECT ApplicationUser Client
# 4 0x00694E9F0A0CD23D 113.0377 3.5% 313 0.3611 0.05 SELECT ExtendedMediaTypeAttribute TopicFilter
# 5 0x813031B8BBC3B329 110.2512 3.4% 206088 0.0005 1.80 COMMIT
# MISC 0xMISC 2218.8264 68.7% 5600850 0.0004 0.0 769 ITEMS
pt-query-digest: Output	

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== =============== ======= ====== ====== ====================================================
# 1 0x2AEA6C2B72904C1E 431.5703 13.4% 1578 0.2735 0.30 SELECT UNION Roles RoleGrants DefaultRolePermissions
# 2 0x97C874BC88FDB2E3 226.4475 7.0% 48 4.7177 49.80 SELECT Event EventAttribute
# 3 0x4A106EF2450AEAC1 119.0458 3.7% 547909 0.0002 0.03 SELECT ApplicationUser Client
# 4 0x00694E9F0A0CD23D 113.0377 3.5% 313 0.3611 0.05 SELECT ExtendedMediaTypeAttribute TopicFilter
# 5 0x813031B8BBC3B329 110.2512 3.4% 206088 0.0005 1.80 COMMIT
# MISC 0xMISC 2218.8264 68.7% 5600850 0.0004 0.0 769 ITEMS
Single Most
Important Metric	

THEN look at each query, starting from the top
Interpreting Digested Logs (Steps)	

!   Generate Digest, sorted by total execution time per query	

! Start with Query #1; work your way down	

!   Don’t get distracted by other queries in the list, or not in the list	

! Ignore the actual SQL until you start tuning
Interpreting Digested Logs (Steps)	

Two main reasons for appearing on the list:	

!   High queries-per-second (high enough that fast queries are making the list)	

!   Expensive query (not running often, but when they do…)	

And also…	

!   “Sort of expensive” — fast enough, except when we run a lot of them
Interpreting Digested Logs (examples)	

# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============== ======= ======= ====== ==================================
# 1 0xA4129148F8ED32B2 607.1264 25.3% 255 2.3809 2.40 SELECT UserAttributes
# 2 0x2AEA6C2B72904C1E 389.5737 16.2% 1346 0.2894 0.24 SELECT UNION Roles RoleGrants
# 3 0xFB33D80D68CDD066 146.5731 6.1% 15175 0.0097 9.27 SELECT PostStatusException
# 4 0xC1EDA7581D372A3F 139.4136 5.8% 4 34.8534 1.35 SELECT TopicFilter FilterGroup
FilterQuery
Interpreting Digested Logs (example 1)	

Reality-based…
Interpreting Digested Logs (example 1)	

# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============== ======= ======= ====== ==================================
# 1 0xA4129148F8ED32B2 607.1264 25.3% 255 2.3809 2.40 SELECT UserAttributes
# 2 0x2AEA6C2B72904C1E 389.5737 16.2% 1346 0.2894 0.24 SELECT UNION Roles RoleGrants
# 3 0xFB33D80D68CDD066 146.5731 6.1% 15175 0.0097 9.27 SELECT PostStatusException
# 4 0xC1EDA7581D372A3F 139.4136 5.8% 4 34.8534 1.35 SELECT TopicFilter FilterGroup
FilterQuery
# Query 1: 0.45 QPS, 1.08x concurrency, ID 0xA4129148F8ED32B2 at byte 1012395036
# Scores: V/M = 2.40
# Time range: 2015-03-29 09:55:10 to 10:04:31
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 255
# Exec time 25 607s 8ms 6s 2s 5s 2s 2s
# Lock time 0 135ms 21us 4ms 529us 2ms 793us 64us
# Rows sent 0 49.95k 0 372 200.58 346.17 160.67 346.17
# Rows examine 0 2.67M 10.73k 10.73k 10.73k 10.73k 0 10.73k
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 0 2.67M 10.73k 10.73k 10.73k 10.73k 0 10.73k
# Bytes sent 0 1.11M 339 7.96k 4.44k 7.31k 3.24k 7.31k
# Query size 0 30.37k 118 122 121.97 118.34 0.35 118.34
Interpreting Digested Logs (example 1)
# Query 1: 0.45 QPS, 1.08x concurrency, ID 0xA4129148F8ED32B2 at byte 1012395036
# Scores: V/M = 2.40
# Time range: 2015-03-29 09:55:10 to 10:04:31
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 255
# Exec time 25 607s 8ms 6s 2s 5s 2s 2s
# Lock time 0 135ms 21us 4ms 529us 2ms 793us 64us
# Rows sent 0 49.95k 0 372 200.58 346.17 160.67 346.17
# Rows examine 0 2.67M 10.73k 10.73k 10.73k 10.73k 0 10.73k
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 0 2.67M 10.73k 10.73k 10.73k 10.73k 0 10.73k
# Bytes sent 0 1.11M 339 7.96k 4.44k 7.31k 3.24k 7.31k
# Query size 0 30.37k 118 122 121.97 118.34 0.35 118.34
Interpreting Digested Logs (example 1)
# Query 1: 0.45 QPS, 1.08x concurrency, ID 0xA4129148F8ED32B2 at byte 1012395036
# Scores: V/M = 2.40
# Time range: 2015-03-29 09:55:10 to 10:04:31
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 255
# Exec time 25 607s 8ms 6s 2s 5s 2s 2s
# Lock time 0 135ms 21us 4ms 529us 2ms 793us 64us
# Rows sent 0 49.95k 0 372 200.58 346.17 160.67 346.17
# Rows examine 0 2.67M 10.73k 10.73k 10.73k 10.73k 0 10.73k
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 0 2.67M 10.73k 10.73k 10.73k 10.73k 0 10.73k
# Bytes sent 0 1.11M 339 7.96k 4.44k 7.31k 3.24k 7.31k
# Query size 0 30.37k 118 122 121.97 118.34 0.35 118.34
Interpreting Digested Logs (example 1)
# Query 1: 0.45 QPS, 1.08x concurrency, ID 0xA4129148F8ED32B2 at byte 1012395036
# Scores: V/M = 2.40
# Time range: 2015-03-29 09:55:10 to 10:04:31
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 255
# Exec time 25 607s 8ms 6s 2s 5s 2s 2s
# Lock time 0 135ms 21us 4ms 529us 2ms 793us 64us
# Rows sent 0 49.95k 0 372 200.58 346.17 160.67 346.17
# Rows examine 0 2.67M 10.73k 10.73k 10.73k 10.73k 0 10.73k
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 0 2.67M 10.73k 10.73k 10.73k 10.73k 0 10.73k
# Bytes sent 0 1.11M 339 7.96k 4.44k 7.31k 3.24k 7.31k
# Query size 0 30.37k 118 122 121.97 118.34 0.35 118.34
Interpreting Digested Logs (example 1)
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms #
# 10ms ##################################################
# 100ms #######
# 1s ################################################################
# 10s+
Interpreting Digested Logs (example 1)
Interpreting Digested Logs (example 1)	

select userId, clientId, userAttributeTypeId, value from UserAttributes
where clientId = 23495 and userAttributeTypeId = 1G
# *************************** 1. row ***************************
# id: 1
# select_type: SIMPLE
# table: UserAttributes
# partitions: NULL
# type: ALL
# possible_keys: NULL
# key: NULL
# key_len: NULL
# ref: NULL
# rows: 11270
# Extra: Using where
Interpreting Digested Logs (example 1)	

select userId, clientId, userAttributeTypeId, value from UserAttributes
where clientId = 23495 and userAttributeTypeId = 1G
# *************************** 1. row ***************************
# id: 1
# select_type: SIMPLE
# table: UserAttributes
# partitions: NULL
# type: ALL
# possible_keys: NULL
# key: NULL
# key_len: NULL
# ref: NULL
# rows: 11270
# Extra: Using where
Interpreting Digested Logs (example 1)	

select userId, clientId, userAttributeTypeId, value from UserAttributes
where clientId = 23495 and userAttributeTypeId = 1G
# *************************** 1. row ***************************
# id: 1
# select_type: SIMPLE
# table: UserAttributes
# partitions: NULL
# type: ALL
# possible_keys: NULL
# key: NULL
# key_len: NULL
# ref: NULL
# rows: 11270
# Extra: Using where
New index required.
Interpreting Digested Logs (example 2)	

Reality-based…
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============== ======= ======= ====== ==================================
# 1 0xA4129148F8ED32B2 607.1264 25.3% 255 2.3809 2.40 SELECT UserAttributes
# 2 0x2AEA6C2B72904C1E 389.5737 16.2% 1346 0.2894 0.24 SELECT UNION Roles RoleGrants
# 3 0xFB33D80D68CDD066 146.5731 6.1% 15175 0.0097 9.27 SELECT PostStatusException
# 4 0xC1EDA7581D372A3F 139.4136 5.8% 4 34.8534 1.35 SELECT TopicFilter FilterGroup
FilterQuery
Interpreting Digested Logs (example 2)
# Query 2: 2.38 QPS, 0.69x concurrency, ID 0x2AEA6C2B72904C1E at byte 367386570
# Scores: V/M = 0.24
# Time range: 2015-03-29 09:55:08 to 10:04:34
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 1346
# Exec time 16 390s 60ms 2s 289ms 740ms 265ms 141ms
# Lock time 0 762ms 228us 16ms 566us 1ms 1ms 348us
# Rows sent 0 379.60k 0 14.55k 288.79 346.17 1.71k 9.83
# Rows examine 42 192.12M 508 3.65M 146.16k 174.27k 563.30k 9.33k
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 42 192.12M 508 3.65M 146.16k 174.27k 563.30k 9.33k
# Bytes sent 0 4.17M 69 160.12k 3.17k 3.69k 18.78k 174.84
# Query size 0 3.45M 2.58k 2.63k 2.62k 2.62k 25 2.62k
Interpreting Digested Logs (example 2)
# Query 2: 2.38 QPS, 0.69x concurrency, ID 0x2AEA6C2B72904C1E at byte 367386570
# Scores: V/M = 0.24
# Time range: 2015-03-29 09:55:08 to 10:04:34
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 1346
# Exec time 16 390s 60ms 2s 289ms 740ms 265ms 141ms
# Lock time 0 762ms 228us 16ms 566us 1ms 1ms 348us
# Rows sent 0 379.60k 0 14.55k 288.79 346.17 1.71k 9.83
# Rows examine 42 192.12M 508 3.65M 146.16k 174.27k 563.30k 9.33k
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 42 192.12M 508 3.65M 146.16k 174.27k 563.30k 9.33k
# Bytes sent 0 4.17M 69 160.12k 3.17k 3.69k 18.78k 174.84
# Query size 0 3.45M 2.58k 2.63k 2.62k 2.62k 25 2.62k
Interpreting Digested Logs (example 2)
# Query 2: 2.38 QPS, 0.69x concurrency, ID 0x2AEA6C2B72904C1E at byte 367386570
# Scores: V/M = 0.24
# Time range: 2015-03-29 09:55:08 to 10:04:34
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 1346
# Exec time 16 390s 60ms 2s 289ms 740ms 265ms 141ms
# Lock time 0 762ms 228us 16ms 566us 1ms 1ms 348us
# Rows sent 0 379.60k 0 14.55k 288.79 346.17 1.71k 9.83
# Rows examine 42 192.12M 508 3.65M 146.16k 174.27k 563.30k 9.33k
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 42 192.12M 508 3.65M 146.16k 174.27k 563.30k 9.33k
# Bytes sent 0 4.17M 69 160.12k 3.17k 3.69k 18.78k 174.84
# Query size 0 3.45M 2.58k 2.63k 2.62k 2.62k 25 2.62k
Interpreting Digested Logs (example 2)
# Query 2: 2.38 QPS, 0.69x concurrency, ID 0x2AEA6C2B72904C1E at byte 367386570
# Scores: V/M = 0.24
# Time range: 2015-03-29 09:55:08 to 10:04:34
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 1346
# Exec time 16 390s 60ms 2s 289ms 740ms 265ms 141ms
# Lock time 0 762ms 228us 16ms 566us 1ms 1ms 348us
# Rows sent 0 379.60k 0 14.55k 288.79 346.17 1.71k 9.83
# Rows examine 42 192.12M 508 3.65M 146.16k 174.27k 563.30k 9.33k
# Rows affecte 0 0 0 0 0 0 0 0
# Rows read 42 192.12M 508 3.65M 146.16k 174.27k 563.30k 9.33k
# Bytes sent 0 4.17M 69 160.12k 3.17k 3.69k 18.78k 174.84
# Query size 0 3.45M 2.58k 2.63k 2.62k 2.62k 25 2.62k
Interpreting Digested Logs (example 2)
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms #############################
# 100ms ################################################################
# 1s #
# 10s+
Interpreting Digested Logs (example 2)
Index problem.	

Interpreting Digested Logs (example 2)
Interpreting Digested Logs (example 3)	

Reality-based…
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============== ======= ======= ====== ==================================
# 1 0xA4129148F8ED32B2 607.1264 25.3% 255 2.3809 2.40 SELECT UserAttributes
# 2 0x2AEA6C2B72904C1E 389.5737 16.2% 1346 0.2894 0.24 SELECT UNION Roles RoleGrants
# 3 0xFB33D80D68CDD066 146.5731 6.1% 15175 0.0097 9.27 SELECT PostStatusException
# 4 0xC1EDA7581D372A3F 139.4136 5.8% 4 34.8534 1.35 SELECT TopicFilter FilterGroup
FilterQuery
Interpreting Digested Logs (example 3)