BCC Tools for disk I/O Analysis and More

A lot of time passed since I had written about bcc tools in my dynamic tracing series. That post was mostly about building bcc tools from GitHub source on Ubuntu 16.04 and using trace utility to add dynamic probe to MariaDB server. Other that that I had presented tplist and mysql_qslower with a couple of slides at several events, but that's all. There are many more tools useful for DBAs in the bundle, and today I am going to describe several of them mostly related to I/O monitoring. It is yet another blog post in support of my upcoming MariaDB Server Fest 2020 session on dynamic tracing.

I was inspired by another cool resentation, "DB AMA: BCC - Tools for BPF-based Linux IO analysis", made by my dear friend and former colleague in Percona, Marcos Albe:

It has much less likes and views that it honestly deserves.

For this post I picked up only some of bcc tools discussed there. Separate post about using bpftrace for similar analysis is in progress, but I can not complete it today, mostly because bpftrace is not supported on this old Ubuntu I have at hand:

openxs@ao756:~/dbs/maria10.5$ uname -a
Linux ao756 4.4.0-187-generic #217-Ubuntu SMP Tue Jul 21 04:18:15 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

So I can not check and copy/paste the details quickly.

I started with rebuilding bcc tools from current source:

openxs@ao756:~/git/bcc$ git log -1
commit ba73657cb8c4dab83dfb89eed4a8b3866255569a
Author: Hao <1075808668@qq.com>
Date:   Sat Sep 12 02:05:29 2020 +0800

    Netqtop 3037 (#3048)

    The tool netqtop uses tracepoints NET_DEV_START_XMIT and NETIF_RECEIVE_SKB to intercept every transmitted and received packet, as a result, considerable performance descent is expected.
    Details for some performance evaluation can be found at
       https://github.com/iovisor/bcc/pull/3048
openxs@ao756:~/git/bcc$

Nothing fancy there, just many tests are still failing:

openxs@ao756:~/git/bcc/build$ make test
...
68% tests passed, 14 tests failed out of 44

Total Test time (real) = 340.86 sec

The following tests FAILED:
          4 - py_test_stat1_b (Failed)
          5 - py_test_bpf_log (Failed)
          6 - py_test_stat1_c (Failed)
          7 - py_test_xlate1_c (Failed)
          8 - py_test_call1 (Failed)
         11 - py_test_trace3_c (Failed)
         15 - py_test_debuginfo (Failed)
         16 - py_test_brb (Failed)
         17 - py_test_brb2 (Failed)
         18 - py_test_clang (Failed)
         23 - py_test_stackid (Failed)
         30 - py_test_tools_smoke (Failed)
         38 - py_test_lpm_trie (Failed)
         44 - lua_test_standalone (Failed)
Errors while running CTest
Makefile:105: recipe for target 'test' failed
make: *** [test] Error 8

but I still had a hope that most of the tools work (and it's really the case). So I executed sudo make install and ended up with the following:

openxs@ao756:~/git/bcc/build$ ls -F /usr/share/bcc/tools/
argdist*       dirtop*          lib/             pythoncalls*  tclobjnew*
bashreadline*  doc/             llcstat*         pythonflow*   tclstat*
bindsnoop*     drsnoop*         mdflush*         pythongc*     tcpaccept*
biolatency*    execsnoop*       memleak*         pythonstat*   tcpconnect*
biolatpcts*    exitsnoop*       mountsnoop*      reset-trace*  tcpconnlat*
biosnoop*      ext4dist*        mysqld_qslower*  rubycalls*    tcpdrop*
biotop*        ext4slower*      netqtop*         rubyflow*     tcplife*
bitesize*      filelife*        netqtop.c        rubygc*       tcpretrans*
bpflist*       fileslower*      nfsdist*         rubyobjnew*   tcprtt*
btrfsdist*     filetop*         nfsslower*       rubystat*     tcpstates*
btrfsslower*   funccount*       nodegc*          runqlat*      tcpsubnet*
cachestat*     funcinterval*    nodestat*        runqlen*      tcptop*
cachetop*      funclatency*     offcputime*      runqslower*   tcptracer*
capable*       funcslower*      offwaketime*     shmsnoop*     tplist*
cobjnew*       gethostlatency*  old/             slabratetop*  trace*
compactsnoop*  hardirqs*        oomkill*         sofdsnoop*    ttysnoop*
cpudist*       inject*          opensnoop*       softirqs*     vfscount*
cpuunclaimed*  javacalls*       perlcalls*       solisten*     vfsstat*
criticalstat*  javaflow*        perlflow*        sslsniff*     wakeuptime*
dbslower*      javagc*          perlstat*        stackcount*   xfsdist*
dbstat*        javaobjnew*      phpcalls*        statsnoop*    xfsslower*
dcsnoop*       javastat*        phpflow*         syncsnoop*    zfsdist*
dcstat*        javathreads*     phpstat*         syscount*     zfsslower*
deadlock*      killsnoop*       pidpersec*       tclcalls*
deadlock.c     klockstat*       profile*         tclflow*
openxs@ao756:~/git/bcc/build$

The tools I am going to try today are highlighted above. I'll run some sysbench tests like this:

openxs@ao756:~/dbs/maria10.5$ sysbench --table-size=1000000 --threads=4 --time=100 --mysql-socket=/tmp/mariadb105.sock --mysql-user=openxs --mysql-db=sbtest --report-interval=5 /usr/share/sysbench/oltp_update_index.lua run
sysbench 1.1.0-faaff4f (using bundled LuaJIT 2.1.0-beta3)

Running the test with following options:
Number of threads: 4
Report intermediate results every 5 second(s)
Initializing random number generator from current time


Initializing worker threads...

Threads started!

[ 5s ] thds: 4 tps: 113.89 qps: 113.89 (r/w/o: 0.00/113.89/0.00) lat (ms,95%): 101.13 err/s: 0.00 reconn/s: 0.00
[ 10s ] thds: 4 tps: 113.60 qps: 113.60 (r/w/o: 0.00/113.60/0.00) lat (ms,95%): 110.66 err/s: 0.00 reconn/s: 0.00
[ 15s ] thds: 4 tps: 110.20 qps: 110.20 (r/w/o: 0.00/110.20/0.00) lat (ms,95%): 144.97 err/s: 0.00 reconn/s: 0.00
[ 20s ] thds: 4 tps: 112.00 qps: 112.00 (r/w/o: 0.00/112.00/0.00) lat (ms,95%): 153.02 err/s: 0.00 reconn/s: 0.00
...

as a test load against recent MariaDB 10.5.6 also built from source and started with mostly default settings and some Performance Schema instrumentation enabled:

 openxs@ao756:~/dbs/maria10.5$ bin/mysqld_safe --no-defaults --port=3311 --socket=/tmp/mariadb105.sock --performance_schema=1 --performance-schema-instrument='memory/%=ON' &
[1] 19616
openxs@ao756:~/dbs/maria10.5$ 200913 13:16:14 mysqld_safe Logging to '/home/openxs/dbs/maria10.5/data/ao756.err'.
200913 13:16:14 mysqld_safe Starting mariadbd daemon with databases from /home/openxs/dbs/maria10.5/data
...

funccount - count functions, tracepoints and USDT probes hits

This tool is useful when you looking for what actually to trace, as it shows number of hits per tracepoint or probe. As usual, you can just call it with --help option to get a lot of details about options:

openxs@ao756:~$ sudo /usr/share/bcc/tools/funccount --help
usage: funccount [-h] [-p PID] [-i INTERVAL] [-d DURATION] [-T] [-r] [-D]
                 [-c CPU]
                 pattern

Count functions, tracepoints, and USDT probes

positional arguments:
  pattern               search expression for events

optional arguments:
  -h, --help            show this help message and exit
  -p PID, --pid PID     trace this PID only
  -i INTERVAL, --interval INTERVAL
                        summary interval, seconds
  -d DURATION, --duration DURATION
                        total duration of trace, seconds
  -T, --timestamp       include timestamp on output
  -r, --regexp          use regular expressions. Default is "*" wildcards
                        only.
  -D, --debug           print BPF program before starting (for debugging
                        purposes)
  -c CPU, --cpu CPU     trace this CPU only

examples:
    ./funccount 'vfs_*'             # count kernel fns starting with "vfs"
    ./funccount -r '^vfs.*'         # same as above, using regular expressions
    ./funccount -Ti 5 'vfs_*'       # output every 5 seconds, with timestamps
    ./funccount -d 10 'vfs_*'       # trace for 10 seconds only
    ./funccount -p 185 'vfs_*'      # count vfs calls for PID 181 only
    ./funccount t:sched:sched_fork  # count calls to the sched_fork tracepoint
    ./funccount -p 185 u:node:gc*   # count all GC USDT probes in node, PID 185
    ./funccount c:malloc            # count all malloc() calls in libc
    ./funccount go:os.*             # count all "os.*" calls in libgo
    ./funccount -p 185 go:os.*      # count all "os.*" calls in libgo, PID 185
    ./funccount ./test:read*        # count "read*" calls in the ./test binary
    ./funccount -c 1 'vfs_*'        # count vfs calls on CPU 1 only

Based on the above I tried to trace everything for a couple of seconds while sysbench was running, and failed:

openxs@ao756:~$ sudo /usr/share/bcc/tools/funccount -i 1 -d 2 '*'
maximum of 1000 probes allowed, attempted 53271

Too many probes to trace. The following commands work though:

openxs@ao756:~$ sudo /usr/share/bcc/tools/funccount -T -i 1 -d 1 'ext4*'
Tracing 509 functions for "ext4*"... Hit Ctrl-C to end.

13:29:37
FUNC                                    COUNT
...
ext4_sync_file                             14
ext4_finish_bio                            14
ext4_get_block_write                       14
ext4_direct_IO                             14
...
ext4_statfs                               110
ext4_htree_store_dirent                   110
ext4_da_write_begin                       112
ext4fs_dirhash                            122
ext4_es_lookup_extent                     143
ext4_journal_check_start                  219
Detaching...
openxs@ao756:~$ sudo /usr/share/bcc/tools/funccount -T -i 1 -d 1 '*sync'
Tracing 181 functions for "*sync"... Hit Ctrl-C to end.

13:32:11
FUNC                                    COUNT
sys_fsync                                   1
SyS_fsync                                   3
journal_end_buffer_io_sync                  8
end_bio_bh_io_sync                         22
do_fsync                                  142
kill_fasync                               158
i915_gem_object_sync                      217
SyS_fdatasync                             232
blk_run_queue_async                       291
sys_fdatasync                             324
try_to_del_timer_sync                     408
run_sync                                  483
del_timer_sync                           1056
Detaching...
openxs@ao756:~$ sudo /usr/share/bcc/tools/funccount -T -i 1 -d 1 '*file'
Tracing 151 functions for "*file"... Hit Ctrl-C to end.

13:32:41
FUNC                                    COUNT
security_mmap_file                          1
apparmor_mmap_file                          1
sock_alloc_file                             3
ext4_release_file                           8
aa_audit_file                              29
ext4_sync_file                             96
anon_inode_getfile                        100
__mnt_want_write_file                     100
__mnt_drop_write_file                     101
trace_create_file                         180
alloc_file                                205
locks_remove_file                         232
tracefs_create_file                       605
Detaching...
openxs@ao756:~$

So, it's clear that some notable number of calls to ext4_sync_file happens and we may want to trace it further. You can use funccount tool to get top N probes for further detailed study.

biotop - block device (disk) I/O by process

We have a way to find out what I/O related functions are oftedn used. But what processes actually use them and do a lot of disk I/O? Ther biotop tool helps to find out:

openxs@ao756:~$ sudo /usr/share/bcc/tools/biotop --help
usage: biotop [-h] [-C] [-r MAXROWS] [interval] [count]

Block device (disk) I/O by process

positional arguments:
  interval              output interval, in seconds
  count                 number of outputs

optional arguments:
  -h, --help            show this help message and exit
  -C, --noclear         don't clear the screen
  -r MAXROWS, --maxrows MAXROWS
                        maximum rows to print, default 20

examples:
    ./biotop            # block device I/O top, 1 second refresh
    ./biotop -C         # don't clear the screen
    ./biotop 5          # 5 second summaries
    ./biotop 5 10       # 5 second summaries, 10 times only

I tried to run it several times as follows while sysbench test was running:

openxs@ao756:~$ sudo /usr/share/bcc/tools/biotop -C
Tracing... Output every 1 secs. Hit Ctrl-C to end

13:41:05 loadavg: 3.63 4.69 7.97 1/764 20587

PID    COMM             D MAJ MIN DISK       I/O  Kbytes  AVGms
19702  mariadbd         W 8   0   sda          1       0  10.85
253    dmcrypt_write    W 8   0   sda        130       0   1.25
0                       W 8   0   sda         63       0  14.23


...
PID    COMM             D MAJ MIN DISK       I/O  Kbytes  AVGms
20714  dd               R 8   0   sda          2       0  20.67
12517  update-manager   R 8   0   sda          3       0 519.19
253    dmcrypt_write    W 8   0   sda         80       0 151.81
4090   mysqld           R 8   0   sda          1       0 506.16
253    dmcrypt_write    R 8   0   sda          1       0   1.04
5917   node_exporter    R 8   0   sda          4       0 422.73
0                       R 8   0   sda          1       0   5.31
1218   percona-qan-age  R 8   0   sda          4       0  72.50
Detaching...

We can see several top I/O users, including mariadbd and dd that I later ran concurrently to prove some points. You probably noted that I have PMM running on this netbook. A lot of I/O is related to dmcrypt_write - that's because I use encrypted disk volumn here. I am a bit surprised to see all zeros (0) for Kbytes column. Maybe there is some problem to get proper counts on this system for the bcc tools.

We see AVGms column in the output above - that's the average time for the I/O (latency) from the issuer to the device, to its completion, in milliseconds. Next tool may help to find out what's behind these average values, how slow the I/O may really be at times.

biolatency - summarize block device I/O latency as a histogram

Averages may hide some rare severe problems, so it makes sense to check the output of biolatency too:

openxs@ao756:~$ sudo /usr/share/bcc/tools/biolatency --help
usage: biolatency [-h] [-T] [-Q] [-m] [-D] [-F] [interval] [count]

Summarize block device I/O latency as a histogram

positional arguments:
  interval            output interval, in seconds
  count               number of outputs

optional arguments:
  -h, --help          show this help message and exit
  -T, --timestamp     include timestamp on output
  -Q, --queued        include OS queued time in I/O time
  -m, --milliseconds  millisecond histogram
  -D, --disks         print a histogram per disk device
  -F, --flags         print a histogram per set of I/O flags

examples:
    ./biolatency            # summarize block I/O latency as a histogram
    ./biolatency 1 10       # print 1 second summaries, 10 times
    ./biolatency -mT 1      # 1s summaries, milliseconds, and timestamps
    ./biolatency -Q         # include OS queued time in I/O time
    ./biolatency -D         # show each disk device separately
    ./biolatency -F         # show I/O flags separately

I've called it as follows to get histograms for 3 seconds, including OS queued time:

openxs@ao756:~$ sudo /usr/share/bcc/tools/biolatency -mQD 1 3
Tracing block device I/O... Hit Ctrl-C to end.


disk = 'sda'
     msecs               : count     distribution
         0 -> 1          : 73       |****************************************|
         2 -> 3          : 4        |**                                      |
         4 -> 7          : 5        |**                                      |
         8 -> 15         : 64       |***********************************     |
        16 -> 31         : 24       |*************                           |
        32 -> 63         : 6        |***                                     |
        64 -> 127        : 2        |*                                       |


disk = 'sda'
     msecs               : count     distribution
         0 -> 1          : 80       |****************************************|
         2 -> 3          : 8        |****                                    |
         4 -> 7          : 2        |*                                       |
         8 -> 15         : 57       |****************************            |
        16 -> 31         : 11       |*****                                   |
        32 -> 63         : 4        |**                                      |
        64 -> 127        : 4        |**                                      |


disk = 'sda'
     msecs               : count     distribution
         0 -> 1          : 48       |****************************************|
         2 -> 3          : 1        |                                        |
         4 -> 7          : 7        |*****                                   |
         8 -> 15         : 45       |*************************************   |
        16 -> 31         : 25       |********************                    |
        32 -> 63         : 11       |*********                               |
openxs@ao756:~$

It is clear from the above that there are many really fst I/O, but many of them take 8-15 milliseconds or even more.

We can do some analysis at filesystem level too. Next two tools help in case of ext4 filesystem (like mine). There are similar tools in bcc tools collections for other types of filesystems.

ext4slower - trace common ext4 file operations slower than a threshold

It could be useful to find out wehat kind of operation (read, write or sync) is slow, and with what file. ext4slower tool may help:

openxs@ao756:~$ sudo /usr/share/bcc/tools/ext4slower --help
usage: ext4slower [-h] [-j] [-p PID] [min_ms]

Trace common ext4 file operations slower than a threshold

positional arguments:
  min_ms             minimum I/O duration to trace, in ms (default 10)

optional arguments:
  -h, --help         show this help message and exit
  -j, --csv          just print fields: comma-separated values
  -p PID, --pid PID  trace this PID only

examples:
    ./ext4slower             # trace operations slower than 10 ms (default)
    ./ext4slower 1           # trace operations slower than 1 ms
    ./ext4slower -j 1        # ... 1 ms, parsable output (csv)
    ./ext4slower 0           # trace all operations (warning: verbose)
    ./ext4slower -p 185      # trace PID 185 only

I tried to aly it to MariaDB server while test was running and ended up with the following:

openxs@ao756:~$ sudo /usr/share/bcc/tools/ext4slower 1 -p`pidof mariadbd`
Tracing ext4 operations slower than 1 ms
TIME     COMM           PID    T BYTES   OFF_KB   LAT(ms) FILENAME
13:55:17 mariadbd       19702  S 0       0          11.32 ib_logfile0
13:55:17 mariadbd       19702  S 0       0          10.97 ib_logfile0
...
13:55:17 mariadbd       19702  S 0       0          10.51 ib_logfile0
13:55:17 mariadbd       19702  S 0       0          44.53 ibdata1
13:55:17 mariadbd       19702  S 0       0          44.14 sbtest1.ibd
13:55:17 mariadbd       19702  S 0       0          20.13 ib_logfile0
...
13:55:17 mariadbd       19702  S 0       0          11.21 ib_logfile0
13:55:17 mariadbd       19702  S 0       0          43.34 ibdata1
13:55:17 mariadbd       19702  S 0       0         179.07 sbtest1.ibd
13:55:17 mariadbd       19702  S 0       0           6.46 ib_logfile0
...
13:55:18 mariadbd       19702  S 0       0          47.79 ibdata1
13:55:18 mariadbd       19702  S 0       0          18.42 ib_logfile0
13:55:18 mariadbd       19702  S 0       0          41.76 ib_logfile0
13:55:18 mariadbd       19702  S 0       0          60.47 ibdata1

Looks like only sync operation where sometimes slow. To double check that slow writes are also reported I started dd concurrently:

openxs@ao756:~/dbs/maria10.5$ dd if=/dev/zero of=test.dd bs=1024 count=1000000
1000000+0 records in
1000000+0 records out
1024000000 bytes (1,0 GB, 977 MiB) copied, 12,4325 s, 82,4 MB/s

and got the following reported:

openxs@ao756:~$ sudo /usr/share/bcc/tools/ext4slower 10
Tracing ext4 operations slower than 10 ms
TIME     COMM           PID    T BYTES   OFF_KB   LAT(ms) FILENAME
13:57:45 dd             20972  W 1024    317088     10.10 test.dd
13:57:45 dd             20972  W 1024    317576    179.25 test.dd
13:57:45 dd             20972  W 1024    322812     15.42 test.dd
13:57:45 dd             20972  W 1024    327394     14.32 test.dd
13:57:46 dd             20972  W 1024    354096     17.61 test.dd
13:57:46 mysqld         4090   W 114688  1024      272.75 ibdata1
^Copenxs@ao756:~$

We can clearly see dd writes at differenyt offsets, 1024 bytes e4ach. Some of them were very slow. mysqld process is for PMM server running in Docker container.

ext4dist - summarize ext4 operation latency

We can further study histograms of latencies per operation with the ext4dist tool:

openxs@ao756:~$ sudo /usr/share/bcc/tools/ext4dist --help
usage: ext4dist [-h] [-T] [-m] [-p PID] [interval] [count]

Summarize ext4 operation latency

positional arguments:
  interval            output interval, in seconds
  count               number of outputs

optional arguments:
  -h, --help          show this help message and exit
  -T, --notimestamp   don't include timestamp on interval output
  -m, --milliseconds  output in milliseconds
  -p PID, --pid PID   trace this PID only

examples:
    ./ext4dist            # show operation latency as a histogram
    ./ext4dist -p 181     # trace PID 181 only
    ./ext4dist 1 10       # print 1 second summaries, 10 times
    ./ext4dist -m 5       # 5s summaries, milliseconds

Here we can see how sync latencies are distributed in general:

openxs@ao756:~$ sudo /usr/share/bcc/tools/ext4dist -T -m
Tracing ext4 operation latency... Hit Ctrl-C to end.
^C

operation = read
     msecs               : count     distribution
         0 -> 1          : 1336     |****************************************|
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 5        |                                        |
        16 -> 31         : 7        |                                        |
        32 -> 63         : 1        |                                        |

operation = write
     msecs               : count     distribution
         0 -> 1          : 10834    |****************************************|
         2 -> 3          : 3        |                                        |
         4 -> 7          : 3        |                                        |
         8 -> 15         : 4        |                                        |
        16 -> 31         : 11       |                                        |
        32 -> 63         : 6        |                                        |
        64 -> 127        : 2        |                                        |

operation = open
     msecs               : count     distribution
         0 -> 1          : 328      |****************************************|

operation = fsync
     msecs               : count     distribution
         0 -> 1          : 8        |                                        |
         2 -> 3          : 2        |                                        |
         4 -> 7          : 40       |                                        |
         8 -> 15         : 2159     |****************************************|
        16 -> 31         : 247      |****                                    |
        32 -> 63         : 319      |*****                                   |
        64 -> 127        : 152      |**                                      |
       128 -> 255        : 84       |*                                       |
       256 -> 511        : 2        |                                        |
openxs@ao756:~$

Other oerations were fast enough.

offwaketime - summarize blocked time by kernel stack trace + waker stack

You may be not even sure what the alication is waiting for, disk I/O or something else. In such cases we can try to profile the off-CPU time spent with tools like offwaketime:

openxs@ao756:~$ sudo /usr/share/bcc/tools/offwaketime --help
usage: offwaketime [-h] [-p PIDS | -t TIDS | -u | -k] [-U | -K] [-d] [-f]
                   [--stack-storage-size STACK_STORAGE_SIZE]
                   [-m MIN_BLOCK_TIME] [-M MAX_BLOCK_TIME] [--state STATE]
                   [duration]

Summarize blocked time by kernel stack trace + waker stack

positional arguments:
  duration              duration of trace, in seconds

optional arguments:
  -h, --help            show this help message and exit
  -p PIDS, --pid PIDS   trace these PIDS only. Can be a comma separated list
                        of PIDS.
  -t TIDS, --tid TIDS   trace these TIDS only. Can be a comma separated list
                        of TIDS.
  -u, --user-threads-only
                        user threads only (no kernel threads)
  -k, --kernel-threads-only
                        kernel threads only (no user threads)
  -U, --user-stacks-only
                        show stacks from user space only (no kernel space
                        stacks)
  -K, --kernel-stacks-only
                        show stacks from kernel space only (no user space
                        stacks)
  -d, --delimited       insert delimiter between kernel/user stacks
  -f, --folded          output folded format
  --stack-storage-size STACK_STORAGE_SIZE
                        the number of unique stack traces that can be stored
                        and displayed (default 1024)
  -m MIN_BLOCK_TIME, --min-block-time MIN_BLOCK_TIME
                        the amount of time in microseconds over which we store
                        traces (default 1)
  -M MAX_BLOCK_TIME, --max-block-time MAX_BLOCK_TIME
                        the amount of time in microseconds under which we
                        store traces (default U64_MAX)
  --state STATE         filter on this thread state bitmask (eg, 2 ==
                        TASK_UNINTERRUPTIBLE) see include/linux/sched.h

examples:
    ./offwaketime             # trace off-CPU + waker stack time until Ctrl-C
    ./offwaketime 5           # trace for 5 seconds only
    ./offwaketime -f 5        # 5 seconds, and output in folded format
    ./offwaketime -m 1000     # trace only events that last more than 1000 usec
    ./offwaketime -M 9000     # trace only events that last less than 9000 usec
    ./offwaketime -p 185      # only trace threads for PID 185
    ./offwaketime -t 188      # only trace thread 188
    ./offwaketime -u          # only trace user threads (no kernel)
    ./offwaketime -k          # only trace kernel threads (no user)
    ./offwaketime -U          # only show user space stacks (no kernel)
    ./offwaketime -K          # only show kernel space stacks (no user)

But my first attempt to use it failed immediately:

openxs@ao756:~$ sudo /usr/share/bcc/tools/offwaketime -f 5 -p`pidof mariadbd`
could not open bpf map: stack_traces, error: Invalid argument
Traceback (most recent call last):
  File "/usr/share/bcc/tools/offwaketime", line 290, in <module>
    b = BPF(text=bpf_text)
  File "/usr/lib/python2.7/dist-packages/bcc/__init__.py", line 364, in __init__
    raise Exception("Failed to compile BPF module %s" % (src_file or "<text>"))
Exception: Failed to compile BPF module <text>

Quck search proved that it is a known problem for Ubuntu 16.04. Wokraround (use a tool from old/ subdirectory for older kernels) helped in this case.

openxs@ao756:~$ sudo /usr/share/bcc/tools/old/offwaketime -f 5
...
mariadbd;entry_SYSCALL_64_fastpath;sys_futex;do_futex;futex_wait;futex_wait_queue_me;schedule;-;futex_wake;do_futex;sys_futex;entry_SYSCALL_64_fastpath;;mariadbd 14206606
percona-qan-api;entry_SYSCALL_64_fastpath;sys_futex;do_futex;futex_wait;futex_wait_queue_me;schedule;-;futex_wake;do_futex;sys_futex;entry_SYSCALL_64_fastpath;;percona-qan-api 14677762
prometheus;entry_SYSCALL_64_fastpath;sys_futex;do_futex;futex_wait;futex_wait_queue_me;schedule;-;futex_wake;do_futex;sys_futex;entry_SYSCALL_64_fastpath;;prometheus 14777599
dockerd;entry_SYSCALL_64_fastpath;sys_futex;do_futex;futex_wait;futex_wait_queue_me;schedule;-;futex_wake;do_futex;sys_futex;entry_SYSCALL_64_fastpath;;dockerd 14925945
consul;entry_SYSCALL_64_fastpath;sys_futex;do_futex;futex_wait;futex_wait_queue_me;schedule;-;futex_wake;do_futex;sys_futex;entry_SYSCALL_64_fastpath;;consul 14973943
mysqld;entry_SYSCALL_64_fastpath;sys_io_getevents;read_events;schedule;-;hrtimer_wakeup;__hrtimer_run_queues;hrtimer_interrupt;local_apic_timer_interrupt;smp_apic_timer_interrupt;apic_timer_interrupt;cpuidle_enter;call_cpuidle;cpu_startup_entry;start_secondary;swapper/1 15502360
prometheus1;entry_SYSCALL_64_fastpath;sys_futex;do_futex;futex_wait;futex_wait_queue_me;schedule;-;futex_wake;do_futex;sys_futex;entry_SYSCALL_64_fastpath;;prometheus1 16239277
sysbench;entry_SYSCALL_64_fastpath;sys_recvfrom;SYSC_recvfrom;sock_recvmsg;unix_stream_recvmsg;unix_stream_read_generic;schedule_timeout;schedule;-;autoremove_wake_function;__wake_up_common;__wake_up_sync_key;sock_def_readable;unix_stream_sendmsg;sock_sendmsg;SYSC_sendto;sys_sendto;entry_SYSCALL_64_fastpath;;mariadbd 19405099
node_exporter;entry_SYSCALL_64_fastpath;sys_futex;do_futex;futex_wait;futex_wait_queue_me;schedule;-;futex_wake;do_futex;sys_futex;entry_SYSCALL_64_fastpath;;node_exporter 23541664
mariadbd;entry_SYSCALL_64_fastpath;sys_futex;do_futex;futex_wait;futex_wait_queue_me;schedule;-;futex_wake_op;do_futex;sys_futex;entry_SYSCALL_64_fastpath;;mariadbd 32664296
openxs@ao756:~$

If I interret the above right, we see waiting on mutex for mariadbd.

Finally, the profile tool: 

openxs@ao756:~$ sudo /usr/share/bcc/tools/profile --help
usage: profile [-h] [-p PID | -L TID] [-U | -K] [-F FREQUENCY | -c COUNT] [-d]
               [-a] [-I] [-f] [--stack-storage-size STACK_STORAGE_SIZE]
               [-C CPU] [--cgroupmap CGROUPMAP] [--mntnsmap MNTNSMAP]
               [duration]

Profile CPU stack traces at a timed interval

positional arguments:
  duration              duration of trace, in seconds

optional arguments:
  -h, --help            show this help message and exit
  -p PID, --pid PID     profile process with this PID only
  -L TID, --tid TID     profile thread with this TID only
  -U, --user-stacks-only
                        show stacks from user space only (no kernel space
                        stacks)
  -K, --kernel-stacks-only
                        show stacks from kernel space only (no user space
                        stacks)
  -F FREQUENCY, --frequency FREQUENCY
                        sample frequency, Hertz
  -c COUNT, --count COUNT
                        sample period, number of events
  -d, --delimited       insert delimiter between kernel/user stacks
  -a, --annotations     add _[k] annotations to kernel frames
  -I, --include-idle    include CPU idle stacks
  -f, --folded          output folded format, one line per stack (for flame
                        graphs)
  --stack-storage-size STACK_STORAGE_SIZE
                        the number of unique stack traces that can be stored
                        and displayed (default 16384)
  -C CPU, --cpu CPU     cpu number to run profile on
  --cgroupmap CGROUPMAP
                        trace cgroups in this BPF map only
  --mntnsmap MNTNSMAP   trace mount namespaces in this BPF map only

examples:
    ./profile             # profile stack traces at 49 Hertz until Ctrl-C
    ./profile -F 99       # profile stack traces at 99 Hertz
    ./profile -c 1000000  # profile stack traces every 1 in a million events
    ./profile 5           # profile at 49 Hertz for 5 seconds only
    ./profile -f 5        # output in folded format for flame graphs
    ./profile -p 185      # only profile process with PID 185
    ./profile -L 185      # only profile thread with TID 185
    ./profile -U          # only show user space stacks (no kernel)
    ./profile -K          # only show kernel space stacks (no user)
    ./profile --cgroupmap mappath  # only trace cgroups in this BPF map
    ./profile --mntnsmap mappath   # only trace mount namespaces in the map

had not worked at all on my old kernel:

openxs@ao756:~$ sudo /usr/share/bcc/tools/profile -U
Sampling at 49 Hertz of all threads by user stack... Hit Ctrl-C to end.
/virtual/main.c:15:10: fatal error: 'uapi/linux/bpf_perf_event.h' file not found
#include <uapi/linux/bpf_perf_event.h>
         ^
1 error generated.
Traceback (most recent call last):
  File "/usr/share/bcc/tools/profile", line 277, in <module>
    b = BPF(text=bpf_text)
  File "/usr/lib/python2.7/dist-packages/bcc/__init__.py", line 364, in __init__
    raise Exception("Failed to compile BPF module %s" % (src_file or "<text>"))
Exception: Failed to compile BPF module <text>

openxs@ao756:~$ sudo /usr/share/bcc/tools/old/profile -U
Sampling at 49 Hertz of all threads by user stack... Hit Ctrl-C to end.
could not open bpf map: stack_traces, error: Invalid argument
BPF initialization failed. perf_misc_flags() may be inlined in your kernel build.
This tool will be updated in the future to support Linux 4.9, which has reliable profiling support. Exiting.

Header file is missing. Proper eBPF instrumentation to use perf events was added only in kernels 4.9+

To summarize:

1. bcc tools allow to do detailed disk I/O analysis at different levels, even on old enough Linux kernels like 4.4
2. funccount tool helps to find out what to trace with more details.
3. Latencies distribution mattes and histograms provided by some bcc tools may help to understand this.
   
4. There is a limit on total number of active probes.
5. There are alternative implementations of some bcc tools for older kernel versions, but looks like its time for all of us to upgrade to Linux kernels 5.x.y.

MariaDB 10.5 and Memory Instrumentation in Performance Schema - Basic Checks

My MariaDB 10.5-related talk at upcoming MariaDB Server Fest is already announced, so I have no other option but to continue writing blog posts while preparing for it. 

In the previous one we enabled memory instrumentation and tried to run some basic queries again the performance_schema.memory_summary_global_by_event_name table. Now I'd like to use it for checking how much memory is allocated to the Performance Schema itself and when this allocation happens. For this I am starting 10.5 with performance_schema and memory instrumentation enabled:

openxs@ao756:~/dbs/maria10.5$ bin/mysqld_safe --no-defaults --port=3311 --socket=/tmp/mariadb105.sock --performance_schema --performance-schema-instrument='memory/%=ON' &
[4] 19144
openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock -e"show global variables like 'performance_schema';;select version(), count(*) from performance_schema.setup_instruments where name like 'memory%' and enabled='yes'"
+--------------------+-------+
| Variable_name      | Value |
+--------------------+-------+
| performance_schema | ON    |
+--------------------+-------+
+----------------+----------+
| version()      | count(*) |
+----------------+----------+
| 10.5.6-MariaDB |      270 |
+----------------+----------+

Let's start the initial memory usage for allocations related to the performance_schema:

openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock -e"select sum(SUM_NUMBER_OF_BYTES_ALLOC) alloc, sum(SUM_NUMBER_OF_BYTES_FREE) free, sum(CURRENT_NUMBER_OF_BYTES_USED) used from performance_schema.memory_summary_global_by_event_name where event_name like 'memory/performance%'"
+----------+------+----------+
| alloc    | free | used     |
+----------+------+----------+
| 97903648 |    0 | 97903648 |
+----------+------+----------+
openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock -e"show engine performance_schema status\G" | tail -4
*************************** 229. row ***************************
  Type: performance_schema
  Name: performance_schema.memory
Status: 97902160

So we know that now with mostly default settings 10.5 uses a bit more than 93M of memory We can also note a difference in the sum of memory allocated according to the memory_summary_global_by_event_name table and the total memory from show engine performance_schema status output. The difference is resent in MySQL 5.7 as well:

openxs@ao756:~/dbs/5.7$ bin/mysqld_safe --no-defaults --port=3310 --socket=/tmp/mysql57.sock --performance_schema=1 --performance-schema-instrument='memory/%=ON' &
[5] 20459
openxs@ao756:~/dbs/5.7$ bin/mysql -uroot --socket=/tmp/mysql57.sock -e"select sum(SUM_NUMBER_OF_BYTES_ALLOC) alloc, sum(SUM_NUMBER_OF_BYTES_FREE) free, sum(CURRENT_NUMBER_OF_BYTES_USED) used from performance_schema.memory_summary_global_by_event_name where event_name like 'memory/performance%'"
+-----------+------+-----------+
| alloc     | free | used      |
+-----------+------+-----------+
| 137641608 |    0 | 137641608 |
+-----------+------+-----------+
openxs@ao756:~/dbs/5.7$ bin/mysql -uroot --socket=/tmp/mysql57.sock -e"show engine performance_schema status\G" | tail -4
*************************** 229. row ***************************
  Type: performance_schema
  Name: performance_schema.memory
Status: 137640120
openxs@ao756:~/dbs/5.7$ bin/mysql -uroot --socket=/tmp/mysql57.sock -e"select 137641608 - 137640120"
+-----------------------+
| 137641608 - 137640120 |
+-----------------------+
|                  1488 |
+-----------------------+

The difference is the same, 1488 bytes, so MariaDB probably inherited the problem that I've reported as Bug #100624 - "Total memory allocation for P_S is different in different sources".

Let's also get top 5 memory users:

openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock -e"select EVENT_NAME, SUM_NUMBER_OF_BYTES_ALLOC alloc, SUM_NUMBER_OF_BYTES_FREE free, CURRENT_NUMBER_OF_BYTES_USED used from performance_schema.memory_summary_global_by_event_name where event_name like 'memory/performance%' order by 2 desc limit 5"
+------------------------------------------------------------------------------+----------+------+----------+
| EVENT_NAME                                                                   | alloc    | free | used     |
+------------------------------------------------------------------------------+----------+------+----------+
| memory/performance_schema/events_statements_summary_by_thread_by_event_name  | 10457088 |    0 | 10457088 |
| memory/performance_schema/memory_summary_by_thread_by_event_name             |  5898240 |    0 |  5898240 |
| memory/performance_schema/events_statements_summary_by_account_by_event_name |  5228544 |    0 |  5228544 |
| memory/performance_schema/events_statements_summary_by_host_by_event_name    |  5228544 |    0 |  5228544 |
| memory/performance_schema/events_statements_summary_by_user_by_event_name    |  5228544 |    0 |  5228544 |
+------------------------------------------------------------------------------+----------+------+----------+

Now let's add some load, 4 threads in a simple sysbench test:

openxs@ao756:~/dbs/maria10.5$ sysbench --table-size=1000000 --threads=4 --time=10 --mysql-socket=/tmp/mariadb105.sock --mysql-user=openxs --mysql-db=sbtest /usr/share/sysbench/oltp_read_only.lua run
sysbench 1.1.0-faaff4f (using bundled LuaJIT 2.1.0-beta3)

Running the test with following options:
Number of threads: 4
...
openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock -e"select sum(SUM_NUMBER_OF_BYTES_ALLOC) alloc, sum(SUM_NUMBER_OF_BYTES_FREE) free, sum(CURRENT_NUMBER_OF_BYTES_USED) used from performance_schema.memory_summary_global_by_event_name where event_name like 'memory/performance%'"
+-----------+------+-----------+
| alloc     | free | used      |
+-----------+------+-----------+
| 109110496 |    0 | 109110496 |
+-----------+------+-----------+
openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock -e"show engine performance_schema status\G" | tail -4
*************************** 229. row ***************************
  Type: performance_schema
  Name: performance_schema.memory
Status: 109108816
openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock -e"select 109110496 - 97903648, 109108816 - 97902160"
+----------------------+----------------------+
| 109110496 - 97903648 | 109108816 - 97902160 |
+----------------------+----------------------+
|             11206848 |             11206656 |
+----------------------+----------------------+

We can see that after the load total memory usage by the performance_schema increased, based on both sources! Moreover, both sources report different values and different increase, but it's still around 11M. If we try more threads:

openxs@ao756:~/dbs/maria10.5$ sysbench --table-size=1000000 --threads=34 --time=10 --mysql-socket=/tmp/mariadb105.sock --mysql-user=openxs --mysql-db=sbtest /usr/share/sysbench/oltp_read_only.lua run
...
openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock -e"select sum(SUM_NUMBER_OF_BYTES_ALLOC) alloc, sum(SUM_NUMBER_OF_BYTES_FREE) free, sum(CURRENT_NUMBER_OF_BYTES_USED) used from performance_schema.memory_summary_global_by_event_name where event_name like 'memory/performance%'"
+-----------+------+-----------+
| alloc     | free | used      |
+-----------+------+-----------+
| 109258144 |    0 | 109258144 |
+-----------+------+-----------+
openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock -e"show engine performance_schema status\G" | tail -4
*************************** 229. row ***************************
  Type: performance_schema
  Name: performance_schema.memory
Status: 109256272
openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock -e"select 109258144 - 109110496"
+-----------------------+
| 109258144 - 109110496 |
+-----------------------+
|                147648 |
+-----------------------+

we see some additional, small increase in total memory allocated and used. Repeating the load with the same concurrency does not change memory allocated. Top 5 memory users now are a bit different:

openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock -e"select EVENT_NAME, SUM_NUMBER_OF_BYTES_ALLOC alloc, SUM_NUMBER_OF_BYTES_FREE free, CURRENT_NUMBER_OF_BYTES_USED used from performance_schema.memory_summary_global_by_event_name where event_name like 'memory/performance%' order by 2 desc limit 5"
+------------------------------------------------------------------------------+----------+------+----------+
| EVENT_NAME                                                                   | alloc    | free | used     |
+------------------------------------------------------------------------------+----------+------+----------+
| memory/performance_schema/events_statements_summary_by_thread_by_event_name  | 10457088 |    0 | 10457088 |
| memory/performance_schema/table_handles                                      |  9502720 |    0 |  9502720 |
| memory/performance_schema/memory_summary_by_thread_by_event_name             |  5898240 |    0 |  5898240 |
| memory/performance_schema/events_statements_summary_by_account_by_event_name |  5228544 |    0 |  5228544 |
| memory/performance_schema/events_statements_summary_by_host_by_event_name    |  5228544 |    0 |  5228544 |
+------------------------------------------------------------------------------+----------+------+----------+

Note that memory/performance_schema/table_handles allocation had increased dynamically and the second row now. 

These dynamic allocations are expected based on fine MySQL manual:

"The Performance Schema dynamically allocates memory incrementally, scaling its memory use to actual server load, instead of allocating required memory during server startup. Once memory is allocated, it is not freed until the server is restarted."

Now back to the table we've used. We do not have any nice comments for the columns:

openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock -e"show create table performance_schema.memory_summary_global_by_event_name\G"            *************************** 1. row ***************************
       Table: memory_summary_global_by_event_name
Create Table: CREATE TABLE `memory_summary_global_by_event_name` (
  `EVENT_NAME` varchar(128) NOT NULL,
  `COUNT_ALLOC` bigint(20) unsigned NOT NULL,
  `COUNT_FREE` bigint(20) unsigned NOT NULL,
  `SUM_NUMBER_OF_BYTES_ALLOC` bigint(20) unsigned NOT NULL,
  `SUM_NUMBER_OF_BYTES_FREE` bigint(20) unsigned NOT NULL,
  `LOW_COUNT_USED` bigint(20) NOT NULL,
  `CURRENT_COUNT_USED` bigint(20) NOT NULL,
  `HIGH_COUNT_USED` bigint(20) NOT NULL,
  `LOW_NUMBER_OF_BYTES_USED` bigint(20) NOT NULL,
  `CURRENT_NUMBER_OF_BYTES_USED` bigint(20) NOT NULL,
  `HIGH_NUMBER_OF_BYTES_USED` bigint(20) NOT NULL
) ENGINE=PERFORMANCE_SCHEMA DEFAULT CHARSET=utf8

Current MariaDB KB article on the table does NOT add much value onm top of the above. So, we have to rely on MySQL manual for explanations of columns' semantics and basic usage principles.

I am trying to focus on features, but end up reporting bugs and problems...

To summarize:

• In MariaDB 10.5 (same as in MySQL 5.7+) memory for performance_schema is allocated not only at startup, but also dynamically at runtime and is never returned back to the system. So we have one more potential "memory leak" to care about.
• Total memory used is reported differently by SHOW ENGINE... and memory_summary_global_by_event_name table. This is a bug.
  
• By default MariaDB 10.5 seems to allocate less memory than MySQL 5.7 for Performance Schema in total. See my old report MDEV-20216 also.
  
• So far we mostly have to rely on fine MySQL 5.7 manual if the details on memory instrumentation are needed.
  

MariaDB 10.5 and Memory Instrumentation in Performance Schema - First Steps

Chances are high for me to speak about MariaDB 10.5 at the upcoming MariaDB Server Fest Online Conference (as my related talk was accepted), so it's time to start writing about it. In this post I am going to do basic checks of the new and long wanted Performance Schema memory instrumentation feature finally ported from MySQL 5.7. Until recently we mostly had to use OS level tools for memory instrumentation, like perf or heap profilers etc.

As usual (see here and there) when I am serious about working with some open source software and formally supporting it, I start with checking how to build it from GitHub source on my own hardware and/or VMs. This time I've tried the usual steps to build MariaDB 10.5.5 on my gold old Ubuntu 16.04 netbook (from fc -l output):

1984     cd git/server/
1985     git branch
1986     git checkout 10.5
1987     git pull
1988     git submodule update --init --recursive
1989     rm CMakeCache.txt
1990     cd build/
1991     rm -rf *
1992     cmake .. -DCMAKE_BUILD_TYPE=RelWithDebInfo -DWITH_SSL=system -DWITH_ZLIB=bundled -DMYSQL_MAINTAINER_MODE=OFF -DENABLED_LOCAL_INFILE=1 -DWITH_JEMALLOC=system -DWITH_INNODB_DISALLOW_WRITES=ON -DCMAKE_INSTALL_PREFIX=/home/openxs/dbs/maria10.5
1993     time make -j 3
...
2001     rm -rf /home/openxs/dbs/maria10.5
2002     make install && make clean
2003     cd /home/openxs/dbs/maria10.5
...
2005     scripts/mysql_install_db --no-defaults
2006     bin/mysqld_safe --no-defaults --port=3309 --socket=/tmp/mariadb.sock --performance_schema=ON &

I am using out of source build in a separate build subdirectory and clean up the remaining of older builds just in case. Options used are typical for this box. I do not disable the TokuDB engine explicitly as it's no longer included anyway.  

Then I removed previous instance, initialized the database and started it as usual, via mysqld_safe with explicit option to enable Performance Schema as it's disabled in MariaDB by default. Note these details though:

openxs@ao756:~/dbs/maria10.5$ ls -l bin/mysqld
lrwxrwxrwx 1 openxs openxs 8 сер  9 14:04 bin/mysqld -> mariadbd
openxs@ao756:~/dbs/maria10.5$ ls -l bin/mariadbd
-rwxr-xr-x 1 openxs openxs 213124184 сер  9 13:57 bin/mariadbd
openxs@ao756:~/dbs/maria10.5$ ls -l ../maria10.4/bin/mysqld
-rwxr-xr-x 1 openxs openxs 178385776 сер  5 19:18 ../maria10.4/bin/mysqld
openxs@ao756:~/dbs/maria10.5$ ls -l ../8.0/bin/mysqld
-rwxr-xr-x 1 openxs openxs 749000640 лип 13 21:35 ../8.0/bin/mysqld

All the mysql* binaries are now symbolic links to mariadb* ones. Also note the relative sizes of the non-stripped binaries comparing to MariaDB 10.4 and MySQL 8.0.21 (that one is impressive).

Now I can try to connect and check what new memory-related settings and tables are available (note that I had to log in as OS user who started the server, as Unix socket authentication plugin is installed and used by default for by default):

openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb.sock test
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 7
Server version: 10.5.5-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 [test]> show grants;
+-------------------------------------------------------------------------------------------------------------------------------------------+
| Grants for openxs@localhost                                                                                                               |
+-------------------------------------------------------------------------------------------------------------------------------------------+
| GRANT ALL PRIVILEGES ON *.* TO `openxs`@`localhost` IDENTIFIED VIA mysql_native_password USING 'invalid' OR unix_socket WITH GRANT OPTION |
+-------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0,000 sec)

MariaDB [test]> select table_name from information_schema.tables where table_schema='performance_schema' and table_name like 'memory%';
+-----------------------------------------+
| table_name                              |
+-----------------------------------------+
| memory_summary_by_account_by_event_name |
| memory_summary_by_host_by_event_name    |
| memory_summary_by_thread_by_event_name  |
| memory_summary_by_user_by_event_name    |
| memory_summary_global_by_event_name     |
+-----------------------------------------+
5 rows in set (0,001 sec)

MariaDB [test]> select count(*) from performance_schema.setup_instruments where name like '%memory%' and enabled='yes';
+----------+
| count(*) |
+----------+
|       70 |
+----------+
1 row in set (0,003 sec)

MariaDB [test]> select count(*) from performance_schema.setup_instruments where name like '%memory%';
+----------+
| count(*) |
+----------+
|      270 |
+----------+
1 row in set (0,003 sec)

MariaDB [test]> select * from performance_schema.setup_instruments where name like '%memory%' and enabled='yes';
+--------------------------------------------------------------------------------+---------+-------+
| NAME                                                                           | ENABLED | TIMED |
+--------------------------------------------------------------------------------+---------+-------+
| memory/performance_schema/mutex_instances                                      | YES     | NO    |
| memory/performance_schema/rwlock_instances                                     | YES     | NO    |
...
| memory/performance_schema/prepared_statements_instances                        | YES     | NO    |
| memory/performance_schema/scalable_buffer                                      | YES     | NO    |
+--------------------------------------------------------------------------------+---------+-------+
70 rows in set (0,003 sec)

We have the expected 5 summary tables and some 270(!)  new instruments, of then 70 related to performance_schema itself are enabled by default. Note that MySQL 5.7.30, for example, has more memory instruments:

openxs@ao756:~/dbs/5.7$ bin/mysql -uroot --socket=/tmp/mysql57.sock -e"select version(), count(*) from performance_schema.setup_instruments where name like 'memory%'"
+-----------+----------+
| version() | count(*) |
+-----------+----------+
| 5.7.30    |      376 |
+-----------+----------+

 We can check InnoDB memory instrumentation and then enable everything for a quick test:

MariaDB [test]> select * from performance_schema.setup_instruments where name like '%memory%innodb%';
+-------------------------------------------+---------+-------+
| NAME                                      | ENABLED | TIMED |
+-------------------------------------------+---------+-------+
| memory/innodb/adaptive hash index         | NO      | NO    |
| memory/innodb/buf_buf_pool                | NO      | NO    |
| memory/innodb/dict_stats_bg_recalc_pool_t | NO      | NO    |
| memory/innodb/dict_stats_index_map_t      | NO      | NO    |
| memory/innodb/dict_stats_n_diff_on_level  | NO      | NO    |
| memory/innodb/other                       | NO      | NO    |
...
| memory/innodb/ut0mem                      | NO      | NO    |
| memory/innodb/ut0new                      | NO      | NO    |
| memory/innodb/ut0pool                     | NO      | NO    |
| memory/innodb/ut0rbt                      | NO      | NO    |
| memory/innodb/ut0wqueue                   | NO      | NO    |
| memory/innodb/xtrabackup                  | NO      | NO    |
+-------------------------------------------+---------+-------+
72 rows in set (0,003 sec)

MariaDB [test]> update performance_schema.setup_instruments set enabled = 'yes', timed = 'yes' where name like '%memory%';
Query OK, 270 rows affected (0,003 sec)
Rows matched: 270  Changed: 270  Warnings: 0

My main initial source of information is this table, summartising memory usage globally:

MariaDB [test]> desc performance_schema.memory_summary_global_by_event_name;
+------------------------------+---------------------+------+-----+---------+-------+
| Field                        | Type                | Null | Key | Default | Extra |
+------------------------------+---------------------+------+-----+---------+-------+
| EVENT_NAME                   | varchar(128)        | NO   |     | NULL    |       |
| COUNT_ALLOC                  | bigint(20) unsigned | NO   |     | NULL    |       |
| COUNT_FREE                   | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_NUMBER_OF_BYTES_ALLOC    | bigint(20) unsigned | NO   |     | NULL    |       |
| SUM_NUMBER_OF_BYTES_FREE     | bigint(20) unsigned | NO   |     | NULL    |       |
| LOW_COUNT_USED               | bigint(20)          | NO   |     | NULL    |       |
| CURRENT_COUNT_USED           | bigint(20)          | NO   |     | NULL    |       |
| HIGH_COUNT_USED              | bigint(20)          | NO   |     | NULL    |       |
| LOW_NUMBER_OF_BYTES_USED     | bigint(20)          | NO   |     | NULL    |       |
| CURRENT_NUMBER_OF_BYTES_USED | bigint(20)          | NO   |     | NULL    |       |
| HIGH_NUMBER_OF_BYTES_USED    | bigint(20)          | NO   |     | NULL    |       |
+------------------------------+---------------------+------+-----+---------+-------+
11 rows in set (0,002 sec)

MariaDB [test]> select event_name,
    ->        sum_number_of_bytes_alloc,
    ->        high_number_of_bytes_used
    -> from
    ->   performance_schema.memory_summary_global_by_event_name
    -> where current_count_used > 0
    -> order by 2 desc;
+--------------------------------------------------------------------------------+---------------------------+---------------------------+
| event_name                                                                     | sum_number_of_bytes_alloc | high_number_of_bytes_used |
+--------------------------------------------------------------------------------+---------------------------+---------------------------+
| memory/performance_schema/events_statements_summary_by_thread_by_event_name    |                  10457088 |                  10457088 |
| memory/performance_schema/memory_summary_by_thread_by_event_name               |                   5898240 |                   5898240 |
| memory/performance_schema/events_statements_summary_by_user_by_event_name      |                   5228544 |                   5228544 |
| memory/performance_schema/events_statements_summary_by_host_by_event_name      |                   5228544 |                   5228544 |
...
| memory/sql/dboptions_hash                                                      |                      1088 |                      1088 |
| memory/sql/user_var_entry                                                      |                       512 |                       512 |
| memory/sql/THD::db                                                             |                         8 |                         8 |
| memory/sql/MPVIO_EXT::auth_info                                                |                         8 |                         8 |
+--------------------------------------------------------------------------------+---------------------------+---------------------------+
71 rows in set (0,002 sec)

Obviously memory is mostly used for the Performanc e Schema itself so far. Now let's run some sysbench test and check what memory usage is reported after it:

openxs@ao756:~/dbs/maria10.5$ sysbench --table-size=1000000 --threads=1 --mysql-socket=/tmp/mariadb.sock --mysql-user=openxs --mysql-db=sbtest /usr/share/sysbench/oltp_read_only.lua prepare
sysbench 1.1.0-faaff4f (using bundled LuaJIT 2.1.0-beta3)

Creating table 'sbtest1'...
Inserting 1000000 records into 'sbtest1'
Creating a secondary index on 'sbtest1'...
openxs@ao756:~/dbs/maria10.5$ sysbench --table-size=1000000 --threads=4 --time=30 --interval=2 --mysql-socket=/tmp/mariadb.sock --mysql-user=openxs --mysql-db=sbtest /usr/share/sysbench/oltp_read_only.lua run
sysbench 1.1.0-faaff4f (using bundled LuaJIT 2.1.0-beta3)
...
[ 2s ] thds: 4 tps: 588.22 qps: 9423.03 (r/w/o: 8244.59/0.00/1178.44) lat (ms,95%): 9.39 err/s: 0.00 reconn/s: 0.00
[ 4s ] thds: 4 tps: 629.50 qps: 10081.05 (r/w/o: 8822.04/0.00/1259.01) lat (ms,95%): 9.06 err/s: 0.00 reconn/s: 0.00
[ 6s ] thds: 4 tps: 604.08 qps: 9672.34 (r/w/o: 8464.17/0.00/1208.17) lat (ms,95%): 8.74 err/s: 0.00 reconn/s: 0.00
[ 8s ] thds: 4 tps: 617.97 qps: 9882.99 (r/w/o: 8647.05/0.00/1235.94) lat (ms,95%): 9.22 err/s: 0.00 reconn/s: 0.00
...

After the test is completed I tried the following query:

MariaDB [test]> select event_name, high_number_of_bytes_used from performance_schema.memory_summary_global_by_event_name where event_name not like '%performance_schema%' order by 2 desc limit 10;
                                            
+----------------------------------------------+---------------------------+
| event_name                                   | high_number_of_bytes_used |
+----------------------------------------------+---------------------------+
| memory/innodb/mem0mem                        |                   9377611 |
| memory/sql/thd::main_mem_root                |                   4286600 |
| memory/innodb/row_merge_sort                 |                   3145728 |
| memory/innodb/row0merge                      |                   2097316 |
| memory/memory/HP_PTRS                        |                   1016352 |
| memory/sql/Prepared_statement::main_mem_root |                    590400 |
| memory/sql/TABLE                             |                    525608 |
| memory/innodb/std                            |                    399192 |
| memory/innodb/row0log                        |                    131474 |
| memory/sql/TABLE_SHARE::mem_root             |                     42272 |
+----------------------------------------------+---------------------------+
10 rows in set (0,003 sec)

The result was surprising to me, as I do not sdee thye InnoDB buffer pool memory usage above. But this is yet another case of Performance Schema instrument that is NOT dynamic. I've reported a bug about these years ago, see Bug #68097 - "Manual does not explain that some P_S instruments must be enabled at startup".

So, I restarted with all memory instruments enabled and reppeated the test:

MariaDB [test]> shutdown;
Query OK, 0 rows affected (0,001 sec)

MariaDB [test]> exit
Bye
[1]+  Done                    bin/mysqld_safe --no-defaults --port=3309 --socket=/tmp/mariadb.sock --performance_schema=ON

openxs@ao756:~/dbs/maria10.5$ bin/mysqld_safe --no-defaults --port=3309 --socket=/tmp/mariadb.sock --performance_schema=ON --performance-schema-instrument='memory/%=ON' &
[1] 29502
openxs@ao756:~/dbs/maria10.5$ 200809 14:53:59 mysqld_safe Logging to '/home/openxs/dbs/maria10.5/data/ao756.err'.
200809 14:53:59 mysqld_safe Starting mariadbd daemon with databases from /home/openxs/dbs/maria10.5/data

openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb.sock -e"select count(*) from performance_schema.setup_instruments where name like 'memory%' and enabled='yes'"
+----------+
| count(*) |
+----------+
|      270 |
+----------+

openxs@ao756:~/dbs/maria10.5$ sysbench --table-size=1000000 --threads=4 --time=30 --report-interval=2 --mysql-socket=/tmp/mariadb.sock --mysql-user=openxs --mysql-db=sbtest /usr/share/sysbench/oltp_read_only.lua run
sysbench 1.1.0-faaff4f (using bundled LuaJIT 2.1.0-beta3)

Running the test with following options:
Number of threads: 4
Report intermediate results every 2 second(s)
Initializing random number generator from current time


Initializing worker threads...

Threads started!

[ 2s ] thds: 4 tps: 606.19 qps: 9715.08 (r/w/o: 8500.70/0.00/1214.39) lat (ms,95%): 10.46 err/s: 0.00 reconn/s: 0.00
[ 4s ] thds: 4 tps: 641.03 qps: 10262.98 (r/w/o: 8980.92/0.00/1282.06) lat (ms,95%): 6.67 err/s: 0.00 reconn/s: 0.00
...

openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb.sock test
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 9
Server version: 10.5.5-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 [test]> select event_name, high_number_of_bytes_used from performance_schema.memory_summary_global_by_event_name where event_name not like '%performance_schema%' and high_number_of_bytes_used > 0 order by 2 desc;
+----------------------------------------------+---------------------------+
| event_name                                   | high_number_of_bytes_used |
+----------------------------------------------+---------------------------+
| memory/innodb/buf_buf_pool                   |                 134217728 |
| memory/sql/XID                               |                  19922944 |
| memory/innodb/ut0pool                        |                   4194480 |
| memory/innodb/hash0hash                      |                   2484000 |
| memory/innodb/os0event                       |                   2120064 |
| memory/memory/HP_PTRS                        |                   1016352 |
| memory/sql/Prepared_statement::main_mem_root |                    590400 |
| memory/sql/TABLE                             |                    351264 |
...
| memory/sql/MDL_context::acquire_locks        |                        16 |
| memory/sql/NAMED_ILINK::name                 |                        16 |
| memory/sql/ignored_db                        |                         8 |
+----------------------------------------------+---------------------------+
70 rows in set (0,003 sec)

Now to line in the outut is exactly the one I've expected. As for the rest, some would require additional efforts to find out what this memory is used for. In conclusion I'd like to use a nice query from this useful blog post to summarise memory usage per "subsystem":

MariaDB [test]> select substring_index(substring_index(event_name, '/', 2), '/', -1) as event_type,
    -> round(sum(CURRENT_NUMBER_OF_BYTES_USED)/1024/1024, 2) as MB_CURRENTLY_USED
    -> from performance_schema.memory_summary_global_by_event_name
    -> group by event_type
    -> having MB_CURRENTLY_USED>0;
+--------------------+-------------------+
| event_type         | MB_CURRENTLY_USED |
+--------------------+-------------------+
| innodb             |            136.95 |
| memory             |              0.21 |
| performance_schema |            104.06 |
| sql                |              0.71 |
+--------------------+-------------------+
4 rows in set (0,003 sec)

Basically, with all instrumentation enabled you can now use Performance Schema in MariaDB 10.5 to find and study memory usdage and leaks, same as in MySQL 5.7+.

Let's check the harvest, what was grown up under the name of MariaDB 10.5 GA...

To summarize:

• MariaDB 10.5 is real, you can build it from GitHub source and it works, including new features memory monitoring tables in Performance Schema. Just make sure to properly enable the instrumentation at startup.
• The public documentation at the moment is very limited or does not exist, so we have to rely on fine MySQL manual (that also misses too many details) etc. I've created this task asking to add documentation for memory* (or all) instruments.
  
• It's yet to be checked if any known related Performance Schema bugs in MySQL are inherited by MariaDB 10.5.
• It's yet to be determined what memory instruments from recent MySQL 5.7.x are missing in recent MariaDB 10.5.x and what are added, and why. Looks like many from the check below:

openxs@ao756:~/dbs/5.7$ bin/mysql -uroot --socket=/tmp/mysql57.sock -e"select name from performance_schema.setup_instruments where name like 'memory%' order by name" > /tmp/mysql57.txt
openxs@ao756:~/dbs/5.7$ bin/mysql --socket=/tmp/mariadb.sock -e"select name from performance_schema.setup_instruments where name like 'memory%' order by name" > /tmp/mariadb.txt
openxs@ao756:~/dbs/5.7$ diff -u /tmp/mysql57.txt /tmp/mariadb.txt > /tmp/ps_memory.txt
openxs@ao756:~/dbs/5.7$ more /tmp/ps_memory.txt
--- /tmp/mysql57.txt    2020-08-09 17:30:27.199204590 +0300
+++ /tmp/mariadb.txt    2020-08-09 17:30:31.459270994 +0300
@@ -1,22 +1,12 @@
 name
-memory/archive/FRM
-memory/archive/record_buffer
-memory/blackhole/blackhole_share
-memory/client/MYSQL
-memory/client/MYSQL_DATA
-memory/client/MYSQL_HANDSHAKE
-memory/client/mysql_options
-memory/client/MYSQL_RES
-memory/client/MYSQL_ROW
-memory/client/MYSQL_STATE_CHANGE_INFO
 memory/csv/blobroot
 memory/csv/row
 memory/csv/tina_set
 memory/csv/TINA_SHARE
 memory/csv/Transparent_file
 memory/innodb/adaptive hash index
-memory/innodb/api0api
 memory/innodb/btr0btr
+memory/innodb/btr0buf
...
openxs@ao756:~/dbs/5.7$ cat /tmp/ps_memory.txt | grep '^+'
+++ /tmp/mariadb.txt    2020-08-09 17:30:31.459270994 +0300
+memory/innodb/btr0buf
+memory/innodb/fil0crypt
+memory/innodb/fts0blex
+memory/innodb/fts0file
+memory/innodb/fts0tlex
+memory/innodb/sync0start
+memory/innodb/trx0seg
+memory/innodb/ut0new
+memory/innodb/xtrabackup
+memory/partition/Partition_admin
+memory/partition/Partition_share
+memory/partition/partition_sort_buffer
openxs@ao756:~/dbs/5.7$

So, stay tuned! More blog posts on MariaDB 10.5 Performance Schema improvements are to be expected.

Dynamic Tracing of C++ Class Member Functions with perf

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 -A

Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 9
Server version: 10.3.24-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 [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. Never give up on dynamic tracing, it works!
2. With your version of perf you may have to use mangled names for C++ class member functions and --no-demangle option to define the probe.
3. You may have to quote the probe while adding, if it has some special characters like ':'. Read the man perf-probe manual carefully also.
4. You may have to study the source code to print the arguments or return values properly.
5. There are other options to deal with C++ class memeber functions. You can refer to them by source file and line number, or even by address that you find in objdump etc.
6. I hope one day tools like bpftrace will let us use the real, not mangled names of functions. I have to check on Fedora 31 if it's already the case.
7. I feel myself cool when some experienced developer asks me something about perf and I can provide an answer, even if not immediately :)

Fun with Bugs #100 - On MySQL Bug Reports I am Subscribed to, Part XXXIV

I delayed this post #100 in the "Fun with Bugs" series for few weeks - the previous one was published 4 weeks ago. The idea was to make it the last one, and for this I needed something to celebrate. Two days ago proper event happened, we have MySQL Bug #100000 reported! Here it is:

• Bug #100000 - "Provide an index hint that only affects the choice of index for NL join". This nice feature request was added by former optimizer developer in MySQL, Øystein Grøvlen. Hundreds of other feature requests are waiting for the attention both from the MySQL Verification Team and from developers, so good to see a feature request getting the number that nobody ever forget!

Actually Øystein Grøvlen created several interesting bug report during that day:

• Bug #99994 - "Index range scan is chosen where table scan takes 40% less time". Clear and simple bug report that relies on the world sample database.
• Bug #99995 - "Histogram is not used for filtering estimate when index is disabled".
• Bug #99996 - "Prefer histogram over index statistics when eq_range_index_dive_limit is exceeded". This was verified as a feature request.
• Bug #99997 - "Range estimates are usually off by a factor of 2 for large ranges". It was declared a duplicate of older bug report I am also subscribed to, Bug #73386 - "For ranges, innodb doubles estimates, or caps estimates to half the table". See also this MariaDB bug report, MDEV-19424 - "InnoDB's records_in_range estimates are capped at about 50%", and links from it for a lot of related discussions. Let's wait and see what vendor resolves this faster...
  The other report, Bug #99998 - "For large ranges, the range estimate will never exceed 50%", is probably also a duplicate of the same old bug.
• Bug #99999 - "EXPLAIN FORMAT=TREE does not show cost/rows for semijoin materialization". Yet another nice and clear bug report.

So, hardly anyone else had a chance to get that #100000 filed. As far as I can see, all these were reported during a very short period of 2 minutes, from "26 Jun 7:57" till "26 Jun 7:58"! Not sure how to do this without some automation or at least all the details ready for quick copy/pasting!

Now back to some older bugs I've subscribed to over last 4 weeks:

• Bug #99791 - "MySQL 8 orphaned table due to unchecked non-existent row format check." As reported by Marc Reilly, tables created in versions < MySQL 8 which use row_format COMPRESSED or REDUNDANT, where row_format is not set explicitly in the Table DDL allow users to create un-prefixed indexes on fields which exceed the maximum column size of 767 bytes. Upgrading to MySQL 8 do nothing with these tables, but as soon as new index is added and reboot happens, such a table becomes inaccessible. What a surprise!
• Bug #99794 - "MySQL 57 client is inefficient at bulkloads/binlog replay". In this bug report  Marc Reilly basically asks to back port the fix from MySQL 8.0.13.
• Bug #99800 - "ps_truncate_all_tables() does not work in super_read_only mode". This regression bug was reported by Lalit Choudhary.
• Bug #99805 - "mysql async client is incomplete". There is no way to determine file descriptor state (should it block on read or write), so it is impossible to use it in asynchronous contexts without busy looping. This bug report by Domas Mituzas was used in one discussion as an argument that MySQL bugs database still gets proper attention from MySQL engineers. It's truly so.
• Bug #99892 - "initialize with innodb_page_size=4096 gets "Specified key was too long" errors". This is a regression vs 5.7 (without a tag). As Mark Callaghan found out, one can not initialize MySQL 8 instance without errors with such a small innodb_page_size.
• Bug #99924 - "The record per key value from InnoDB is not suitable when n_diff is zero". As reported by Ze Yang, due to lack of locking when server reads the innodb_rec_per_key, the n_diff value may be 0 (not set) while the table->stat_n_rows is > 0. As a result (see great comment by Øystein Grøvlen), if a table object is opened during the recalculation of statistics, the rec_per_key for a column/index may be quite misleading. It will be interpreted as all rows have the same value, and the index will probably not be chosen for any non-covering scans. There is a patch suggested (to set rec_per_key to 1 or 10 in such case), as well as other suggestion to set the value REC_PER_KEY_UNKNOWN. Useful reading!
• Bug #99933  - "In-memory hash join will only use two-thirds of join buffer". Yet another bug report related to hash joins from Øystein Grøvlen, with a fix suggested. See also his Bug #99934 - "Hash join adds columns to the hash table that is not needed." There is a lot of work ahead to improve the implementation of this new feature in MySQL 8.
• Bug #99935 - "innodb_doublewrite_files is not correct when innodb_buffer_pool_size > 1G". Just 2 files are created instead of 16 according to the manual. This bug was reported by Satya Bodapati.
• Bug #99943 - "Hash join does not work for Semijoin and Antijoin". This bug report from Tibor Korocz was "Verified", but later comments suggest that it's more like wrong expectations/interpretation of cases when the feature has to be used (it is supposed to be used instead of BNL, but not instead of semijoin materialization and subquery materialization). Let's wait and see how it ends up...
• Bug #99966 - "Switching to use NUMA-SMART Counter for statistical counters". Great bug report from Krunal Bauskar, with a patch suggested. I hope to get a NUMA system one day myself to understand the challenges and performance problems there better.  

So, that's it, my very last post in the "Fun with Bugs" series that started more than 7 years ago. The series where I listed most of the interesting bug reports I keep an eye on, since Bug #2. It was a long way with a lot of fun and a lot of (rarely appreciated) work in the process, but now my watch has ended. I am not going to try to micro manage MySQL bugs processing any more and finally let the MySQL Verification Team do their job without my regular attention. Good luck!

Percona had recently started to blog about bugs, so I am sure they will keep an eye and share lists of important bugs on a regular basis. They should really care more than I do these days.