How to Add Probe Inside a Function and Access Local Variables with bpftrace

During several my talks on bpftrace I mentioned that it is possible to add probe to "every other" line of the code, same as with perf, but had never demonstrated how to do this. Looks like it's time to show both this and access to local variables declared inside the function we trace, as I am going to speak about bpftrace again at FOSDEM (and have to share something new and cool).

Consider the following debugging session with latest MariaDB server 10.8 built from GitHub source (as usual, for my own work I use only my own builds from current source) on Ubuntu 20.04:

openxs@ao756:~/dbs/maria10.8$ sudo gdb -p `pidof mariadbd`
GNU gdb (Ubuntu 9.2-0ubuntu1~20.04.1) 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 200650
[New LWP 200652]
[New LWP 200653]
[New LWP 200654]
[New LWP 200655]
[New LWP 200656]
[New LWP 200659]
[New LWP 200662]
[New LWP 200663]
[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--
0x00007f7b8424caff in __GI___poll (fds=0x557960733d38, 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 do_command
Breakpoint 1 at 0x55795e867570: file /home/openxs/git/server/sql/sql_parse.cc, line 1197.
(gdb) c
Continuing.

Basically I've attached to running mariadbd process and set a breakpoint on do_command(), and then let it continue working. In another terminal I've connected to server and got the breakpoint hit immediately:

[New Thread 0x7f7b5dbf0700 (LWP 200680)]
[New Thread 0x7f7b6c084700 (LWP 200797)]
[Switching to Thread 0x7f7b6c084700 (LWP 200797)]

Thread 11 "mariadbd" hit Breakpoint 1, do_command (thd=0x7f7b4c001738,
    blocking=blocking@entry=true)
    at /home/openxs/git/server/sql/sql_parse.cc:1197
1197    {
(gdb) bt
#0  do_command (thd=0x7f7b4c001738, blocking=blocking@entry=true)
    at /home/openxs/git/server/sql/sql_parse.cc:1197
#1  0x000055795e97df07 in do_handle_one_connection (connect=<optimized out>,
    put_in_cache=true) at /home/openxs/git/server/sql/sql_connect.cc:1418
#2  0x000055795e97e23d in handle_one_connection (arg=arg@entry=0x55796079f798)
    at /home/openxs/git/server/sql/sql_connect.cc:1312
#3  0x000055795ecc7e8d in pfs_spawn_thread (arg=0x557960733dd8)
    at /home/openxs/git/server/storage/perfschema/pfs.cc:2201
#4  0x00007f7b84686609 in start_thread (arg=<optimized out>)
    at pthread_create.c:477
#5  0x00007f7b84259293 in clone ()
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

From this state in gdb we can trace execution step by step:

(gdb) n
[New Thread 0x7f7b5ebf2700 (LWP 200800)]
1213      if (thd->async_state.m_state == thd_async_state::enum_async_state::RESUMED)
(gdb) n
1229      thd->lex->current_select= 0;
(gdb) n
1237      if (!thd->skip_wait_timeout)
(gdb) n
1238        my_net_set_read_timeout(net, thd->get_net_wait_timeout());
(gdb) n
1241      thd->clear_error(1);
(gdb) n
1243      net_new_transaction(net);
(gdb) n
1246      thd->start_bytes_received= thd->status_var.bytes_received;
(gdb) n
1264      packet_length= my_net_read_packet(net, 1);
(gdb) n
1266      if (unlikely(packet_length == packet_error))
(gdb) n
1300      packet= (char*) net->read_pos;
(gdb) n
1309      if (packet_length == 0)                       /* safety */
(gdb) n
1316      packet[packet_length]= '\0';                  /* safety */
(gdb) n
1319      command= fetch_command(thd, packet);
(gdb) p packet
$1 = 0x7f7b4c008d08 "\003select @@version_comment limit 1"
(gdb) q
A debugging session is active.

        Inferior 1 [process 200650] will be detached.

Quit anyway? (y or n) y
Detaching from program: /home/openxs/dbs/maria10.8/bin/mariadbd, process 200650
[Inferior 1 (process 200650) detached]

In that session above I moved to the next step until I've got to the place in the code where local variable packet got a value, zero-terminated string. I know from the previous experience that it's value is the SQL statement to be executed (in most cases). So, I printed it to find out that mysql command line client starts with finding the server version comment to output.

Question is: can we do the same with bpftrace, attache the probe to the instruction at/around line 1316 of the sql/sql_parse.cc and print the value of the local variable named packet as a string? 

It should be possible, as we can do this with perf or even raw ftrace probes. This is how we can find all "tracable" lines in the code of do_command() function with perf:

openxs@ao756:~/dbs/maria10.8$ sudo perf probe -x /home/openxs/dbs/maria10.8/bin/mysqld --line do_command
<do_command@/home/openxs/git/server/sql/sql_parse.cc:0>
      0  dispatch_command_return do_command(THD *thd, bool blocking)
         {
      2    dispatch_command_return return_value;
           char *packet= 0;
           ulong packet_length;
           NET *net= &thd->net;
           enum enum_server_command command;
           DBUG_ENTER("do_command");

         #ifdef WITH_WSREP
           DBUG_ASSERT(!thd->async_state.pending_ops() ||
                       (WSREP(thd) &&
                        thd->wsrep_trx().state() == wsrep::transaction::s_abort>
         #else
           DBUG_ASSERT(!thd->async_state.pending_ops());
         #endif

           if (thd->async_state.m_state == thd_async_state::enum_async_state::R>
           {
             /*
              Resuming previously suspended command.
              Restore the state
             */
     23      command = thd->async_state.m_command;
     24      packet = thd->async_state.m_packet.str;
             packet_length = (ulong)thd->async_state.m_packet.length;
             goto resume;
           }

...
    104    packet= (char*) net->read_pos;
           /*
             'packet_length' contains length of data, as it was stored in packet
             header. In case of malformed header, my_net_read returns zero.
             If packet_length is not zero, my_net_read ensures that the returned
             number of bytes was actually read from network.
             There is also an extra safety measure in my_net_read:
             it sets packet[packet_length]= 0, but only for non-zero packets.
           */
    113    if (packet_length == 0)                       /* safety */
           {
             /* Initialize with COM_SLEEP packet */
    116      packet[0]= (uchar) COM_SLEEP;
    117      packet_length= 1;
           }
           /* Do not rely on my_net_read, extra safety against programming erro>
    120    packet[packet_length]= '\0';                  /* safety */


    123    command= fetch_command(thd, packet);
...
    221    DBUG_ASSERT(thd->m_digest == NULL);
           DBUG_ASSERT(thd->m_statement_psi == NULL);
         #ifdef WITH_WSREP
           if (packet_length != packet_error)
           {
             /* there was a command to process, and before_command() has been c>
             if (unlikely(wsrep_service_started))
    228        wsrep_after_command_after_result(thd);
           }
         #endif /* WITH_WSREP */
           DBUG_RETURN(return_value);

openxs@ao756:~/dbs/maria10.8$

So, basically we need a probe on line 120 to match the place where I printed the value in gdb. Let's create it with perf:

openxs@ao756:~/dbs/maria10.8$ sudo perf probe -x /home/openxs/dbs/maria10.8/bin/mariadbd 'do_command:120 packet:string'
Added new event:
  probe_mariadbd:do_command_L120 (on do_command:120 in /home/openxs/dbs/maria10.8/bin/mariadbd with packet:string)

You can now use it in all perf tools, such as:

        perf record -e probe_mariadbd:do_command_L120 -aR sleep 1

Now, we can check what user probe was really created by that command line:

openxs@ao756:~/dbs/maria10.8$ sudo cat /sys/kernel/tracing/uprobe_events
p:probe_mariadbd/do_command_L120 /home/openxs/dbs/maria10.8/bin/mariadbd:0x00000000007b761f packet_string=+0(%r10):string

So, the probe is attached to some address, 0x7b761f, in the mariadb binary. Looks like we refer to the register, r10, while trying to access local variable, packet.

Now let's delete this probe (we'll add it back with bpftrace soon) and try to make sense of that address:

openxs@ao756:~/dbs/maria10.8$ sudo perf probe --del 'probe_mariadbd:do_command*'
Removed event: probe_mariadbd:do_command_L120
openxs@ao756:~/dbs/maria10.8$ objdump -tT /home/openxs/dbs/maria10.8/bin/mariadbd | grep do_command
00000000007b7570 g     F .text  00000000000007e9              _Z10do_commandP3THDb
00000000007b7570 g    DF .text  00000000000007e9  Base        _Z10do_commandP3THDb

Note that based on the above the entry address of the do_command() function in the binary is 0x7b7570, a bit smaller than 0x7b761f. The difference is 0x7b761f - 0x7b7570 = 0xaf or 175 in decimal. 

Can we come up to the address for the probe  without perf? Yes, we can do it by checking the assembly code of the function, for example, in gdb:

openxs@ao756:~/dbs/maria10.8$ ps aux | grep 'mariadbd ' | grep -v grep
openxs    200650  0.0  2.4 1341032 94976 ?       Sl   січ30   0:05 /home/openxs/dbs/maria10.8/bin/mariadbd --no-defaults --basedir=/home/openxs/dbs/maria10.8 --datadir=/home/openxs/dbs/maria10.8/data --plugin-dir=/home/openxs/dbs/maria10.8/lib/plugin --log-error=/home/openxs/dbs/maria10.8/data/ao756.err --pid-file=ao756.pid --socket=/tmp/mariadb.sock --port=3309
openxs@ao756:~/dbs/maria10.8$ sudo gdb -p `pidof mariadbd`
GNU gdb (Ubuntu 9.2-0ubuntu1~20.04.1) 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 200650
[New LWP 200652]
[New LWP 200653]
[New LWP 200654]
[New LWP 200655]
[New LWP 200662]
[New LWP 200663]
[New LWP 204349]
[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--
0x00007f7b8424caff in __GI___poll (fds=0x557960733d38, 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) disass /m do_command
Dump of assembler code for function do_command(THD*, bool):
1142    static bool wsrep_command_no_result(char command)

1143    {
1144      return (command == COM_STMT_PREPARE          ||
   0x000055795e8679d0 <+1120>:  cmp    $0x16,%al
   0x000055795e8679d2 <+1122>:  je     0x55795e8679dc <do_command(THD*, bool)+1132>
   0x000055795e8679d4 <+1124>:  cmp    $0x1c,%al
   0x000055795e8679d6 <+1126>:  jne    0x55795e867b50 <do_command(THD*, bool)+1504>
   0x000055795e8679dc <+1132>:  mov    $0x1,%esi

1145              command == COM_STMT_FETCH            ||
1146              command == COM_STMT_SEND_LONG_DATA   ||
1147              command == COM_STMT_CLOSE);
1148    }
1149    #endif /* WITH_WSREP */
1150    #ifndef EMBEDDED_LIBRARY
1151    static enum enum_server_command fetch_command(THD *thd, char *packet)

1152    {
1153      enum enum_server_command
--Type <RET> for more, q to quit, c to continue without paging--
   0x000055795e867628 <+184>:   movzbl %al,%r15d

1154        command= (enum enum_server_command) (uchar) packet[0];
1155      DBUG_ENTER("fetch_command");

1156
1157      if (command >= COM_END ||
   0x000055795e86762c <+188>:   lea    -0x20(%r15),%edx
   0x000055795e867630 <+192>:   cmp    $0xd9,%edx
   0x000055795e867636 <+198>:   jbe    0x55795e8676f0 <do_command(THD*, bool)+384>
   0x000055795e86763c <+204>:   cmp    $0xff,%al
   0x000055795e86763e <+206>:   je     0x55795e8676f0 <do_command(THD*, bool)+384>

1158          (command >= COM_MDB_GAP_BEG && command <= COM_MDB_GAP_END))
1159        command= COM_END;                           // Wrong command

1160
1161      DBUG_PRINT("info",("Command on %s = %d (%s)",

1162                         vio_description(thd->net.vio), command,
1163                         command_name[command].str));
--Type <RET> for more, q to quit, c to continue without paging--
1164      DBUG_RETURN(command);

1165    }
1166
1167    /**
1168      Read one command from connection and execute it (query or simple command).
1169      This function is to be used by different schedulers (one-thread-per-connection,
1170      pool-of-threads)
1171
1172      For profiling to work, it must never be called recursively.
1173
1174      @param thd - client connection context
1175
1176      @param blocking - wait for command to finish.
1177                        if false (nonblocking), then the function might
1178                        return when command is "half-finished", with
1179                        DISPATCH_COMMAND_WOULDBLOCK.
1180                        Currenly, this can *only* happen when using
1181                        threadpool. The command will resume, after all outstanding
1182                        async operations (i.e group commit) finish.
--Type <RET> for more, q to quit, c to continue without paging--
1183                        Threadpool scheduler takes care of "resume".
1184
1185      @retval
1186        DISPATCH_COMMAND_SUCCESS - success
1187      @retval
1188        DISPATCH_COMMAND_CLOSE_CONNECTION  request of THD shutdown
1189              (s. dispatch_command() description)
1190      @retval
1191        DISPATCH_COMMAND_WOULDBLOCK - need to wait for asyncronous operations
1192                                      to finish. Only returned if parameter
1193                                      'blocking' is false.
1194    */
1195
1196    dispatch_command_return do_command(THD *thd, bool blocking)
1197    {
   0x000055795e867570 <+0>:     endbr64

1198      dispatch_command_return return_value;

1199      char *packet= 0;

1200      ulong packet_length;
--Type <RET> for more, q to quit, c to continue without paging--

1201      NET *net= &thd->net;

1202      enum enum_server_command command;

1203      DBUG_ENTER("do_command");

1204
1205    #ifdef WITH_WSREP
1206      DBUG_ASSERT(!thd->async_state.pending_ops() ||

1207                  (WSREP(thd) &&
1208                   thd->wsrep_trx().state() == wsrep::transaction::s_aborted));
1209    #else
1210      DBUG_ASSERT(!thd->async_state.pending_ops());
1211    #endif
1212
1213      if (thd->async_state.m_state == thd_async_state::enum_async_state::RESUMED)
   0x000055795e867574 <+4>:     push   %rbp
   0x000055795e867575 <+5>:     mov    %rsp,%rbp
   0x000055795e867578 <+8>:     push   %r15
--Type <RET> for more, q to quit, c to continue without paging--
   0x000055795e86757a <+10>:    push   %r14
   0x000055795e86757c <+12>:    push   %r13
   0x000055795e86757e <+14>:    mov    %esi,%r13d
   0x000055795e867581 <+17>:    push   %r12
   0x000055795e867583 <+19>:    push   %rbx
   0x000055795e867584 <+20>:    mov    %rdi,%rbx
   0x000055795e867587 <+23>:    sub    $0x78,%rsp
   0x000055795e86758b <+27>:    cmpl   $0x2,0x6270(%rdi)
   0x000055795e867592 <+34>:    je     0x55795e867770 <do_command(THD*, bool)+512>
   0x000055795e867598 <+40>:    mov    0x58(%rdi),%rax
   0x000055795e86759c <+44>:    cmpb   $0x0,0x279e(%rdi)
   0x000055795e8675a3 <+51>:    lea    0x290(%rdi),%r14

1214      {
1215        /*
1216         Resuming previously suspended command.
1217         Restore the state
1218        */
1219        command = thd->async_state.m_command;
   0x000055795e867770 <+512>:   mov    0x6278(%rdi),%r10
   0x000055795e867777 <+519>:   mov    0x6280(%rdi),%r12
   0x000055795e86777e <+526>:   movzbl %sil,%r8d
--Type <RET> for more, q to quit, c to continue without paging--
   0x000055795e867782 <+530>:   mov    %rdi,%rsi
   0x000055795e867785 <+533>:   mov    0x6274(%rdi),%r15d

1220        packet = thd->async_state.m_packet.str;

1221        packet_length = (ulong)thd->async_state.m_packet.length;

1222        goto resume;

1223      }
1224
1225      /*
1226        indicator of uninitialized lex => normal flow of errors handling
1227        (see my_message_sql)
1228      */
1229      thd->lex->current_select= 0;
   0x000055795e8675aa <+58>:    movq   $0x0,0xd38(%rax)

1230
1231      /*
1232        This thread will do a blocking read from the client which
1233        will be interrupted when the next command is received from
1234        the client, the connection is closed or "net_wait_timeout"
--Type <RET> for more, q to quit, c to continue without paging--
1235        number of seconds has passed.
1236      */
1237      if (!thd->skip_wait_timeout)
   0x000055795e8675b5 <+69>:    je     0x55795e867710 <do_command(THD*, bool)+416>

1238        my_net_set_read_timeout(net, thd->get_net_wait_timeout());
1239
1240      /* Errors and diagnostics are cleared once here before query */
1241      thd->clear_error(1);
1242
1243      net_new_transaction(net);
   0x000055795e8675dd <+109>:   mov    0x13f0(%rbx),%rax
   0x000055795e8675e4 <+116>:   mov    $0x1,%esi
   0x000055795e8675e9 <+121>:   mov    %r14,%rdi
   0x000055795e8675ec <+124>:   movl   $0x0,0x2f0(%rbx)

1244
1245      /* Save for user statistics */
1246      thd->start_bytes_received= thd->status_var.bytes_received;
   0x000055795e8675f6 <+134>:   mov    %rax,0x4040(%rbx)

1247
--Type <RET> for more, q to quit, c to continue without paging--
1248      /*
1249        Synchronization point for testing of KILL_CONNECTION.
1250        This sync point can wait here, to simulate slow code execution
1251        between the last test of thd->killed and blocking in read().
1252
1253        The goal of this test is to verify that a connection does not
1254        hang, if it is killed at this point of execution.
1255        (Bug#37780 - main.kill fails randomly)
1256
1257        Note that the sync point wait itself will be terminated by a
1258        kill. In this case it consumes a condition broadcast, but does
1259        not change anything else. The consumed broadcast should not
1260        matter here, because the read/recv() below doesn't use it.
1261      */
1262      DEBUG_SYNC(thd, "before_do_command_net_read");

1263
1264      packet_length= my_net_read_packet(net, 1);
   0x000055795e8675fd <+141>:   callq  0x55795ebda8a0 <my_net_read_packet(NET*, my_bool)>
   0x000055795e867602 <+146>:   mov    %rax,%r12

1265
--Type <RET> for more, q to quit, c to continue without paging--
1266      if (unlikely(packet_length == packet_error))
   0x000055795e867605 <+149>:   cmp    $0xffffffffffffffff,%rax
   0x000055795e867609 <+153>:   je     0x55795e8678d0 <do_command(THD*, bool)+864>

1267      {
1268        DBUG_PRINT("info",("Got error %d reading command from socket %s",

1269                           net->error,
1270                           vio_description(net->vio)));
1271
1272        /* Instrument this broken statement as "statement/com/error" */
1273        thd->m_statement_psi= MYSQL_REFINE_STATEMENT(thd->m_statement_psi,
   0x000055795e8678d0 <+864>:   mov    0x3b78(%rbx),%rdi

1274                                                     com_statement_info[COM_END].
1275                                                     m_key);
1276
1277
1278        /* Check if we can continue without closing the connection */
1279
1280        /* The error must be set. */
--Type <RET> for more, q to quit, c to continue without paging--
1281        DBUG_ASSERT(thd->is_error());

1282        thd->protocol->end_statement();
   0x000055795e8678ee <+894>:   mov    0x558(%rbx),%rdi
   0x000055795e8678f5 <+901>:   callq  0x55795e79f7e0 <Protocol::end_statement()>

1283
1284        /* Mark the statement completed. */
1285        MYSQL_END_STATEMENT(thd->m_statement_psi, thd->get_stmt_da());
1286        thd->m_statement_psi= NULL;
   0x000055795e86791b <+939>:   cmpb   $0x3,0x324(%rbx)
   0x000055795e867922 <+946>:   mov    $0x1,%r13d
   0x000055795e867928 <+952>:   movq   $0x0,0x3b78(%rbx)

1287        thd->m_digest= NULL;
   0x000055795e867933 <+963>:   movq   $0x0,0x3b30(%rbx)

1288
1289        if (net->error != 3)
   0x000055795e86793e <+974>:   jne    0x55795e86794a <do_command(THD*, bool)+986>

--Type <RET> for more, q to quit, c to continue without paging--
1290        {
1291          return_value= DISPATCH_COMMAND_CLOSE_CONNECTION;     // We have to close it.
1292          goto out;
1293        }
1294
1295        net->error= 0;
   0x000055795e867940 <+976>:   movb   $0x0,0x324(%rbx)

1296        return_value= DISPATCH_COMMAND_SUCCESS;

1297        goto out;
   0x000055795e867947 <+983>:   xor    %r13d,%r13d

1298      }
1299
1300      packet= (char*) net->read_pos;
   0x000055795e86760f <+159>:   mov    0x2b0(%rbx),%r10

1301      /*
1302        'packet_length' contains length of data, as it was stored in packet
1303        header. In case of malformed header, my_net_read returns zero.
1304        If packet_length is not zero, my_net_read ensures that the returned
--Type <RET> for more, q to quit, c to continue without paging--
1305        number of bytes was actually read from network.
1306        There is also an extra safety measure in my_net_read:
1307        it sets packet[packet_length]= 0, but only for non-zero packets.
1308      */
1309      if (packet_length == 0)                       /* safety */
   0x000055795e867616 <+166>:   test   %rax,%rax
   0x000055795e867619 <+169>:   je     0x55795e8676e0 <do_command(THD*, bool)+368>

1310      {
1311        /* Initialize with COM_SLEEP packet */
1312        packet[0]= (uchar) COM_SLEEP;
   0x000055795e8676e0 <+368>:   movb   $0x0,(%r10)

1313        packet_length= 1;
   0x000055795e8676e4 <+372>:   mov    $0x1,%r12d
   0x000055795e8676ea <+378>:   jmpq   0x55795e86761f <do_command(THD*, bool)+175>
   0x000055795e8676ef <+383>:   nop

1314      }
1315      /* Do not rely on my_net_read, extra safety against programming errors. */
--Type <RET> for more, q to quit, c to continue without paging--
1316      packet[packet_length]= '\0';                  /* safety */
   0x000055795e86761f <+175>:   movb   $0x0,(%r10,%r12,1)

1317
1318
1319      command= fetch_command(thd, packet);
   0x000055795e867624 <+180>:   movzbl (%r10),%eax

1320
1321    #ifdef WITH_WSREP
1322      DEBUG_SYNC(thd, "wsrep_before_before_command");

1323      /*
1324        If this command does not return a result, then we
1325        instruct wsrep_before_command() to skip result handling.
1326        This causes BF aborted transaction to roll back but keep
1327        the error state until next command which is able to return
1328        a result to the client.
1329      */
1330      if (unlikely(wsrep_service_started) &&
   0x000055795e867644 <+212>:   lea    0x1862105(%rip),%rcx        # 0x5579600c9750 <wsrep_service_started>
   0x000055795e86764b <+219>:   cmpb   $0x0,(%rcx)
--Type <RET> for more, q to quit, c to continue without paging--q
Quit
(gdb) quit
A debugging session is active.

        Inferior 1 [process 200650] will be detached.

Quit anyway? (y or n) y
Detaching from program: /home/openxs/dbs/maria10.8/bin/mariadbd, process 200650
[Inferior 1 (process 200650) detached]

At this stage we can stop debugging and quit from gdb. We see that line 1316 in the code (were packet is properly formed and ready for printing) matches (decimal) offset 175 from the beginning of the function. Now we can add that to the start of the function from objdump to find the address for the probe, 0x7b761f.

The only remaining detail is how to print the content of the register r10 as a zero terminated string. Just read fine bpftrace manual for this, and you can come up with the following:

openxs@ao756:~/dbs/maria10.8$ cd ~/git/bpftrace/
openxs@ao756:~/git/bpftrace$ cd build/
openxs@ao756:~/git/bpftrace/build$ sudo src/bpftrace -e 'uprobe:/home/openxs/dbs/maria10.8/bin/mariadbd:0x00000000007b761f { printf("Function: %s packet: %s\n", func, str(reg("r10"))); }'
[sudo] password for openxs:
Attaching 1 probe...
Function: do_command(THD*, bool) packet: select @@version_comment limit 1
Function: do_command(THD*, bool) packet: select 1 + 1
^C

This is what I've got from the probe while in another terminal I've connected and executed the following:

openxs@ao756:~/dbs/maria10.8$ bin/mysql
ERROR 2002 (HY000): Can't connect to local server through socket '/tmp/mysql.sock' (2)
openxs@ao756:~/dbs/maria10.8$ bin/mysql --socket=/tmp/mariadb.sock
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 4
Server version: 10.8.1-MariaDB Source distribution

Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]> select 1 + 1;
+-------+
| 1 + 1 |
+-------+
|     2 |
+-------+
1 row in set (0.000 sec)

So, as long as you know the address of instruction inside the function code, you can attach a probe to it. You can safely experiment, as if the address is surely wrong:

openxs@ao756:~/git/bpftrace/build$ sudo src/bpftrace -e 'uprobe:/home/openxs/dbs/maria10.8/bin/mariadbd:0x00000000007b761e { printf("Function: %s packet: %s\n", func, str(reg("r10"))); }'
Attaching 1 probe...
ERROR: Could not add uprobe into middle of instruction: /home/openxs/dbs/maria10.8/bin/mariadbd:_Z10do_commandP3THDb+174
openxs@ao756:~/git/bpftrace/build$ sudo src/bpftrace -e 'uprobe:/home/openxs/dbs/maria10.8/bin/mariadbd:0x00000000008b761f { printf("Function: %s packet: %s\n", func, str(reg("r10"))); }'
Attaching 1 probe...
ERROR: Could not add uprobe into middle of instruction: /home/openxs/dbs/maria10.8/bin/mariadbd:_ZN14partition_info25set_up_default_partitionsEP3THDP7handlerP14HA_CREATE_INFOj+799

the tool will tell you and do no harm.

Nice conbination of old Tower and new buildings in the City of London. Combining bpftrace with good old gdb is also nice.

To summarize:

1.  It is possible to add a user probe to every assembly insturction inside the function with bpftrace (or perf, or ftrace, as long as you know what you are doing).
2. It is possible to access CPU registers in the bpftrace probes.
3. One can surely access, print etc local varaibles inside functions, as long as the address or register where it is stored is determined.
4. It is surely easier and faster to do all the above with some knowledge of gdb and assembly language for your CPU.
5. It is still fun to try to solve more complex problems with bpftrace, so more posts are expected. Stay tuned!
   

DTrace Basics and Tracing Every MariaDB Server Function Call

In my previous post I've explained how to build MariaDB Server 10.8 from GitHub source on macOS. This kind of (totally unsupported by both MariaDB Corporation and Foundation) build may be used to study new interesting testing, troubleshooting and performance problem solving options that DTrace provides.

To start adding custom probes and doing something non-trivial one has to understand (or, better, master) some basics of the language used. Code in the sample support-files/dtrace/query-time.d program looked clear and familiar enough (at least for those who've seen bpftrace probes). It consists of several probes like this:

mysql*:::query-start
{
   self->query = copyinstr(arg0);
   self->connid = arg1;
   self->db    = copyinstr(arg2);
   self->who   = strjoin(copyinstr(arg3),strjoin("@",copyinstr(arg4)));
   self->querystart = timestamp;
}

As we can read in the manual, the format for the probe specification is provider:module:function:name. An empty component in a probe specification matches anything. You can also describe probes with a pattern matching syntax that is similar to the syntax that is used by shell. 

In the case above  (USDT) provider name should start with mysql, we do not care about module and function (actually we maybe have USDT with the name in different functions), and we refer to the probe by name. 

If you are wondering to see other kinds of specific probes, you can check dtrace -l output:

Yuliyas-Air:~ Valerii$ sudo dtrace -l | head -20
dtrace: system integrity protection is on, some features will not be available

   ID   PROVIDER            MODULE                          FUNCTION NAME
    1     dtrace                                                     BEGIN
    2     dtrace                                                     END
    3     dtrace                                                     ERROR
...
   42    profile                                                     tick-1000
   43    profile                                                     tick-5000
   44  mach_trap                                        kern_invalid entry
   45  mach_trap                                        kern_invalid return
   46  mach_trap                    _kernelrpc_mach_vm_allocate_trap entry
Yuliyas-Air:~ Valerii$ sudo dtrace -l | tail -4
dtrace: system integrity protection is on, some features will not be available

254755   pid82428          mariadbd            do_command(THD*, bool) 5e4
254917   pid82428 libsystem_malloc.dylib                            malloc return
467101 security_exception639          csparser _ZN8Security7CFErrorC2Ev [Security::CFError::CFError()] throw-cf
467102 security_exception639          csparser _ZN8Security9UnixErrorC2Eib [Security::UnixError::UnixError(int, bool)] throw-unix

We should study different providers that DTrace supports:

• dtrace - few special probes: BEGIN, END and ERROR.
  
• profile - this provider includes probes that are associated with an interrupt that fires at some regular, specified time interval .profile-N probes basically fire N times per second on every CPU. tick-N probes fire on only one CPU per interval.
  
• syscall - enables you to trace every system call entry and return.
• pid* - enables tracing of any user process, as specified by its pid. It basically allows to trace entries (with entry probe name) and returns (with return probe name) to every user function, among other things.
  
• ...
  

There are more providers actually, but those mentioned above allow to start reading and writing DTrace scripts for MariaDB server tracing and profiling, so let's stop listing them for now.

As we can see from this output 

Yuliyas-Air:~ Valerii$ dtrace
Usage: dtrace [-aACeFHlqSvVwZ] [-arch i386|x86_64] [-b bufsz] [-c cmd] [-D name[=def]]
        [-I path] [-L path] [-o output] [-p pid] [-s script] [-U name]
        [-x opt[=val]]

        [-P provider [[ predicate ] action ]]
        [-m [ provider: ] module [[ predicate ] action ]]
        [-f [[ provider: ] module: ] func [[ predicate ] action ]]
        [-n [[[ provider: ] module: ] func: ] name [[ predicate ] action ]]
        [-i probe-id [[ predicate ] action ]] [ args ... ]

        predicate -> '/' D-expression '/'
           action -> '{' D-statements '}'
...

for each probe we can define optional predicate (in slashes), expression that must evaluate to true (non-zero integer value) when probe fires for optional action (in curly brackets) to be executed. Action is a sequence of DTrace statements separated by semicolons. Note that DTrace does NOT support loops or complex conditional execution in the actions, for good reasons discussed elsewhere. We may also have optional arguments for the probe.

In our query-start probe above there is no predicate, so the action is executed unconditionally when we hit it. We use some built-in functions (like copyinsrt()) and variables, like arg0, arg1 and timestamp. We'll discuss them in details in some other post, but arg0 ... arg9 obviously refer to the first ten arguments of the probe and timestamp is the current value of a nanosecond timestamp counter.

In the action we see several assignments to self->something. These are thread-local variables that share a common name in your D code but refer to separate data storage associated with each operating system thread.

Now we can try to add some probes. Given this information:

Yuliyas-Air:~ Valerii$ ps aux | grep mariadbd
Valerii          37341   0.0  0.0  4267752    700 s003  S+   10:47AM   0:00.01 grep mariadbd
Valerii          82428   0.0  0.1  4834244   5960   ??  S    Wed09PM 116:47.57 /Users/Valerii/dbs/maria10.8/bin/mariadbd --no-defaults --basedir=/Users/Valerii/dbs/maria10.8 --datadir=/Users/Valerii/dbs/maria10.8/data --plugin-dir=/Users/Valerii/dbs/maria10.8/lib/plugin --log-error=/Users/Valerii/dbs/maria10.8/data/Yuliyas-Air.err --pid-file=Yuliyas-Air.pid

and knowing that function name portion of the current probe's description is avaiable ad probefunc built-in variable, we can try to trace the enter into the every tracable function in this MariaDB server process:

Yuliyas-Air:~ Valerii$ sudo dtrace -n 'pid82428:::entry { printf ("\nEnter %s", probefunc); }' | more
dtrace: system integrity protection is on, some features will not be available

dtrace: description 'pid82428:::entry ' matched 240404 probes
CPU     ID                    FUNCTION:NAME
  1 128445            cerror_nocancel:entry
Enter cerror_nocancel
  1 129499        _pthread_testcancel:entry
Enter _pthread_testcancel
  1 128444                    __error:entry
Enter __error
  1 129505    _pthread_cond_updateval:entry
Enter _pthread_cond_updateval
  1 129429         pthread_mutex_lock:entry
Enter pthread_mutex_lock
  1  36852                  my_hrtime:entry
Enter my_hrtime
  1 122312              clock_gettime:entry
Enter clock_gettime
  1 122657               gettimeofday:entry
Enter gettimeofday
  1 128412    __commpage_gettimeofday:entry
Enter __commpage_gettimeofday
  1 128413 __commpage_gettimeofday_internal:entry
Enter __commpage_gettimeofday_internal
  1 128343         mach_absolute_time:entry
Enter mach_absolute_time
:

I've used faimiliar C-style printf() function to print some custom string including the name of the function when we hit the probe. Note that dtrace attached probes to 240404 different functions without any problem, in default configuration. We immediately started to gte the output that shows function calls happening in background threads all the time. I've used more to be able to copy-paste small portion of the output and then stopped tracing with Ctrl+C after quiting from more.

Note that by default for each hit of the probe we get probe identifier, CPU that it fired on, function and probe name reported. Add -q option to suppress this and see only what we explicitly print in the probe:

Yuliyas-Air:~ Valerii$ sudo dtrace -q -n 'pid82428:::entry { printf ("\nEnter %s", probefunc); }' | more
dtrace: system integrity protection is on, some features will not be available


Enter cerror_nocancel
Enter _pthread_testcancel
Enter __error
Enter _pthread_cond_updateval
Enter pthread_mutex_lock
Enter my_hrtime
Enter clock_gettime
Enter gettimeofday
Enter __commpage_gettimeofday
Enter __commpage_gettimeofday_internal
...

If we want to trace all processes with "mariadbd" as the name of the executable, we can add predicate to the probe that does not specify pid at all:

Yuliyas-Air:~ Valerii$ sudo dtrace -q -n ':::entry / execname == "mariadbd" / { printf ("\nEnter %s", probefunc); }' | more
dtrace: system integrity protection is on, some features will not be available


Enter cerror_nocancel
Enter _pthread_testcancel
Enter __error
Enter _pthread_cond_updateval
Enter pthread_mutex_lock
Enter my_hrtime
Enter clock_gettime
Enter gettimeofday
...

So, we can produce a raw trace (to be stored or processed by some user level code outside of DTrace). But what if we would like to do some more advanced processing in the probe itself and share only the results? For example, we run some MariaDB tests and would like to know how many times specific function in the code was executed (if at all) in the process?

For this we have to use aggregations and rely on aggregate functions to do the job in kernel space. For now it's enough to know that @name[key] is the aggregation name indexed by the key (you can use several keys separated by commas) and count() aggregation function simly counts the number of times it was called. 

Another inportant detail to study to create useful DTrace scripts is scripts arguments substitution. When called with -s option dtrace prowides a set of built-in macro variables to the script, with nsame starting with $. Of them $0 ... $9 have the same meenings as in shell, so $1 is the first argument of the script.

With the above taken into account, we can use the following basic DTrace script to count function executions per name in any user process (quiet option has the same effect as -q):

Yuliyas-Air:~ Valerii$ cat /tmp/codecoverage.d
#!/usr/sbin/dtrace -s
#pragma D option quiet
pid$1::$2:entry {
        @calls[probefunc] = count();
}

This script substitutes the first argument for the process id in the pid provider and the second argument for the function name in the probe, thus we create one or more probes. The aggregation's collected results are printed by default when dtrace script ends, but there is also the printa() function to do this explicitly in the probes if needed. Let's try to apply this to MariaDB server 10.8 running as process 82428 and trace all functions (hence '*' as the explicite second argument):

Yuliyas-Air:~ Valerii$ sudo /tmp/codecoverage.d 82428 '*' >/tmp/res.txt
dtrace: system integrity protection is on, some features will not be available

^C
Yuliyas-Air:~ Valerii$ ls -l /tmp/res.txt
-rw-r--r--  1 Valerii  wheel  58772 Jan 28 20:53 /tmp/res.txt
Yuliyas-Air:~ Valerii$ head -10 /tmp/res.txt


  ACL_USER* find_by_username_or_anon<ACL_USER>(ACL_USER*, unsigned long, char const*, char const*, char const*, char const*, char                1
  ACL_USER::copy(st_mem_root*)                                      1
  Apc_target::init(st_mysql_mutex*)                                 1
  Binary_string::copy(char const*, unsigned long)                   1
  CONNECT::create_thd(THD*)                                         1
  Create_func_arg1::create_func(THD*, st_mysql_const_lex_string*, List<Item>*)                1
  Create_func_sleep::create_1_arg(THD*, Item*)                      1
  Current_schema_tracker::update(THD*, set_var*)                    1
Yuliyas-Air:~ Valerii$ tail -10 /tmp/res.txt
  buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool)            33895
  pthread_self                                                  36422
  mtr_t::memcpy_low(buf_block_t const&, unsigned short, void const*, unsigned long)            44143
  unsigned char* mtr_t::log_write<(unsigned char)48>(page_id_t, buf_page_t const*, unsigned long, bool, unsigned long)            44167
  mach_boottime_usec                                            45007
  mtr_t::modify(buf_block_t const&)                             45609
  pthread_mutex_unlock                                          56530
  pthread_mutex_lock                                            57295
  pthread_cond_broadcast                                        64197
  _platform_memmove$VARIANT$Haswell                             72767
Yuliyas-Air:~ Valerii$ cat /tmp/res.txt | grep do_command
  do_command(THD*, bool)                                            4

I've executed just several statements (4 if you check do_command() executions) over a short enough period of time, but some functions like pthread_mutex_lock were executed thousands of times in the background. Now we have a lame code coverage testing method that works at MariaDB server scale (unlike with bpftrace on Linux). There are performance implications (huge impact when I tried to do the same while running sysbench test with many concurrent threads) and limitations of internal buffer sizes that may cause some probes to be skipped etc, but basically it works!

DTrace is almost as beautiful as Côte d'Azur :)

 To summarize:

1. We checked basic building blocks of simple DTrace one liners and scripts in some details, including probe structure, main providers, some built-in variables, thread-local variables referenced via self-> and aggregations.
   
2. It is possible to add probes to each and every function in MariaDB server 10.8 and do both raw tracing and aggregation in the kernel context. Lame code coverage scripts do work.
3. It is possible to create parametrized, generic scripts with command line arguments and other macros substituted.
   
4. DTrace language is similar to what we see later implemented in bpftrace. After some checks of the manual one can easily switch from one tool to the other for basic tasks.
5. Built-in variablers and functions may be named differently than in bpftrace.
6. There are many more details to cover and interesting scripts to use with MariaDB server, so stay tuned!
   

Accessing Complex Structures in MariaDB Server Code in bpftrace Probes - First Steps

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:

1. 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.
2. Inlcuding existing headers is NOT possible and is hardly practical for complex software like MariaDB that uses C++ nowadays.
3. 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.
4. bpftrace is cool, but you already know that!