[MDEV-8178] Wrong progress report for operations on InnoDB tables Created: 2015-05-19  Updated: 2015-12-10  Resolved: 2015-12-10

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.0, 10.1
Fix Version/s: 10.0.23, 10.1.10

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergey Vojtovich
Resolution: Fixed Votes: 2
Labels: None

Sprint: 10.0.23

 Description   

Initially reported on the mailing list: https://lists.launchpad.net/maria-discuss/msg02495.html .

Stage: 1 of 72 'altering table' 350% of stage done.

Reproducible as described.

Dataset: salaries table in the employees sample database.

Statements that exhibit the incorrect behaviour:

ALTER TABLE salaries ENGINE = Innodb;
 
ALTER TABLE salaries ADD id INT NULL;
 
ALTER TABLE salaries DROP id;
 
ALTER TABLE salaries ROW_FORMAT = COMPRESSED;

I also saw the mentioned 350% and some other values, e.g.

MariaDB [employees]> ALTER TABLE salaries ADD id INT NULL;
 
Stage: 1 of 85 'altering table'    200% of stage done

MyISAM looks reasonable (2 stages, below 100% progress).

Not reproducible on 5.5.
10.0 has a different problem – progress for InnoDB tables is not reported at all.



 Comments   
Comment by Jiri Kavalik [ 2015-06-19 ]

After MDEV-8179 it showed on 10.0.20 today:

optimize table sazky;
 
Stage: 1 of 149 'altering table'   1.33% of stage done
 
Stage: 1 of 149 'altering table'   15.8% of stage done
 
Stage: 1 of 149 'altering table'    100% of stage done
 
 -- until here tmp file has stable size of 320K, and only after getting to 100% it started to grow by some MB per second
 
Stage: 1 of 149 'altering table'    350% of stage done
 
Stage: 1 of 149 'altering table'    800% of stage done
 
Stage: 1 of 14 'altering table'   14.3% of stage done 
Stage: 1 of 10 'altering table'     20% of stage done 
Stage: 1 of 14 'altering table'   14.3% of stage done 
Stage: 1 of 15 'altering table'   12.5% of stage done 
Stage: 1 of 11 'altering table'   16.7% of stage done 
Stage: 1 of 9 'altering table'     20% of stage done  
Stage: 1 of 12 'altering table'   16.7% of stage done 
Stage: 1 of 18 'altering table'   11.1% of stage done 
Stage: 1 of 8 'altering table'     25% of stage done  
+----------------+----------+----------+-------------------------------------------------------------------+
 
| Table          | Op       | Msg_type | Msg_text                                                          |
 
+----------------+----------+----------+-------------------------------------------------------------------+
 
| vic_main.sazky | optimize | note     | Table does not support optimize, doing recreate + analyze instead |
 
| vic_main.sazky | optimize | status   | OK                                                                |
 
+----------------+----------+----------+-------------------------------------------------------------------+
 
2 rows in set (3 min 1.22 sec)
 

show table status like 'sazky'\G
 
*************************** 1. row ***************************
 
           Name: sazky
 
         Engine: InnoDB
 
        Version: 10
 
     Row_format: Compact
 
           Rows: 1138155
 
 Avg_row_length: 153
 
    Data_length: 174800896
 
Max_data_length: 0
 
   Index_length: 246022144
 
      Data_free: 0
 
...

Comment by Michaël de groot [ 2015-09-22 ]

I experienced this (InnoDB, 71 stages, up to 900%) on 10.0.21 as well.

Comment by Jean Weisbuch [ 2015-09-29 ]

I am hitting this bug on 10.0.21 but with another additional issue : The progress on the CLI starts but after few seconds get stuck and the "STAGE", "MAX_STAGE" and "PROGRESS" columns of "I_S.PROCESSLIST" are all showing 0 for the alter query.

Happened with an INDEX creation on an InnoDB table and on a "ALTER TABLE xxx KEY_BLOCK_SIZE=0" (on a table that had "ROW_FORMAT=DYNAMIC" and "KEY_BLOCK_SIZE=8").

Comment by Christian Rishøj [ 2015-11-17 ]

Still seeing this on 10.1.8:

MariaDB [music]> ALTER TABLE items ADD INDEX (datePriceChanged);
 
Stage: 1 of 207 'altering table'   5.77% of stage done
 
Stage: 1 of 207 'altering table'   15.4% of stage done
 
Stage: 1 of 207 'altering table'   38.5% of stage done
 
Stage: 1 of 207 'altering table'   85.7% of stage done
 
Stage: 1 of 207 'altering table'    175% of stage done
 
Stage: 1 of 207 'altering table'    400% of stage done
 
 

Comment by Tomas Mozes [ 2015-11-30 ]

Same problem with MariaDB 10.0.22 on Gentoo Linux (amd64).

MariaDB [db]> optimize table tbl;
Stage: 1 of 69 'altering table' 650% of stage done

MariaDB [db]> optimize table tbl;
Stage: 1 of 69 'altering table' 1.4e+03% of stage done

Comment by Jan Lindström (Inactive) [ 2015-11-30 ]

10.1: storage/[xtradb|innobase]/row/row0merge.cc function row_merge_sort line 254 there is thd_progress_init(trx->mysql_thd, num_runs); maybe should make sure that num_runs is correct here. This could be naturally be some other bug...

Comment by Sergey Vojtovich [ 2015-12-09 ]

jplindst, please review fix for this bug. Even though it fixes described problem, I'd say InnoDB progress report is still misleading: e.g. for given queries row merge takes just ~20 seconds of ~10 minutes, so that one can watch "Stage: 1 of 1 'altering table' 98.7% of stage done" for about 9 remaining minutes.

Comment by Jan Lindström (Inactive) [ 2015-12-09 ]

What InnoDB or something else is doing those remaining 9 minutes ?

Comment by Sergey Vojtovich [ 2015-12-09 ]

I didn't analyze it.

Comment by Jan Lindström (Inactive) [ 2015-12-10 ]

Ok to push.

Generated at Thu Feb 08 07:25:13 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.