Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-15213

UPDATEs are slow after instant ADD COLUMN

    Details

      Description

      Consider the following test case, test_instant_alter.sql (that was created mostly to illustrate how fast instant ADD COLUMN is relative to other statements against the table):

      show variables like '%version%';
      drop table if exists t;
      create table t(id int auto_increment primary key, c1 int);
      insert into t(c1) values (0);
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
      insert into t(c1) select rand()*1000 from t;
       
      select count(*) from t;
      show table status like 't'\G
      analyze table t;
      show table status like 't'\G
       
      alter table t add column c2 char(200) default repeat('a',200);
       
      show table status like 't'\G
       
      update t set c2 = 'b'; -- 1
      update t set c2 = 'c'; -- 2
      update t set c2 = 'd'; -- 3
       
      analyze table t;
      show table status like 't'\G
      optimize table t;
      show table status like 't'\G
       
      show create table t\G
       
      alter table t force;
      update t set c2 = 'e'; -- 4
      update t set c2 = 'f'; -- 5
       
      analyze table t;
      show table status like 't'\G
      

      To prove the point (how fast is instant ALTER TABLE ... ADD COLUMN is and how much it influeces later changes to the rows of the table), I run it under MariaDB 10.3.5, 10.2.12 and Percona Server 5.7.20.

      It turned out that while ALTER TABLE itself is indeed instant in 10.3.5, subsequent updates to all rows of the table that set non-default value to newly added column (marked with 1, 2 and 3 in the comments) are executed unexpectedly slow, both comparing to similar updates after full table rebuild (ALTER TABLE t FORCE, marked as 5 and 6 in the comments). Moreover, total time to run the entire test case is much worse on 10.35 comparing to 10.2.12 and other versions the same scenario was tested against.

      Results are as follows, for example on my Ubuntu 14.04 netbook:

      openxs@ao756:~/dbs/maria10.3$ time bin/mysql -vvv -uroot --socket=/tmp/mariadb.sock test <~/test_instant_alter.sql > ~/instant_1035_new_innodb.txt
       
      real    6m46.066s
      user    0m0.022s
      sys     0m0.004s
       
      openxs@ao756:~/dbs/maria10.2$ time bin/mysql -vvv -uroot --socket=/tmp/mariadb.sock test <~/test_instant_alter.sql > ~/instant_10212_innodb.txt
       
      real    4m35.802s
      user    0m0.014s
      sys     0m0.013s
      

      or the following on Fedroa 27 quadcore box:

      [openxs@fc23 maria10.3]$ time bin/mysql -vvv -uroot --socket=/tmp/mariadb.sock test <~/test_instant_alter.sql > ~/instant_1035_innodb.txt
       
      real    5m40.820s
      user    0m0.009s
      sys     0m0.005s
       
      [openxs@fc23 maria10.2]$ time bin/mysql -vvv -uroot --socket=/tmp/mariadb.sock test <~/test_instant_alter.sql > ~/instant_10213_innodb.txt
       
      real    3m46.452s
      user    0m0.011s
      sys     0m0.003s
      

      In all cases servers where freshly installed and started with --no-defaults, like this:

      openxs@ao756:~$ bin/mysqld_safe --no-defaults --port=3308 --socket=/tmp/mariadb.sock &
      

      Relative times of individual statements were as follows, for example:

      --------------
      alter table t add column c2 char(200) default repeat('a',200)
      --------------
       
      Query OK, 0 rows affected (0.035 sec)
      Records: 0  Duplicates: 0  Warnings: 0
       
      --------------
      show table status like 't'
      --------------
       
      *************************** 1. row ***************************
                 Name: t
               Engine: InnoDB
              Version: 11
           Row_format: Dynamic
                 Rows: 523848
       Avg_row_length: 31
          Data_length: 16269312
      Max_data_length: 0
         Index_length: 0
            Data_free: 4194304
       Auto_increment: 786406
          Create_time: 2018-02-05 15:04:54
          Update_time: 2018-02-05 15:04:54
           Check_time: NULL
            Collation: latin1_swedish_ci
             Checksum: NULL
       Create_options:
              Comment:
      1 row in set (0.000 sec)
       
      --------------
      update t set c2 = 'b'
      --------------
       
      Query OK, 524288 rows affected (56.504 sec)
      Rows matched: 524288  Changed: 524288  Warnings: 0
       
      --------------
      update t set c2 = 'c'
      --------------
       
      Query OK, 524288 rows affected (56.892 sec)
      Rows matched: 524288  Changed: 524288  Warnings: 0
       
      --------------
      update t set c2 = 'd'
      --------------
       
      Query OK, 524288 rows affected (1 min 3.755 sec)
      Rows matched: 524288  Changed: 524288  Warnings: 0
       
      ...
      --------------
      alter table t force
      --------------
       
      Query OK, 0 rows affected (39.913 sec)
      Records: 0  Duplicates: 0  Warnings: 0
       
      --------------
      update t set c2 = 'e'
      --------------
       
      Query OK, 524288 rows affected (27.636 sec)
      Rows matched: 524288  Changed: 524288  Warnings: 0
       
      --------------
      update t set c2 = 'f'
      --------------
       
      Query OK, 524288 rows affected (1 min 35.323 sec)
      Rows matched: 524288  Changed: 524288  Warnings: 0
      

      In case of 10.2.12 we see:

      --------------
      alter table t add column c2 char(200) default repeat('a',200)
      --------------
       
      Query OK, 0 rows affected (30.02 sec)
      Records: 0  Duplicates: 0  Warnings: 0
       
      --------------
      show table status like 't'
      --------------
       
      *************************** 1. row ***************************
                 Name: t
               Engine: InnoDB
              Version: 11
           Row_format: Dynamic
                 Rows: 516360
       Avg_row_length: 289
          Data_length: 149569536
      Max_data_length: 0
         Index_length: 0
            Data_free: 5242880
       Auto_increment: 786406
          Create_time: 2018-01-30 19:18:45
          Update_time: NULL
           Check_time: NULL
            Collation: latin1_swedish_ci
             Checksum: NULL
       Create_options:
              Comment:
      1 row in set (0.00 sec)
       
      --------------
      update t set c2 = 'b'
      --------------
       
      Query OK, 524288 rows affected (27.39 sec)
      Rows matched: 524288  Changed: 524288  Warnings: 0
       
      --------------
      update t set c2 = 'c'
      --------------
       
      Query OK, 524288 rows affected (32.87 sec)
      Rows matched: 524288  Changed: 524288  Warnings: 0
       
      --------------
      update t set c2 = 'd'
      --------------
       
      Query OK, 524288 rows affected (32.98 sec)
      Rows matched: 524288  Changed: 524288  Warnings: 0
      

      So, on 10.3.5 the time to execute UPDATE varies a lot, but is larger than in 10.2.12 after normal ALTER, and also those executed immediately after ALTER are usually slower.

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                axel Axel Schwenke
                Reporter:
                valerii Valerii Kravchuk
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: