[MDEV-15213] UPDATEs are slow after instant ADD COLUMN - Jira

XML

Word

Printable

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Won't Fix
Affects Version/s: 10.3.5
Fix Version/s: 10.3.6
Component/s: Data Definition - Alter Table, Data Manipulation - Update
Labels:
- regression
Environment:
Ubuntu 14.04, Fedora 27

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

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

scaling.png
35 kB
2018-04-16 10:38

Issue Links

relates to

MDEV-15914 performance regression for mass update

Closed

Activity

People

Assignee:: Axel Schwenke

Reporter:: Valerii Kravchuk

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Dates

Created:: 2018-02-05 17:47

Updated:: 2023-12-14 12:33

Resolved:: 2018-04-19 09:42

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.