Troubleshooting High Disk IO Utilization in Linux

1. Background Introduction

As a DBA, it is inevitable to encounter performance issues. How should we troubleshoot when we face performance problems? For instance, under high concurrency, if we experience slow business response and long processing times, how do we start the investigation? This article will analyze how to diagnose and locate issues when IO is high.

2. Environment Reproduction

  • Environment Configuration: This test uses a 128C_512G_4T SSD server configuration, and the MySQL version is 8.0.27.
  • Scenario Simulation: Using sysbench to create 5 tables, each with 200 million rows, executing SQL statements that produce Cartesian product queries, generating IO to simulate business pressure. First, use sysbench for data stress testing.

3. System-Level Fault Diagnosis

Shell> sysbench --test=/usr/local/share/sysbench/oltp_insert.lua --mysql-host=XXX --mysql-port=3306 --mysql-user=pcms --mysql-password=abc123 --mysql-db=sysbench --percentile=99 --table-size=2000000000 --tables=5 --threads=1000 prepare

Using sysbench to simulate high concurrency.

shell> sysbench --test=/usr/local/share/sysbench/oltp_write_only.lua --mysql-host=xxx --mysql-port=3306 --mysql-user=pcms --mysql-password=abc123 --mysql-db=sysbench --percentile=99 --table-size=2000000000 --tables=5 --threads=1000 --max-time=60000 --report-interval=1 --threads=1000 --max-requests=0 --mysql-ignore-errors=all run

Executing Cartesian product SQL statement.

mysql> select SQL_NO_CACHE b.id,a.k from sbtest_a a left join sbtest_b b on a.id=b.id group by a.k order by b.c desc;

3.1 Check Current Server Status

shell> top
top - 19:49:05 up 10 days,  8:16,  2 users,  load average: 72.56, 40.21, 17.08
Tasks: 1288 total,   1 running, 586 sleeping,   0 stopped,   0 zombie
%Cpu(s): 19.7 us,  4.2 sy,  0.0 ni, 75.9 id,  1.0 wa,  0.0 hi,  0.2 si,  0.0 st
KiB Mem : 53542118+total, 23667507+free, 22735366+used, 71392448 buff/cache
KiB Swap:        0 total,        0 free,        0 used. 23128006+avail Mem

From the above, we can see: the current one-minute load is 72.56, and it is on the rise, indicating there is IO pressure.

3.2 Check the IO Status of Current Disk Devices

shell> iostat -m -x 1
Linux 4.14.0-115.el7a.0.1.aarch64 (mysql-4)  01/08/2022  _aarch64_ (128 CPU)
Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00     0.00 14213.00 27430.00   222.08   465.15    33.80     5.39    0.13    0.14    0.12   0.02  86.00
sdb               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-1              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-2              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

From the above, it can be seen that there are multiple physical disks, and the IO pressure on the sda disk is relatively high.

3.3 Check the Current IO Read and Write Status of the sda Disk

shell> iostat -d /dev/sda -m -x 1
Linux 4.14.0-115.el7a.0.1.aarch64 (mysql-4)  01/08/2022  _aarch64_ (128 CPU)
Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda            0.00     0.17    7.86   81.23     0.29     3.96    97.88     0.23    2.53    0.22    2.76   0.04   0.33
Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda            0.00     0.00 21109.00 42839.00   329.81   710.90    33.33    19.47    0.30    0.16    0.37   0.02  96.00
Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda            0.00     0.00 19287.00 41404.00   301.36   692.29    33.53    15.73    0.26    0.18    0.30   0.02  93.00
Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda            0.00     0.00 22135.00 43044.00   345.86  1165.18    47.48   100.87    1.55    0.20    2.24   0.01  97.00

From the above, it can be seen that the pressure on the sda disk is relatively high, with the write speed significantly greater than the read speed, indicating a large amount of IO writing currently.

3.4 Check Which Application is Using High IO on the sda Disk

shell> pidstat -d  1
Linux 4.14.0-115.el7a.0.1.aarch64 (mysql-4)  01/08/2022  _aarch64_ (128 CPU)
08:01:43 PM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
08:01:44 PM  1000     73739  62018.35 171346.79      0.00  mysqld
08:01:44 PM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
08:01:45 PM  1000     73739 145328.00 435216.00      0.00  mysqld
08:01:45 PM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
08:01:46 PM  1000     73739 141488.00 433232.00      0.00  mysqld

From the above, it can be seen that the application occupying high IO is mysql, with pid 73739.

3.5 Analyze Which Thread in the Application is Using High IO

shell> pidstat -dt -p 73739 1  Execute for two or three seconds
Average:     1000         -     73823      0.00 233133.98      0.00  |__mysqld
Average:     1000         -     74674      0.00 174291.26      0.00  |__mysqld
11:56:18 PM  1000         -     74770 124928.00  74688.00      0.00  |__mysqld
11:56:17 PM  1000         -     74770 124603.77  73358.49      0.00  |__mysqld
Average:     1000         -     74770 124761.17  74003.88      0.00  |__mysqld

From the above, it can be seen that the thread 74770 is using high IO.

3.6 Analyze What This Thread is Doing

Shell> perf trace -t 74770 -o /tmp/tmp_aa.pstrace
Shell> cat /tmp/tmp_aa.pstrace
  2850.656 ( 1.915 ms): futex(uaddr: 0x653ae9c4, op: WAIT|PRIVATE_FLAG, val: 1)               = 0
  2852.572 ( 0.001 ms): futex(uaddr: 0x653ae990, op: WAKE|PRIVATE_FLAG, val: 1)               = 0
  2852.601 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68)             = 0
  2852.690 ( 0.040 ms): write(fd: 159, buf: 0xd7a30020, count: 65536)                         = 65536
  2852.796 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68)             = 0
  2852.798 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f58)             = 0
  2852.939 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f38)             = 0
  2852.950 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68)             = 0
  2852.977 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68)             = 0
  2853.029 ( 0.035 ms): write(fd: 64, buf: 0xcd51e020, count: 65536)                          = 65536
  2853.164 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f68)             = 0
  2853.167 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f58)             = 0
  2853.302 ( 0.001 ms): clock_gettime(which_clock: MONOTONIC, tp: 0xfff7bd470f38)             = 0

From the above, it can be seen that this thread is currently writing multiple files, with file descriptors being 64 and 159.

3.7 Check What These File Descriptors Are

shell> lsof -p 73739|grep 159u
mysqld 73739 mysql  159u   REG                8,0   212143246  7046482357 /mysql/mysqldata/16320fff-5fd5-4c47-889a-a9e1a8591d0d/tmp/#7046482357 (deleted)
[root@mysql-4 ~]# lsof -p 73739|grep 64u
mysqld 73739 mysql   64u   REG                8,0   211872724  6979323031 /mysql/mysqldata/16320fff-5fd5-4c47-889a-a9e1a8591d0d/tmp/#6979323031 (deleted)

From the above, it can be seen that this thread is writing a large number of temporary files.

4. Analyze MySQL Application

4.1 Check the Current Session List

mysql> select * from information_schema.processlist where command !='sleep';
|  9 | pcms             | 172.16.76.12:57596 | sysbench | Query            |   67 | executing                                                     | select SQL_NO_CACHE b.id,a.k from sbtest_a a left join sbtest_b b on a.id=b.id group by a.k order by b.c desc |   66477 |         0 |             0 |

From the above, it can be seen that this SQL has been executing for 67 seconds, and this SQL uses group by and order by, which will inevitably generate IO.

4.2 Query Session by Thread ID

mysql> select * from threads where thread_os_id=74770\\G;
*************************** 1. row ***************************
          THREAD_ID: 95
               NAME: thread/sql/one_connection
               TYPE: FOREGROUND
     PROCESSLIST_ID: 9
   PROCESSLIST_USER: pcms
   PROCESSLIST_HOST: 172.16.76.12
     PROCESSLIST_DB: sysbench
PROCESSLIST_COMMAND: Query
   PROCESSLIST_TIME: 91
  PROCESSLIST_STATE: NULL
   PROCESSLIST_INFO: select SQL_NO_CACHE b.id,a.k from sbtest_a a left join sbtest_b b on a.id=b.id group by a.k order by b.c desc
   PARENT_THREAD_ID: 1
               ROLE: NULL
       INSTRUMENTED: YES
            HISTORY: YES
    CONNECTION_TYPE: TCP/IP
       THREAD_OS_ID: 74770
     RESOURCE_GROUP: USR_default
1 row in set (0.00 sec)

From the above, it can be seen that by querying the threads table, it can be verified that this thread frequently creates temporary tables, which is due to this SQL.

4.3 Check the Execution Plan of This SQL Statement for Further Confirmation

mysql> explain select SQL_NO_CACHE b.id,a.k from sbtest_a a left join sbtest_b b on a.id=b.id group by a.k order by b.c desc\G;
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: a
   partitions: NULL
         type: ALL
possible_keys: NULL
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 1
     filtered: 100.00
        Extra: Using temporary; Using filesort
*************************** 2. row ***************************
           id: 1
  select_type: SIMPLE
        table: b
   partitions: NULL
         type: eq_ref
possible_keys: PRIMARY
          key: PRIMARY
      key_len: 4
          ref: sysbench.a.id
         rows: 1
     filtered: 100.00
        Extra: NULL
2 rows in set, 2 warnings (0.00 sec)

From the above, it can be seen that the execution plan of this SQL uses temporary tables and temporary files, which matches our previous investigation expectations.

4.4 Check Global Status for Further Confirmation

mysql> show global status like '%tmp%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 3     |
| Created_tmp_files       | 22    |
| Created_tmp_tables      | 8     |
+-------------------------+-------+

By executing it several times, we can see that the values of tmp_files and tmp_disk_tables are increasing, indicating a large number of temporary files and disk temporary tables are being created, which matches the behavior of this thread.

5. Fault Handling

Through the above series of checks, we have analyzed that the sda disk currently has the highest IO utilization, and the mysqld program occupies the most. Through investigation, we found that a thread is frequently creating temporary tables or temporary files, and by logging into MySQL to check the session and thread view, we can find that it is caused by a slow SQL. Checking the execution plan of this slow SQL will also create temporary tables and temporary files, which is consistent with our previous investigation expectations. At this point, we need to optimize this slow SQL, and the optimization steps will be handled by the DBA, which will be ignored here. After the slow SQL optimization is completed, we can continue to observe IO to see if there is a decrease.

6. Code Analysis

We can use pstack to trace the thread number and obtain the current thread stack information. Remember that pstack will call gdb for debugging.

shell> pstack 74770 >/tmp/74770.pstack
Thread 1 (process 74770):
#0  ha_innobase::general_fetch (this=0xea654228, buf=0xea662028 "\212t\317\030\002", direction=1, match_mode=0  ) at /builds/naiwei.fang/percona-server/storage/innobase/handler/ha_innodb.cc:11159
#1  0x0000000000d9913c in handler::ha_rnd_next (this=0xea654228, buf=0xea662028 "\212t\317\030\002") at /builds/naiwei.fang/percona-server/sql/handler.cc:3173
#2  0x0000000000f77db0 in TableScanIterator::Read (this=0xd256d5e8) at /builds/naiwei.fang/percona-server/sql/row_iterator.h:208
#3  0x000000000124c714 in WriteRowsToChunks (xxhash_seed=899339, write_to_build_chunk=true, write_rows_with_null_in_join_key=false, join_key_buffer=0xd01fdb98, tables_to_get_rowid_for=0, chunks=0xd01fdb58, join_conditions=..., tables=..., iterator=0xd256d5e8, thd=0xdb888000) at /builds/naiwei.fang/percona-server/sql/hash_join_iterator.cc:282
#4  HashJoinIterator::BuildHashTable (this=this@entry=0xd01fd028) at /builds/naiwei.fang/percona-server/sql/hash_join_iterator.cc:495
#5  0x000000000124c8ac in Init (this=0xd01fd028) at /builds/naiwei.fang/percona-server/sql/hash_join_iterator.cc:203
#6  HashJoinIterator::Init (this=0xd01fd028) at /builds/naiwei.fang/percona-server/sql/hash_join_iterator.cc:145
#7  0x00000000010eca14 in Query_expression::ExecuteIteratorQuery (this=0xdec3a8b8, thd=thd@entry=0xdb888000) at /builds/naiwei.fang/percona-server/sql/sql_union.cc:1224
#8  0x00000000010ecccc in Query_expression::execute (this=this@entry=0xdec3a8b8, thd=thd@entry=0xdb888000) at /builds/naiwei.fang/percona-server/sql/sql_union.cc:1284
#9  0x0000000001083db0 in Sql_cmd_dml::execute_inner (this=0xd256bcb0, thd=0xdb888000) at /builds/naiwei.fang/percona-server/sql/sql_select.cc:791
#10 0x000000000108cac8 in Sql_cmd_dml::execute (this=0xd256bcb0, thd=0xdb888000) at /builds/naiwei.fang/percona-server/sql/sql_select.cc:575
#11 0x00000000010384e8 in mysql_execute_command (thd=thd@entry=0xdb888000, first_level=first_level@entry=true) at /builds/naiwei.fang/percona-server/sql/sql_parse.cc:4677
#12 0x000000000103b314 in dispatch_sql_command (thd=thd@entry=0xdb888000, parser_state=parser_state@entry=0xfff7bd4735b0, update_userstat=update_userstat@entry=false) at /builds/naiwei.fang/percona-server/sql/sql_parse.cc:5273
#13 0x000000000103ccf0 in dispatch_command (thd=thd@entry=0xdb888000, com_data=0xffffb467c4d0, com_data@entry=0xfff7bd474640, command=COM_QUERY) at /builds/naiwei.fang/percona-server/sql/sql_parse.cc:1938
#14 0x000000000103da40 in do_command (thd=thd@entry=0xdb888000) at /builds/naiwei.fang/percona-server/sql/sql_parse.cc:1386
#15 0x0000000001152ca8 in handle_connection (arg=arg@entry=0xda53ab10) at /builds/naiwei.fang/percona-server/sql/conn_handler/connection_handler_per_thread.cc:307
#16 0x00000000022bc3ec in pfs_spawn_thread (arg=<optimized out>) at /builds/naiwei.fang/percona-server/storage/perfschema/pfs.cc:2899
#17 0x0000ffffb43c7c48 in start_thread () from /lib64/libpthread.so.0
#18 0x0000ffffb3c0f600 in thread_start () from /lib64/libc.so.6

Enjoy Great SQL 🙂

《Practical MGR》 Video Course

Click this mini program to directly reach B station

Or copy the link and open it in the browser

  • https://space.bilibili.com/136385008

Recommended Articles:

  • Technical Sharing | Why MGRA Consistency Mode is Not Recommended

  • Great SQL Quarterly Report (2021.12.26)

  • Wanda #18, How to Quickly Recover the Expanding Undo Table Space in MySQL 8.0

  • Wanda #15, What Situations Can Cause MGRA Service to Fail to Start

  • MySQL High Availability Architecture Evolution and Practice

  • Technical Sharing | Load Data Causes Primary Key Loss Mystery

About Great SQL:

Great SQL is a community dedicated to improving MySQL database maintenance.

Follow us for more technical good articles, click on “Watch”!

We can also be directly added by scanning the code to join the Great SQL community.

WeChat Group: Great SQL Community

Troubleshooting High Disk IO Utilization in Linux

Join QQ Group: Great SQL Community

Troubleshooting High Disk IO Utilization in Linux

Want to see more technical good articles, click on “Watch”!

Related posts

  1. Real-Time Scheduling Strategies for AI Quality Inspection Systems Enabled by Multi-Access Edge Computing
  2. Linux MySQL Installation Tutorial
  3. Installation and Basic Operations of GIT in Embedded Linux

Leave a Comment