Monitoring an online MySQL ALTER TABLE using Performance Schema

Recently a client asked me how long it would take for an ALTER TABLE to complete. Generally the answer is “it depends”. While this was running on a production system I tried with the Performance Schema in MySQL 5.6 to work out some answer to this question. While I never got to investigate various tests using INPLACE and COPY for comparison, Morgan Tocker made the request for experiences with online ALTER in A closer look at Online DDL in MySQL 5.6. Hopefully somebody with more time can expand on my preliminary observations.

Using Mark Leith’s ps_helper (older version) I monitored the File I/O to see if I could determine when using innodb_file_per_table the percentage of table writing to be completed.

Other data access on this slave server was disabled, so these results represent the I/O of a single ALTER TABLE statement.

  • We can clearly see the reading of the Txxxxxxxxxxxxxx.ibd table,starting at 4.03G, then 7.79G, and following that a peak of 9.75 GB.
  • We see the writing of Txxxxxxxxxxxxxx.ibd in the last samples, and it completes 9.85 GB, the “write_pct” is shows ~50%, a good indicator of a total read and write of the table
  • What we also see is an “Innodb Merge Temp File” which is initially all writes, an indication of what may be a “copy”, however what is *interesting* is the amount of reads and writes are 6X the size of the underlying table
  • Recall that this server is effectively *idle*, so there is no need to be keeping version information of actual table changes
  • This “Innodb Merge Temp File” also works in 1MB chunks, so comparing the “count” values between the base table of 16K operations can be misleading if you just look at count deltas during the process.

Given more time, I would have performed more extensive monitoring including timestamps, and run a test using the COPY algorithm to see if this took less time.

Sample 1

mysql> select * from ps_helper.io_global_by_file_by_bytes limit 10;
+---------------------------------------------+------------+------------+-----------+-------------+---------------+-----------+-----------+-----------+
| file                                        | count_read | total_read | avg_read  | count_write | total_written | avg_write | total     | write_pct |
+---------------------------------------------+------------+------------+-----------+-------------+---------------+-----------+-----------+-----------+
| @@datadir/nsikeyword/Txxxxxxxxxxxxxx.ibd    |     264207 | 4.03 GiB   | 16.00 KiB |         191 | 2.98 MiB      | 16.00 KiB | 4.03 GiB  |      0.07 |
| @@datadir/Innodb Merge Temp File            |          0 | 0 bytes    | 0 bytes   |        1912 | 1.87 GiB      | 1.00 MiB  | 1.87 GiB  |    100.00 |
| @@datadir/ibdata1                           |        412 | 8.41 MiB   | 20.89 KiB |         693 | 46.52 MiB     | 68.73 KiB | 54.92 MiB |     84.69 |
| @@datadir/ib_logfile1                       |          2 | 64.50 KiB  | 32.25 KiB |       16670 | 11.92 MiB     | 750 bytes | 11.98 MiB |     99.47 |
| /mysql/binlog/mysql-relay-bin.003236        |        749 | 5.85 MiB   | 8.00 KiB  |       49943 | 5.85 MiB      | 123 bytes | 11.70 MiB |     50.00 |
| @@datadir/mysql/slave_master_info.ibd       |          4 | 64.00 KiB  | 16.00 KiB |           0 | 0 bytes       | 0 bytes   | 64.00 KiB |      0.00 |
| @@datadir/mysql/slave_relay_log_info.ibd    |          4 | 64.00 KiB  | 16.00 KiB |           0 | 0 bytes       | 0 bytes   | 64.00 KiB |      0.00 |
| @@datadir/mysql/slave_worker_info.ibd       |          4 | 64.00 KiB  | 16.00 KiB |           0 | 0 bytes       | 0 bytes   | 64.00 KiB |      0.00 |
+---------------------------------------------+------------+------------+-----------+-------------+---------------+-----------+-----------+-----------+

Sample 2

mysql> select * from ps_helper.io_global_by_file_by_bytes limit 10;
+---------------------------------------------+------------+------------+-----------+-------------+---------------+-----------+-----------+-----------+
| file                                        | count_read | total_read | avg_read  | count_write | total_written | avg_write | total     | write_pct |
+---------------------------------------------+------------+------------+-----------+-------------+---------------+-----------+-----------+-----------+
| @@datadir/nsikeyword/Txxxxxxxxxxxxxx.ibd    |     510483 | 7.79 GiB   | 16.00 KiB |         191 | 2.98 MiB      | 16.00 KiB | 7.79 GiB  |      0.04 |
| @@datadir/Innodb Merge Temp File            |          0 | 0 bytes    | 0 bytes   |        3517 | 3.43 GiB      | 1.00 MiB  | 3.43 GiB  |    100.00 |
| @@datadir/ibdata1                           |        412 | 8.41 MiB   | 20.89 KiB |         693 | 46.52 MiB     | 68.73 KiB | 54.92 MiB |     84.69 |
| @@datadir/ib_logfile1                       |          2 | 64.50 KiB  | 32.25 KiB |       16670 | 11.92 MiB     | 750 bytes | 11.98 MiB |     99.47 |
| /mysql/binlog/mysql-relay-bin.003236        |        749 | 5.85 MiB   | 8.00 KiB  |       49943 | 5.85 MiB      | 123 bytes | 11.70 MiB |     50.00 |
| @@datadir/mysql/slave_master_info.ibd       |          4 | 64.00 KiB  | 16.00 KiB |           0 | 0 bytes       | 0 bytes   | 64.00 KiB |      0.00 |
| @@datadir/mysql/slave_relay_log_info.ibd    |          4 | 64.00 KiB  | 16.00 KiB |           0 | 0 bytes       | 0 bytes   | 64.00 KiB |      0.00 |
| @@datadir/mysql/slave_worker_info.ibd       |          4 | 64.00 KiB  | 16.00 KiB |           0 | 0 bytes       | 0 bytes   | 64.00 KiB |      0.00 |
+---------------------------------------------+------------+------------+-----------+-------------+---------------+-----------+-----------+-----------+

Sample 3

mysql> select * from ps_helper.io_global_by_file_by_bytes limit 10;
+---------------------------------------------+------------+------------+-----------+-------------+---------------+-----------+------------+-----------+
| file                                        | count_read | total_read | avg_read  | count_write | total_written | avg_write | total      | write_pct |
+---------------------------------------------+------------+------------+-----------+-------------+---------------+-----------+------------+-----------+
| @@datadir/Innodb Merge Temp File            |      19503 | 19.05 GiB  | 1.00 MiB  |       23798 | 23.24 GiB     | 1.00 MiB  | 42.29 GiB  |     54.96 |
| @@datadir/nsikeyword/Txxxxxxxxxxxxxx.ibd    |     638920 | 9.75 GiB   | 16.00 KiB |         191 | 2.98 MiB      | 16.00 KiB | 9.75 GiB   |      0.03 |
| @@datadir/ibdata1                           |        412 | 8.41 MiB   | 20.89 KiB |         693 | 46.52 MiB     | 68.73 KiB | 54.92 MiB  |     84.69 |
| @@datadir/ib_logfile1                       |          2 | 64.50 KiB  | 32.25 KiB |       16670 | 11.92 MiB     | 750 bytes | 11.98 MiB  |     99.47 |
| /mysql/binlog/mysql-relay-bin.003236        |        749 | 5.85 MiB   | 8.00 KiB  |       49943 | 5.85 MiB      | 123 bytes | 11.70 MiB  |     50.00 |
| @@datadir/mysql/proc.MYD                    |        692 | 423.96 KiB | 627 bytes |           0 | 0 bytes       | 0 bytes   | 423.96 KiB |      0.00 |
| @@datadir/mysql/slave_master_info.ibd       |          4 | 64.00 KiB  | 16.00 KiB |           0 | 0 bytes       | 0 bytes   | 64.00 KiB  |      0.00 |
| @@datadir/mysql/slave_relay_log_info.ibd    |          4 | 64.00 KiB  | 16.00 KiB |           0 | 0 bytes       | 0 bytes   | 64.00 KiB  |      0.00 |
+---------------------------------------------+------------+------------+-----------+-------------+---------------+-----------+------------+-----------+

Sample 4

mysql> select * from ps_helper.io_global_by_file_by_bytes limit 10;
+---------------------------------------------+------------+------------+-----------+-------------+---------------+-----------+------------+-----------+
| file                                        | count_read | total_read | avg_read  | count_write | total_written | avg_write | total      | write_pct |
+---------------------------------------------+------------+------------+-----------+-------------+---------------+-----------+------------+-----------+
| @@datadir/Innodb Merge Temp File            |      36865 | 36.00 GiB  | 1.00 MiB  |       41160 | 40.20 GiB     | 1.00 MiB  | 76.20 GiB  |     52.75 |
| @@datadir/nsikeyword/Txxxxxxxxxxxxxx.ibd    |     638920 | 9.75 GiB   | 16.00 KiB |         191 | 2.98 MiB      | 16.00 KiB | 9.75 GiB   |      0.03 |
| @@datadir/ibdata1                           |        412 | 8.41 MiB   | 20.89 KiB |         693 | 46.52 MiB     | 68.73 KiB | 54.92 MiB  |     84.69 |
| @@datadir/ib_logfile1                       |          2 | 64.50 KiB  | 32.25 KiB |       16670 | 11.92 MiB     | 750 bytes | 11.98 MiB  |     99.47 |
| /mysql/binlog/mysql-relay-bin.003236        |        749 | 5.85 MiB   | 8.00 KiB  |       49943 | 5.85 MiB      | 123 bytes | 11.70 MiB  |     50.00 |
| @@datadir/mysql/proc.MYD                    |        692 | 423.96 KiB | 627 bytes |           0 | 0 bytes       | 0 bytes   | 423.96 KiB |      0.00 |
| @@datadir/mysql/slave_master_info.ibd       |          4 | 64.00 KiB  | 16.00 KiB |           0 | 0 bytes       | 0 bytes   | 64.00 KiB  |      0.00 |
| @@datadir/mysql/slave_relay_log_info.ibd    |          4 | 64.00 KiB  | 16.00 KiB |           0 | 0 bytes       | 0 bytes   | 64.00 KiB  |      0.00 |
+---------------------------------------------+------------+------------+-----------+-------------+---------------+-----------+------------+-----------+

Sample 5

mysql> select * from ps_helper.io_global_by_file_by_bytes limit 10;
+---------------------------------------------+------------+------------+-----------+-------------+---------------+------------+------------+-----------+
| file                                        | count_read | total_read | avg_read  | count_write | total_written | avg_write  | total      | write_pct |
+---------------------------------------------+------------+------------+-----------+-------------+---------------+------------+------------+-----------+
| @@datadir/Innodb Merge Temp File            |      57009 | 55.67 GiB  | 1.00 MiB  |       60144 | 58.73 GiB     | 1.00 MiB   | 114.41 GiB |     51.34 |
| @@datadir/nsikeyword/Txxxxxxxxxxxxxx.ibd    |     638922 | 9.75 GiB   | 16.00 KiB |       92839 | 2.56 GiB      | 28.88 KiB  | 12.31 GiB  |     20.78 |
| @@datadir/ibdata1                           |        412 | 8.41 MiB   | 20.89 KiB |        8081 | 1.44 GiB      | 186.98 KiB | 1.45 GiB   |     99.43 |
| @@datadir/ib_logfile0                       |          4 | 3.50 KiB   | 896 bytes |        4443 | 845.59 MiB    | 194.89 KiB | 845.60 MiB |    100.00 |
| @@datadir/ib_logfile1                       |          2 | 64.50 KiB  | 32.25 KiB |       19327 | 735.53 MiB    | 38.97 KiB  | 735.60 MiB |     99.99 |
| /mysql/binlog/mysql-relay-bin.003236        |        749 | 5.85 MiB   | 8.00 KiB  |       49943 | 5.85 MiB      | 123 bytes  | 11.70 MiB  |     50.00 |
| @@datadir/mysql/proc.MYD                    |        696 | 426.43 KiB | 627 bytes |           0 | 0 bytes       | 0 bytes    | 426.43 KiB |      0.00 |
| @@datadir/mysql/slave_master_info.ibd       |          4 | 64.00 KiB  | 16.00 KiB |           0 | 0 bytes       | 0 bytes    | 64.00 KiB  |      0.00 |
+---------------------------------------------+------------+------------+-----------+-------------+---------------+------------+------------+-----------+

Sample 6

mysql> select * from ps_helper.io_global_by_file_by_bytes limit 10;
+---------------------------------------------+------------+------------+-----------+-------------+---------------+------------+------------+-----------+
| file                                        | count_read | total_read | avg_read  | count_write | total_written | avg_write  | total      | write_pct |
+---------------------------------------------+------------+------------+-----------+-------------+---------------+------------+------------+-----------+
| @@datadir/Innodb Merge Temp File            |      60144 | 58.73 GiB  | 1.00 MiB  |       60144 | 58.73 GiB     | 1.00 MiB   | 117.47 GiB |     50.00 |
| @@datadir/nsikeyword/Txxxxxxxxxxxxxx.ibd    |     638922 | 9.75 GiB   | 16.00 KiB |      348927 | 9.85 GiB      | 29.61 KiB  | 19.60 GiB  |     50.27 |
| @@datadir/ibdata1                           |        427 | 8.64 MiB   | 20.72 KiB |       31941 | 5.30 GiB      | 173.84 KiB | 5.30 GiB   |     99.84 |
| @@datadir/ib_logfile0                       |          4 | 3.50 KiB   | 896 bytes |       15763 | 2.97 GiB      | 197.34 KiB | 2.97 GiB   |    100.00 |
| @@datadir/ib_logfile1                       |          2 | 64.50 KiB  | 32.25 KiB |       29864 | 2.72 GiB      | 95.62 KiB  | 2.72 GiB   |    100.00 |
| /mysql/binlog/mysql-relay-bin.003236        |        749 | 5.85 MiB   | 8.00 KiB  |       49943 | 5.85 MiB      | 123 bytes  | 11.70 MiB  |     50.00 |
| @@datadir/mysql/proc.MYD                    |        700 | 428.89 KiB | 627 bytes |           0 | 0 bytes       | 0 bytes    | 428.89 KiB |      0.00 |
| @@datadir/mysql/innodb_index_stats.ibd      |          5 | 80.00 KiB  | 16.00 KiB |           1 | 16.00 KiB     | 16.00 KiB  | 96.00 KiB  |     16.67 |
+---------------------------------------------+------------+------------+-----------+-------------+---------------+------------+------------+-----------+

Comments

  1. says

    This is a known issue :

    Bug 17657223 – EXCESSIVE TEMPORARY FILE USAGE IN ALTER TABLE

    see also : Bug 15940619 – OPTIMIZE THE REDO LOG WRITES RELATED TO INDEX CREATION