2022-03-17
Starting from v8.0.27, the MySQL daemon shows its thread names at the OS level too, for better troubleshooting. The MySQL 8.0.27 release notes say this:
To assist monitoring and troubleshooting, the Performance Schema instrumentation is now used to export names of instrumented threads to the operating system. This enables utilities that display thread names, such as debuggers and the Unix ps command, to display distinct mysqld thread names rather than “mysqld”. This feature is supported only on Linux, macOS, and Windows.
This instrumented thread naming allows you to do this:
$ ps -Lp `pgrep mysqld` -o tid,cmd,comm TID CMD COMMAND 5405 /usr/sbin/mysqld mysqld 6033 /usr/sbin/mysqld ib_io_ibuf 6034 /usr/sbin/mysqld ib_io_log 6044 /usr/sbin/mysqld ib_pg_flush_co 6045 /usr/sbin/mysqld ib_pg_flush-1 ... 6683 /usr/sbin/mysqld evt_sched 6684 /usr/sbin/mysqld sig_handler 6689 /usr/sbin/mysqld xpl_accept-2 6691 /usr/sbin/mysqld gtid_zip ... 88185 /usr/sbin/mysqld connection 88198 /usr/sbin/mysqld connection 88201 /usr/sbin/mysqld connection
The “connection” threads above are the foreground ones serving your application connections (and running SQL), the others are various background threads, doing all kinds of lower level I/O & internal maintenance tasks.
Previously, you’d have needed to log in to MySQL and query performance_schema.threads to map the OS thread ID to the MySQL thread ID for seeing the context of what was this thread’s purpose inside the database:
mysql> select name,type from performance_schema.threads where thread_os_id = 6683; +----------------------------+------------+ | name | type | +----------------------------+------------+ | thread/sql/event_scheduler | FOREGROUND | +----------------------------+------------+ 1 row in set (0.00 sec)
You can run all kinds of clever sysadmin SQL commands in shell by piping ps and basic command line tools together, to summarize your current MySQLd activity viewed from the OS level:
$ sudo ps -Lp `pgrep mysqld` -o s,comm,wchan | sort | uniq -c | sort -nbr | head -15
44 D connection iomap_dio_rw
17 R connection -
2 S connection futex_wait_queue_me
1 S xpl_worker-2 futex_wait_queue_me
1 S xpl_worker-1 futex_wait_queue_me
1 S xpl_accept-2 ep_poll
1 S xpl_accept-1 futex_wait_queue_me
1 S sig_handler do_sigtimedwait
1 S mysqld poll_schedule_timeout.constprop.13
1 S ib_srv_wkr-3 futex_wait_queue_me
1 S ib_srv_wkr-2 futex_wait_queue_me
1 S ib_srv_wkr-1 futex_wait_queue_me
1 S ib_srv_purge futex_wait_queue_me
1 S ib_srv_mon futex_wait_queue_me
1 S ib_srv_lock_to futex_wait_queue_me
In the above scenario we had 17 user connection threads busy running on CPU (or at least trying to run on CPU) and 44 threads were waiting in D state (usually, but not always, disk I/O), having gone to sleep in the iomap_dio_rw kernel function in Linux. Of course this was just one snapshot in time, for getting a better overview of what’s happening over time, I should run this command multiple times to get a bigger sample size.
Note that I ran ps with sudo to get the
WCHANprinted properly. Modern Linux versions hide WCHAN contents (and show just a-) from non-privileged users.
There’s more interesting thread state info available in the /proc filesystem that ps does not show, so let’s use my pSnapper tool from the 0x.tools toolset:
$ psn -p mysql
Linux Process Snapper v1.1.0 by Tanel Poder [https://0x.tools]
Sampling /proc/stat for 5 seconds... finished.
=== Active Threads =================================================
samples | avg_threads | comm | state
--------------------------------------------------------------------
479 | 4.79 | (connection) | Disk (Uninterruptible)
192 | 1.92 | (connection) | Running (ON CPU)
96 | 0.96 | (ib_log_flush) | Disk (Uninterruptible)
62 | 0.62 | (ib_log_writer) | Disk (Uninterruptible)
53 | 0.53 | (ib_srv_wkr-*) | Disk (Uninterruptible)
22 | 0.22 | (ib_pg_flush-*) | Disk (Uninterruptible)
21 | 0.21 | (ib_srv_wkr-*) | Running (ON CPU)
17 | 0.17 | (ib_srv_purge) | Disk (Uninterruptible)
15 | 0.15 | (ib_pg_flush-*) | Running (ON CPU)
10 | 0.10 | (ib_io_wr-*) | Running (ON CPU)
9 | 0.09 | (ib_pg_flush_co) | Disk (Uninterruptible)
7 | 0.07 | (ib_srv_purge) | Running (ON CPU)
3 | 0.03 | (ib_log_writer) | Running (ON CPU)
3 | 0.03 | (ib_pg_flush_co) | Running (ON CPU)
2 | 0.02 | (ib_log_fl_notif) | Running (ON CPU)
1 | 0.01 | (ib_io_rd-*) | Running (ON CPU)
1 | 0.01 | (ib_log_checkpt) | Disk (Uninterruptible)
1 | 0.01 | (ib_log_flush) | Running (ON CPU)
samples: 100 (expected: 100)
total processes: 2, threads: 105
runtime: 5.01, measure time: 0.85
Looks like MySQL changes the comm field of the thread. Let’s add the cmdline to the column list:
$ psn -p mysql -G cmdline
Linux Process Snapper v1.1.0 by Tanel Poder [https://0x.tools]
Sampling /proc/cmdline, stat for 5 seconds... finished.
=== Active Threads ===================================================================
samples | avg_threads | comm | state | cmdline
--------------------------------------------------------------------------------------
647 | 6.47 | (connection) | Disk (Uninterruptible) | /usr/sbin/mysqld
253 | 2.53 | (connection) | Running (ON CPU) | /usr/sbin/mysqld
96 | 0.96 | (ib_log_flush) | Disk (Uninterruptible) | /usr/sbin/mysqld
64 | 0.64 | (ib_log_writer) | Disk (Uninterruptible) | /usr/sbin/mysqld
56 | 0.56 | (ib_srv_wkr-*) | Disk (Uninterruptible) | /usr/sbin/mysqld
28 | 0.28 | (ib_pg_flush-*) | Disk (Uninterruptible) | /usr/sbin/mysqld
12 | 0.12 | (ib_srv_purge) | Disk (Uninterruptible) | /usr/sbin/mysqld
11 | 0.11 | (ib_pg_flush-*) | Running (ON CP
