MariaDB 10.1.1: Monitoring progress and temporal memory usage of Online DDL in InnoDB

Introduction

Online DDL is a new feature in MariaDB 10.0. Online DDL is processed through below 4 tasks in sequence.

  1. InnoDB::ha_prepare_inplace_alter_table(..)
  2. InnoDB::ha_inplace_alter_table(..)
  3. InnoDB::ha_commit_inplace_alter_table(..)
  4. mysql_rename_table(..)

InnoDB storage engine allocates temporal memory buffer for transaction logging in phase 1 where row changes during this phase are logged. Size of this buffer is at start sort_buffer_size and it can be grown up to innodb_online_alter_log_max size. During phase 2 thread processing the ALTER statement will copy old table’s rows to a new altered table. After this MariaDB will take exclusive lock for target table and applies row log buffer to the new altered table.

This introduces a new unpredictable failure case row log buffer overflow. MariaDB server will rollback ALTER statement if row log buffer overflows. Thus, there is following problems:

  • If row log buffer size is too small the ALTER statement is rolled back and you have wasted precious time and resources.
  • If row log buffer is too big, you have wasted precious main-memory that could be used e.g. for buffer pool.
  • Currently, there is no way to see how much row log buffer is used and how much there is free space.
  • Currently, there is not even estimate how much work has been done and how much there is till to be done.
  • Currently, merge sort phase could also take a long time and there is no progress information.

Improvements

There is two improvements in MariaDB 10.1: new status variables and progress information for online DDL.

New status variables and progress info

MariaDB Corporation would like to thank Matt, Seong Uck Lee from Kakao for contributing a patch that has now merged to MariaDB 10.1.

First of all there is three new global status variables.

  • Innodb_onlineddl_rowlog_rows: Shows how many rows is stored in the row log buffer.
  • Innodb_onlineddl_rowlog_pct_used: Shows row log buffer usage in 5-digit integer  (10000 means 100.00% ).
  • Innodb_onlineddl_pct_progress: Shows the progress of in-place alter table. It might be not so accurate because in-place alter is highly dependent on disk and buffer pool status.

Lets consider as an example where we have InnoDB table containing 150000 rows and we try to add a new column.

CREATE TABLE tb_onlineddl1 (
pk1 int(11) NOT NULL,
pk2 bigint(20) NOT NULL,
fd1 bigint(20) DEFAULT NULL,
fd2 bigint(20) DEFAULT NULL,
fd3 datetime DEFAULT NULL,
fd4 text,
fd5 varchar(50) DEFAULT NULL,
fd6 bigint(20) DEFAULT NULL,
fd7 bigint(20) DEFAULT NULL,
PRIMARY KEY (pk1, pk2),
UNIQUE KEY ux1 (pk2, pk1),
KEY ix1 (fd6, fd7)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;

ALTER TABLE tb_onlineddl1 ADD x VARCHAR(5), LOCK=NONE, ALGORITHM=INPLACE;

Concurrently, if we add new row, update some rows and delete few rows

insert into tb_onlineddl1 values (200000, 200000, 1,1, NULL,'insert', 'insert', 1,1);
update tb_onlineddl1 set fd5='update' where pk1 between 2000 and 3000;
delete from tb_onlineddl1 where pk1 between 6000 and 7000;
show status like 'Innodb_onlineddl%';

Variable_name	Value
Innodb_onlineddl_rowlog_rows	2003
Innodb_onlineddl_rowlog_pct_used	26
Innodb_onlineddl_pct_progress	5677

This means that at the time of status statement there were 2003 rows on row log, 23% of memory allocated for row log is used, and online alter table has completed 56.77% of it’s work.

There is also additional output at error log, as example:

141022 15:49:59 [Note] InnoDB: Online DDL : Start
141022 15:49:59 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
141022 15:50:01 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
141022 15:50:01 [Note] InnoDB: Online DDL : Start merge-sorting index PRIMARY (1 / 3), estimated cost : 18.0263
141022 15:50:01 [Note] InnoDB: Online DDL : merge-sorting has estimated 33 runs
141022 15:50:01 [Note] InnoDB: Online DDL : merge-sorting current run 1 estimated 33 runs
141022 15:50:01 [Note] InnoDB: Online DDL : merge-sorting current run 2 estimated 17 runs
141022 15:50:01 [Note] InnoDB: Online DDL : merge-sorting current run 3 estimated 9 runs
141022 15:50:01 [Note] InnoDB: Online DDL : merge-sorting current run 4 estimated 5 runs
141022 15:50:01 [Note] InnoDB: Online DDL : merge-sorting current run 5 estimated 3 runs
141022 15:50:02 [Note] InnoDB: Online DDL : merge-sorting current run 6 estimated 2 runs
141022 15:50:02 [Note] InnoDB: Online DDL : End of  merge-sorting index PRIMARY (1 / 3)
141022 15:50:02 [Note] InnoDB: Online DDL : Start building index PRIMARY (1 / 3), estimated cost : 27.0395
141022 15:50:11 [Note] InnoDB: Online DDL : End of building index PRIMARY (1 / 3)
141022 15:50:11 [Note] InnoDB: Online DDL : Completed
141022 15:50:11 [Note] InnoDB: Online DDL : Start merge-sorting index ux1 (2 / 3), estimated cost : 5.7895
141022 15:50:11 [Note] InnoDB: Online DDL : merge-sorting has estimated 2 runs
141022 15:50:11 [Note] InnoDB: Online DDL : merge-sorting current run 1 estimated 2 runs
141022 15:50:11 [Note] InnoDB: Online DDL : End of  merge-sorting index ux1 (2 / 3)
141022 15:50:11 [Note] InnoDB: Online DDL : Start building index ux1 (2 / 3), estimated cost : 8.6842
141022 15:50:17 [Note] InnoDB: Online DDL : End of building index ux1 (2 / 3)
141022 15:50:17 [Note] InnoDB: Online DDL : Completed
141022 15:50:17 [Note] InnoDB: Online DDL : Start merge-sorting index ix1 (3 / 3), estimated cost : 6.1842
141022 15:50:17 [Note] InnoDB: Online DDL : merge-sorting has estimated 3 runs
141022 15:50:17 [Note] InnoDB: Online DDL : merge-sorting current run 1 estimated 3 runs
141022 15:50:17 [Note] InnoDB: Online DDL : merge-sorting current run 2 estimated 2 runs
141022 15:50:17 [Note] InnoDB: Online DDL : End of  merge-sorting index ix1 (3 / 3)
141022 15:50:17 [Note] InnoDB: Online DDL : Start building index ix1 (3 / 3), estimated cost : 9.2763
141022 15:50:23 [Note] InnoDB: Online DDL : End of building index ix1 (3 / 3)
141022 15:50:23 [Note] InnoDB: Online DDL : Completed

Merge sort progress

Additionally, show processlist statement will output estimate of index merge sort progress, e.g.

MariaDB [test]> show processlist;
+----+------+-----------+------+---------+------+----------------+--------------------------------------------------------------------------+----------+
| Id | User | Host      | db   | Command | Time | State          | Info                                                                     | Progress |
+----+------+-----------+------+---------+------+----------------+--------------------------------------------------------------------------+----------+
|  3 | root | localhost | test | Sleep   |   23 |                | NULL                                                                     |    0.000 |
|  4 | root | localhost | test | Query   |    0 | init           | show processlist                                                         |    0.000 |
|  5 | root | localhost | test | Query   |   28 | altering table | ALTER TABLE tb_onlineddl1 ADD x VARCHAR(5), LOCK=NONE, ALGORITHM=INPLACE |    0.356 |
+----+------+-----------+------+---------+------+----------------+--------------------------------------------------------------------------+----------+
3 rows in set (0.00 sec)

Links

http://seonguck.blogspot.kr/2014/09/what-is-problem-of-mysql-online-ddl.html
http://kakao-dbe.blogspot.kr/2014/09/mysql-status-variables-for-innodb.html