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 CPU) | /usr/sbin/mysqld
10 | 0.10 | (ib_pg_flush_co) | Disk (Uninterruptible) | /usr/sbin/mysqld
9 | 0.09 | (ib_srv_wkr-*) | Running (ON CPU) | /usr/sbin/mysqld
8 | 0.08 | (ib_io_rd-*) | Running (ON CPU) | /usr/sbin/mysqld
8 | 0.08 | (ib_srv_purge) | Running (ON CPU) | /usr/sbin/mysqld
7 | 0.07 | (ib_io_wr-*) | Running (ON CPU) | /usr/sbin/mysqld
3 | 0.03 | (ib_pg_flush_co) | Running (ON CPU) | /usr/sbin/mysqld
2 | 0.02 | (ib_log_flush) | Running (ON CPU) | /usr/sbin/mysqld
2 | 0.02 | (ib_log_writer) | Running (ON CPU) | /usr/sbin/mysqld
Ok, the cmdline still shows /usr/bin/mysqld for all threads, just like in previous MySQL versions.
As a sidenote, interestingly Postgres (that does process naming) uses the /proc fields in an opposite manner:
$ psn -p post -a -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
-------------------------------------------------------------------------------------------------------
100 | 1.00 | (postmaster) | Sleep (Interruptible) | /usr/pgsql-14/bin/postmaster
100 | 1.00 | (postmaster) | Sleep (Interruptible) | postgres: autovacuum launcher
100 | 1.00 | (postmaster) | Sleep (Interruptible) | postgres: background writer
100 | 1.00 | (postmaster) | Sleep (Interruptible) | postgres: checkpointer
100 | 1.00 | (postmaster) | Sleep (Interruptible) | postgres: logger
100 | 1.00 | (postmaster) | Sleep (Interruptible) | postgres: logical replication launcher
100 | 1.00 | (postmaster) | Sleep (Interruptible) | postgres: stats collector
100 | 1.00 | (postmaster) | Sleep (Interruptible) | postgres: walwriter
On Postgres, each process has its comm shown as the generic postmaster and the cmdline shows the context, the purpose of this process (more about this in a future post).
Ok, back to MySQL. Thanks to its thread naming and pSnapper’s ability to link together thread states and their current system calls, you can easily report MySQL behavior all the way to the Linux kernel level:
$ sudo psn -p mysql -G syscall
Linux Process Snapper v1.1.0 by Tanel Poder [https://0x.tools]
Sampling /proc/syscall, stat for 5 seconds... finished.
=== Active Threads =================================================================
samples | avg_threads | comm | state | syscall
------------------------------------------------------------------------------------
614 | 6.14 | (connection) | Disk (Uninterruptible) | pread64
242 | 2.42 | (connection) | Running (ON CPU) | [running]
90 | 0.90 | (ib_log_flush) | Disk (Uninterruptible) | fsync
64 | 0.64 | (ib_log_writer) | Disk (Uninterruptible) | pwrite64
43 | 0.43 | (connection) | Disk (Uninterruptible) | fdatasync
42 | 0.42 | (connection) | Disk (Uninterruptible) | [running]
42 | 0.42 | (connection) | Running (ON CPU) | pread64
42 | 0.42 | (ib_pg_flush-*) | Disk (Uninterruptible) | pwrite64
42 | 0.42 | (ib_srv_wkr-*) | Disk (Uninterruptible) | pread64
16 | 0.16 | (connection) | Disk (Uninterruptible) | pwrite64
16 | 0.16 | (ib_srv_purge) | Disk (Uninterruptible) | pread64
15 | 0.15 | (connection) | Running (ON CPU) | futex
13 | 0.13 | (connection) | Running (ON CPU) | ppoll
11 | 0.11 | (ib_pg_flush_co) | Disk (Uninterruptible) | pwrite64
9 | 0.09 | (ib_srv_wkr-*) | Running (ON CPU) | [running]
7 | 0.07 | (ib_srv_wkr-*) | Running (ON CPU) | pread64
5 | 0.05 | (ib_io_rd-*) | Running (ON CPU) | io_getevents
4 | 0.04 | (ib_pg_flush-*) | Running (ON CPU) | [running]
3 | 0.03 | (ib_io_rd-*) | Running (ON CPU) | [running]
3 | 0.03 | (ib_log_flush) | Disk (Uninterruptible) | [running]
3 | 0.03 | (ib_log_flush) | Running (ON CPU) | fsync
We see lots of threads spending their time in system calls like pread64, pwrite64, fsync and fdatasync. These syscalls are simple enough and take just one file descriptor as the first argument, thus psn can walk the /proc filesystem further and report the filenames involved. I’m using the filenamesum (not filename) option to strip out digits in directory and file names - to get a more terse summary on my screen (scroll right to see the filename output):
$ sudo psn -p mysql -G syscall,filenamesum
Linux Process Snapper v1.1.0 by Tanel Poder [https://0x.tools]
Sampling /proc/syscall, stat for 5 seconds... finished.
=== Active Threads ======================================================================================================
samples | avg_threads | comm | state | syscall | filenamesum
-------------------------------------------------------------------------------------------------------------------------
671 | 6.71 | (connection) | Disk (Uninterruptible) | pread64 | /data*/mysql/sbtest/sbtest*.ibd
235 | 2.35 | (connection) | Running (ON CPU) | [running] |
90 | 0.90 | (ib_log_flush) | Disk (Uninterruptible) | fsync | /data*/mysql/ib_logfile*
69 | 0.69 | (ib_log_writer) | Disk (Uninterruptible) | pwrite64 | /data*/mysql/ib_logfile*
47 | 0.47 | (ib_srv_wkr-*) | Disk (Uninterruptible) | pread64 | /data*/mysql/sbtest/sbtest*.ibd
44 | 0.44 | (connection) | Disk (Uninterruptible) | fdatasync | /data*/mysql/binlog.*
33 | 0.33 | (ib_pg_flush-*) | Disk (Uninterruptible) | pwrite64 | /data*/mysql/#ib_*_*.dblwr
19 | 0.19 | (connection) | Running (ON CPU) | pread64 | /data*/mysql/sbtest/sbtest*.ibd
17 | 0.17 | (connection) | Disk (Uninterruptible) | [running] |
15 | 0.15 | (connection) | Running (ON CPU) | futex |
15 | 0.15 | (connection) | Running (ON CPU) | ppoll |
14 | 0.14 | (connection) | Disk (Uninterruptible) | pwrite64 | /data*/mysql/#ib_*_*.dblwr
14 | 0.14 | (ib_pg_flush_co) | Disk (Uninterruptible) | pwrite64 | /data*/mysql/#ib_*_*.dblwr
14 | 0.14 | (ib_srv_purge) | Disk (Uninterruptible) | pread64 | /data*/mysql/sbtest/sbtest*.ibd
So, at the OS level you can now see the MySQL thread name (purpose) and what it is trying to do in the kernel (syscall, filename name (purpose).
But that’s not all, you can also see what are your MySQL threads doing inside the kernel (wchan, kstack). You can measure how much time your threads are spending in the kernel submitting I/O or waiting for already submitted I/O to complete. Or, not even getting to submitting the I/O yet as they got stuck in the kernel somewhere (waiting for an inode lock or a previous filesystem journal sync, etc):
$ sudo psn -p mysql -G syscall,wchan,kstack
Linux Process Snapper v1.1.0 by Tanel Poder [https://0x.tools]
Sampling /proc/syscall, stat, wchan, stack for 5 seconds... finished.
=== Active Threads =============================================================================================================================================================================================================================================================================================================================================================================================
samples | avg_threads | comm | state | syscall | wchan | kstack
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
428 | 4.28 | (connection) | Disk (Uninterruptible) | pread64 | __iomap_dio_rw | __x64_sys_pread64()->ksys_pread64()->vfs_read()->__vfs_read()->new_sync_read()->xfs_file_read_iter()->xfs_file_dio_aio_read()->iomap_dio_rw()->__iomap_dio_rw()
138 | 1.38 | (connection) | Running (ON CPU) | [running] | 0 | -
64 | 0.64 | (ib_log_flush) | Disk (Uninterruptible) | fsync | __xfs_log_force_lsn.isra.26 | __x64_sys_fsync()->do_fsync()->vfs_fsync_range()->xfs_file_fsync()->xfs_log_force_lsn()->__xfs_log_force_lsn.isra.26()
34 | 0.34 | (connection) | Disk (Uninterruptible) | fdatasync | __xfs_log_force_lsn.isra.26 | __x64_sys_fdatasync()->do_fsync()->vfs_fsync_range()->xfs_file_fsync()->xfs_log_force_lsn()->__xfs_log_force_lsn.isra.26()
33 | 0.33 | (ib_srv_wkr-*) | Disk (Uninterruptible) | pread64 | __iomap_dio_rw | __x64_sys_pread64()->ksys_pread64()->vfs_read()->__vfs_read()->new_sync_read()->xfs_file_read_iter()->xfs_file_dio_aio_read()->iomap_dio_rw()->__iomap_dio_rw()
32 | 0.32 | (ib_log_writer) | Disk (Uninterruptible) | pwrite64 | rwsem_down_write_slowpath | __x64_sys_pwrite64()->ksys_pwrite64()->vfs_write()->__vfs_write()->new_sync_write()->xfs_file_write_iter()->xfs_file_buffered_aio_write()->xfs_file_aio_write_checks()->file_modified()->file_update_time()->xfs_vn_update_time()->xfs_ilock()->rwsem_down_write_slowpath()
31 | 0.31 | (ib_log_writer) | Disk (Uninterruptible) | pwrite64 | rwsem_down_write_slowpath | __x64_sys_pwrite64()->ksys_pwrite64()->vfs_write()->__vfs_write()->new_sync_write()->xfs_file_write_iter()->xfs_file_buffered_aio_write()->iomap_file_buffered_write()->iomap_apply()->xfs_file_iomap_begin()->xfs_file_iomap_begin_delay()->xfs_ilock()->rwsem_down_write_slowpath()
26 | 0.26 | (connection) | Disk (Uninterruptible) | pread64 | 0 | -
26 | 0.26 | (connection) | Running (ON CPU) | [running] | __iomap_dio_rw | __x64_sys_pread64()->ksys_pread64()->vfs_read()->__vfs_read()->new_sync_read()->xfs_file_read_iter()->xfs_file_dio_aio_read()->iomap_dio_rw()->__iomap_dio_rw()
22 | 0.22 | (ib_pg_flush-*) | Disk (Uninterruptible) | pwrite64 | __iomap_dio_rw | __x64_sys_pwrite64()->ksys_pwrite64()->vfs_write()->__vfs_write()->new_sync_write()->xfs_file_write_iter()->xfs_file_dio_aio_write()->iomap_dio_rw()->__iomap_dio_rw()
21 | 0.21 | (connection) | Running (ON CPU) | pread64 | 0 | -
14 | 0.14 | (connection) | Running (ON CPU) | [running] | poll_schedule_timeout.constprop.13 | -
13 | 0.13 | (connection) | Disk (Uninterruptible) | [running] | __iomap_dio_rw | __x64_sys_pread64()->ksys_pread64()->vfs_read()->__vfs_read()->new_sync_read()->xfs_file_read_iter()->xfs_file_dio_aio_read()->iomap_dio_rw()->__iomap_dio_rw()
13 | 0.13 | (connection) | Running (ON CPU) | [running] | 0 | __x64_sys_ppoll()->do_sys_poll()->poll_schedule_timeout.constprop.13()
13 | 0.13 | (ib_log_flush) | Disk (Uninterruptible) | fsync | wait_on_page_bit | __x64_sys_fsync()->do_fsync()->vfs_fsync_range()->xfs_file_fsync()->file_write_and_wait_range()->__filemap_fdatawait_range()->wait_on_page_writeback()->wait_on_page_bit()
12 | 0.12 | (ib_srv_purge) | Disk (Uninterruptible) | pread64 | __iomap_dio_rw | __x64_sys_pread64()->ksys_pread64()->vfs_read()->__vfs_read()->new_sync_read()->xfs_file_read_iter()->xfs_file_dio_aio_read()->iomap_dio_rw()->__iomap_dio_rw()
11 | 0.11 | (connection) | Disk (Uninterruptible) | fdatasync | wait_on_page_bit | __x64_sys_fdatasync()->do_fsync()->vfs_fsync_range()->xfs_file_fsync()->file_write_and_wait_range()->__filemap_fdatawait_range()->wait_on_page_writeback()->wait_on_page_bit()
11 | 0.11 | (ib_log_flush) | Disk (Uninterruptible) | fsync | xlog_wait | __x64_sys_fsync()->do_fsync()->vfs_fsync_range()->xfs_file_fsync()->xfs_log_force_lsn()->__xfs_log_force_lsn.isra.26()->xlog_wait()
Scroll the above output all the way to the right to see the full stack trace of your MySQL threads that are working (or stuck) inside Linux kernel for one reason or another. The stack trace tells you the story of how you got there!
Ok, that’s all for today!
- Modern JVM versions also name Java threads and you can measure them at the OS level
- If you’re interested in learning more about the Linux task state sampling approach, check out my other Linux performance & troubleshooting articles, hacking session videos and my Practical Linux Performance & Troubleshooting online training course too!
- Also, thanks to Lefred for notifying me about this MySQL improvement!
