I\'ve started to write posts about dynamic tracing on Linux last year, and basic examples presented here and there make it look like in general with perf it\'s already easy to add dynamic probe for entry and return for any function, or even for every other line of code inside the function (that perf probe -x --line shows). Numerous examples of adding probes to do_command(), dispatch_command() in MySQL or MariaDB code (or even malloc() provided by the libraries) etc kind of illustrated if not proved that.
It turned out that when one tries to use this method in a more generic case against MySQL or MariaDB code things may get way more complicated. The reason is that the code these days is mostly C++ and one often has to trace class member functions, not just plain global C functions. The problem can be easily demonstrated this way:
openxs@ao756:~/dbs/maria10.3$ ps aux | grep dbsopenxs 30377 0.8 3.2 1849476 125008 pts/18 Sl 14:03 0:00 /home/openxs/dbs/maria10.3/bin/mysqld --no-defaults --basedir=/home/openxs/dbs/maria10.3 --datadir=/home/openxs/dbs/maria10.3/data --plugin-dir=/home/openxs/dbs/maria10.3/lib/plugin --log-error=/home/openxs/dbs/maria10.3/data/ao756.err --pid-file=ao756.pid --socket=/tmp/mariadb.sock --port=3309...openxs@ao756:~$ perf versionperf version 4.4.219
So, I have a nice MariaDB 10.3.x server built from GitHub source as usual, up and running on my netbook/\"bedroom test server\" with Ubuntu 16.04.6 LTS (GNU/Linux 4.4.0-179-generic x86_64). Let\'s assume I want to add a probe to some method that I clearly see and can use in gdb, like this:
openxs@ao756:~/dbs/maria10.3$ sudo gdb -p 30377GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.5) 7.11.1...[New LWP 30447][Thread debugging using libthread_db enabled]Using host libthread_db library \"/lib/x86_64-linux-gnu/libthread_db.so.1\".0x00007fd8b1b1f80d in poll () at ../sysdeps/unix/syscall-template.S:8484 ../sysdeps/unix/syscall-template.S: No such file or directory.(gdb) b ha_heap::records_in_rangeBreakpoint 1 at 0x55f7d3aeccf0: file /home/openxs/git/server/storage/heap/ha_heap.cc, line 586.(gdb)
So, gdb kindly understands method names and one may expect the same from perf. Now if I quit gdb and try to add probe:
openxs@ao756:~/dbs/maria10.3$ perf probe -x /home/openxs/dbs/maria10.3/bin/mysqld ha_heap::records_in_rangeSemantic error :There is non-digit char in line number. Error: Command Parse Error.openxs@ao756:~/dbs/maria10.3$
The reason is that perf probe syntax
PROBE SYNTAX Probe points are defined by following syntax. 1) Define event based on function name [EVENT=]FUNC[@SRC][:RLN|+OFFS|%return|;PTN] [ARG ...] 2) Define event based on source file with line number [EVENT=]SRC:ALN [ARG ...] 3) Define event based on source file with lazy pattern [EVENT=]SRC;PTN [ARG ...]...
uses the : character for line
numbers, and this conflicts with the C++ scope syntax. It could probably infer that :: is not a line number, but nobody has written that yet, as of version 4.4.219.
Let\'s try to find out if there is still a way to add the probe. First, let\'s check if perf sees any similar functions, using the --funcs option:
openxs@ao756:~/dbs/maria10.3$ perf probe -x /home/openxs/dbs/maria10.3/bin/mysqld --funcs | grep records_in_rangeha_heap::records_in_rangeha_innobase::records_in_rangeha_maria::records_in_rangeha_myisam::records_in_rangeha_myisammrg::records_in_rangeha_partition::records_in_rangeha_seq::records_in_rangehandler::records_in_rangehp_rb_records_in_rangemaria_records_in_rangemi_records_in_rangemyrg_records_in_rangeopenxs@ao756:~/dbs/maria10.3$ perf probe -x /home/openxs/dbs/maria10.3/bin/mysqld --funcs --no-demangle | grep records_in_rangehp_rb_records_in_rangemaria_records_in_rangemi_records_in_rangemyrg_records_in_rangeopenxs@ao756:~/dbs/maria10.3$
In theory --no-demangle means that demangling is disabled:
--demangle Demangle application symbols. --no-demangle is also available for disabling demangling.
and I expected to see the original mangled name to refer to. But I see demangled name as one of functions I can use (while I can NOT), but do not see mangled name at all. This looks inconsistent and would be really unfortunate if true. I am sure the function exists and is visible. Quick search in Google gave a hint in this nice post, there is a filter that disables showing names starting with \'_\' by default:
--filter=FILTER
(Only for --vars and --funcs) Set filter. FILTER is a
combination of glob pattern, see FILTER PATTERN for detail. Default
FILTER is \"!k???tab_* &
!crc_*\" for --vars, and \"!_*\" for --funcs. If several filters are specified, only the last filter is used.
So, let\'s try non-default filter:
openxs@ao756:~/dbs/maria10.3$ perf probe -x /home/openxs/dbs/maria10.3/bin/mysqld --funcs --no-demangle --filter \'*\' | grep records_in_range_ZN11ha_innobase16records_in_rangeEjP12st_key_rangeS1__ZN12ha_myisammrg16records_in_rangeEjP12st_key_rangeS1__ZN12ha_partition16records_in_rangeEjP12st_key_rangeS1__ZN6ha_seq16records_in_rangeEjP12st_key_rangeS1__ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1__ZN7handler16records_in_rangeEjP12st_key_rangeS1__ZN8ha_maria16records_in_rangeEjP12st_key_rangeS1__ZN9ha_myisam16records_in_rangeEjP12st_key_rangeS1_hp_rb_records_in_rangemaria_records_in_rangemi_records_in_rangemyrg_records_in_rangeopenxs@ao756:~/dbs/maria10.3$
The mangles name we are looking for is _ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_. I\'d expect it should work, as we had to use mangled names even for functions that are not members of any class with ftrace. So, let\'s try (I need sudo on Ubuntu for adding probe to work):
openxs@ao756:~/dbs/maria10.3$ sudo perf probe -x /home/openxs/dbs/maria10.3/bin/mysqld _ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_[sudo] password for openxs:Probe point \'_ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_\' not found. Error: Failed to add events.openxs@ao756:~/dbs/maria10.3$ sudo perf probe --no-demangle -x /home/openxs/dbs/maria10.3/bin/mysqld _ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_Added new event: probe_mysqld:_ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_ (on _ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_ in /home/openxs/dbs/maria10.3/bin/mysqld)You can now use it in all perf tools, such as: perf record -e probe_mysqld:_ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_ -aR sleep 1openxs@ao756:~/dbs/maria10.3$
As you can see, adding the mangled function name and --no-demangle option worked. I can add a probe at function exit to print the returned value as well:
openxs@ao756:~/dbs/maria10.3$ sudo perf probe --no-demangle -x /home/openxs/dbs/maria10.3/bin/mysqld --add ha_heap_records_in_range_ret=\'_ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_%return records=$retval:u32\'Added new event: probe_mysqld:ha_heap_records_in_range_ret (on _ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_%return in /home/openxs/dbs/maria10.3/bin/mysqld with records=$retval:u32)You can now use it in all perf tools, such as: perf record -e probe_mysqld:ha_heap_records_in_range_ret -aR sleep 1openxs@ao756:~/dbs/maria10.3$
As you can see I had to give an explicit another name to the exit probe and I tried to see the return value. I also had to find out what data type should be used for the return value (it\'s ulong or u32 in perms of perf/ftrace, see the source code). My perf is not smart enough to infer this.
Now if I try to record the probe:
openxs@ao756:~/dbs/maria10.3$ sudo perf record -e probe_mysqld:ha_heap_records_in_range_ret -aR sleep 1000^C[ perf record: Woken up 1 times to write data ][ perf record: Captured and wrote 0.904 MB perf.data (2 samples) ]openxs@ao756:~/dbs/maria10.3$
while doing something with MEMORY table in another session:
openxs@ao756:~/dbs/maria10.3$ bin/mysql -uroot --socket=/tmp/mariadb.sock testReading table information for completion of table and column namesYou can turn off this feature to get a quicker startup with -AWelcome to the MariaDB monitor. Commands end with ; or g.Your MariaDB connection id is 9Server version: 10.3.24-MariaDB Source distributionCopyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.Type \'help;\' or \'h\' for help. Type \'c\' to clear the current input statement.MariaDB [test] > show create table theapG*************************** 1. row *************************** Table: theapCreate Table: CREATE TABLE `theap` ( `id` int(11) DEFAULT NULL, `c1` int(11) DEFAULT NULL, KEY `id` (`id`), KEY `c1` (`c1`) USING BTREE) ENGINE=MEMORY DEFAULT CHARSET=latin11 row in set (0,000 sec)MariaDB [test] > select * from theap;+------+------+| id | c1 |+------+------+| 1 | 1 || 2 | 2 || 3 | 3 |+------+------+3 rows in set (0,001 sec)MariaDB [test] > explain select * from theap where c1 between 2 and 3;+------+-------------+-------+-------+---------------+------+---------+------+------+-------------+| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |+------+-------------+-------+-------+---------------+------+---------+------+------+-------------+| 1 | SIMPLE | theap | range | c1 | c1 | 5 | NULL | 1 | Using where |+------+-------------+-------+-------+---------------+------+---------+------+------+-------------+1 row in set (0,001 sec)MariaDB [test] > select * from theap where c1 between 2 and 3;+------+------+| id | c1 |+------+------+| 2 | 2 || 3 | 3 |+------+------+2 rows in set (0,001 sec)
I can see that it worked:
openxs@ao756:~/dbs/maria10.3$ sudo perf script > /tmp/trace.txtopenxs@ao756:~/dbs/maria10.3$ cat /tmp/trace.txt mysqld 31547 [001] 326219.193101: probe_mysqld:ha_heap_records_in_range_ret: (55f7d3aeccf0
Dynamic Tracing of C++ Class Member Functions with perf appeared first on MariaDB.org
I've started to write posts about dynamic tracing on Linux last year, and basic examples presented here and there make it look like in general with perf it's already easy to add dynamic probe for entry and return for any function, or even for every other line of code inside the function (that perf probe -x <path to binary> --line <function name> shows). Numerous examples of adding probes to do_command(), dispatch_command() in MySQL or MariaDB code (or even malloc() provided by the libraries) etc kind of illustrated if not proved that.
It turned out that when one tries to use this method in a more generic case against MySQL or MariaDB code things may get way more complicated. The reason is that the code these days is mostly C++ and one often has to trace class member functions, not just plain global C functions. The problem can be easily demonstrated this way:
openxs@ao756:~/dbs/maria10.3$ ps aux | grep dbs
openxs 30377 0.8 3.2 1849476 125008 pts/18 Sl 14:03 0:00 /home/openxs/dbs/maria10.3/bin/mysqld --no-defaults --basedir=/home/openxs/dbs/maria10.3 --datadir=/home/openxs/dbs/maria10.3/data --plugin-dir=/home/openxs/dbs/maria10.3/lib/plugin --log-error=/home/openxs/dbs/maria10.3/data/ao756.err --pid-file=ao756.pid --socket=/tmp/mariadb.sock --port=3309
...
openxs@ao756:~$ perf version
perf version 4.4.219
So, I have a nice MariaDB 10.3.x server built from GitHub source as usual, up and running on my netbook/"bedroom test server" with Ubuntu 16.04.6 LTS (GNU/Linux 4.4.0-179-generic x86_64). Let's assume I want to add a probe to some method that I clearly see and can use in gdb, like this:
openxs@ao756:~/dbs/maria10.3$ sudo gdb -p 30377
GNU gdb (Ubuntu 7.11.1-0ubuntu1~16.5) 7.11.1
...
[New LWP 30447]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007fd8b1b1f80d in poll () at ../sysdeps/unix/syscall-template.S:84
84 ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) b ha_heap::records_in_range
Breakpoint 1 at 0x55f7d3aeccf0: file /home/openxs/git/server/storage/heap/ha_heap.cc, line 586.
(gdb)
So, gdb kindly understands method names and one may expect the same from perf. Now if I quit gdb and try to add probe:
openxs@ao756:~/dbs/maria10.3$ perf probe -x /home/openxs/dbs/maria10.3/bin/mysqld ha_heap::records_in_range
Semantic error :There is non-digit char in line number.
Error: Command Parse Error.
openxs@ao756:~/dbs/maria10.3$
The reason is that perf probe syntax
PROBE SYNTAX
Probe points are defined by following syntax.1) Define event based on function name
[EVENT=]FUNC[@SRC][:RLN|+OFFS|%return|;PTN] [ARG ...]2) Define event based on source file with line number
[EVENT=]SRC:ALN [ARG ...]3) Define event based on source file with lazy pattern
[EVENT=]SRC;PTN [ARG ...]
...
uses the : character for line numbers, and this conflicts with the C++ scope syntax. It could probably infer that :: is not a line number, but nobody has written that yet, as of version 4.4.219.
Let's try to find out if there is still a way to add the probe. First, let's check if perf sees any similar functions, using the --funcs option:
openxs@ao756:~/dbs/maria10.3$ perf probe -x /home/openxs/dbs/maria10.3/bin/mysqld --funcs | grep records_in_range
ha_heap::records_in_range
ha_innobase::records_in_range
ha_maria::records_in_range
ha_myisam::records_in_range
ha_myisammrg::records_in_range
ha_partition::records_in_range
ha_seq::records_in_range
handler::records_in_range
hp_rb_records_in_range
maria_records_in_range
mi_records_in_range
myrg_records_in_range
openxs@ao756:~/dbs/maria10.3$ perf probe -x /home/openxs/dbs/maria10.3/bin/mysqld --funcs --no-demangle | grep records_in_range
hp_rb_records_in_range
maria_records_in_range
mi_records_in_range
myrg_records_in_range
openxs@ao756:~/dbs/maria10.3$
In theory --no-demangle means that demangling is disabled:
--demangle
Demangle application symbols. --no-demangle is also available for
disabling demangling.
and I expected to see the original mangled name to refer to. But I see demangled name as one of functions I can use (while I can NOT), but do not see mangled name at all. This looks inconsistent and would be really unfortunate if true. I am sure the function exists and is visible. Quick search in Google gave a hint in this nice post, there is a filter that disables showing names starting with '_' by default:
- --filter=FILTER
- (Only for --vars and --funcs) Set filter. FILTER is a combination of glob pattern, see FILTER PATTERN for detail. Default FILTER is "!k???tab_* & !crc_*" for --vars, and "!_*" for --funcs. If several filters are specified, only the last filter is used.
So, let's try non-default filter:
openxs@ao756:~/dbs/maria10.3$ perf probe -x /home/openxs/dbs/maria10.3/bin/mysqld --funcs --no-demangle --filter '*' | grep records_in_range
_ZN11ha_innobase16records_in_rangeEjP12st_key_rangeS1_
_ZN12ha_myisammrg16records_in_rangeEjP12st_key_rangeS1_
_ZN12ha_partition16records_in_rangeEjP12st_key_rangeS1_
_ZN6ha_seq16records_in_rangeEjP12st_key_rangeS1_
_ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_
_ZN7handler16records_in_rangeEjP12st_key_rangeS1_
_ZN8ha_maria16records_in_rangeEjP12st_key_rangeS1_
_ZN9ha_myisam16records_in_rangeEjP12st_key_rangeS1_
hp_rb_records_in_range
maria_records_in_range
mi_records_in_range
myrg_records_in_range
openxs@ao756:~/dbs/maria10.3$
The mangles name we are looking for is _ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_. I'd expect it should work, as we had to use mangled names even for functions that are not members of any class with ftrace. So, let's try (I need sudo on Ubuntu for adding probe to work):
openxs@ao756:~/dbs/maria10.3$ sudo perf probe -x /home/openxs/dbs/maria10.3/bin/mysqld _ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_
[sudo] password for openxs:
Probe point '_ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_' not found.
Error: Failed to add events.
openxs@ao756:~/dbs/maria10.3$ sudo perf probe --no-demangle -x /home/openxs/dbs/maria10.3/bin/mysqld _ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_
Added new event:
probe_mysqld:_ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_ (on _ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_ in /home/openxs/dbs/maria10.3/bin/mysqld)You can now use it in all perf tools, such as:
perf record -e probe_mysqld:_ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_ -aR sleep 1
openxs@ao756:~/dbs/maria10.3$
As you can see, adding the mangled function name and --no-demangle option worked. I can add a probe at function exit to print the returned value as well:
openxs@ao756:~/dbs/maria10.3$ sudo perf probe --no-demangle -x /home/openxs/dbs/maria10.3/bin/mysqld --add ha_heap_records_in_range_ret='_ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_%return records=$retval:u32'
Added new event:
probe_mysqld:ha_heap_records_in_range_ret (on _ZN7ha_heap16records_in_rangeEjP12st_key_rangeS1_%return in /home/openxs/dbs/maria10.3/bin/mysqld with records=$retval:u32)You can now use it in all perf tools, such as:
perf record -e probe_mysqld:ha_heap_records_in_range_ret -aR sleep 1
openxs@ao756:~/dbs/maria10.3$
As you can see I had to give an explicit another name to the exit probe and I tried to see the return value. I also had to find out what data type should be used for the return value (it's ulong or u32 in perms of perf/ftrace, see the source code). My perf is not smart enough to infer this.
Now if I try to record the probe:
openxs@ao756:~/dbs/maria10.3$ sudo perf record -e probe_mysqld:ha_heap_records_in_range_ret -aR sleep 1000
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.904 MB perf.data (2 samples) ]openxs@ao756:~/dbs/maria10.3$
while doing something with MEMORY table in another session:
openxs@ao756:~/dbs/maria10.3$ bin/mysql -uroot --socket=/tmp/mariadb.sock test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -AWelcome to the MariaDB monitor. Commands end with ; or \g.
Your MariaDB connection id is 9
Server version: 10.3.24-MariaDB Source distributionCopyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
MariaDB [test]> show create table theap\G
*************************** 1. row ***************************
Table: theap
Create Table: CREATE TABLE `theap` (
`id` int(11) DEFAULT NULL,
`c1` int(11) DEFAULT NULL,
KEY `id` (`id`),
KEY `c1` (`c1`) USING BTREE
) ENGINE=MEMORY DEFAULT CHARSET=latin1
1 row in set (0,000 sec)MariaDB [test]> select * from theap;
+------+------+
| id | c1 |
+------+------+
| 1 | 1 |
| 2 | 2 |
| 3 | 3 |
+------+------+
3 rows in set (0,001 sec)MariaDB [test]> explain select * from theap where c1 between 2 and 3;
+------+-------------+-------+-------+---------------+------+---------+------+------+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+------+-------------+-------+-------+---------------+------+---------+------+------+-------------+
| 1 | SIMPLE | theap | range | c1 | c1 | 5 | NULL | 1 | Using where |
+------+-------------+-------+-------+---------------+------+---------+------+------+-------------+
1 row in set (0,001 sec)MariaDB [test]> select * from theap where c1 between 2 and 3;
+------+------+
| id | c1 |
+------+------+
| 2 | 2 |
| 3 | 3 |
+------+------+
2 rows in set (0,001 sec)
I can see that it worked:
openxs@ao756:~/dbs/maria10.3$ sudo perf script > /tmp/trace.txt
openxs@ao756:~/dbs/maria10.3$ cat /tmp/trace.txt mysqld 31547 [001] 326219.193101: probe_mysqld:ha_heap_records_in_range_ret: (55f7d3aeccf0 <- 55f7d35df8da) records=0x1
mysqld 31547 [001] 326224.706375: probe_mysqld:ha_heap_records_in_range_ret: (55f7d3aeccf0 <- 55f7d35df8da) records=0x1
openxs@ao756:~/dbs/maria10.3$
It works as expected! You may want to find out why it returned the value we see (1 in hex) etc, but basically it works,
| Never give up! I want Sam to be remembered for this attitude... |
To summarize:
| # | Наименование новости | Тональность | Информативность | Дата публикации |
|---|---|---|---|---|
| 1 | How to Add Probe Inside a Function and Access Local Variables with bpftrace | 0 | 5.9 | 04-02-2022 |
| 2 | Dynamic Tracing of Memory Allocations in MySQL With bcc Tools | 0 | 5.04 | 12-05-2021 |
| 3 | Dynamic Tracing of pthread_mutex_lock in MariaDB – First Steps | 0 | 6.5 | 20-09-2020 |
| 4 | Off-CPU Analysis Attempt to Find the Reason of Performance Regression in MariaDB 10.4 | 0 | 11.2 | 09-05-2021 |
| 5 | Dynamic Tracing for Finding and Solving MariaDB (and MySQL) Performance Problems on Linux – Percona Live ONLINE Talk Preview | 0 | 9.47 | 05-05-2020 |
| 6 | MariaDB 10.5 and Memory Instrumentation in Performance Schema – Basic Checks | 0 | 7.67 | 24-08-2020 |
| 7 | bpftrace as a code/function coverage tool for MariaDB server | 0 | 6.46 | 03-10-2021 |
| 8 | MariaDB 10.5 and Memory Instrumentation in Performance Schema – First Steps | 0 | 8.6 | 09-08-2020 |
| 9 | BCC Tools for disk I/O Analysis and More | 0 | 6.22 | 13-09-2020 |
| 10 | Playing with recent bpftrace and MariaDB 10.5 on Fedora – Part II, Using the Existing Tools | 0 | 7.98 | 24-01-2021 |