Adding a timestamp to each breakpoint "command" execution was the next step, and for this I've suggested to use plain "shell date" command. Redirecting output to the same file gdb uses to log everything indeed did the trick. Let me document it here for readers and myself. I'll consider the example of logging SQL queries I've used in the previous blog post on dynamic tracing with perf and use recent Percona Server 5.7.28-31 on Ubuntu 16.04 for tests.
Skipping the details already explained in that previous post, let's assume I want to set a breakpoint at the dispatch_command() function and print the value of com_data->com_query.query every time it hit it. This is what I did with gdb after attaching it to the proper mysqld process:
...Key detail here is to use command and refer to the breakpoint by number, 1, and then append the output of the date command to the gdb.txt file in the current directory that is used by default to log the gdb output.
[New LWP 6562]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007fc563d8774d in poll () at ../sysdeps/unix/syscall-template.S:84
84 ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) set height 0
(gdb) set log on
Copying output to gdb.txt.
(gdb) b dispatch_command
Breakpoint 1 at 0xbe9660: file /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc, line 1254.
(gdb) command 1
Type commands for breakpoint(s) 1, one per line.
End with a line saying just "end".
>shell date >> ./gdb.txt
>p com_data->com_query.query
>continue
>end
(gdb) continue
Continuing.
Then in another shell I executed the following:
openxs@ao756:~$ mysql -uroot testI had the output in the gdb window, but what's more important is that I've got it in the gdb.txt file as well. The content looked as follows:
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.7.28-31-log Percona Server (GPL), Release '31', Revision 'd14ef86'
Copyright (c) 2009-2019 Percona LLC and/or its affiliates
Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> select 1;
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.04 sec)
mysql> select 2;
+---+
| 2 |
+---+
| 2 |
+---+
1 row in set (0.04 sec)
mysql> shutdown;
Query OK, 0 rows affected (0.04 sec)
mysql> quit
Bye
openxs@ao756:~$ ls -l gdb.txtThat's it. For basic tracing of any function calls in MySQL or MariaDB server (or any binary with debuginfo available) including timestamps and any arguments, variables or expressions printed you do not strictly need anything but gdb. With different format options for date command you can format timestamp any way you need, for example, you can remove day and month names etc and get even nanosecond precision if you prefer:
-rw-r--r-- 1 root root 7123 лис 17 19:21 gdb.txt
openxs@ao756:~$ cat gdb.txt
Breakpoint 1 at 0xbe9660: file /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc, line 1254.
Type commands for breakpoint(s) 1, one per line.
End with a line saying just "end".
Continuing.
[New Thread 0x7fc566411700 (LWP 6611)]
[Switching to Thread 0x7fc566411700 (LWP 6611)]
Thread 29 "mysqld" hit Breakpoint 1, dispatch_command (thd=thd@entry=
0x7fc548631000, com_data=com_data@entry=0x7fc566410da0, command=COM_QUERY)
at /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc:1254
1254 /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc: No such file or directory.
неділя, 17 листопада 2019 19:20:47 +0200
$1 = 0x7fc54865b021 "show databases"
Thread 29 "mysqld" hit Breakpoint 1, dispatch_command (
thd=thd@entry=0x7fc548631000, com_data=com_data@entry=0x7fc566410da0,
command=COM_QUERY)
at /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc:1254
1254 in /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc
неділя, 17 листопада 2019 19:20:47 +0200
$2 = 0x7fc54865b021 "show tables"
...
Thread 29 "mysqld" hit Breakpoint 1, dispatch_command (
thd=thd@entry=0x7fc548631000, com_data=com_data@entry=0x7fc566410da0,
command=COM_QUERY)
at /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc:1254
1254 in /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc
неділя, 17 листопада 2019 19:20:47 +0200
$9 = 0x7fc54865b021 "select @@version_comment limit 1"
Thread 29 "mysqld" hit Breakpoint 1, dispatch_command (
thd=thd@entry=0x7fc548631000, com_data=com_data@entry=0x7fc566410da0,
command=COM_QUERY)
at /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc:1254
1254 in /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc
неділя, 17 листопада 2019 19:21:01 +0200
$10 = 0x7fc54865b021 "select 1"
Thread 29 "mysqld" hit Breakpoint 1, dispatch_command (
thd=thd@entry=0x7fc548631000, com_data=com_data@entry=0x7fc566410da0,
command=COM_QUERY)
at /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc:1254
1254 in /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc
неділя, 17 листопада 2019 19:21:08 +0200
$11 = 0x7fc54865b021 "select 2"
Thread 29 "mysqld" hit Breakpoint 1, dispatch_command (
thd=thd@entry=0x7fc548631000, com_data=com_data@entry=0x7fc566410da0,
command=COM_QUERY)
at /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc:1254
1254 in /mnt/workspace/percona-server-5.7-debian-binary-rocks-new/label_exp/min-xenial-x64/test/percona-server-5.7-5.7.28-31/sql/sql_parse.cc
неділя, 17 листопада 2019 19:21:12 +0200
$12 = 0x7fc54865b021 "shutdown"
[Thread 0x7fc566411700 (LWP 6611) exited]
Thread 1 "mysqld" received signal SIGUSR1, User defined signal 1.
[Switching to Thread 0x7fc56645b780 (LWP 6525)]
0x00007fc563d8774d in poll () at ../sysdeps/unix/syscall-template.S:84
84 ../sysdeps/unix/syscall-template.S: No such file or directory.
Detaching from program: /usr/sbin/mysqld, process 6525
openxs@ao756:~$
openxs@ao756:~$ for i in `seq 1 20`; do sleep 0.1; date +'%H:%m:%S.%N'; done
20:11:41.126205172
20:11:41.230087681
...
20:11:42.996521734
20:11:43.100229347
openxs@ao756:~$
* * *
 |
| Sometimes event basic tools allow to get useful results. This photo was made with my dumb Nokia phone while running. Just a stop for a moment. Nice and useful result, IMHO, same as with gdb trick discussed here. |
This kind of tracing comes with a cost, both in terms of performance impact (awful) and additional steps to parse the output (we do not really care about all that breakpoint details, we justneed a timestamp and some values printed). eBPF and related dynamic tracing tools (bcc trace and bpftrace) may help with both problems, as I am going to demonstrate in upcoming blog posts. Stay tuned!
No comments:
Post a Comment