I had already written many blog posts about bpftrace. All my public talks devoted to bpftrace included a slide about "problems", and one of them usually sounded like this:
...access to complex structures (bpftrace needs headers)...
So, today I decided to demonstrate how to resolve this minor problem. As an example I tried to reproduce gdb debugging steps from this older post. I want to trace and report table and row level locks set during execution of various SQL statements against InnoDB tables in MariaDB Server 10.6.6 built from more or less current GitHub code. To reduce the performance impact I'll use recent version of bpftrace build from GitHub source:
openxs@ao756:~/git/bpftrace/build$ src/bpftrace --version
bpftrace v0.14.0-50-g4228
First thing to find out (given the same test case as in that older blog post) is what functions to add uprobe on and what information is available. Let's start with gdb and set a couple of breakpoints on lock_tables and lock_row_lock functions:
openxs@ao756:~/dbs/maria10.6$ sudo gdb -p `pidof mariadbd`
GNU gdb (Ubuntu 9.2-0ubuntu1~20.04) 9.2
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word".
Attaching to process 14850
[New LWP 14852]
[New LWP 14853]
[New LWP 14854]
[New LWP 14855]
[New LWP 14859]
[New LWP 14861]
[New LWP 14862]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
--Type <RET> for more, q to quit, c to continue without paging--
0x00007f126bc04aff in __GI___poll (fds=0x55ef5e36c838, nfds=3,
timeout=timeout@entry=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
29 ../sysdeps/unix/sysv/linux/poll.c: No such file or directory.
(gdb) b lock_table
Breakpoint 1 at 0x55ef5c44a840: lock_table. (4 locations)
(gdb) b lock_rec_lock
Breakpoint 2 at 0x55ef5c1c4896: lock_rec_lock. (2 locations)
(gdb) c
Continuing.
[New Thread 0x7f1245ffd700 (LWP 14899)]
[New Thread 0x7f1246fff700 (LWP 14900)]
[New Thread 0x7f1268518700 (LWP 14904)]
[Switching to Thread 0x7f1268518700 (LWP 14904)]
Thread 11 "mariadbd" hit Breakpoint 1, lock_table (table=0x7f1218065b20,
mode=LOCK_IS, thr=0x7f121806cc10)
at /home/openxs/git/server/storage/innobase/lock/lock0lock.cc:3481
warning: Source file is more recent than executable.
3481 {
(gdb) p table
$1 = (dict_table_t *) 0x7f1218065b20
(gdb) p table->name
$2 = {m_name = 0x7f1218020908 "test/tt", static part_suffix = "#P#"}
(gdb) c
Continuing.
Thread 11 "mariadbd" hit Breakpoint 1, lock_table (table=0x7f1218065b20,
mode=LOCK_IS, thr=0x7f121806cc10)
at /home/openxs/git/server/storage/innobase/include/que0que.ic:37
warning: Source file is more recent than executable.
37 return(thr->graph->trx);
(gdb) c
Continuing.
Thread 11 "mariadbd" hit Breakpoint 2, lock_rec_lock (impl=false, mode=2,
block=0x7f12480325a0, heap_no=2, index=0x7f1218066f90, thr=0x7f121806cc10)
at /home/openxs/git/server/storage/innobase/include/que0que.ic:37
37 return(thr->graph->trx);
(gdb) p index
$3 = (dict_index_t *) 0x7f1218066f90
(gdb) p index->name
$4 = {m_name = 0x7f1218067120 "PRIMARY"}
(gdb) p index->table->name
$5 = {m_name = 0x7f1218020908 "test/tt", static part_suffix = "#P#"}
(gdb) p index->table
$6 = (dict_table_t *) 0x7f1218065b20
(gdb) q
A debugging session is active.
Inferior 1 [process 14850] will be detached.
Quit anyway? (y or n) y
Detaching from program: /home/openxs/dbs/maria10.6/bin/mariadbd, process 14850
[Inferior 1 (process 14850) detached]
openxs@ao756:~/dbs/maria10.6$
From the above we already see that breakpoints are set in more than one place (so we expect more that one function name to match for the uprobe). We also see some structures used as functions arguments to access, and so we need a way to define them for tracing.
Now, if we try something lame to add a probe (should be done as root or via sudo) for just lock_tables:
openxs@ao756:~/git/bpftrace/build$ src/bpftrace -e 'uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table { printf("lock_table: %p, %d, %p\n", arg0, arg1, arg2); }'
ERROR: bpftrace currently only supports running as the root user.
openxs@ao756:~/git/bpftrace/build$ sudo src/bpftrace -e 'uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table { printf("lock_table: %p, %d, %p\n", arg0, arg1, arg2); }'
[sudo] password for openxs:
Attaching 20 probes...
^C
we can already suspect something bad, as we ended up with 20 probes. We can even list them in a readable way:
openxs@ao756:~/git/bpftrace/build$ sudo src/bpftrace -l 'uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table' | c++filt
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table(dict_table_t*, lock_mode, que_thr_t*)
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_tables(THD*, TABLE_LIST*, unsigned int, unsigned int)
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_names(THD*, DDL_options_st const&, TABLE_LIST*, TABLE_LIST*, unsigned long, unsigned int)
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_names(THD*, DDL_options_st const&, TABLE_LIST*, TABLE_LIST*, unsigned long, unsigned int) [clone .cold]
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_create(dict_table_t*, unsigned int, trx_t*, ib_lock_t*)
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_for_trx(dict_table_t*, trx_t*, lock_mode)
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_has_locks(dict_table_t*)
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_resurrect(dict_table_t*, trx_t*, lock_mode)
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_resurrect(dict_table_t*, trx_t*, lock_mode) [clone .cold]
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_lock_list_init(ut_list_base<ib_lock_t, ut_list_node<ib_lock_t> lock_table_t::*>*)
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_print(_IO_FILE*, ib_lock_t const*)
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_print(_IO_FILE*, ib_lock_t const*) [clone .cold]
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_wsrep(dict_table_t*, lock_mode, que_thr_t*, trx_t*)
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_wsrep(dict_table_t*, lock_mode, que_thr_t*, trx_t*) [clone .cold]
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_dequeue(ib_lock_t*, bool)
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_dequeue(ib_lock_t*, bool) [clone .cold]
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_dequeue(ib_lock_t*, bool) [clone .constprop.0]
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table_dequeue(ib_lock_t*, bool) [clone .constprop.0] [clone .cold]
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_tables_precheck(THD*, TABLE_LIST*)
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_tables_open_and_lock_tables(THD*, TABLE_LIST*)
openxs@ao756:~/git/bpftrace/build$ sudo src/bpftrace -l 'uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table' | wc -l
20
So, as expected, out probe maptaches any function with "lock_tables" in its name, and using the first row of the output (demangled function signature) does NOT help:
openxs@ao756:~/git/bpftrace/build$ sudo src/bpftrace -l 'uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table' | head -1 | c++filt
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table(dict_table_t*, lock_mode, que_thr_t*)
openxs@ao756:~/git/bpftrace/build$ sudo src/bpftrace -l 'uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table(dict_table_t*, lock_mode, que_thr_t*)'
stdin:1:1-59: ERROR: syntax error, unexpected (, expecting {
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table(dict_table_t*, lock_mode, que_thr_t*)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
We can NOT use demandled signature, but we can use mangled equivalent:
openxs@ao756:~/git/bpftrace/build$ sudo src/bpftrace -l 'uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_table' | head -1
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:_Z10lock_tableP12dict_table_t9lock_modeP9que_thr_t
Like this:
openxs@ao756:~/git/bpftrace/build$ sudo src/bpftrace -e 'uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:_Z10lock_tableP12dict_table_t9lock_modeP9que_thr_t
{ printf("lock_table: %p, %d, %p\n", arg0, arg1, arg2); }'
Attaching 1 probe...
lock_table: 0x7f1218065b20, 0, 0x7f121806cc10
lock_table: 0x7f121801d690, 4, 0x7f1218068d60
lock_table: 0x7f121801d690, 1, 0x7f1218068d60
lock_table: 0x7f122400d350, 1, 0x7f121807a158
lock_table: 0x7f122400d350, 1, 0x7f121807a158
lock_table: 0x7f12240101e0, 1, 0x7f121807a900
lock_table: 0x7f12240101e0, 1, 0x7f121807a900
lock_table: 0x7f12240101e0, 1, 0x7f121807a900
lock_table: 0x7f12240101e0, 1, 0x7f121807a900
lock_table: 0x7f12240101e0, 1, 0x7f121807a900
lock_table: 0x7f12240101e0, 1, 0x7f121807a900
^C
I've got the above output whilke execvuting rhis SQL statement:
MariaDB [test]> insert into t(val) select 100 from tt;
Query OK, 4 rows affected (0.038 sec)
Records: 4 Duplicates: 0 Warnings: 0
A bit more table level lock requests than one would expect, and from more than one thread. This can be explained, but the real problem is that we see lock mode, locking thread address but NOT the actual name of the locked table (that is hidden inside a complex structure). Fro0m gdb output we know that the first argument (arg0) of the function is a pointer to dict_table_t structure, but how is it defined?
I do not know InnoDB source code by heart, so I have to search (with some assumptions in mind this is easier):
openxs@ao756:~/git/server$ grep -rn 'struct dict_table_t' * | grep '\.h'
storage/innobase/include/row0import.h:34:struct dict_table_t;
storage/innobase/include/srv0start.h:33:struct dict_table_t;
storage/innobase/include/dict0mem.h:1788:struct dict_table_t {
storage/innobase/include/dict0types.h:39:struct dict_table_t;
I've highlighted the line where structure definition begins, so I can see what's there (only the much later important part is quoted):
...
public:
/** Id of the table. */
table_id_t id;
/** dict_sys.id_hash chain node */
dict_table_t* id_hash;
/** Table name in name_hash */
table_name_t name;
...
Even the name is not a simple scalar data type, so we can find the definition in te code (I had not cared much to make sure this is really a 10.6 branhc, assuming that some basic things do not change that often in MariaDB, optimistic approach):
openxs@ao756:~/git/server$ vi +102 storage/innobase/include/dict0types.h
struct table_name_t
{
/** The name in internal representation */
char* m_name;
/** Default constructor */
table_name_t() {}
/** Constructor */
table_name_t(char* name) : m_name(name) {}
/** @return the end of the schema name */
const char* dbend() const
{
const char* sep = strchr(m_name, '/');
ut_ad(sep);
return sep;
}
/** @return the length of the schema name, in bytes */
size_t dblen() const { return size_t(dbend() - m_name); }
/** Determine the filename-safe encoded table name.
@return the filename-safe encoded table name */
const char* basename() const { return dbend() + 1; }
/** The start of the table basename suffix for partitioned tables */
static const char part_suffix[4];
/** Determine the partition or subpartition name suffix.
@return the partition name
@retval NULL if the table is not partitioned */
const char* part() const { return strstr(basename(), part_suffix); }
/** @return whether this is a temporary or intermediate table name */
inline bool is_temporary() const;
};
I do not care about fun ction members, just data stored in the strucute (highlughted). Moreover, read this part of bpftrace reference carefully:
You can define your own structs when needed. In some cases, kernel structs are not declared in the kernel headers package, and are declared manually in bpftrace tools (or partial structs are: enough to reach the member to dereference).
Thing is, while we theoretically can use #include in bpftrace, structured used in MariaDB server are defined in so many heards amd are so specific and sometimes deeply nested, that usually it's easier to use properly sised placeholderns in explicit struct definitions. You can get proper sizes from gdb:
(gdb) p sizeof(table_id_t)
$1 = 8
(gdb) p sizeof(dict_table_t *)
$2 = 8
(gdb) p sizeof(long long)
$3 = 8
Taking the above into account, we can try to define structured like these:
struct table_name_t
{
char* m_name;
char part_suffix[4];
}
struct dict_table_t {
long long id;
struct dict_table_t* id_hash;
struct table_name_t name;
}
in our bpftrace code to be able to pproperly derefence the table name as a null-terminated string:
openxs@ao756:~/git/bpftrace/build$ sudo src/bpftrace -e '
>
> struct table_name_t
> {
> char* m_name;
> char part_suffix[4];
> }
>
> struct dict_table_t {
> long long id;
> struct dict_table_t* id_hash;
> struct table_name_t name;
> }
>
> uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:_Z10lock_tableP12dict_table_t9lock_modeP9que_thr_t
> { printf("lock_table: %s, %d, %p\n", str(((struct dict_table_t *)arg0)->name.m_name), arg1, arg2); }'
Attaching 1 probe...
lock_table: test/tt, 0, 0x7f121806cc10
lock_table: test/t, 4, 0x7f1218068d60
lock_table: test/t, 1, 0x7f1218068d60
lock_table: mysql/innodb_table_stats, 1, 0x7f122800e7d8
lock_table: mysql/innodb_table_stats, 1, 0x7f122800e7d8
lock_table: mysql/innodb_index_stats, 1, 0x7f122800ef80
lock_table: mysql/innodb_index_stats, 1, 0x7f122800ef80
lock_table: mysql/innodb_index_stats, 1, 0x7f122800ef80
lock_table: mysql/innodb_index_stats, 1, 0x7f122800ef80
lock_table: mysql/innodb_index_stats, 1, 0x7f122800ef80
lock_table: mysql/innodb_index_stats, 1, 0x7f122800ef80
^C
Looks good enough as a proof of concept already. We see how to define simplified structured containing just enough information to find and derefernce items of complex nested structures used all over the MariaDB server code.
I'd surely want to add a probe to lock_row_lock too, and for this I need some more gdb outputs from the breakpoint set:
Thread 11 "mariadbd" hit Breakpoint 2, lock_rec_lock (impl=false, mode=2,
block=0x7f12480325a0, heap_no=2, index=0x7f1218066f90, thr=0x7f121806cc10)
at /home/openxs/git/server/storage/innobase/include/que0que.ic:37
37 return(thr->graph->trx);
(gdb) p index
$3 = (dict_index_t *) 0x7f1218066f90
(gdb) p index->name
$4 = {m_name = 0x7f1218067120 "PRIMARY"}
(gdb) p index->table->name
$5 = {m_name = 0x7f1218020908 "test/tt", static part_suffix = "#P#"}
(gdb) p index->table
$6 = (dict_table_t *) 0x7f1218065b20
(gdb) p index->id
$7 = 48
(gdb) p sizeof(index->id)
$8 = 8
(gdb) p sizeof(index->heap)
$9 = 8
(gdb) p sizeof(index->name)
$10 = 8
(gdb) p impl
$11 = false
(gdb) p sizeof(impl)
$12 = 1
(gdb) p sizeof(mode)
$13 = 4
I can surely find the defintion of dict_index_t structure and work based on it:
struct dict_index_t {
/** Maximum number of fields */
static constexpr unsigned MAX_N_FIELDS= (1U << 10) - 1;
index_id_t id; /*!< id of the index */
mem_heap_t* heap; /*!< memory heap */
id_name_t name; /*!< index name */
dict_table_t* table; /*!< back pointer to table */
...
but sizes above are actually enough to come up with a proper code like this:
sudo src/bpftrace -e '
struct table_name_t
{
char* m_name;
char part_suffix[4];
}
struct dict_table_t {
long long id;
struct dict_table_t* id_hash;
struct table_name_t name;
}
struct dict_index_t {
long long id;
long long heap;
char* name;
struct dict_table_t* table;
}
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:_Z10lock_tableP12dict_table_t9lock_modeP9que_thr_t
{ printf("lock_table: %s, mode: %d, thread: %p\n",
str(((struct dict_table_t *)arg0)->name.m_name),
arg1,
arg2); }
uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_rec_lock
{ printf("lock_rec_lock: impl (%d) mode %d index %s rec of %s, thread: %p\n",
arg0,
arg1,
str(((struct dict_index_t *)arg4)->name),
str(((struct dict_index_t *)arg4)->table->name.m_name),
arg5); }
that produces the following:
openxs@ao756:~/git/bpftrace/build$ sudo src/bpftrace -e '
>
> struct table_name_t
> {
> char* m_name;
> char part_suffix[4];
> }
>
> struct dict_table_t {
> long long id;
> struct dict_table_t* id_hash;
> struct table_name_t name;
> }
>
> struct dict_index_t {
> long longid;
> long longheap;
> char*name;
> struct dict_table_t*table;
> }
>
> uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:_Z10lock_tableP12dict_table_t9lock_modeP9que_thr_t
> { printf("lock_table: %s, mode: %d, thread: %p\n",
> str(((struct dict_table_t *)arg0)->name.m_name),
> arg1,
> arg2); }
>
> uprobe:/home/openxs/dbs/maria10.6/bin/mariadbd:lock_rec_lock
> { printf("lock_rec_lock: impl (%d) mode %d index %s rec of %s, thread: %p\n",
> arg0,
> arg1,
> str(((struct dict_index_t *)arg4)->name),
> str(((struct dict_index_t *)arg4)->table->name.m_name),
> arg5); }
>
> '
Attaching 3 probes...
lock_table: test/tt, mode: 0, thread: 0x7f121806cc10
lock_rec_lock: impl (0) mode 2 index PRIMARY rec of test/tt, thread: 0x7f121806cc10
lock_table: test/t, mode: 4, thread: 0x7f1218068d60
lock_table: test/t, mode: 1, thread: 0x7f1218068d60
lock_rec_lock: impl (0) mode 2 index PRIMARY rec of test/tt, thread: 0x7f121806cc10
lock_rec_lock: impl (0) mode 2 index PRIMARY rec of test/tt, thread: 0x7f121806cc10
lock_rec_lock: impl (0) mode 2 index PRIMARY rec of test/tt, thread: 0x7f121806cc10
lock_rec_lock: impl (0) mode 2 index PRIMARY rec of test/tt, thread: 0x7f121806cc10
lock_table: mysql/innodb_table_stats, mode: 1, thread: 0x7f123400ebc8
lock_rec_lock: impl (0) mode 3 index PRIMARY rec of mysql/innodb_table_stats, thread: 0x7f123400ebc8
lock_rec_lock: impl (0) mode 3 index PRIMARY rec of mysql/innodb_table_stats, thread: 0x7f123400ebc8
lock_table: mysql/innodb_table_stats, mode: 1, thread: 0x7f123400ebc8
lock_rec_lock: impl (0) mode 1026 index PRIMARY rec of mysql/innodb_table_stats, thread: 0x7f123400ebc8
lock_table: mysql/innodb_index_stats, mode: 1, thread: 0x7f123400f370
lock_rec_lock: impl (0) mode 3 index PRIMARY rec of mysql/innodb_index_stats, thread: 0x7f123400f370
lock_rec_lock: impl (0) mode 3 index PRIMARY rec of mysql/innodb_index_stats, thread: 0x7f123400f370
lock_table: mysql/innodb_index_stats, mode: 1, thread: 0x7f123400f370
lock_rec_lock: impl (0) mode 1026 index PRIMARY rec of mysql/innodb_index_stats, thread: 0x7f123400f370
lock_table: mysql/innodb_index_stats, mode: 1, thread: 0x7f123400f370
lock_rec_lock: impl (0) mode 3 index PRIMARY rec of mysql/innodb_index_stats, thread: 0x7f123400f370
lock_rec_lock: impl (0) mode 3 index PRIMARY rec of mysql/innodb_index_stats, thread: 0x7f123400f370
lock_table: mysql/innodb_index_stats, mode: 1, thread: 0x7f123400f370
lock_rec_lock: impl (0) mode 1026 index PRIMARY rec of mysql/innodb_index_stats, thread: 0x7f123400f370
lock_table: mysql/innodb_index_stats, mode: 1, thread: 0x7f123400f370
lock_rec_lock: impl (0) mode 3 index PRIMARY rec of mysql/innodb_index_stats, thread: 0x7f123400f370
lock_rec_lock: impl (0) mode 3 index PRIMARY rec of mysql/innodb_index_stats, thread: 0x7f123400f370
lock_table: mysql/innodb_index_stats, mode: 1, thread: 0x7f123400f370
lock_rec_lock: impl (0) mode 1026 index PRIMARY rec of mysql/innodb_index_stats, thread: 0x7f123400f370
^C
while this SQL is executed, for example:
MariaDB [test]> insert into t(val) select 100 from tt;
Query OK, 4 rows affected (0.080 sec)
Records: 4 Duplicates: 0 Warnings: 0
Please, check that older post from proper interpretation of the output, including contants used to represent lock mode etc. The idea here was to show that bpftrace understands a subset of C/C++ struct statement and show the ways to create such simplified strucutres to be able to dereference and access deeply nexted arguments if needed for tracing.
 |
| A bit more advanced code may show more details about the individual rows locked... |
* * *
To summarize:
- With some efforts like source code checks and gdb breakpoints/prints one can eventually figure out what structures to define to be able to access members of complex structures typical for MariaDB and MySQL server code in the bpftrace code.
- Inlcuding existing headers is NOT possible and is hardly practical for complex software like MariaDB that uses C++ nowadays.
- bpftrace, with some efforts like those presented above, allows to study what happens in complex server operations (like InnoDB locking) easily, safely and with minimal impact on a running system.
- bpftrace is cool, but you already know that!
No comments:
Post a Comment