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

Wrong progress report for operations on InnoDB tables

Details

    • 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.

      Attachments

        Issue Links

          links to

          Web Link Github revision

          Activity

            Ascending order - Click to sort in descending order
            jkavalik Jiri Kavalik added a comment - - edited

            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
            		 
            ...

            jkavalik Jiri Kavalik added a comment - - edited 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 ...
            michaeldg Michaël de groot added a comment -

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

            michaeldg Michaël de groot added a comment - I experienced this (InnoDB, 71 stages, up to 900%) on 10.0.21 as well.
            jb-boin Jean Weisbuch added a comment -

            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").

            jb-boin Jean Weisbuch added a comment - 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 ").
            crishoj Christian Rishøj added a comment -

            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
            		 
             

            crishoj Christian Rishøj added a comment - 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  
            hydrapolic Tomáš Mózes added a comment -

            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

            hydrapolic Tomáš Mózes added a comment - 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
            jplindst Jan Lindström (Inactive) added a comment -

            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...

            jplindst Jan Lindström (Inactive) added a comment - 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...
            svoj Sergey Vojtovich added a comment - - edited

            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.

            svoj Sergey Vojtovich added a comment - - edited 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.
            jplindst Jan Lindström (Inactive) added a comment -

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

            jplindst Jan Lindström (Inactive) added a comment - What InnoDB or something else is doing those remaining 9 minutes ?
            svoj Sergey Vojtovich added a comment -

            I didn't analyze it.

            svoj Sergey Vojtovich added a comment - I didn't analyze it.
            jplindst Jan Lindström (Inactive) added a comment -

            Ok to push.

            jplindst Jan Lindström (Inactive) added a comment - Ok to push.

            People

              svoj Sergey Vojtovich
              elenst Elena Stepanova
              Votes:
              2 Vote for this issue
              Watchers:
              10 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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