1Demonstrations of dbslower, the Linux eBPF/bcc version.
2
3
4dbslower traces queries served by a MySQL or PostgreSQL server, and prints
5those that exceed a latency (query time) threshold. By default a threshold of
61 ms is used. For example:
7
8# dbslower mysql
9Tracing database queries for pids 25776 slower than 1 ms...
10TIME(s)        PID          MS QUERY
111.315800       25776  2000.999 call getproduct(97)
123.360380       25776     3.226 call getproduct(6)
13^C
14
15This traced two queries slower than 1ms, one of which is very slow: over 2
16seconds. We can filter out the shorter ones and keep only the really slow ones:
17
18# dbslower mysql -m 1000
19Tracing database queries for pids 25776 slower than 1000 ms...
20TIME(s)        PID          MS QUERY
211.421264       25776  2002.183 call getproduct(97)
223.572617       25776  2001.381 call getproduct(97)
235.661411       25776  2001.867 call getproduct(97)
247.748296       25776  2001.329 call getproduct(97)
25^C
26
27This looks like a pattern -- we keep making this slow query every 2 seconds
28or so, and it takes approximately 2 seconds to run.
29
30By default, dbslower will try to detect mysqld and postgres processes, but if
31necessary, you can specify the process ids with the -p switch:
32
33# dbslower mysql -p $(pidof mysql)
34Tracing database queries for pids 25776 slower than 1 ms...
35TIME(s)        PID          MS QUERY
362.002125       25776     3.340 call getproduct(7)
372.045006       25776  2001.558 call getproduct(97)
384.131863       25776  2002.275 call getproduct(97)
396.190513       25776     3.248 call getproduct(33)
40^C
41
42Specifying 0 as the threshold will print all the queries:
43
44# dbslower mysql -m 0
45Tracing database queries for pids 25776 slower than 0 ms...
46TIME(s)        PID          MS QUERY
476.003720       25776     2.363 /* mysql-connector-java-5.1.40 ( Revision: 402933ef52cad9aa82624e80acbea46e3a701ce6 ) */SELECT  @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_conn
486.599219       25776     0.068 SET NAMES latin1
496.613944       25776     0.057 SET character_set_results = NULL
506.645228       25776     0.059 SET autocommit=1
516.653798       25776     0.059 SET sql_mode='NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES'
526.682184       25776     2.526 select * from users where id = 0
536.767888       25776     0.288 select id from products where userid = 0
546.790642       25776     2.255 call getproduct(0)
556.809865       25776     0.218 call getproduct(1)
566.846878       25776     0.248 select * from users where id = 1
576.847623       25776     0.166 select id from products where userid = 1
586.867363       25776     0.244 call getproduct(2)
596.868162       25776     0.107 call getproduct(3)
606.874726       25776     0.208 select * from users where id = 2
616.881722       25776     0.260 select id from products where userid = 2
62^C
63
64Here we can see the MySQL connector initialization and connection establishment,
65before the actual queries start coming in.
66
67
68USAGE:
69# dbslower -h
70usage: dbslower.py [-h] [-v] [-p [PIDS [PIDS ...]]] [-x PATH] [-m THRESHOLD]
71                   {mysql,postgres}
72
73positional arguments:
74  {mysql,postgres}      the database engine to use
75
76optional arguments:
77  -h, --help            show this help message and exit
78  -v, --verbose         print the BPF program
79  -p [PID [PID ...]], --pid [PID [PID ...]]
80                        the pid(s) to trace
81  -x PATH, --exe PATH   path to binary
82  -m THRESHOLD, --threshold THRESHOLD
83                        trace queries slower than this threshold (ms)
84
85examples:
86    dbslower postgres            # trace PostgreSQL queries slower than 1ms
87    dbslower postgres -p 188 322 # trace specific PostgreSQL processes
88    dbslower mysql -p 480 -m 30  # trace MySQL queries slower than 30ms
89    dbslower mysql -p 480 -v     # trace MySQL queries and print the BPF program
90    dbslower mysql -x $(which mysqld)  # trace MySQL queries with uprobes
91