Linux /proc Filesystem for MySQL DBAs - Part I, Basics

Happy New Year 2021, dear readers of my blog!

We used to have real winters at this time of the year. Not any more...

Among other good things that happened on December 31, 2020, I was informed that my talk "Linux /proc filesystem for MySQL DBAs" was accepted for FOSDEM 2021 MySQL devroom. So, it's time to get back to blogging that I abandoned for a while in favor of this YouTube channel, and share some details to refer to on my slides.

This is not my first talk or blog post in "Something for MySQL DBAs" series. There were some in the past, like these:

• "gdb tips and tricks for MySQL DBAs"
• "Using strace for MySQL Troubleshooting"
• "How lsof Utility May Help MySQL DBAs"
• "Windows Tools for MySQL DBAs: Basic Minidump Analysis"
• ...  and so on
  

My colleague once said that eventually I have to end up with something like "/dev/null for MySQL DBAs" kind of talk. I am not yet there, but I still think that the more OS level tools DBAs know the better they can do the job.

The idea of talking about /proc filesystem was inspired by the fact that I use some files there on a regular basis while doing my job and by this great talk by Tanel Poder and his 0x.tools, a small set of open-source utilities for analyzing application performance on Linux based mostly on /proc sampling. 

I am planning to cover most part of the upcoming talk in a mini-series of three blog posts. In this post I am going to present some basic information about the /proc filesystem and some files and directories there that would be surely useful for MySQL DBAs, as well as (who could imagine) some related MySQL bug reports. In another one I'll discuss how threads in the process are represented in the /proc filesystem (as well as ps and top outputs). Finally in the third post I am going to show some use cases for the 0x.tools and summarize the benefits and use cases for /proc sampling approaches.

* * *

Basically, the proc filesystem is a pseudo-filesystem which provides an interface to kernel data structures. It is commonly mounted at /proc:   

openxs@ao756:~$ cat /etc/issue
Ubuntu 16.04.7 LTS \n \l

openxs@ao756:~$ mount | grep '/proc'
proc on /proc type proc (rw,nosuid,nodev,noexec,relatime)
...

Most  of it is read-only, but some files allow to change kernel variables. For the purpose of this discussion I skip mount options and most of the /proc/* files and proceed to /proc subdirectories, one per each process running, named after PID. I have the following mysqld process (of Percona Server 5.7.x) running:

openxs@ao756:~$ ps aux | grep mysqld
...
mysql    30580  0.7  8.1 746308 313984 ?       Sl   Jan02   9:55 /usr/sbin/mysqld --daemonize --pid-file=/var/run/mysqld/mysqld.pid

So there will be the /proc/30580 directory with the following content:

openxs@ao756:~$ ls -F /proc/30580
ls: cannot read symbolic link '/proc/30580/cwd': Permission denied
ls: cannot read symbolic link '/proc/30580/root': Permission denied
ls: cannot read symbolic link '/proc/30580/exe': Permission denied
attr/            cpuset   limits      net/           projid_map  stat
autogroup        cwd@     loginuid    ns/            root@       statm
auxv             environ  map_files/  numa_maps      sched       status
cgroup           exe@     maps        oom_adj        schedstat   syscall
clear_refs       fd/      mem         oom_score      sessionid   task/
cmdline          fdinfo/  mountinfo   oom_score_adj  setgroups   timers
comm             gid_map  mounts      pagemap        smaps       uid_map
coredump_filter  io       mountstats  personality    stack       wchan

I highlighted the files and directories I consider most useful. Note also "Permission denied" messages above that you may get while accessing some files in /proc, even related to the processes you own. You may still need root/sudo access (or belong to some dedicated group) to read them.

Now let me give short descriptions or hints about the content of the highlighted files and directories (see man 5 proc to get more details):

• task/[tid] - task subdirectory contains subdirectories of the form task/[tid], which contain corresponding information about each of the threads in the process, where tid is the kernel thread ID of the thread. In my case:
  
  openxs@ao756:~$ ls -F /proc/30580/task/
  2488/  30580/  30584/  30588/  30592/  30598/  30602/  30606/  31972/  3622/
  2493/  30581/  30585/  30589/  30593/  30599/  30603/  30607/  3618/
  2800/  30582/  30586/  30590/  30594/  30600/  30604/  30608/  3620/
  2805/  30583/  30587/  30591/  30597/  30601/  30605/  30609/  3621/
  
  Each of them in turn has files and subdirectories similar to those /proc/pid ones that I discuss below:
  
  openxs@ao756:~$ sudo ls -F /proc/30580/task/30592
  attr/       cpuset   io         net/           personality  smaps    wchan
  auxv        cwd@     limits     ns/            projid_map   stack
  cgroup      environ  loginuid   numa_maps      root@        stat
  children    exe@     maps       oom_adj        sched        statm
  clear_refs  fd/      mem        oom_score      schedstat    status
  cmdline     fdinfo/  mountinfo  oom_score_adj  sessionid    syscall
  comm        gid_map  mounts     pagemap        setgroups    uid_map
  
  
• cmdline - this read-only file contains the command line (argv) that the process wants you to see, as strings terminated by null bytes ('\0'). This is how you can check the content to see each string separately:
  
  openxs@ao756:~$ strings /proc/30580/cmdline
  /usr/sbin/mysqld
  --daemonize
  --pid-file=/var/run/mysqld/mysqld.pid
  
  
• comm - command name (up to 16 characters including the terminating null byte, longer values truncated) associated with the process. In my case:
  
  openxs@ao756:~$ cat /proc/30580/comm
  mysqld
  
  Individual threads can set different comm values. There is a useful feature request for MySQL threads to be named according to their role. It is Bug #70858 - "Set thread name" by Daniël van Eeden.
  
  
• coredump_filter - this file can be used to control which memory segments are written to the core dump file in the event that a core dump is performed for the process with the corresponding PID. The value in the file is a bit mask of memory mapping types:

  bit 0  Dump anonymous private mappings.
  bit 1  Dump anonymous shared mappings.
  bit 2  Dump file-backed private mappings.
  bit 3  Dump file-backed shared mappings.
  bit 4  Dump ELF headers.
  bit 5  Dump private huge pages.
  ...
  

  By default bits 0, 1, 4 and 5 are set, so we see hex value 33 in the file:
  
  openxs@ao756:~$ cat /proc/30580/coredump_filter
  00000033
  
  We can control core dump size to some extent by writing to this file. Other, way more important files in /proc that are related to core dumps are presented in man 5 core and in other sources. Read them to decode, for example, this output that is typical for systemd-based systems (and do not look for the core.* files related to the mysqld process in the datadir desperately after that):
  
  openxs@ao756:~$ cat /proc/sys/kernel/core_pattern
  |/usr/share/apport/apport %p %s %c %d %P %E
  
  
• environ - this file contains the initial environment that was set when the currently executing program was started. The entries are separated by null bytes, so you can check them like this:
  
  openxs@ao756:~$ sudo strings /proc/30580/environ
  LANG=en_US.UTF-8
  ...
  LC_TIME=uk_UA.UTF-8
  PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin
  HOME=/nonexistent
  LOGNAME=mysql
  USER=mysql
  SHELL=/bin/false
  STARTTIMEOUT=120
  STOPTIMEOUT=600
  LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libjemalloc.so.1
  
  Note the last 3 variables above. They show systemd timeouts for the unit and jemalloc preloaded.
  
  
• fd/ - this subdirectory contains one entry for each file which the process has open. The name is its file descriptor and it is a symbolic link to the actual file:
  
  openxs@ao756:~$ sudo ls -l /proc/30580/fd/
  total 0
  lr-x------ 1 mysql mysql 64 Jan  5 19:09 0 -> /dev/null
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 1 -> socket:[822912]
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 10 -> /var/lib/mysql/ib_logfile1
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 11 -> /var/lib/mysql/ibdata1
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 12 -> /var/lib/mysql/xb_doublewrite
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 13 -> /tmp/ibGEsYuO (deleted)
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 14 -> /var/lib/mysql/ibtmp1
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 15 -> /var/lib/mysql/sbtest/sbtest3.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 16 -> /var/lib/mysql/mysql/plugin.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 17 -> /var/lib/mysql/mysql/gtid_executed.ibd
  l-wx------ 1 mysql mysql 64 Jan  5 19:09 18 -> /var/lib/mysql/ao756-bin.000089
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 19 -> socket:[822935]
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 2 -> socket:[822912]
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 20 -> socket:[822936]
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 21 -> /var/lib/mysql/mysql/server_cost.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 22 -> /var/lib/mysql/mysql/engine_cost.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 23 -> /var/lib/mysql/mysql/db.MYI
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 24 -> /var/lib/mysql/mysql/db.MYD
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 25 -> /var/lib/mysql/mysql/user.MYI
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 26 -> /var/lib/mysql/mysql/user.MYD
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 27 -> /var/lib/mysql/mysql/event.MYI
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 28 -> /var/lib/mysql/mysql/event.MYD
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 29 -> /var/lib/mysql/mysql/time_zone_leap_second.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 3 -> /var/lib/mysql/ao756-bin.index
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 30 -> /var/lib/mysql/mysql/time_zone_name.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 31 -> /var/lib/mysql/mysql/time_zone.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 32 -> /var/lib/mysql/mysql/time_zone_transition_type.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 33 -> /var/lib/mysql/mysql/time_zone_transition.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 34 -> /var/lib/mysql/mysql/innodb_table_stats.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 35 -> /var/lib/mysql/sbtest/sbtest2.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 36 -> /var/lib/mysql/sbtest/sbtest4.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 39 -> /var/lib/mysql/sbtest/sbtest1.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 4 -> /var/lib/mysql/sbtest/sbtest5.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 40 -> /var/lib/mysql/mysql/servers.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 41 -> /var/lib/mysql/mysql/slave_master_info.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 42 -> /var/lib/mysql/mysql/slave_relay_log_info.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 43 -> /var/lib/mysql/mysql/slave_worker_info.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 45 -> /var/lib/mysql/mysql/innodb_index_stats.ibd
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 5 -> /var/lib/mysql/ib_logfile0
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 6 -> /tmp/ibmKNTQP (deleted)
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 7 -> /tmp/ib2GbIR1 (deleted)
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 8 -> /tmp/ibME5wSd (deleted)
  lrwx------ 1 mysql mysql 64 Jan  5 19:09 9 -> /tmp/ibyiPjXB (deleted)
  
  In the above we see stderr (descriptor 2) is pointing out to socket:[822912]. We can get some more information about this inode in /proc/net and in other sources:
  
  openxs@ao756:~$ strings /proc/net/unix | grep 822912
  0000000000000000: 00000003 00000000 00000000 0001 03 822912
  openxs@ao756:~$ sudo netstat -n --program | grep 822912
  unix  3      [ ]         STREAM     CONNECTED     822912   30580/mysqld
  
  The information in fd/ is similar to what you may get from lsof, but it is "always there" while lsof must be installed separately.
  
  
• fdinfo/ - files in this subdirectory provide more information about the corresponding file descriptor. Let's check 3 -> /var/lib/mysql/ao756-bin.index:
  
  openxs@ao756:~$ sudo cat /proc/30580/fdinfo/3
  pos:    1691
  flags:  0100002
  mnt_id: 24
  openxs@ao756:~$ sudo ls -l /var/lib/mysql/ao756-bin.index
  -rw-r----- 1 mysql mysql 1691 Jan  2 17:35 /var/lib/mysql/ao756-bin.index
  
  and then some InnoDB file, for example, 5 -> /var/lib/mysql/ib_logfile0:
  
  openxs@ao756:~$ sudo cat /proc/30580/fdinfo/5
  pos:    0
  flags:  0100002
  mnt_id: 24
  lock:   1: POSIX  ADVISORY  WRITE 30580 fc:01:11143169 0 EOF
  openxs@ao756:~$ cat /proc/30580/mountinfo | grep ^'24 '
  24 0 252:1 / / rw,relatime shared:1 - ext4 /dev/mapper/ubuntu--vg-root rw,errors=remount-ro,data=ordered
  
  As we can see the details include file offset (pos), octal number that displays the file access mode and file status flags (flags), id of the mountpoint for the file that we were able to find in /proc/$PID/mountinfo (/ file system in this case), and some other details depending on file type. For redo log we see lock record with the details about the write lock set on this file by the mysqld process. You can see it among all the file locks in /proc/locks too:
  
  openxs@ao756:~$ cat /proc/locks | grep fc:01:11143169
  30: POSIX  ADVISORY  WRITE 30580 fc:01:11143169 0 EOF
  
  See "File locking in Linux" by Victor Gaydov for much more details.
  
  
• io - this file contains I/O statistics for the process, for example:
  
  openxs@ao756:~$ sudo cat /proc/30580/io
  rchar: 198026951
  wchar: 2365236669
  syscr: 8014
  syscw: 92558
  read_bytes: 49184768
  write_bytes: 3394945024
  cancelled_write_bytes: 171876352
  
  Here we can see number of characters read and written (maybe just to the pagecache, without physical I/O), number of system calls to read and write, number of bytes read and written to the storage and, in cancelled_write_bytes, number of written bytes which this process caused to not happen, by truncating pagecache (when deleting the file created, for example).
  
  It's important to note that the same information is properly tracked for the individual threads. For example, this is the page cleaner thread of our Percona Server (more on why I am so sure while comm is not set is in the next post):
  
  openxs@ao756:~$ sudo cat /proc/30580/task/30592/io
  rchar: 0
  wchar: 912518825
  syscr: 0
  syscw: 2092
  read_bytes: 0
  write_bytes: 1813786624
  cancelled_write_bytes: 0
  
  and we can see that it did notable share of all writes.
  
  
• limits - this file provides the details about the actual resource limits for the process:
  
  This is my personal most often used file in the /proc filesystem, at least while working on support issues with customers.
  
  openxs@ao756:~$ cat /proc/30580/limits
  Limit                     Soft Limit           Hard Limit           Units
  Max cpu time              unlimited            unlimited            seconds
  Max file size             unlimited            unlimited            bytes
  Max data size             unlimited            unlimited            bytes
  Max stack size            8388608              unlimited            bytes
  Max core file size        0                    unlimited            bytes
  Max resident set          unlimited            unlimited            bytes
  Max processes             14893                14893                processes
  Max open files            1024                 4096                 files
  Max locked memory         65536                65536                bytes
  Max address space         unlimited            unlimited            bytes
  Max file locks            unlimited            unlimited            locks
  Max pending signals       14893                14893                signals
  Max msgqueue size         819200               819200               bytes
  Max nice priority         0                    0
  Max realtime priority     0                    0
  Max realtime timeout      unlimited            unlimited            us
  
  I highlighted rows most imortant in the context of MySQL server - limit on number of processes (and thus threads and connections, thread pool aside) and limit on number of open files. Users often assume values very different from those actually used, for various reasons... Note that on modern kernels one does NOT need root/sudo to check the limits of process that belongs to a different user.
  
  
• maps - this file contains currently mapped memory regions and their access permissions. It is also very imortant to check in case of MySQL server. Consider the following examle:
  
  openxs@ao756:~$ sudo cat /proc/30580/maps | more
  00400000-019d6000 r-xp 00000000 fc:01 12066751                           /usr/sbin/mysqld
  01bd6000-01cb7000 r--p 015d6000 fc:01 12066751                           /usr/sbin/mysqld
  01cb7000-01d67000 rw-p 016b7000 fc:01 12066751                           /usr/sbin/mysqld
  01d67000-01e48000 rw-p 00000000 00:00 0
  7fe19d400000-7fe1a2000000 rw-p 00000000 00:00 0
  ...
  7fe1caa17000-7fe1caa4a000 r-xp 00000000 fc:01 12064860                   /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
  7fe1caa4a000-7fe1cac4a000 ---p 00033000 fc:01 12064860                   /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
  7fe1cac4a000-7fe1cac4c000 r--p 00033000 fc:01 12064860                   /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
  7fe1cac4c000-7fe1cac4d000 rw-p 00035000 fc:01 12064860                   /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
  ...
  7fe1cae33000-7fe1cae38000 rw-s 00000000 00:0d 822928                     /[aio]
  (deleted)
  7fe1cae38000-7fe1cae42000 rw-p 00000000 00:00 0
  7fe1cae42000-7fe1cae44000 rw-s 00000000 00:0d 822929                     /[aio]
  (deleted)
  ...
  7fe1cae73000-7fe1cae74000 r--p 00025000 fc:01 1311186                    /lib/x86_64-linux-gnu/ld-2.23.so
  7fe1cae74000-7fe1cae75000 rw-p 00026000 fc:01 1311186                    /lib/x86_64-linux-gnu/ld-2.23.so
  7fe1cae75000-7fe1cae76000 rw-p 00000000 00:00 0
  7ffe2f559000-7ffe2f57d000 rw-p 00000000 00:00 0                          [stack]
  7ffe2f5c6000-7ffe2f5c8000 r--p 00000000 00:00 0                          [vvar]
  7ffe2f5c8000-7ffe2f5ca000 r-xp 00000000 00:00 0                          [vdso]
  ffffffffff600000-ffffffffff601000 r-xp 00000000 00:00 0                  [vsyscall]
  
  The format of the output lines is simple: range of addresses in the address space of the process, permissions, offset, device (major:minor), inode and pathname. Permissions r/w/x have usual meanings, while s means shared and p - private. Offset represents offset in the related file, if any. Device represents where the inode is located amd inode corresponds the given pathname (inode 0 is for the memory region). The pathname field will usually be the file that is backing the mapping. This is the huge memory-mapped file for the Galera cache, for examle:
  
  7ed567fff000-7fd568000000 rw-s 00000000 fd:0f 2147676724                 /home/mariadb-data/galera.cache
  
  See also map_files/* for memory-mapped files for the process:
  
  openxs@ao756:~$ sudo ls -l /proc/30580/map_files/ | more
  total 0
  lr-------- 1 mysql mysql 64 Jan  6 16:42 1bd6000-1cb7000 -> /usr/sbin/mysqld
  lr-------- 1 mysql mysql 64 Jan  6 16:42 1cb7000-1d67000 -> /usr/sbin/mysqld
  lr-------- 1 mysql mysql 64 Jan  6 16:42 400000-19d6000 -> /usr/sbin/mysqld
  lr-------- 1 mysql mysql 64 Jan  6 16:42 7fe1c01ed000-7fe1c01f8000 -> /lib/x86_6
  4-linux-gnu/libnss_files-2.23.so
  lr-------- 1 mysql mysql 64 Jan  6 16:42 7fe1c01f8000-7fe1c03f7000 -> /lib/x86_6
  4-linux-gnu/libnss_files-2.23.so
  ...
  
  
• numa_maps - this file displays information about a process's NUMA memory policy and allocation. Each line contains information about a memory range used by the process, displaying - among other information - the effective memory policy for that memory range and on which nodes the pages have been allocated. Consider the following example (single node only, sorry):
  
  openxs@ao756:~$ sudo cat /proc/30580/numa_maps | more
  00400000 default file=/usr/sbin/mysqld mapped=1551 active=1061 N0=1551 kernelpagesize_kB=4
  01bd6000 default file=/usr/sbin/mysqld anon=37 dirty=1 mapped=99 swapcache=36 active=0 N0=99 kernelpagesize_kB=4
  01cb7000 default file=/usr/sbin/mysqld anon=46 dirty=45 mapped=71 swapcache=1 active=0 N0=71 kernelpagesize_kB=4
  01d67000 default anon=115 dirty=93 swapcache=22 active=2 N0=115 kernelpagesize_kB=4
  ...
  7fe1caa17000 default file=/usr/lib/x86_64-linux-gnu/libjemalloc.so.1 mapped=14 mapmax=2 N0=14 kernelpagesize_kB=4
  7fe1caa4a000 default file=/usr/lib/x86_64-linux-gnu/libjemalloc.so.1
  7fe1cac4a000 default file=/usr/lib/x86_64-linux-gnu/libjemalloc.so.1 anon=2 dirty=1 swapcache=1 active=0 N0=2 kernelpagesize_kB=4
  7fe1cac4c000 default file=/usr/lib/x86_64-linux-gnu/libjemalloc.so.1 anon=1 dirty=1 active=0 N0=1 kernelpagesize_kB=4
  ...
  7fe1cae71000 default file=/[aio]\040(deleted)
  7fe1cae72000 default anon=1 swapcache=1 active=0 N0=1 kernelpagesize_kB=4
  7fe1cae73000 default file=/lib/x86_64-linux-gnu/ld-2.23.so anon=1 swapcache=1 ac
  tive=0 N0=1 kernelpagesize_kB=4
  7fe1cae74000 default file=/lib/x86_64-linux-gnu/ld-2.23.so anon=1 dirty=1 active
  =0 N0=1 kernelpagesize_kB=4
  7fe1cae75000 default anon=1 dirty=1 active=0 N0=1 kernelpagesize_kB=4
  7ffe2f559000 default stack anon=32 dirty=30 swapcache=2 active=3 N0=32 kernelpag
  esize_kB=4
  7ffe2f5c6000 default
  7ffe2f5c8000 default
  
  In the above we see starting address of the range, policy (all default in my case), NUMA node (N0 in my case) for the allocation and number of pages allocated (see N0=1551), dirty pages (dirty=30), number of pages that have an associated entry on a swap device (swapcache=2) etc. See also man 7 numa for many more details.
  
  
• oom_score - this file displays the current score that the kernel gives to this process for the purpose of selecting a process for the OOM-killer. A higher score means that the process is more likely to be selected by the OOM-killer. The range is basically 0-1000, where 1000 basically means the process uses all the memory. Process with the value 0 in this file will never be killed. My server has low enough value:
  
  openxs@ao756:~$ sudo cat /proc/30580/oom_score
  40
  
  
• oom_score_adj - this file can be used to adjust the OOM score used to select which process gets killed in out-of-memory conditions. Each candidate task is assigned a value ranging from 0 (never kill) to 1000 (always kill) to determine which process is targeted. The value of oom_score_adj is added to the OOM score before it is used to determine which task to kill. Acceptable values range from -1000 (OOM_SCORE_ADJ_MIN) to +1000 (OOM_SCORE_ADJ_MAX). This allows user space to control the preference for OOM-killing, ranging from always preferring a certain task or completely disabling it from OOM killing.
  
  In practice you just write large negative valuer into the file:
  
  openxs@ao756:~$ sudo cat /proc/30580/oom_score
  40
  openxs@ao756:~$ sudo cat /proc/30580/oom_score_adj
  0
  openxs@ao756:~$ sudo echo -100 > /proc/30580/oom_score_adj
  -bash: /proc/30580/oom_score_adj: Permission denied
  openxs@ao756:~$ sudo su -
  root@ao756:~# echo -100 > /proc/30580/oom_score_adj
  root@ao756:~# exit
  logout
  openxs@ao756:~$ sudo cat /proc/30580/oom_score_adj
  -100
  openxs@ao756:~$ sudo cat /proc/30580/oom_score
  0
  
  In my case I had to become root to be able to adjust the score. Read this nice blog post, "MySQL, OOM Killer, and everything related", for more details.
  
  
• sched - scheduler related statistcis for the process. Not that it is much documented (see some hints here and there), but the output is more or less clear:
  
  openxs@ao756:~$ sudo cat /proc/30580/sched
  mysqld (30580, #threads: 37)
  -------------------------------------------------------------------
  se.exec_start                                :     259734254.219078
  se.vruntime                                  :        102780.674970
  se.sum_exec_runtime                          :           354.092211
  se.statistics.sum_sleep_runtime              :      38046805.925355
  se.statistics.wait_start                     :             0.000000
  se.statistics.sleep_start                    :     259734254.219078
  se.statistics.block_start                    :             0.000000
  se.statistics.sleep_max                      :      11587559.290106
  se.statistics.block_max                      :          2466.143746
  se.statistics.exec_max                       :             4.005223
  se.statistics.slice_max                      :             2.790630
  se.statistics.wait_max                       :            22.567269
  se.statistics.wait_sum                       :            85.791532
  se.statistics.wait_count                     :                  748
  se.statistics.iowait_sum                     :          5117.788260
  se.statistics.iowait_count                   :                  524
  se.nr_migrations                             :                   50
  se.statistics.nr_migrations_cold             :                    0
  se.statistics.nr_failed_migrations_affine    :                    0
  se.statistics.nr_failed_migrations_running   :                   10
  se.statistics.nr_failed_migrations_hot       :                    5
  se.statistics.nr_forced_migrations           :                    0
  se.statistics.nr_wakeups                     :                  658
  se.statistics.nr_wakeups_sync                :                  104
  se.statistics.nr_wakeups_migrate             :                   42
  se.statistics.nr_wakeups_local               :                  468
  se.statistics.nr_wakeups_remote              :                  190
  se.statistics.nr_wakeups_affine              :                   22
  se.statistics.nr_wakeups_affine_attempts     :                   55
  se.statistics.nr_wakeups_passive             :                    0
  se.statistics.nr_wakeups_idle                :                    0
  avg_atom                                     :             0.477857
  avg_per_cpu                                  :             7.081844
  nr_switches                                  :                  741
  nr_voluntary_switches                        :                  659
  nr_involuntary_switches                      :                   82
  se.load.weight                               :                 1024
  se.avg.load_sum                              :              6000742
  se.avg.util_sum                              :                22528
  se.avg.load_avg                              :                  125
  se.avg.util_avg                              :                    0
  se.avg.last_update_time                      :      259734254219078
  policy                                       :                    0
  prio                                         :                  120
  clock-delta                                  :                   60
  mm->numa_scan_seq                            :                    0
  numa_pages_migrated                          :                    0
  numa_preferred_nid                           :                   -1
  total_numa_faults                            :                    0
  current_node=0, numa_group_id=0
  numa_faults node=0 task_private=0 task_shared=0 group_private=0 group_shared=0
  
  and you can reset most counters by writing 0 to the file:
  
  openxs@ao756:~$ sudo su -
  root@ao756:~# echo 0 > /proc/30580/sched
  root@ao756:~# exit
  logout
  openxs@ao756:~$ sudo cat /proc/30580/sched
  mysqld (30580, #threads: 37)
  -------------------------------------------------------------------
  se.exec_start                                :     259734254.219078
  se.vruntime                                  :        102780.674970
  se.sum_exec_runtime                          :           354.092211
  se.statistics.sum_sleep_runtime              :             0.000000
  se.statistics.wait_start                     :             0.000000
  se.statistics.sleep_start                    :             0.000000
  se.statistics.block_start                    :             0.000000
  se.statistics.sleep_max                      :             0.000000
  se.statistics.block_max                      :             0.000000
  se.statistics.exec_max                       :             0.000000
  se.statistics.slice_max                      :             0.000000
  se.statistics.wait_max                       :             0.000000
  se.statistics.wait_sum                       :             0.000000
  se.statistics.wait_count                     :                    0
  se.statistics.iowait_sum                     :             0.000000
  se.statistics.iowait_count                   :                    0
  se.nr_migrations                             :                   50
  se.statistics.nr_migrations_cold             :                    0
  se.statistics.nr_failed_migrations_affine    :                    0
  se.statistics.nr_failed_migrations_running   :                    0
  se.statistics.nr_failed_migrations_hot       :                    0
  se.statistics.nr_forced_migrations           :                    0
  se.statistics.nr_wakeups                     :                    0
  se.statistics.nr_wakeups_sync                :                    0
  se.statistics.nr_wakeups_migrate             :                    0
  se.statistics.nr_wakeups_local               :                    0
  se.statistics.nr_wakeups_remote              :                    0
  se.statistics.nr_wakeups_affine              :                    0
  se.statistics.nr_wakeups_affine_attempts     :                    0
  se.statistics.nr_wakeups_passive             :                    0
  se.statistics.nr_wakeups_idle                :                    0
  avg_atom                                     :             0.477857
  avg_per_cpu                                  :             7.081844
  nr_switches                                  :                  741
  nr_voluntary_switches                        :                  659
  nr_involuntary_switches                      :                   82
  se.load.weight                               :                 1024
  se.avg.load_sum                              :              6000742
  se.avg.util_sum                              :                22528
  se.avg.load_avg                              :                  125
  se.avg.util_avg                              :                    0
  se.avg.last_update_time                      :      259734254219078
  policy                                       :                    0
  prio                                         :                  120
  clock-delta                                  :                   77
  mm->numa_scan_seq                            :                    0
  numa_pages_migrated                          :                    0
  numa_preferred_nid                           :                   -1
  total_numa_faults                            :                    0
  current_node=0, numa_group_id=0
  numa_faults node=0 task_private=0 task_shared=0 group_private=0 group_shared=0
  
  then run some load and check the impact. The values are displayed in milliseconds; they’re tracked in nanoseconds, and scaled by one million.
  
  
• smaps - this file shows memory consumption for each of the process's mappings (see maps above). For each mapping there is a series of lines:
  
  openxs@ao756:~$ sudo cat /proc/30580/smaps | more
  00400000-019d6000 r-xp 00000000 fc:01 12066751                           /usr/sbin/mysqld
  Size:              22360 kB
  Rss:                6204 kB
  Pss:                6204 kB
  Shared_Clean:          0 kB
  Shared_Dirty:          0 kB
  Private_Clean:      6204 kB
  Private_Dirty:         0 kB
  Referenced:         5704 kB
  Anonymous:             0 kB
  AnonHugePages:         0 kB
  Shared_Hugetlb:        0 kB
  Private_Hugetlb:       0 kB
  Swap:                  0 kB
  SwapPss:               0 kB
  KernelPageSize:        4 kB
  MMUPageSize:           4 kB
  Locked:                0 kB
  VmFlags: rd ex mr mw me dw sd
  01bd6000-01cb7000 r--p 015d6000 fc:01 12066751                           /usr/sb
  in/mysqld
  Size:                900 kB
  ...
  
  These lines show the size of the mapping, the amount of the mapping that is currently resident in RAM ("Rss"), the process's proportional share of this mapping ("Pss"), the number of clean and dirty shared pages in the mapping, and the number of clean and dirty private pages in the mapping. "Referenced" indicates the amount of memory currently marked as referenced or accessed. "Anonymous" shows the amount of memory that does not belong to any file. "Swap" shows how much would-be-anonymous memory is also used, but out on swap, "VmFlags" represents the kernel flags associated with the virtual memory area as a set of two character flags, and so on.
  
  
• stack - this file provides a symbolic trace of the function calls in this process's kernel stack. Here is what I have for the process and one of its threads (actually MySQL server's main thread and page cleaner thread as we'll see in the next post in this series):
  
  openxs@ao756:~$ sudo cat /proc/30580/stack
  [<ffffffff81233b94>] poll_schedule_timeout+0x44/0x70
  [<ffffffff81235223>] do_sys_poll+0x4b3/0x570
  [<ffffffff81235329>] do_restart_poll+0x49/0x80
  [<ffffffff81097155>] sys_restart_syscall+0x25/0x30
  [<ffffffff81869c5b>] entry_SYSCALL_64_fastpath+0x22/0xd0
  [<ffffffffffffffff>] 0xffffffffffffffff
  openxs@ao756:~$ sudo cat /proc/30580/task/30592/stack
  [<ffffffff811097c0>] futex_wait_queue_me+0xc0/0x120
  [<ffffffff8110a4f6>] futex_wait+0x116/0x270
  [<ffffffff8110ca60>] do_futex+0x120/0x5a0
  [<ffffffff8110cf61>] SyS_futex+0x81/0x180
  [<ffffffff81869c5b>] entry_SYSCALL_64_fastpath+0x22/0xd0
  [<ffffffffffffffff>] 0xffffffffffffffff
  
  For other threads we'll see more interesting stacks when they are waiting for disk etc. Stay tuned! Note that if you'll check wchan file for the process:
  
  openxs@ao756:~$ sudo strings /proc/30580/wchan
  poll_schedule_timeout
  
  we'll see the top line of the output above (hex values aside) as a null-terminated string. This is a "wait channel", the symbolic name corresponding to the location in the kernel where the process is sleeping.
  
  
• stat - status information about the process, used by ps. This file is a set of fields separated by spaces, so it is easy to parse by some script or load into the database. Domas Mituzas once reported a bug, Bug #72027 - "LOAD_FILE() does not work on dynamic files" (fixed only in MySQL 8.0.15+), based on failed attempts to apply LOAD_DATA() to stat file in /proc.
  
  Output starts with PID and comm fields, followed by the process state and other details. For example:
  
  openxs@ao756:~$ cat /proc/30580/stat
  30580 (mysqld) S 1 30579 30579 0 -1 4194368 1007759 0 360 0 68598 13573 0 0 20 0 37 0 218060678 764219392 76109 18446744073709551615 1 1 0 0 0 0 540679 12288 1768 0 0 0 17 1 0 0 513 0 0 0 0 0 0 0 0 0 0
  
  The value of state is a single character:
  
  • R  Running
  • S  Sleeping in an interruptible wait
  • D  Waiting in uninterruptible disk sleep
  • Z  Zombie
  • T  Stopped (on a signal)
  • t  Tracing stop
  • ... some other values were also used in the past
    
  Then we see identifiers of the parent process and process group, followed by the session id and controlling terminal (-1), and so on. Field 20 is the number of threads in the process, fields 23 and 24 virtual memory size and resident set size, in bytes. Just read the manual if you plan to interpretad these lines somewhere. Note that sudo/root is not needed to see the details about the process of the other user.
  
  
• statm - this file provides information about memory usage, measured in (4K) pages:
  
  openxs@ao756:~$ cat /proc/30580/statm
  186577 76109 2515 5590 0 169800 0
  
  Again we see just space-separated fields, easy to parse. The fileds are total size, resident, shared, text (code) size, next one (former lib) is always 0, then data + stack size and dirty pages. Some of these values may be inaccurate because of internal kernel optimizations applied.
  
  
• status -  this file provides much of the information from stat and statm in a format that's easier for humans to read. For example:
  openxs@ao756:~$ cat /proc/30580/status
  Name:   mysqld
  State:  S (sleeping)
  Tgid:   30580
  Ngid:   0
  Pid:    30580
  PPid:   1
  TracerPid:      0
  Uid:    116     116     116     116
  Gid:    125     125     125     125
  FDSize: 128
  Groups: 125
  NStgid: 30580
  NSpid:  30580
  NSpgid: 30579
  NSsid:  30579
  VmPeak:   746308 kB
  VmSize:   746308 kB
  VmLck:         0 kB
  VmPin:         0 kB
  VmHWM:    328248 kB
  VmRSS:    304436 kB
  VmData:   679056 kB
  VmStk:       144 kB
  VmExe:     22360 kB
  VmLib:      7784 kB
  VmPTE:      1036 kB
  VmPMD:        16 kB
  VmSwap:    13256 kB
  HugetlbPages:          0 kB
  Threads:        37
  SigQ:   0/14893
  SigPnd: 0000000000000000
  ShdPnd: 0000000000000000
  SigBlk: 0000000000084007
  SigIgn: 0000000000003000
  SigCgt: 00000001800006e8
  CapInh: 0000000000000000
  CapPrm: 0000000000000000
  CapEff: 0000000000000000
  CapBnd: 0000003fffffffff
  CapAmb: 0000000000000000
  Seccomp:        0
  Speculation_Store_Bypass:       thread vulnerable
  Cpus_allowed:   ff
  Cpus_allowed_list:      0-7
  Mems_allowed:   00000000,00000001
  Mems_allowed_list:      0
  voluntary_ctxt_switches:        687
  nonvoluntary_ctxt_switches:     82
  
  The values are supposed to be clear for a reader. If not - just check man 5 proc.
  
  
• syscall - this file exposes the system call number and argument registers for the system call currently being executed by the process, followed by the values of the stack pointer and program counter registers. The values of all six argument registers are exposed, although most system calls use fewer registers. If the process is blocked, but not in a system call, thensystem call number is -1, followed by just the values of the stack pointer and program counter. If process is not blocked, then the file contains just the string "running". For example, this is my ad hoc poor man threads monitoring script of a kind applied to the mysqld process executing some sysbench load:
  
  openxs@ao756:~$ for dir in `ls /proc/30580/task`; do echo -n $dir': '; 2>/dev/null sudo cat /proc/$dir/syscall; done | more
  2389: 202 0x1db141c 0x80 0x834e8 0x0 0x1db1400 0x41a70 0x7fe1cace9fb0 0x7fe1ca807360
  2390: 202 0x1db141c 0x80 0x834e5 0x0 0x1db1400 0x41a70 0x7fe1c00e4fb0 0x7fe1ca807360
  2391: 202 0x1db141c 0x80 0x83505 0x0 0x1db1400 0x41a7d 0x7fe1c00a3fb0 0x7fe1ca807360
  2392: 202 0x1db141c 0x80 0x834fe 0x0 0x1db1400 0x41a7d 0x7fe1b6a39fb0 0x7fe1ca807360
  2393: 202 0x1db141c 0x80 0x83504 0x0 0x1db1400 0x41a7d 0x7fe1b6a7afb0 0x7fe1ca807360
  2394: 202 0x1db141c 0x80 0x83501 0x0 0x1db1400 0x41a7d 0x7fe1c0125fb0 0x7fe1ca807360
  2395: running
  2488: 202 0x1db141c 0x80 0x8351e 0x0 0x1db1400 0x41a8a 0x7fe1cadedfb0 0x7fe1ca807360
  2493: 202 0x1db141c 0x80 0x83518 0x0 0x1db1400 0x41a8a 0x7fe1cad2afb0 0x7fe1ca807360
  2800: 75 0x12 0x1 0x0 0x0 0x0 0x1db0870 0x7fe1c01e8f50 0x7fe1c876a8dd
  30580: 7 0x7fe1c13b9e98 0x2 0xffffffff 0x7fe1c84539d0 0x0 0x7fe1c8453700 0x7ffe2
  f57a590 0x7fe1c876880d
  30581: 128 0x7fe1c0bfed70 0x7fe1c0bfedf0 0x0 0x8 0x0 0x7ffe2f57a5d0 0x7fe1c0bfec
  c0 0x7fe1c86a3b36
  30582: 208 0x7fe1cae58000 0x1 0x100 0x7fe1c7c76000 0x7fe1b3bfe750 0x7fe1b3bff9c0
  ...
  
  Here you can see a running thread and various system calls for other threads. If only I could map numbers to something useful... Smart people can as you'll find out in the next posts.
  

Let me stop checking /proc at this stage, otherwise I'll end up with a yet another MySQL-illustrated manual page for /proc with a size of the large book chapter.

In the next post I am going to describe MySQL threads monitoring with /proc, ps and top sampling, based on the information presented here.

Installing the Latest MariaDB from the Repository on Debian 10 and Downgrading to Older Minor Version

 I had not written any new blog posts here since this one for quite a some time, for two reasons. First of all, I have another project to spend time on, not related to any software at all. Not that it is very successful so far, but I enjoy the process and the results... I was also a bit disappointed by the lack of reactions to some previous posts I considered really useful like this one on BCC tools or the other one on tracing the mutex locks.

Anyway, I write posts here mostly for myself to be used as references later, as it was proved by the sad experience over last 30 years or so that I can forget the solutions of both minor and serious problems I once successfully resolved... So I am going to document one of tests of this week when I had to downgrade MariaDB to some previous version on Debian 10 due to some regression bug. Yes, shit happens and there are regression bugs reported once in a while for MariaDB, all kindly marked with the "regression" label after checks.

I like to use Docker for such tests, so this time I used debian:buster from the official images, pulled and started bash there. I tried to follow this fine MariaDB KB article that is mostly correct, but miss some small details. So, this is what I did:

1. Starting fresh and executing the repository configuration script

openxs@ao756:~$ sudo docker run -it debian:buster bash
root@8af6489c0df8:/# curl -sS https://downloads.mariadb.com/MariaDB/mariadb_repo_setup | bash
bash: curl: command not found

I had to know better, We need to update and install curl package first:

root@8af6489c0df8:/# apt-get update
...
root@8af6489c0df8:/# apt-get install curl
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following additional packages will be installed:
  ca-certificates krb5-locales libcurl4 libgssapi-krb5-2 libk5crypto3
  libkeyutils1 libkrb5-3 libkrb5support0 libldap-2.4-2 libldap-common
  libnghttp2-14 libpsl5 librtmp1 libsasl2-2 libsasl2-modules
  libsasl2-modules-db libssh2-1 libssl1.1 openssl publicsuffix
Suggested packages:
  krb5-doc krb5-user libsasl2-modules-gssapi-mit
  | libsasl2-modules-gssapi-heimdal libsasl2-modules-ldap libsasl2-modules-otp
  libsasl2-modules-sql
The following NEW packages will be installed:
  ca-certificates curl krb5-locales libcurl4 libgssapi-krb5-2 libk5crypto3
  libkeyutils1 libkrb5-3 libkrb5support0 libldap-2.4-2 libldap-common
  libnghttp2-14 libpsl5 librtmp1 libsasl2-2 libsasl2-modules
  libsasl2-modules-db libssh2-1 libssl1.1 openssl publicsuffix
0 upgraded, 21 newly installed, 0 to remove and 0 not upgraded.
Need to get 5010 kB of archives.
After this operation, 11.9 MB of additional disk space will be used.
Do you want to continue? [Y/n]
...
done.
root@8af6489c0df8:/# curl -sS https://downloads.mariadb.com/MariaDB/mariadb_repo_setup | bash
[error] The following package is needed by the script, but not installed:
            apt-transport-https
        Please install and rerun the script.

OK, so let's install this one too:

root@8af6489c0df8:/# apt-get install apt-transport-https 
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following NEW packages will be installed:
  apt-transport-https
0 upgraded, 1 newly installed, 0 to remove and 0 not upgraded.
Need to get 149 kB of archives.
After this operation, 156 kB of additional disk space will be used.
Get:1 http://deb.debian.org/debian buster/main amd64 apt-transport-https all 1.8.2.1 [149 kB]
Fetched 149 kB in 0s (848 kB/s)
debconf: delaying package configuration, since apt-utils is not installed
Selecting previously unselected package apt-transport-https.
(Reading database ... 7160 files and directories currently installed.)
Preparing to unpack .../apt-transport-https_1.8.2.1_all.deb ...
Unpacking apt-transport-https (1.8.2.1) ...
Setting up apt-transport-https (1.8.2.1) ...

root@8af6489c0df8:/# curl -sS https://downloads.mariadb.com/MariaDB/mariadb_repo_setup | bash
[info] Repository file successfully written to /etc/apt/sources.list.d/mariadb.list
[info] Adding trusted package signing keys...
[info] Running apt-get update...
[info] Done adding trusted package signing keys

Now we are ready to continue with adding the repository for MariaDB 10.5.

2. Adding the repository

KB says we should start with adding software-properties-common package:

root@8af6489c0df8:/# apt-get install software-properties-common
Reading package lists... Done
...
0 upgraded, 71 newly installed, 0 to remove and 0 not upgraded.
Need to get 31.6 MB of archives.
After this operation, 139 MB of additional disk space will be used.
Do you want to continue? [Y/n]
...
Setting up software-properties-common (0.96.20.2-2) ...
Processing triggers for systemd (241-7~deb10u4) ...
Processing triggers for libc-bin (2.28-10) ...
Processing triggers for dbus (1.12.20-0+deb10u1) ...
root@8af6489c0df8:/#

Now we can add the repository:

root@8af6489c0df8:/# add-apt-repository 'deb [arch=amd64,arm64,ppc64el] http://sfo1.mirrors.digitalocean.com/mariadb/repo/10.4/debian buster main'

root@8af6489c0df8:/# apt-get update
Hit:1 http://security.debian.org/debian-security buster/updates InRelease
Hit:2 http://deb.debian.org/debian buster InRelease
Hit:3 http://deb.debian.org/debian buster-updates InRelease
Get:5 http://sfo1.mirrors.digitalocean.com/mariadb/repo/10.4/debian buster InRelease [4635 B]
Hit:4 https://downloads.mariadb.com/MariaDB/mariadb-10.5/repo/debian buster InRelease
Hit:6 https://downloads.mariadb.com/Tools/debian buster InRelease
Get:7 https://dlm.mariadb.com/repo/maxscale/latest/debian buster InRelease [3515 B]
Get:8 http://sfo1.mirrors.digitalocean.com/mariadb/repo/10.4/debian buster/main amd64 Packages [29.1 kB]
Get:9 http://sfo1.mirrors.digitalocean.com/mariadb/repo/10.4/debian buster/main ppc64el Packages [19.7 kB]
Get:10 http://sfo1.mirrors.digitalocean.com/mariadb/repo/10.4/debian buster/main arm64 Packages [19.8 kB]
Fetched 76.7 kB in 2s (50.7 kB/s)
Reading package lists... Done

Note that I asked for 10.4 and got 10.5 in the outputs and on one of the next steps. One day I'll figure out why it was so...

3. Importing the MariaDB GPG public key

KB articles says I have to install dirmngr first starting from Debian 9, so I did it:

root@8af6489c0df8:/# apt-get install dirmngr
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following additional packages will be installed:
  gnupg gnupg-l10n gnupg-utils gpg gpg-agent gpg-wks-client gpg-wks-server
  gpgconf gpgsm libassuan0 libksba8 libnpth0 pinentry-curses
Suggested packages:
  dbus-user-session pinentry-gnome3 tor parcimonie xloadimage scdaemon
  pinentry-doc
The following NEW packages will be installed:
  dirmngr gnupg gnupg-l10n gnupg-utils gpg gpg-agent gpg-wks-client
  gpg-wks-server gpgconf gpgsm libassuan0 libksba8 libnpth0 pinentry-curses
0 upgraded, 14 newly installed, 0 to remove and 0 not upgraded.
Need to get 7089 kB of archives.
After this operation, 14.9 MB of additional disk space will be used.
Do you want to continue? [Y/n]
...
Setting up gnupg (2.2.12-1+deb10u1) ...
Processing triggers for libc-bin (2.28-10) ...
root@8af6489c0df8:/#

Then I called apt-key as suggested by the KB article, with the key fingerprint listed there:

root@8af6489c0df8:/# apt-key adv --recv-keys --keyserver hkp://keyserver.ubuntu.com:80 0xF1656F24C74CD1D8
Executing: /tmp/apt-key-gpghome.h3pkEOHaEm/gpg.1.sh --recv-keys --keyserver hkp://keyserver.ubuntu.com:80 0xF1656F24C74CD1D8
...

4. Installing MariaDB packages with apt-get

Finally I can install what I need:

root@8af6489c0df8:/# apt-get install mariadb-server galera-4 mariadb-client libmariadb3 mariadb-backup mariadb-common
Reading package lists... Done
Building dependency tree
Reading state information... Done
The following additional packages will be installed:
  gawk libaio1 libcgi-fast-perl libcgi-pm-perl libdbd-mariadb-perl libdbi-perl
  libencode-locale-perl libfcgi-perl libgdbm-compat4 libgdbm6 libgpm2
  libhtml-parser-perl libhtml-tagset-perl libhtml-template-perl
  libhttp-date-perl libhttp-message-perl libio-html-perl
  liblwp-mediatypes-perl libmpfr6 libncurses6 libpcre2-8-0 libperl5.28
  libpopt0 libprocps7 libreadline5 libsigsegv2 libterm-readkey-perl
  libtimedate-perl liburi-perl libwrap0 lsof mariadb-client-10.5
  mariadb-client-core-10.5 mariadb-server-10.5 mariadb-server-core-10.5
  mysql-common netbase perl perl-modules-5.28 procps psmisc rsync socat
Suggested packages:
  gawk-doc libclone-perl libmldbm-perl libnet-daemon-perl
  libsql-statement-perl gdbm-l10n gpm libdata-dump-perl
  libipc-sharedcache-perl libwww-perl mailx mariadb-test netcat-openbsd
  perl-doc libterm-readline-gnu-perl | libterm-readline-perl-perl make
  libb-debug-perl liblocale-codes-perl openssh-client openssh-server
The following NEW packages will be installed:
  galera-4 gawk libaio1 libcgi-fast-perl libcgi-pm-perl libdbd-mariadb-perl
  libdbi-perl libencode-locale-perl libfcgi-perl libgdbm-compat4 libgdbm6
  libgpm2 libhtml-parser-perl libhtml-tagset-perl libhtml-template-perl
  libhttp-date-perl libhttp-message-perl libio-html-perl
  liblwp-mediatypes-perl libmariadb3 libmpfr6 libncurses6 libpcre2-8-0
  libperl5.28 libpopt0 libprocps7 libreadline5 libsigsegv2
  libterm-readkey-perl libtimedate-perl liburi-perl libwrap0 lsof
  mariadb-backup mariadb-client mariadb-client-10.5 mariadb-client-core-10.5
  mariadb-common mariadb-server mariadb-server-10.5 mariadb-server-core-10.5
  mysql-common netbase perl perl-modules-5.28 procps psmisc rsync socat
0 upgraded, 49 newly installed, 0 to remove and 0 not upgraded.
Need to get 44.7 MB of archives.
After this operation, 302 MB of additional disk space will be used.
Do you want to continue? [Y/n]
...

and start the service (called mariadb, as 10.5 is installed):

root@8af6489c0df8:/# service mariadb start
[ ok ] Starting MariaDB database server: mariadbd.
root@8af6489c0df8:/# mysql
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 12
Server version: 10.5.8-MariaDB-1:10.5.8+maria~buster mariadb.org binary 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)]>

So, this is how installation from the repository is done. Now what if we need to downgrade to some older minor version, let's say, to 10.5.6?

5. Downgrading to specific minor release

MariaDB KB article explains the process. For this you can create a repository with the URL hard-coded to that specific minor release. You can get these URLs from the MariaDB Foundation's archives. I tried:

root@8af6489c0df8:/# add-apt-repository 'deb [arch=amd64,arm64,ppc64el] http://archive.mariadb.org/mariadb-10.5.6/repo/debian/ buster main'

root@8af6489c0df8:/# apt-get update
Hit:1 http://deb.debian.org/debian buster InRelease
Hit:2 http://security.debian.org/debian-security buster/updates InRelease
Hit:3 http://deb.debian.org/debian buster-updates InRelease
Hit:6 http://sfo1.mirrors.digitalocean.com/mariadb/repo/10.4/debian buster InRelease
Get:4 https://archive.mariadb.org/mariadb-10.5.6/repo/debian buster InRelease [3154 B]
Hit:5 https://downloads.mariadb.com/MariaDB/mariadb-10.5/repo/debian buster InRelease
Hit:7 https://downloads.mariadb.com/Tools/debian buster InRelease
Get:8 https://dlm.mariadb.com/repo/maxscale/latest/debian buster InRelease [3515 B]
Get:9 https://archive.mariadb.org/mariadb-10.5.6/repo/debian buster/main amd64 Packages [36.0 kB]
Fetched 42.7 kB in 2s (23.6 kB/s)
Reading package lists... Done
N: Skipping acquire of configured file 'main/binary-ppc64el/Packages' as repository 'http://archive.mariadb.org/mariadb-10.5.6/repo/debian buster InRelease' doesn't support architecture 'ppc64el'
N: Skipping acquire of configured file 'main/binary-arm64/Packages' as repository 'http://archive.mariadb.org/mariadb-10.5.6/repo/debian buster InRelease' doesn't support architecture 'arm64'

and from the messages above it seems the repository is taken into account during update. The repository is added to the list:

root@8af6489c0df8:/# cat /etc/apt/sources.list
# deb http://snapshot.debian.org/archive/debian/20201117T000000Z buster main
deb http://deb.debian.org/debian buster main
# deb http://snapshot.debian.org/archive/debian-security/20201117T000000Z buster/updates main
deb http://security.debian.org/debian-security buster/updates main
# deb http://snapshot.debian.org/archive/debian/20201117T000000Z buster-updates main
deb http://deb.debian.org/debian buster-updates main
deb [arch=ppc64el,arm64,amd64] http://sfo1.mirrors.digitalocean.com/mariadb/repo/10.4/debian buster main
# deb-src [arch=ppc64el,arm64,amd64] http://sfo1.mirrors.digitalocean.com/mariadb/repo/10.4/debian buster main
deb [arch=amd64,ppc64el,arm64] http://archive.mariadb.org/mariadb-10.5.6/repo/debian/ buster main
# deb-src [arch=amd64,ppc64el,arm64] http://archive.mariadb.org/mariadb-10.5.6/repo/debian/ buster main
root@8af6489c0df8:/#

but upgrade suggested nothing to do:

root@8af6489c0df8:/# apt-get upgrade
Reading package lists... Done
Building dependency tree
Reading state information... Done
Calculating upgrade... Done
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.

The problem is that this added repository has no priority over existing one. You can find some related details on how to fix that in Debian Wiki, while I've got a hint from smart customer actually. I had to create a file in /etc/apt/preferences.d/ for that, to pin thew repository on top for all packages it provides:

root@8af6489c0df8:/# cat /etc/apt/preferences.d/mariadb.pref
Package: *
Pin: origin archive.mariadb.org
Pin-Priority: 1001
root@8af6489c0df8:/#

Now we can downgrade:

root@8af6489c0df8:/# apt-get upgrade
Reading package lists... Done
Building dependency tree
Reading state information... Done
Calculating upgrade... Done
The following packages will be DOWNGRADED:
  galera-4 libmariadb3 mariadb-backup mariadb-client mariadb-client-10.5
  mariadb-client-core-10.5 mariadb-common mariadb-server mariadb-server-10.5
  mariadb-server-core-10.5 mysql-common
0 upgraded, 0 newly installed, 11 downgraded, 0 to remove and 0 not upgraded.
Need to get 32.4 MB of archives.
After this operation, 158 kB of additional disk space will be used.
Do you want to continue? [Y/n]
 ...
Setting up galera-4 (26.4.5-buster) ...
Setting up mysql-common (1:10.5.6+maria~buster) ...
Setting up mariadb-common (1:10.5.6+maria~buster) ...
Setting up libmariadb3:amd64 (1:10.5.6+maria~buster) ...
Setting up mariadb-server-core-10.5 (1:10.5.6+maria~buster) ...
Setting up mariadb-client-core-10.5 (1:10.5.6+maria~buster) ...
Setting up mariadb-backup (1:10.5.6+maria~buster) ...
Setting up mariadb-client-10.5 (1:10.5.6+maria~buster) ...
Setting up mariadb-client (1:10.5.6+maria~buster) ...
Setting up mariadb-server-10.5 (1:10.5.6+maria~buster) ...
Installing new version of config file /etc/logrotate.d/mysql-server ...
debconf: unable to initialize frontend: Dialog
debconf: (No usable dialog-like program is installed, so the dialog based frontend cannot be used. at /usr/share/perl5/Debconf/FrontEnd/Dialog.pm line 76.)
debconf: falling back to frontend: Readline
invoke-rc.d: could not determine current runlevel
invoke-rc.d: policy-rc.d denied execution of stop.
invoke-rc.d: could not determine current runlevel
invoke-rc.d: policy-rc.d denied execution of start.
Setting up mariadb-server (1:10.5.6+maria~buster) ...
Processing triggers for systemd (241-7~deb10u4) ...
Processing triggers for libc-bin (2.28-10) ...

Note that Galera library is also downgraded. You may want to avoid that and list packages with priority in a less generic way. 

Now we can restart the service and check that downgrade really happened as expected:

root@8af6489c0df8:/# service mariadb restart
[ ok ] Stopping MariaDB database server: mariadbd.
[ ok ] Starting MariaDB database server: mariadbd.
root@8af6489c0df8:/# mysql
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 11
Server version: 10.5.6-MariaDB-1:10.5.6+maria~buster mariadb.org binary 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)]> show variables like '%version%';
+-----------------------------------+------------------------------------------+
| Variable_name                     | Value                                    |
+-----------------------------------+------------------------------------------+
| in_predicate_conversion_threshold | 1000                                     |
| innodb_version                    | 10.5.6                                   |
| protocol_version                  | 10                                       |
| slave_type_conversions            |                                          |
| system_versioning_alter_history   | ERROR                                    |
| system_versioning_asof            | DEFAULT                                  |
| tls_version                       | TLSv1.1,TLSv1.2,TLSv1.3                  |
| version                           | 10.5.6-MariaDB-1:10.5.6+maria~buster     |
| version_comment                   | mariadb.org binary distribution          |
| version_compile_machine           | x86_64                                   |
| version_compile_os                | debian-linux-gnu                         |
| version_malloc_library            | system                                   |
| version_source_revision           | 5b8ab1934a10966336e66751bc13fc66923b02f6 |
| version_ssl_library               | OpenSSL 1.1.1d  10 Sep 2019              |
| wsrep_patch_version               | wsrep_26.22                              |
+-----------------------------------+------------------------------------------+
15 rows in set (0.002 sec)

So, the roblem is resolved, and all steps are documented for me to find them later online easily. I rarely use packages, as I prefer to build myself from GitHub sources or at least rely on .tar.gz binaries and tools like MySQL Sandbox for my tests, so this excercise was really needed.

Now you know what I had to work on this week. In the video above you can check what I had for breakfast, if you are interested :)

To summarize:

1. MariaDB KB has a lot of details on installation and downgrade, but some of them are still missing.
2. In case of .deb pakages installed from the MariaDB repositories one has to pin specific packages to the repositories providing older versions (like those from http://archive.mariadb.org/) and to set higher priority for this repository in some .pref file in the /etc/apt/preferences.d/ directory.
3. Docker is useful for testing installation steps and anything in a clean environment. It's easy to miss some step otherwise.
4. Those who are interested in what exact regression bug forced me to consider and document downgrade procesude can just ask in comments :)
   

Stored Procedures Instrumentation in MariaDB 10.5

MariaDB 10.5 added a lot of instrumentation around stored procedures, functions and events along the lines of MySQL WL#5766. In this blog post I'll try to check how it works and provide some details that are still missing in the MariaDB Knowledge Base.

So, in frames of porting most of Performance Schema from MySQL 5.7 to MariaDB 10.5 four new types of Performance Schema objects were added:

MariaDB [performance_schema]> select distinct(object_type) from setup_objects; 
+-------------+
| object_type |
+-------------+
| EVENT       |
| FUNCTION    |
| PROCEDURE   |
| TABLE       |
| TRIGGER     |
+-------------+
5 rows in set (0,001 sec)

MariaDB [performance_schema]> select * from setup_objects where object_type != 'TABLE' and object_schema not in ('mysql', 'performance_schema', 'information_schema');
+-------------+---------------+-------------+---------+-------+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | ENABLED | TIMED |
+-------------+---------------+-------------+---------+-------+
| EVENT       | %             | %           | YES     | YES   |
| FUNCTION    | %             | %           | YES     | YES   |
| PROCEDURE   | %             | %           | YES     | YES   |
| TRIGGER     | %             | %           | YES     | YES   |
+-------------+---------------+-------------+---------+-------+
4 rows in set (0,001 sec)

MariaDB [performance_schema]> select version();
+----------------+
| version()      |
+----------------+
| 10.5.7-MariaDB |
+----------------+
1 row in set (0,000 sec)

As you can see from the above, these objects are enabled and timed by default in all databases besides system ones. Additional 20 instruments were also added, enabled and timed by default:

MariaDB [performance_schema]> select * from setup_instruments where name like 'statement/sp/%' or name like 'statement/scheduler%';
+---------------------------------+---------+-------+
| NAME                            | ENABLED | TIMED |
+---------------------------------+---------+-------+
| statement/sp/stmt               | YES     | YES   |
| statement/sp/set                | YES     | YES   |
| statement/sp/set_trigger_field  | YES     | YES   |
| statement/sp/jump               | YES     | YES   |
| statement/sp/jump_if_not        | YES     | YES   |
| statement/sp/freturn            | YES     | YES   |
| statement/sp/preturn            | YES     | YES   |
| statement/sp/hpush_jump         | YES     | YES   |
| statement/sp/hpop               | YES     | YES   |
| statement/sp/hreturn            | YES     | YES   |
| statement/sp/cpush              | YES     | YES   |
| statement/sp/cpop               | YES     | YES   |
| statement/sp/copen              | YES     | YES   |
| statement/sp/cclose             | YES     | YES   |
| statement/sp/cfetch             | YES     | YES   |
| statement/sp/agg_cfetch         | YES     | YES   |
| statement/sp/cursor_copy_struct | YES     | YES   |
| statement/sp/error              | YES     | YES   |
| statement/sp/set_case_expr      | YES     | YES   |
| statement/scheduler/event       | YES     | YES   |
+---------------------------------+---------+-------+
20 rows in set (0,002 sec)

In the above I do not see any direct match to most of statements used in stored procedures. You may be wondering what statement/sp/jump_if_not is, for example. These instruments are representing instructions of the low level sp_instr language used to implement the semantics of flow control statements and exception handlers. See more details about them in the MySQL Source Code documentation. As I use a non-debug build, attempt to see these instructions from the procedure using SHOW PROCEDURE CODE statement surely failed:

MariaDB [performance_schema]> show procedure code sbtest.p_sbtest1;
ERROR 1289 (HY000): The 'SHOW PROCEDURE|FUNCTION CODE' feature is disabled; you need MariaDB built with '--with-debug' to have it working

The statement/sp/stmt instrument represents usual DDL or DML statement that is executed "as is".

To check how these new instrument work I deci8ded to add a trigger calling a primitive stored procedure to the table created by sysbench:

MariaDB [sbtest]> show create table sbtest1\G
*************************** 1. row ***************************
       Table: sbtest1
Create Table: CREATE TABLE `sbtest1` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `k` int(11) NOT NULL DEFAULT 0,
  `c` char(120) NOT NULL DEFAULT '',
  `pad` char(60) NOT NULL DEFAULT '',
  PRIMARY KEY (`id`),
  KEY `k_1` (`k`)
) ENGINE=InnoDB AUTO_INCREMENT=1000001 DEFAULT CHARSET=latin1
1 row in set (0,001 sec)

MariaDB [sbtest]> set sql_mode='ORACLE';
Query OK, 0 rows affected (0,000 sec)

MariaDB [sbtest]> delimiter //
MariaDB [sbtest]> create procedure p_sbtest1(id int) as begin select k into @k from sbtest1 t where t.id = id; set @i := 0; for i in 1..round(@k/1000)+1 loop set @i := @i + 1; end loop; end;//
Query OK, 0 rows affected (0,058 sec)

MariaDB [sbtest]> create trigger tr1 after update on sbtest1 for each row call p_sbtest1(new.id);//
Query OK, 0 rows affected (0,086 sec)

MariaDB [sbtest]> delimiter ;

This is a primitive procedure that runs some loop to add delay. For fun I've used ORACLE mode and for loop inherited from PL/SQL that is really nice.

With all these in place I ran the following simple sysbench oltp_update_index.lua test for 50 seconds:

openxs@ao756:~/dbs/maria10.5$ sysbench --table-size=1000000 --threads=4 --time=50 --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: 130.61 qps: 130.61 (r/w/o: 0.00/130.61/0.00) lat (ms,95%): 55.82 err/s: 0.00 reconn/s: 0.00
...

and while it was running checked current stored procedure-related statements multiple times with the following SELECT:

MariaDB [performance_schema]> select * from events_statements_current where event_name like 'statement/sp/%'\G
Empty set (0,001 sec)

In all cases I've got zero rows. That's because related consumer is not enabled by default:

MariaDB [performance_schema]> select * from setup_consumers;
+----------------------------------+---------+
| NAME                             | ENABLED |
+----------------------------------+---------+
| events_stages_current            | NO      |
| events_stages_history            | NO      |
| events_stages_history_long       | NO      |
| events_statements_current        | NO      |
| events_statements_history        | NO      |
| events_statements_history_long   | NO      |
| events_transactions_current      | NO      |
| events_transactions_history      | NO      |
| events_transactions_history_long | NO      |
| events_waits_current             | NO      |
| events_waits_history             | NO      |
| events_waits_history_long        | NO      |
| global_instrumentation           | YES     |
| thread_instrumentation           | YES     |
| statements_digest                | YES     |
+----------------------------------+---------+
15 rows in set (0,001 sec)

I've enables all of them with  update setup_consumers set enabled = 'YES'; and retried the test:

MariaDB [performance_schema]> select * from events_statements_current where event_name like 'statement/sp/%'\G
...
*************************** 2. row ***************************
              THREAD_ID: 54
               EVENT_ID: 1375298
           END_EVENT_ID: NULL
             EVENT_NAME: statement/sp/set
                 SOURCE:
            TIMER_START: 1751798753952000
              TIMER_END: 1751800198407000
             TIMER_WAIT: 1444455000
              LOCK_TIME: 0
               SQL_TEXT: NULL
                 DIGEST: NULL
            DIGEST_TEXT: NULL
         CURRENT_SCHEMA: sbtest
            OBJECT_TYPE: PROCEDURE
          OBJECT_SCHEMA: sbtest
            OBJECT_NAME: p_sbtest1
  OBJECT_INSTANCE_BEGIN: NULL
            MYSQL_ERRNO: 0
...
      NESTING_EVENT_ID: 1373590
     NESTING_EVENT_TYPE: STATEMENT
    NESTING_EVENT_LEVEL: 2
*************************** 3. row ***************************
              THREAD_ID: 56
               EVENT_ID: 1335724
           END_EVENT_ID: NULL
             EVENT_NAME: statement/sp/stmt
                 SOURCE:
            TIMER_START: 1751791595187000
              TIMER_END: 1751800213219000
             TIMER_WAIT: 8618032000
              LOCK_TIME: 0
               SQL_TEXT: call p_sbtest1(new.id)
                 DIGEST: NULL
            DIGEST_TEXT: NULL
         CURRENT_SCHEMA: sbtest
            OBJECT_TYPE: TRIGGER
          OBJECT_SCHEMA: sbtest
            OBJECT_NAME: tr1
  OBJECT_INSTANCE_BEGIN: NULL
            MYSQL_ERRNO: 0
...
      NESTING_EVENT_ID: 1335719
     NESTING_EVENT_TYPE: STATEMENT
    NESTING_EVENT_LEVEL: 1
*************************** 4. row ***************************
              THREAD_ID: 56
               EVENT_ID: 1337567
           END_EVENT_ID: NULL
             EVENT_NAME: statement/sp/stmt
                 SOURCE:
            TIMER_START: 1751799809228000
              TIMER_END: 1751800221029000
             TIMER_WAIT: 411801000
              LOCK_TIME: 0
               SQL_TEXT: SET @i := @i + 1
                 DIGEST: NULL
            DIGEST_TEXT: NULL
         CURRENT_SCHEMA: sbtest
            OBJECT_TYPE: PROCEDURE
          OBJECT_SCHEMA: sbtest
            OBJECT_NAME: p_sbtest1
  OBJECT_INSTANCE_BEGIN: NULL
            MYSQL_ERRNO: 0
      RETURNED_SQLSTATE: NULL
           MESSAGE_TEXT: NULL
                 ERRORS: 0
...
      NESTING_EVENT_ID: 1335724
     NESTING_EVENT_TYPE: STATEMENT
    NESTING_EVENT_LEVEL: 2
...
*************************** 6. row ***************************
              THREAD_ID: 57
               EVENT_ID: 1342865
           END_EVENT_ID: NULL
             EVENT_NAME: statement/sp/jump_if_not
                 SOURCE:
            TIMER_START: 1751800236059000
              TIMER_END: 1751800238311000
             TIMER_WAIT: 2252000
              LOCK_TIME: 0
               SQL_TEXT: NULL
                 DIGEST: NULL
            DIGEST_TEXT: NULL
         CURRENT_SCHEMA: sbtest
            OBJECT_TYPE: PROCEDURE
          OBJECT_SCHEMA: sbtest
            OBJECT_NAME: p_sbtest1
  OBJECT_INSTANCE_BEGIN: NULL
            MYSQL_ERRNO: 0
      RETURNED_SQLSTATE: NULL
           MESSAGE_TEXT: NULL
                 ERRORS: 0
               WARNINGS: 0
          ROWS_AFFECTED: 0
              ROWS_SENT: 0
          ROWS_EXAMINED: 0
CREATED_TMP_DISK_TABLES: 0
     CREATED_TMP_TABLES: 0
       SELECT_FULL_JOIN: 0
 SELECT_FULL_RANGE_JOIN: 0
           SELECT_RANGE: 0
     SELECT_RANGE_CHECK: 0
            SELECT_SCAN: 0
      SORT_MERGE_PASSES: 0
             SORT_RANGE: 0
              SORT_ROWS: 0
              SORT_SCAN: 0
          NO_INDEX_USED: 0
     NO_GOOD_INDEX_USED: 0
       NESTING_EVENT_ID: 1342859
     NESTING_EVENT_TYPE: STATEMENT
    NESTING_EVENT_LEVEL: 2
6 rows in set (0,001 sec)

I highlighted some of the interesting column values above. We see SOURCE is always empty (like in  MDEV-23827 I've reported while working on the previous post). Looks like this is a common problem for all kinds of instrumentation and I suspect it may have something to do with compile time adding of PSI keys discussed in MDEV-22841. We also see statements from both trigger and procedure, with different NESTING_EVENT_LEVEL. So, basically this new instrumentation work, even though on non-debug builds matching the stored procedure statements reported to flow control statements may become non-trivial. Let's hope most of the time spent is actually spent on nested DML and DDL statements and not on flow control itself.

Additionally there is a new summary table, events_statements_summary_by_program:

MariaDB [performance_schema]> select * from events_statements_summary_by_program\G
*************************** 1. row ***************************
                OBJECT_TYPE: TRIGGER
              OBJECT_SCHEMA: sbtest
                OBJECT_NAME: tr1
                 COUNT_STAR: 16858
             SUM_TIMER_WAIT: 171716322309000
             MIN_TIMER_WAIT: 0
             AVG_TIMER_WAIT: 10186043000
             MAX_TIMER_WAIT: 69867594000
           COUNT_STATEMENTS: 9193
        SUM_STATEMENTS_WAIT: 107504946033000
        MIN_STATEMENTS_WAIT: 4378538000
        AVG_STATEMENTS_WAIT: 11694217000
        MAX_STATEMENTS_WAIT: 69849730000
              SUM_LOCK_TIME: 0
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 0
          SUM_ROWS_EXAMINED: 0
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 0
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 0
     SUM_NO_GOOD_INDEX_USED: 0
*************************** 2. row ***************************
                OBJECT_TYPE: PROCEDURE
              OBJECT_SCHEMA: sbtest
                OBJECT_NAME: p_sbtest1
                 COUNT_STAR: 16858
             SUM_TIMER_WAIT: 170865294923000
             MIN_TIMER_WAIT: 0
             AVG_TIMER_WAIT: 10135561000
             MAX_TIMER_WAIT: 69774831000
           COUNT_STATEMENTS: 18368282
        SUM_STATEMENTS_WAIT: 70946124125000
        MIN_STATEMENTS_WAIT: 112000
        AVG_STATEMENTS_WAIT: 3862000
        MAX_STATEMENTS_WAIT: 26757028000
              SUM_LOCK_TIME: 0
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 0
          SUM_ROWS_EXAMINED: 8686
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 0
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 0
     SUM_NO_GOOD_INDEX_USED: 0
2 rows in set (0,001 sec)

and there we have the entire new section of 4 columns:

        SUM_STATEMENTS_WAIT: 70946124125000
        MIN_STATEMENTS_WAIT: 112000
        AVG_STATEMENTS_WAIT: 3862000
        MAX_STATEMENTS_WAIT: 26757028000

for time spent on executing individual statements within procedure or trigger. We can subtract SUM_STATEMENTS_WAIT from SUM_WAIT to find out how much time was spent on "flow control" overhead inside the stored procedure.

We now have more insights into the internal working of all this machinery...

To summarize, MariaDB 10.5, among other things, added instrumentation for stored procedures, functions, triggers and events. It is enabled by default for all non-system databases and is ready to use if you enable related consumers. I hope lack of official documentation at the moment will not prevent users from checking most time consuming stored program units and details of their internal work via Performance Schema. They may easily find out that they are actually bad for performance...

Metadata Locks Instrumentation in MariaDB 10.5

There are different ways to study metadata locks in MySQL and MariaDB, as I once described in details. Until recently MariaDB had not provided the performance_schema.metadata_locks table, but it was finally added in 10.5. So, now you can easily get the details in a way that became the easiest and most well known since MySQL 5.7. You just have to make sure performance_schema is enabled at startup:

openxs@ao756:~/dbs/maria10.5$ bin/mysqld_safe --no-defaults --port=3311 --socket=/tmp/mariadb105.sock --performance_schema=1 &
[1] 23626
openxs@ao756:~/dbs/maria10.5$ 200927 18:26:41 mysqld_safe Logging to '/home/openxs/dbs/maria10.5/data/ao756.err'.
200927 18:26:41 mysqld_safe Starting mariadbd daemon with databases from /home/openxs/dbs/maria10.5/data

openxs@ao756:~/dbs/maria10.5$ bin/mysql --socket=/tmp/mariadb105.sock
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 3
Server version: 10.5.6-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 @@performance_schema;
+----------------------+
| @@performance_schema |
+----------------------+
|                    1 |
+----------------------+
1 row in set (0,000 sec)

MariaDB [(none)]> use performance_schema
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
MariaDB [performance_schema]> show tables like '%metadata%';
+-------------------------------------------+
| Tables_in_performance_schema (%metadata%) |
+-------------------------------------------+
| metadata_locks                            |
+-------------------------------------------+
1 row in set (0,001 sec)

MariaDB [performance_schema]> select * from setup_instruments where name like '%metadata%';
+---------------------------------------------------------+---------+-------+
| NAME                                                    | ENABLED | TIMED |
+---------------------------------------------------------+---------+-------+
| wait/io/file/csv/metadata                               | YES     | YES   |
| stage/sql/Waiting for schema metadata lock              | NO      | NO    |
| stage/sql/Waiting for table metadata lock               | NO      | NO    |
| stage/sql/Waiting for stored function metadata lock     | NO      | NO    |
| stage/sql/Waiting for stored procedure metadata lock    | NO      | NO    |
| stage/sql/Waiting for stored package body metadata lock | NO      | NO    |
| stage/sql/Waiting for trigger metadata lock             | NO      | NO    |
| stage/sql/Waiting for event metadata lock               | NO      | NO    |
| memory/performance_schema/metadata_locks                | YES     | NO    |
| wait/lock/metadata/sql/mdl                              | NO      | NO    |
+---------------------------------------------------------+---------+-------+
10 rows in set (0,034 sec)

So, the metadata_locks table is there and we just need to enable wait/lock/metadata/sql/mdl instrument:

MariaDB [performance_schema]> update setup_instruments set enabled = 'YES', timed='YES' where name like 'wait%mdl';
Query OK, 1 row affected (0,030 sec)
Rows matched: 1  Changed: 1  Warnings: 0

MariaDB [performance_schema]> select * from metadata_locks\G
*************************** 1. row ***************************
          OBJECT_TYPE: TABLE
        OBJECT_SCHEMA: performance_schema
          OBJECT_NAME: metadata_locks
OBJECT_INSTANCE_BEGIN: 140032981253664
            LOCK_TYPE: SHARED_READ
        LOCK_DURATION: TRANSACTION
          LOCK_STATUS: GRANTED
               SOURCE:
      OWNER_THREAD_ID: 13
       OWNER_EVENT_ID: 1
1 row in set (0,001 sec)

MariaDB [performance_schema]> select connection_id();
+-----------------+
| connection_id() |
+-----------------+
|               3 |
+-----------------+
1 row in set (0,000 sec)

MariaDB [performance_schema]> select * from threads where processlist_id = 3\G
*************************** 1. row ***************************
          THREAD_ID: 13
               NAME: thread/sql/one_connection
               TYPE: FOREGROUND
     PROCESSLIST_ID: 3
   PROCESSLIST_USER: openxs
   PROCESSLIST_HOST: localhost
     PROCESSLIST_DB: performance_schema
PROCESSLIST_COMMAND: Query
   PROCESSLIST_TIME: 0
  PROCESSLIST_STATE: Sending data
   PROCESSLIST_INFO: select * from threads where processlist_id = 3
   PARENT_THREAD_ID: 1
               ROLE: NULL
       INSTRUMENTED: YES
            HISTORY: YES
    CONNECTION_TYPE: Socket
       THREAD_OS_ID: 23719
1 row in set (0,018 sec)

The output above shows that one has to join to threads table on thread_id = metadata_locks.owner_thread_id to get the details for thread that set metadata lock: 

MariaDB [performance_schema]> SELECT OBJECT_TYPE, OBJECT_SCHEMA, OBJECT_NAME, LOCK_TYPE, LOCK_STATUS, THREAD_ID, PROCESSLIST_ID, PROCESSLIST_INFO FROM performance_schema.metadata_locks INNER JOIN performance_schema.threads ON THREAD_ID = OWNER_THREAD_ID WHERE PROCESSLIST_ID <> CONNECTION_ID()\G
*************************** 1. row ***************************
     OBJECT_TYPE: BACKUP
   OBJECT_SCHEMA: NULL
     OBJECT_NAME: NULL
       LOCK_TYPE: BACKUP_DDL
     LOCK_STATUS: PENDING
       THREAD_ID: 50
  PROCESSLIST_ID: 21
PROCESSLIST_INFO: drop database test
1 row in set (0,001 sec)

In the cases above we see the lock, SHARED_READ, on the table we access, performance_schema.metadata_locks, set by thread that reads from the table. Then we see how to avoid seeing locks set by current connection and how to get current statement (or other SHOW PROCESSLIST details) for the thread associated with the lock.

I noted that SOURCE column in the metadata_locks table is empty. It seems to be the case for other locks too, like those caused by sysbench test running:

MariaDB [performance_schema]> select * from metadata_locks limit 5\G
*************************** 1. row ***************************
          OBJECT_TYPE: TABLE
        OBJECT_SCHEMA: sbtest
          OBJECT_NAME: sbtest1
OBJECT_INSTANCE_BEGIN: 140032787904800
            LOCK_TYPE: SHARED_WRITE
        LOCK_DURATION: TRANSACTION
          LOCK_STATUS: GRANTED
               SOURCE:
      OWNER_THREAD_ID: 34
       OWNER_EVENT_ID: 1
*************************** 2. row ***************************
          OBJECT_TYPE: BACKUP
        OBJECT_SCHEMA: NULL
          OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140032778203712
            LOCK_TYPE: BACKUP_TRANS_DML
        LOCK_DURATION: STATEMENT
          LOCK_STATUS: GRANTED
               SOURCE:
      OWNER_THREAD_ID: 34
       OWNER_EVENT_ID: 1
*************************** 3. row ***************************
          OBJECT_TYPE: TABLE
        OBJECT_SCHEMA: sbtest
          OBJECT_NAME: sbtest1
OBJECT_INSTANCE_BEGIN: 140033249782768
            LOCK_TYPE: SHARED_WRITE
        LOCK_DURATION: TRANSACTION
          LOCK_STATUS: GRANTED
               SOURCE:
      OWNER_THREAD_ID: 33
       OWNER_EVENT_ID: 1
*************************** 4. row ***************************
          OBJECT_TYPE: BACKUP
        OBJECT_SCHEMA: NULL
          OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140033248057584
            LOCK_TYPE: BACKUP_TRANS_DML
        LOCK_DURATION: STATEMENT
          LOCK_STATUS: GRANTED
               SOURCE:
      OWNER_THREAD_ID: 33
       OWNER_EVENT_ID: 1
*************************** 5. row ***************************
          OBJECT_TYPE: TABLE
        OBJECT_SCHEMA: sbtest
          OBJECT_NAME: sbtest1
OBJECT_INSTANCE_BEGIN: 140033449398688
            LOCK_TYPE: SHARED_WRITE
        LOCK_DURATION: TRANSACTION
          LOCK_STATUS: GRANTED
               SOURCE:
      OWNER_THREAD_ID: 32
       OWNER_EVENT_ID: 1
5 rows in set (0,001 sec)

MariaDB [performance_schema]>

I do not think that it is normal, as in MySQL 8.0.21, for example, I still see the reference to the line of source code where the lock is set:

openxs@ao756:~/dbs/8.0$ bin/mysql --socket=/tmp/mysql8.sock -uroot performance_schema
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 8
Server version: 8.0.21 Source distribution

Copyright (c) 2000, 2020, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

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

mysql> flush tables with read lock;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from metadata_locks\G
*************************** 1. row ***************************
          OBJECT_TYPE: GLOBAL
        OBJECT_SCHEMA: NULL
          OBJECT_NAME: NULL
          COLUMN_NAME: NULL
OBJECT_INSTANCE_BEGIN: 139972651847648
            LOCK_TYPE: SHARED
        LOCK_DURATION: EXPLICIT
          LOCK_STATUS: GRANTED
               SOURCE: lock.cc:1033
      OWNER_THREAD_ID: 49
       OWNER_EVENT_ID: 112
*************************** 2. row ***************************
          OBJECT_TYPE: COMMIT
        OBJECT_SCHEMA: NULL
          OBJECT_NAME: NULL
          COLUMN_NAME: NULL
OBJECT_INSTANCE_BEGIN: 139972651711440
            LOCK_TYPE: SHARED
        LOCK_DURATION: EXPLICIT
          LOCK_STATUS: GRANTED
               SOURCE: lock.cc:1108
      OWNER_THREAD_ID: 49
       OWNER_EVENT_ID: 112
...

I reported this immediately as a bug, MDEV-23827 - "performance_schema.metadata_locks.source column is always empty".

The details in this table that are not covered by the MySQL manual require some investigation. You probably noted BACKUP_TRANS_DML as a lock type above. Another example (that you may get while mariabackup a.k.a mariadb-backup in 10.5 is running):

MariaDB [performance_schema]> select * from metadata_locks\G
*************************** 1. row ***************************
          OBJECT_TYPE: BACKUP
        OBJECT_SCHEMA: NULL
          OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140032980286816
            LOCK_TYPE: BACKUP_START
        LOCK_DURATION: EXPLICIT
          LOCK_STATUS: GRANTED
               SOURCE:
      OWNER_THREAD_ID: 44
       OWNER_EVENT_ID: 1
...

I've investigated similar details in the past for MySQL and Percona Server, by code review and some gdb tests. I'd expect to see these values documented somewhere in the mdl.h file in the source code. Here is what we have:

openxs@ao756:~/git/server$ grep -rn BACKUP_TRANS_DML *
mysql-test/main/mdl.result:13:MDL_BACKUP_TRANS_DML      Backup lock
mysql-test/main/mdl.result:19:MDL_BACKUP_TRANS_DML      Backup lock
sql/mdl.h:295:#define MDL_BACKUP_TRANS_DML enum_mdl_type(8)
sql/mdl.cc:134:  { C_STRING_WITH_LEN("MDL_BACKUP_TRANS_DML") },
sql/mdl.cc:490:               MDL_BIT(MDL_BACKUP_TRANS_DML)));
sql/mdl.cc:1633:  MDL_BIT(MDL_BACKUP_DML) | MDL_BIT(MDL_BACKUP_TRANS_DML) | MDL_BIT(MDL_BACKUP_SYS_DML) | MDL_BIT(MDL_BACKUP_DDL) | MDL_BIT(MDL_BACKUP_ALTER_COPY),
sql/mdl.cc:1634:  MDL_BIT(MDL_BACKUP_DML) | MDL_BIT(MDL_BACKUP_TRANS_DML) | MDL_BIT(MDL_BACKUP_SYS_DML) | MDL_BIT(MDL_BACKUP_DDL) | MDL_BIT(MDL_BACKUP_ALTER_COPY) | MDL_BIT(MDL_BACKUP_COMMIT),
sql/sql_base.cc:2048:      mdl_type= MDL_BACKUP_TRANS_DML;
storage/perfschema/table_helper.cc:636:    case MDL_BACKUP_TRANS_DML:
storage/perfschema/table_helper.cc:637:      PFS_engine_table::set_field_varchar_utf8(f, STRING_WITH_LEN("BACKUP_TRANS_DML"));
openxs@ao756:~/git/server$

This is what we have in sql/mdl.h in MariaDB 10.5:

    258 /** Backup locks */
    259
    260 /**
    261   Block concurrent backup
    262 */
    263 #define MDL_BACKUP_START enum_mdl_type(0)
    264 /**
    265    Block new write requests to non transactional tables
    266 */
    267 #define MDL_BACKUP_FLUSH enum_mdl_type(1)
    268 /**
    269    In addition to previous locks, blocks running requests to non trans tables
    270    Used to wait until all DML usage of on trans tables are finished
    271 */
    272 #define MDL_BACKUP_WAIT_FLUSH enum_mdl_type(2)
    273 /**
    274    In addition to previous locks, blocks new DDL's from starting
    275 */
    276 #define MDL_BACKUP_WAIT_DDL enum_mdl_type(3)
    277 /**
    278    In addition to previous locks, blocks commits
    279 */
    280 #define MDL_BACKUP_WAIT_COMMIT enum_mdl_type(4)
    281
    282 /**
    283   Blocks (or is blocked by) statements that intend to modify data. Acquired
    284   before commit lock by FLUSH TABLES WITH READ LOCK.
    285 */
    286 #define MDL_BACKUP_FTWRL1 enum_mdl_type(5)
    287
    288 /**
    289   Blocks (or is blocked by) commits. Acquired after global read lock by
    290   FLUSH TABLES WITH READ LOCK.
    291 */
    292 #define MDL_BACKUP_FTWRL2 enum_mdl_type(6)
    293
    294 #define MDL_BACKUP_DML enum_mdl_type(7)
    295 #define MDL_BACKUP_TRANS_DML enum_mdl_type(8)
    296 #define MDL_BACKUP_SYS_DML enum_mdl_type(9)
...

I see creative re-use of the values from enum_mdl_type.

The last bug not the least, this is how the global read lock and the metadata lock wait look like:

MariaDB [performance_schema]> flush tables with read lock;
Query OK, 0 rows affected (0,090 sec)

MariaDB [performance_schema]> select * from metadata_locks\G
*************************** 1. row ***************************
          OBJECT_TYPE: BACKUP
        OBJECT_SCHEMA: NULL
          OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140033115590992
            LOCK_TYPE: BACKUP_FTWRL1
        LOCK_DURATION: EXPLICIT
          LOCK_STATUS: GRANTED
               SOURCE:
      OWNER_THREAD_ID: 56
       OWNER_EVENT_ID: 1
...
MariaDB [performance_schema]> select * from metadata_locks\G
*************************** 1. row ***************************
          OBJECT_TYPE: BACKUP
        OBJECT_SCHEMA: NULL
          OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140033115590992
            LOCK_TYPE: BACKUP_FTWRL1
        LOCK_DURATION: EXPLICIT
          LOCK_STATUS: GRANTED
               SOURCE:
      OWNER_THREAD_ID: 56
       OWNER_EVENT_ID: 1
*************************** 2. row ***************************
          OBJECT_TYPE: BACKUP
        OBJECT_SCHEMA: NULL
          OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: 140032979653216
            LOCK_TYPE: BACKUP_DDL
        LOCK_DURATION: STATEMENT
          LOCK_STATUS: PENDING
               SOURCE:
      OWNER_THREAD_ID: 50
       OWNER_EVENT_ID: 1
*************************** 3. row ***************************
          OBJECT_TYPE: TABLE
        OBJECT_SCHEMA: performance_schema
          OBJECT_NAME: metadata_locks
OBJECT_INSTANCE_BEGIN: 140033113928032
            LOCK_TYPE: SHARED_READ
        LOCK_DURATION: TRANSACTION
          LOCK_STATUS: GRANTED
               SOURCE:
      OWNER_THREAD_ID: 56
       OWNER_EVENT_ID: 1
3 rows in set (0,000 sec)

MariaDB [performance_schema]> select * from information_schema.metadata_lock_info\G
*************************** 1. row ***************************
    THREAD_ID: 23
    LOCK_MODE: MDL_BACKUP_FTWRL2
LOCK_DURATION: NULL
    LOCK_TYPE: Backup lock
 TABLE_SCHEMA:
   TABLE_NAME:
1 row in set (0,001 sec)

The last statement above shows that the old way to check metadata locks, via metadata_lock_info plugin, had provided much less details. We could not even distinguish lock from lock wait (pending lock) with it!

Are there any locks on that bridge? Go figure...

Finally, even with metadata_locks table in place, finding the details about the exact blocking lock may be not trivial. See this blog post for some idea on how to do this based on assumption that blocking lock is surely set earlier than pending one.