1 Demonstrations of dbslower, the Linux eBPF/bcc version. 2 3 4 dbslower traces queries served by a MySQL or PostgreSQL server, and prints 5 those that exceed a latency (query time) threshold. By default a threshold of 6 1 ms is used. For example: 7 8 # dbslower mysql 9 Tracing database queries for pids 25776 slower than 1 ms... 10 TIME(s) PID MS QUERY 11 1.315800 25776 2000.999 call getproduct(97) 12 3.360380 25776 3.226 call getproduct(6) 13 ^C 14 15 This traced two queries slower than 1ms, one of which is very slow: over 2 16 seconds. We can filter out the shorter ones and keep only the really slow ones: 17 18 # dbslower mysql -m 1000 19 Tracing database queries for pids 25776 slower than 1000 ms... 20 TIME(s) PID MS QUERY 21 1.421264 25776 2002.183 call getproduct(97) 22 3.572617 25776 2001.381 call getproduct(97) 23 5.661411 25776 2001.867 call getproduct(97) 24 7.748296 25776 2001.329 call getproduct(97) 25 ^C 26 27 This looks like a pattern -- we keep making this slow query every 2 seconds 28 or so, and it takes approximately 2 seconds to run. 29 30 By default, dbslower will try to detect mysqld and postgres processes, but if 31 necessary, you can specify the process ids with the -p switch: 32 33 # dbslower mysql -p $(pidof mysql) 34 Tracing database queries for pids 25776 slower than 1 ms... 35 TIME(s) PID MS QUERY 36 2.002125 25776 3.340 call getproduct(7) 37 2.045006 25776 2001.558 call getproduct(97) 38 4.131863 25776 2002.275 call getproduct(97) 39 6.190513 25776 3.248 call getproduct(33) 40 ^C 41 42 Specifying 0 as the threshold will print all the queries: 43 44 # dbslower mysql -m 0 45 Tracing database queries for pids 25776 slower than 0 ms... 46 TIME(s) PID MS QUERY 47 6.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 48 6.599219 25776 0.068 SET NAMES latin1 49 6.613944 25776 0.057 SET character_set_results = NULL 50 6.645228 25776 0.059 SET autocommit=1 51 6.653798 25776 0.059 SET sql_mode='NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES' 52 6.682184 25776 2.526 select * from users where id = 0 53 6.767888 25776 0.288 select id from products where userid = 0 54 6.790642 25776 2.255 call getproduct(0) 55 6.809865 25776 0.218 call getproduct(1) 56 6.846878 25776 0.248 select * from users where id = 1 57 6.847623 25776 0.166 select id from products where userid = 1 58 6.867363 25776 0.244 call getproduct(2) 59 6.868162 25776 0.107 call getproduct(3) 60 6.874726 25776 0.208 select * from users where id = 2 61 6.881722 25776 0.260 select id from products where userid = 2 62 ^C 63 64 Here we can see the MySQL connector initialization and connection establishment, 65 before the actual queries start coming in. 66 67 68 USAGE: 69 # dbslower -h 70 usage: dbslower.py [-h] [-v] [-p [PIDS [PIDS ...]]] [-m THRESHOLD] 71 {mysql,postgres} 72 73 positional arguments: 74 {mysql,postgres} the database engine to use 75 76 optional 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 -m THRESHOLD, --threshold THRESHOLD 82 trace queries slower than this threshold (ms) 83 84 examples: 85 dbslower postgres # trace PostgreSQL queries slower than 1ms 86 dbslower postgres -p 188 322 # trace specific PostgreSQL processes 87 dbslower mysql -p 480 -m 30 # trace MySQL queries slower than 30ms 88 dbslower mysql -p 480 -v # trace MySQL queries and print the BPF program 89
