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.

MySQL Support Engineer's Chronicles, Issue #10

As promised, I am trying to write one blog post in this series per week. So, even though writing about InnoDB row formats took a lot of time and efforts this weekend, I still plan to summarize my findings, questions, discussions, bugs and links I've collected over this week.

I've shared two links this week on Facebook that got a lot of comments (unlike links to my typical blog posts). The first one was to Marko Mäkelä's blog post at MariaDB.com, "InnoDB Quality Improvements in MariaDB Server". I do not see any comments (or any obvious way to comment) there, but the comments I've got at Facebook were mostly related to the statement that  

"We are no longer merging new MySQL features with MariaDB..."

noted in the text by Mark Callaghan and to the idea that "InnoDB" is a trademark of Oracle, so using it to refer to a fork (that is incompatible with the "upstream" InnoDB in too many ways since MariaDB 10.1 probably) is wrong, as stated by Matt Lord and Sunny Bains. People in the comments mostly agree that a new name makes sense (there are more reasons to give it now anyway than in the case of XtraDB by Percona), and we had a lot of nice and funny suggestions on Slack internally (FudDB was not among them, this is a registered trademark of Miguel Angel Nieto for many years already). We shell see how this may end up, but I would not be surprised by a new name announced soon. I suggest you to read comments in any case if you have a Facebook account, many of them are interesting.

The second link was to Kaj Arnö's post at mariadb.org, "On Contributions, Pride and Cockiness". It's worth checking just because of Monty's photo there. Laurynas Biveinis stated in the comments that any comparison of number of pull requests (open and processed) is meaningless when development model used by other parties is different (closed, with contributions coming mostly via bug reports in case of Oracle, or all changes, external and internal, coming via pull requests in case of Percona). MariaDB uses a mix of a kind, where some contributions from contractors come via pull requests, while engineers from MariaDB Corporation work on GitHub sources of MariaDB Server directly. Anyway (meaningless statistics aside), MariaDB seems to be the easiest target for contributions from Community at the moment, and nobody argued against that. My followers also agreed that the same workflow for internal and external contributions is a preferred development model in ideal world.

This kind of public discussions of (serious and funny) MySQL-related matters on Facebook (along with public discussions on MySQL bugs) make me think the way I use my Facebook page is proper and good for the mankind.

Now back to notes made while working on Support issues. This week I had to explain one case when MariaDB server was shut down normally (but unexpectedly for DBA):

2019-05-22 10:37:55 0 [Note] /usr/libexec/mysqld (initiated by: unknown): Normal shutdown

This Percona blog post summarizes different ways to find a process which sent a HUP/KILL/TERM or other signal to the mysqld process. I've used SystemTap-based solution like suggested in that blog post in the past successfully. In this context I find this summary of the ways to force MySQL to fail useful. for all kinds of testing. SELinux manual is also useful to re-read at times.

This week I've spent a lot of time and some efforts trying to reproduce the error (1942 and/or 1940 if anyone cares) on Galera node acting as an async replication slave. These efforts ended up with a bug report, MDEV-19572. Surely the idea to replicate MyISAM tables outside of mysql database to Galera cluster is bad at multiple levels, but why the error after running for a long time normally? In the process of testing I was reading various remotely related posts, so checked this and that... I also hit other problems in the process. Like this crash that happened probably while sending some signal to the node unintentionally:

190523 17:19:46 [ERROR] mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.

To report this bug, see https://mariadb.com/kb/en/reporting-bugs

We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

Server version: 10.2.23-MariaDB-log
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=3
max_threads=153
thread_count=65544
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 467240 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x0 thread_stack 0x49000
/home/openxs/dbs/maria10.2/bin/mysqld(my_print_stacktrace+0x29)[0x7f6475eb5b49]
/home/openxs/dbs/maria10.2/bin/mysqld(handle_fatal_signal+0x33d)[0x7f64759d50fd]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7f6473887330]
/home/openxs/dbs/maria10.2/bin/mysqld(+0xb3b817)[0x7f6475ebc817]
/home/openxs/dbs/maria10.2/bin/mysqld(+0xb3b9e6)[0x7f6475ebc9e6]
/home/openxs/dbs/maria10.2/bin/mysqld(+0xb3bb8a)[0x7f6475ebcb8a]
/home/openxs/dbs/maria10.2/bin/mysqld(lf_hash_delete+0x61)[0x7f6475ebcfa1]
/home/openxs/dbs/maria10.2/bin/mysqld(+0x601eed)[0x7f6475982eed]
include/my_atomic.h:298(my_atomic_storeptr)[0x7f6475983464]
sql/table_cache.cc:534(tdc_delete_share_from_hash)[0x7f6475811f17]
sql/table_cache.cc:708(tdc_purge(bool))[0x7f64759351ea]
sql/sql_base.cc:376(close_cached_tables(THD*, TABLE_LIST*, bool, unsigned long))[0x7f64757c9ec7]
nptl/pthread_create.c:312(start_thread)[0x7f647387f184]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f6472d8c03d]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

I was not able so far top find the exact some backtrace in any known MariaDB bug, so one day I'll have to try to reproduce this crash as well.

I try to check some MariaDB ColumnStore issues from time ot time, for a change, and this week I ended up reading this KB page while trying to understand how much we can control placement of data there.

Finally, for the records, this is the way to "fix" InnoDB statistics if needed (and the need is real as you can find out from Bug #95507 - "innodb_stats_method is not honored when innodb_stats_persistent=ON" reported by my colleague Sergei Petrunia):

update mysql.innodb_index_stats set last_update=now(), stat_value=445000000 where database_name='test' and table_name='t1' and index_name='i1' and stat_name='n_diff_pfx01';

I like to return to familiar nice places and topics, like Regent's Canal or MySQL bugs...

The last bug not the least, MySQL bugs. This week I've subscribed to the following (already "Verified") interesting bug reports (besides the one mentioned above):

• Bug #95484 - "EXCHANGE PARTITION works wrong/weird with different ROW_FORMAT.". Jean-François Gagné found out that there is a way to have partitions with different row_format values in the same InnoDB table, at least in MySQL 5.7. So why is this not supported officially? See also his Bug #95478 - "CREATE TABLE LIKE does not honour ROW_FORMAT.". It's a week of ROW_FORMAT studies for me, for sure!
• Bug #95462 - "Data comparison broke in MySQL 8.0.16". It's common knowledge how much I like regression bugs. MySQL 8.0.16 introduced a new one, reported by
  Raman Haran, probably based on some good and valid intentions. But undocumented changes in behavior in GA versions are hardly acceptable, no matter what are the intentions.

That's all for now. Some more links to MySQL bugs from me are always available on Twitter.

What May Cause MySQL ERROR 1213

Probably all of us, MySQL users, DBAs and developers had seen error 1213 more than once, in one context or the other:

mysql> select * from t1;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

The first thing that comes to mind in this case is: "OK, we have InnoDB deadlock, let's check the details", followed by the SHOW ENGINE INNODB STATUS check, like this:

mysql> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2018-12-08 17:41:11 0x7f2f8b8db700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 12 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 59 srv_active, 0 srv_shutdown, 14824 srv_idle
srv_master_thread log flush and writes: 14882
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 326
OS WAIT ARRAY INFO: signal count 200
RW-shared spins 0, rounds 396, OS waits 195
RW-excl spins 0, rounds 120, OS waits 4
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 396.00 RW-shared, 120.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 14960
Purge done for trx's n:o < 14954 undo n:o < 0 state: running but idle
History list length 28
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421316960193880, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421316960192752, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
--------
FILE I/O
--------
...

Now, what if you get the output like the one above? Without any LATEST DETECTED DEADLOCK section? I've seen people wondering how is it even possible and trying to find some suspicious bug somewhere...

Do not be in a hurry - time to recall that there are actually at least 4 quite common reasons to get error 2013 in modern (5.5+) version of MySQL, MariaDB and Friends:

1. InnoDB deadlock happened
2. Metadata deadlock happened
3. If you are lucky enough to use Galera cluster, Galera conflict happened
4. Deadlock happened in some other storage engine (for example, MyRocks)

I am not lucky enough to use MySQL's group replication yet, but I know that conflicts there are also possible. I am just not sure if error 1213 is also reported in that case. Feel free to check with a test case similar to the one I've used for Galera below.

I also suspect deadlocks with other engines are also possible. As a bonus point, I'll demonstrate the deadlock with MyRocks also.

Let's reproduce these 3 cases one by one and check how to get more information on them. In all cases it's enough to have at most 2 InnoDB tables with just two rows:

mysql> show create table t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `id` int(11) NOT NULL,
  `c1` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

mysql> show create table t2\G
*************************** 1. row ***************************
       Table: t2
Create Table: CREATE TABLE `t2` (
  `id` int(11) NOT NULL,
  `c1` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

mysql> select * from t1;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
|  2 |    2 |
+----+------+
2 rows in set (0.00 sec)

mysql> select * from t2;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
|  2 |    2 |
+----+------+
2 rows in set (0.00 sec)

We'll need two sessions, surely.

InnoDB Deadlock

With InnoDB and tables above it's really easy to end up with a deadlock. In the first session execute the following:

mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t1 where id = 1 for update;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
+----+------+
1 row in set (0.00 sec)

In the second session execute:

mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t1 where id = 2 for update;
+----+------+
| id | c1   |
+----+------+
|  2 |    2 |
+----+------+
1 row in set (0.02 sec)

Now in the first session try to access the row with id=2 asking for incompatible lock:

mysql> select * from t1 where id = 2 for update;

This statement hangs waiting for a lock (up to innodb_lock_wait_timeout seconds). Try to access the row with id=1 asking for incompatible lock in the second session, and you'll get the deadlock error:

mysql> select * from t1 where id = 1 for update;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

at this moment SELECT in the first transaction returns data:

+----+------+
| id | c1   |
+----+------+
|  2 |    2 |
+----+------+
1 row in set (5.84 sec)

It's that simple, one table and two rows is enough. We can get the details in the output of SHOW ENGINE INNODB STATUS:

...
------------------------
LATEST DETECTED DEADLOCK
------------------------
2018-12-08 18:32:59 0x7f2f8b8db700
*** (1) TRANSACTION:
TRANSACTION 15002, ACTIVE 202 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 8, OS thread handle 139842181244672, query id 8545 localhost root statistics
select * from t1 where id = 2 for update
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 94 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 15002 lock_mode X locks rec but not gap waiting
*** (2) TRANSACTION:
TRANSACTION 15003, ACTIVE 143 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 9, OS thread handle 139842181510912, query id 8546 localhost root statistics
select * from t1 where id = 1 for update
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 94 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 15003 lock_mode X locks rec but not gap
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 94 page no 3 n bits 72 index PRIMARY of table `test`.`t1` trx id 15003 lock_mode X locks rec but not gap waiting
*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
...

In the case above I've used Percona Server  5.7.24-26 (why not). Details of output may vary depending on version (and bugs it has :).  If you use MariaDB 5.5+, in case of InnoDB deadlock special innodb_deadlocks status variable is also incremented.

Metadata Deadlock

Unlike with InnoDB deadlocks, chances that you've seen deadlocks with metadata locks involved are low. One may spend notable time trying to reproduce such a deadlock, but (as usual) quck check of MySQL bugs database may help to find an easy to reproduce case. I mean Bug #65890 - "Deadlock that is not a deadlock with transaction and lock tables".

So, let's try the following scenario with two sessions and out InnoDB tables, t1 and t2. In one session:

mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t2 for update;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
|  2 |    2 |
+----+------+
2 rows in set (0.00 sec)

In another session:

mysql> lock tables t1 write, t2 write;

It hangs, waiting as long as lock_wait_timeout. We can check what happens with metadata locks using performance_schema.metadata_locks table (as we use MySQL or Percona Server 5.7+, more on setup, alternatives for MariaDB etc here and there). In the first session:

mysql> select * from performance_schema.metadata_locks;
+-------------+--------------------+----------------+-----------------------+----------------------+---------------+-------------+--------+-----------------+----------------+
| OBJECT_TYPE | OBJECT_SCHEMA      | OBJECT_NAME    | OBJECT_INSTANCE_BEGIN | LOCK_TYPE            | LOCK_DURATION | LOCK_STATUS | SOURCE | OWNER_THREAD_ID | OWNER_EVENT_ID |
+-------------+--------------------+----------------+-----------------------+----------------------+---------------+-------------+--------+-----------------+----------------+
| TABLE       | test               | t2             |       139841686765904 | SHARED_WRITE         | TRANSACTION   | GRANTED     |        |              45 |           2850 || GLOBAL      | NULL               | NULL           |       139841688088672 | INTENTION_EXCLUSIVE  | STATEMENT     | GRANTED     |        |              46 |            205 |
| SCHEMA      | test               | NULL           |       139841688088912 | INTENTION_EXCLUSIVE  | TRANSACTION   | GRANTED     |        |              46 |            205 |
| TABLE       | test               | t1             |       139841688088992 | SHARED_NO_READ_WRITE | TRANSACTION   | GRANTED     |        |              46 |            207 |
| TABLE       | test               | t2             |       139841688089072 | SHARED_NO_READ_WRITE | TRANSACTION   | PENDING     |        |              46 |            208 || TABLE       | performance_schema | metadata_locks |       139841686219040 | SHARED_READ          | TRANSACTION   | GRANTED     |        |              45 |           3003 |
+-------------+--------------------+----------------+-----------------------+----------------------+---------------+-------------+--------+-----------------+----------------+
6 rows in set (0.00 sec)

As soon as we try this in the first session:

mysql> select * from t1;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

we get the same deadlock error 1213 and LOCK TABLES in the second session completes. We can find nothing about this deadlock in the output of SHOW ENGINE INNODB STATUS (as shared at the beginning of this post). I am also not aware about any status variables to count metadata deadlocks.

You can find some useful information about metadata deadlocks in the manual.

Galera Conflict

For simplicity I'll use MariaDB 10.1.x and simple 2 nodes setup on the same box as I described here. I'll start first node as a new cluster and create tables for this test:

openxs@ao756:~/dbs/maria10.1$ bin/mysqld_safe --defaults-file=/home/openxs/galera/mynode1.cnf --wsrep-new-cluster &
[1] 13022
openxs@ao756:~/dbs/maria10.1$ 181208 20:40:52 mysqld_safe Logging to '/tmp/mysql-node1.err'.
181208 20:40:52 mysqld_safe Starting mysqld daemon with databases from /home/openxs/galera/node1

openxs@ao756:~/dbs/maria10.1$ bin/mysql  --socket=/tmp/mysql-node1.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 4
Server version: 10.1.34-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]> drop table t1, t2;
ERROR 1051 (42S02): Unknown table 'test.t2'
MariaDB [test]> create table t1(id int, c1 int, primary key(id));
Query OK, 0 rows affected (0.29 sec)

MariaDB [test]> create table t2(id int, c1 int, primary key(id));
Query OK, 0 rows affected (0.22 sec)

MariaDB [test]> insert into t1 values (1,1), (2,2);
Query OK, 2 rows affected (0.07 sec)
Records: 2  Duplicates: 0  Warnings: 0

MariaDB [test]> insert into t2 values (1,1), (2,2);
Query OK, 2 rows affected (0.18 sec)
Records: 2  Duplicates: 0  Warnings: 0

Then I'll start second node, make sure it joined the cluster and has the same data:

openxs@ao756:~/dbs/maria10.1$ bin/mysqld_safe --defaults-file=/home/openxs/galera/mynode2.cnf &
[2] 15110
openxs@ao756:~/dbs/maria10.1$ 181208 20:46:11 mysqld_safe Logging to '/tmp/mysql-node2.err'.
181208 20:46:11 mysqld_safe Starting mysqld daemon with databases from /home/openxs/galera/node2

openxs@ao756:~/dbs/maria10.1$ bin/mysql --socket=/tmp/mysql-node2.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 4
Server version: 10.1.34-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 status like 'wsrep_cluster%';
+--------------------------+--------------------------------------+
| Variable_name            | Value                                |
+--------------------------+--------------------------------------+
| wsrep_cluster_conf_id    | 4                                    |
| wsrep_cluster_size       | 2                                    |
| wsrep_cluster_state_uuid | b1d227b1-0211-11e6-8ce0-3644ad2b03dc |
| wsrep_cluster_status     | Primary                              |
+--------------------------+--------------------------------------+
4 rows in set (0.04 sec)

MariaDB [test]> select * from t2;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
|  2 |    2 |
+----+------+
2 rows in set (0.02 sec)

Now we are ready to try to provoke Galera conflict. For this we have to try to update the same data in transactions on two different nodes. In one session connected to node1:

MariaDB [test]> select @@wsrep_node_name;
+-------------------+
| @@wsrep_node_name |
+-------------------+
| node1             |
+-------------------+
1 row in set (0.00 sec)

MariaDB [test]> start transaction;
Query OK, 0 rows affected (0.00 sec)

MariaDB [test]> update test.t1 set c1 = 5 where id=1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

In another session connected to other node:

MariaDB [test]> select @@wsrep_node_name;
+-------------------+
| @@wsrep_node_name |
+-------------------+
| node2             |
+-------------------+
1 row in set (0.00 sec)

MariaDB [test]> start transaction;
Query OK, 0 rows affected (0.00 sec)

MariaDB [test]> update test.t1 set c1 = 6 where id=1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Now in the first we can COMMIT successfully:

MariaDB [test]> commit;
Query OK, 0 rows affected (0.12 sec)

But if we try to COMMIT in the second:

MariaDB [test]> commit;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

We get that same error 1213 about the deadlock. Surely you'll see nothing about this deadlock in INNODB STATUS output, as it was NOT an InnoDB deadlock, but Galera conflict. Check these status variables on the node2:

MariaDB [test]> show status like 'wsrep_local%';
+----------------------------+--------------------------------------+
| Variable_name              | Value                                |
+----------------------------+--------------------------------------+
| wsrep_local_bf_aborts      | 1                                    |
| wsrep_local_cached_downto  | 75                                   |
| wsrep_local_cert_failures  | 0                                    |
| wsrep_local_commits        | 0                                    |
| wsrep_local_index          | 0                                    |
| wsrep_local_recv_queue     | 0                                    |
| wsrep_local_recv_queue_avg | 0.000000                             |
| wsrep_local_recv_queue_max | 1                                    |
| wsrep_local_recv_queue_min | 0                                    |
| wsrep_local_replays        | 0                                    |
| wsrep_local_send_queue     | 0                                    |
| wsrep_local_send_queue_avg | 0.000000                             |
| wsrep_local_send_queue_max | 1                                    |
| wsrep_local_send_queue_min | 0                                    |
| wsrep_local_state          | 4                                    |
| wsrep_local_state_comment  | Synced                               |
| wsrep_local_state_uuid     | b1d227b1-0211-11e6-8ce0-3644ad2b03dc |
+----------------------------+--------------------------------------+
17 rows in set (0.01 sec)

If wsrep_local_bf_aborts > 0, you had conflicts and local transaction was rolled back to prevent them. We can see that remote one wins, on node2:

MariaDB [test]> select * from t1;
+----+------+
| id | c1   |
+----+------+
|  1 |    5 |
|  2 |    2 |
+----+------+
2 rows in set (0.00 sec)

To summarize, in Galera "first commit wins" and local transaction involved in conflict is always a looser. You can get a lot of information about conflicts in the error log if you enable conflict logging features through wsrep_log_conflicts and cert.log_conflicts. See this fine manual for details.

MyRocks Deadlock

We can easily check how deadlocks are processed by MyRocks by just loading the plugin for the engine, converting tables to MyRocks and trying the same InnoDB scenario with the same Percona Server we used initially. But first, if you use Percona binaries you have to install a separate package:

openxs@ao756:~$ dpkg -l | grep rocksdb
openxs@ao756:~$ sudo apt-get install percona-server-rocksdb-5.7
[sudo] password for openxs:
Reading package lists... Done
Building dependency tree
...
Unpacking percona-server-rocksdb-5.7 (5.7.24-26-1.trusty) ...
Setting up percona-server-rocksdb-5.7 (5.7.24-26-1.trusty) ...


 * This release of Percona Server is distributed with RocksDB storage engine.
 * Run the following script to enable the RocksDB storage engine in Percona Server:

        ps-admin --enable-rocksdb -u <mysql_admin_user> -p[mysql_admin_pass] [-S <socket>] [-h <host> -P <port>]

Percona's manual has a lot more details and relies on separate ps-admin script, but basically you have to INSTALL PLUGINs like this (check script's code):

mysql> INSTALL PLUGIN ROCKSDB SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.86 sec)

mysql> INSTALL PLUGIN ROCKSDB_CFSTATS SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.06 sec)

mysql> INSTALL PLUGIN ROCKSDB_DBSTATS SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.08 sec)

mysql> INSTALL PLUGIN ROCKSDB_PERF_CONTEXT SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_PERF_CONTEXT_GLOBAL SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.06 sec)

mysql> INSTALL PLUGIN ROCKSDB_CF_OPTIONS SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_GLOBAL_INFO SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_COMPACTION_STATS SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_DDL SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.06 sec)

mysql> INSTALL PLUGIN ROCKSDB_INDEX_FILE_MAP SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_LOCKS SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_TRX SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.05 sec)

mysql> INSTALL PLUGIN ROCKSDB_DEADLOCK SONAME 'ha_rocksdb.so';
Query OK, 0 rows affected (0.06 sec)

Then check that the engine is there and convert tables:

mysql> show engines;
+--------------------+---------+----------------------------------------------------------------------------+--------------+------+------------+
| Engine             | Support | Comment                                                                    | Transactions | XA   | Savepoints |
+--------------------+---------+----------------------------------------------------------------------------+--------------+------+------------+
| ROCKSDB            | YES     | RocksDB storage engine                                                     | YES          | YES  | YES        |
...

mysql> alter table t1 engine=rocksdb;
Query OK, 2 rows affected (0.64 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> alter table t2 engine=rocksdb;
Query OK, 2 rows affected (0.58 sec)
Records: 2  Duplicates: 0  Warnings: 0

Now we are ready to try the same InnoDB scenario. Just note that lock wait timeout for MyRocks is defined by the rocksdb_lock_wait_timeout that is small by default, 1 second, do you have have to increase it first. You also have to set rocksdb_deadlock_detect to ON (as it's OFF by default):

mysql> set global rocksdb_lock_wait_timeout=50;
Query OK, 0 rows affected (0.00 sec)

mysql> set global rocksdb_deadlock_detect=ON;
Query OK, 0 rows affected (0.00 sec)

mysql> \r
Connection id:    14
Current database: test

mysql> start transaction;
Query OK, 0 rows affected (0.02 sec)

mysql> select * from t1 where id = 1 for update;
+----+------+
| id | c1   |
+----+------+
|  1 |    1 |
+----+------+
1 row in set (0.00 sec)

Then in the second session:

mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from t1 where id = 2 for update;
+----+------+
| id | c1   |
+----+------+
|  2 |    2 |
+----+------+
1 row in set (0.00 sec)

In the first:

mysql> select * from t1 where id = 2 for update;

and in the second we can get deadlock error:

mysql> select * from t1 where id = 1 for update;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
mysql> show global status like '%deadlock%';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| rocksdb_row_lock_deadlocks | 1     |
+----------------------------+-------+
1 row in set (0.00 sec)

Note that MyRocks has status variable to count deadlocks. Note that Percona Server still does NOT seem to support SHOW ENGINE ROCKSDB TRANSACTION STATUS statement available upstream:

mysql> show engine rocksdb transaction status\G
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'transaction status' at line 1

I was not able to find a bug about this (sorry if I missed it), and just reported new task to Percona's JIRA: PS-5114 - "Add support for SHOW ENGINE ROCKSDB TRANSACTION STATUS".

That's probably more than enough for single blog post (that is mostly NOT about bugs). One day I'll refresh my knowledge of MyRocks etc and maybe write more about deadlocks troubleshooting there.

Do not be surprised if you can not find anything in INNODB STATUS when you get error 1213, just proceed with further steps. There are other reasons to explore. Venice hides a lot early in the morning...

To summarize, do not be surprised that after you got MySQL error 1213 you see no information about recent InnoDB deadlock - there are at least 3 more reasons for this error to be reported, as explained above. You should know your configuration and use several other commands and sources of information to pinpoint what exactly happened and why.