Bug #94971 Incorrect key file error during log apply table stage in online DDL
Submitted: 10 Apr 2019 15:45 Modified: 6 May 2019 16:21
Reporter: monty solomon Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.7.21 OS:Any
Assigned to: MySQL Verification Team CPU Architecture:Any

[10 Apr 2019 15:45] monty solomon 
Description:
ALTER TABLE forms
  MODIFY COLUMN `formGuid` char(36) CHARACTER SET ascii COLLATE ascii_bin NOT NULL,
  LOCK=NONE

Incorrect key file for table 'forms'; try to repair it

How to repeat:
Migration stage status: 0.30058%
		Rows completed: 385693
		Rows estimated: 128316253
		Stage: read PK and internal sort
Migration stage status: 0.59546113%
		Rows completed: 764078
		Rows estimated: 128317021
		Stage: read PK and internal sort
Migration stage status: 0.896113%
		Rows completed: 1149869
		Rows estimated: 128317405
		Stage: read PK and internal sort
Migration stage status: 1.1921535%
		Rows completed: 1529745
		Rows estimated: 128317789
		Stage: read PK and internal sort
Migration stage status: 1.4705839%
		Rows completed: 1887032
		Rows estimated: 128318557
		Stage: read PK and internal sort
Migration stage status: 1.7130339%
		Rows completed: 2198147
		Rows estimated: 128318941
		Stage: read PK and internal sort
Migration stage status: 1.9893371%
		Rows completed: 2552704
		Rows estimated: 128319325
		Stage: read PK and internal sort
Migration stage status: 2.28047%
		Rows completed: 2926301
		Rows estimated: 128320093
		Stage: read PK and internal sort
Migration stage status: 2.5703738%
		Rows completed: 3298316
		Rows estimated: 128320477
		Stage: read PK and internal sort
Migration stage status: 2.8487682%
		Rows completed: 3655575
		Rows estimated: 128321245
		Stage: read PK and internal sort
Migration stage status: 3.153293%
		Rows completed: 4046357
		Rows estimated: 128321629
		Stage: read PK and internal sort
Migration stage status: 3.6720839%
		Rows completed: 4712106
		Rows estimated: 128322397
		Stage: read PK and internal sort
Migration stage status: 4.208095%
		Rows completed: 5399961
		Rows estimated: 128323165
		Stage: read PK and internal sort
Migration stage status: 4.71325%
		Rows completed: 6048210
		Rows estimated: 128323549
		Stage: read PK and internal sort
Migration stage status: 5.1887717%
		Rows completed: 6658456
		Rows estimated: 128324317
		Stage: read PK and internal sort
Migration stage status: 5.7020526%
		Rows completed: 7317142
		Rows estimated: 128324701
		Stage: read PK and internal sort
Migration stage status: 6.228553%
		Rows completed: 7992796
		Rows estimated: 128325085
		Stage: read PK and internal sort
Migration stage status: 6.742684%
		Rows completed: 8652581
		Rows estimated: 128325469
		Stage: read PK and internal sort
Migration stage status: 7.2924047%
		Rows completed: 9358069
		Rows estimated: 128326237
		Stage: read PK and internal sort
Migration stage status: 7.846108%
		Rows completed: 10068646
		Rows estimated: 128326621
		Stage: read PK and internal sort
Migration stage status: 8.416871%
		Rows completed: 10801119
		Rows estimated: 128327005
		Stage: read PK and internal sort
Migration stage status: 9.007481%
		Rows completed: 11559065
		Rows estimated: 128327389
		Stage: read PK and internal sort
Migration stage status: 9.578731%
		Rows completed: 12292245
		Rows estimated: 128328541
		Stage: read PK and internal sort
Migration stage status: 10.125623%
		Rows completed: 12994142
		Rows estimated: 128329309
		Stage: read PK and internal sort
Migration stage status: 10.656018%
		Rows completed: 13674836
		Rows estimated: 128329693
		Stage: read PK and internal sort
Migration stage status: 11.158717%
		Rows completed: 14319991
		Rows estimated: 128330077
		Stage: read PK and internal sort
Migration stage status: 11.663282%
		Rows completed: 14967589
		Rows estimated: 128330845
		Stage: read PK and internal sort
Migration stage status: 12.161174%
		Rows completed: 15606584
		Rows estimated: 128331229
		Stage: read PK and internal sort
Migration stage status: 12.646948%
		Rows completed: 16230130
		Rows estimated: 128332381
		Stage: read PK and internal sort
Migration stage status: 13.174465%
		Rows completed: 16907156
		Rows estimated: 128332765
		Stage: read PK and internal sort
Migration stage status: 13.684193%
		Rows completed: 17561355
		Rows estimated: 128333149
		Stage: read PK and internal sort
Migration stage status: 14.231253%
		Rows completed: 18263525
		Rows estimated: 128333917
		Stage: read PK and internal sort
Migration stage status: 14.790827%
		Rows completed: 18981704
		Rows estimated: 128334301
		Stage: read PK and internal sort
Migration stage status: 15.367916%
		Rows completed: 19722367
		Rows estimated: 128334685
		Stage: read PK and internal sort
Migration stage status: 15.966728%
		Rows completed: 20490974
		Rows estimated: 128335453
		Stage: read PK and internal sort
Migration stage status: 16.566315%
		Rows completed: 21260582
		Rows estimated: 128336221
		Stage: read PK and internal sort
Migration stage status: 17.14197%
		Rows completed: 21999488
		Rows estimated: 128336989
		Stage: read PK and internal sort
Migration stage status: 17.724463%
		Rows completed: 22747179
		Rows estimated: 128337757
		Stage: read PK and internal sort
Migration stage status: 18.318302%
		Rows completed: 23509367
		Rows estimated: 128338141
		Stage: read PK and internal sort
Migration stage status: 18.876831%
		Rows completed: 24226321
		Rows estimated: 128338909
		Stage: read PK and internal sort
Migration stage status: 19.45907%
		Rows completed: 24973634
		Rows estimated: 128339293
		Stage: read PK and internal sort
Migration stage status: 20.03446%
		Rows completed: 25712162
		Rows estimated: 128339677
		Stage: read PK and internal sort
Migration stage status: 20.575134%
		Rows completed: 26406219
		Rows estimated: 128340445
		Stage: read PK and internal sort
Migration stage status: 21.05562%
		Rows completed: 27022961
		Rows estimated: 128340829
		Stage: read PK and internal sort
Migration stage status: 21.45583%
		Rows completed: 27536754
		Rows estimated: 128341597
		Stage: read PK and internal sort
Migration stage status: 21.824347%
		Rows completed: 28009800
		Rows estimated: 128341981
		Stage: read PK and internal sort
Migration stage status: 22.205297%
		Rows completed: 28498890
		Rows estimated: 128342749
		Stage: read PK and internal sort
Migration stage status: 22.65062%
		Rows completed: 29070517
		Rows estimated: 128343133
		Stage: read PK and internal sort
Migration stage status: 23.186995%
		Rows completed: 29759184
		Rows estimated: 128344285
		Stage: read PK and internal sort
Migration stage status: 23.764402%
		Rows completed: 30500344
		Rows estimated: 128344669
		Stage: read PK and internal sort
Migration stage status: 24.292341%
		Rows completed: 31178112
		Rows estimated: 128345437
		Stage: read PK and internal sort
Migration stage status: 24.81884%
		Rows completed: 31854039
		Rows estimated: 128346205
		Stage: read PK and internal sort
Migration stage status: 25.369951%
		Rows completed: 32561466
		Rows estimated: 128346589
		Stage: read PK and internal sort
Migration stage status: 25.890785%
		Rows completed: 33230141
		Rows estimated: 128347357
		Stage: read PK and internal sort
Migration stage status: 26.40638%
		Rows completed: 33891991
		Rows estimated: 128347741
		Stage: read PK and internal sort
Migration stage status: 26.947721%
		Rows completed: 34587000
		Rows estimated: 128348509
		Stage: read PK and internal sort
Migration stage status: 27.45908%
		Rows completed: 35243635
		Rows estimated: 128349661
		Stage: read PK and internal sort
Migration stage status: 27.97878%
		Rows completed: 35910889
		Rows estimated: 128350429
		Stage: read PK and internal sort
Migration stage status: 28.48042%
		Rows completed: 36554959
		Rows estimated: 128351197
		Stage: read PK and internal sort
Migration stage status: 28.94457%
		Rows completed: 37150925
		Rows estimated: 128351965
		Stage: read PK and internal sort
Migration stage status: 29.408672%
		Rows completed: 37746835
		Rows estimated: 128352733
		Stage: read PK and internal sort
Migration stage status: 29.93688%
		Rows completed: 38424918
		Rows estimated: 128353117
		Stage: read PK and internal sort
Migration stage status: 30.490145%
		Rows completed: 39135404
		Rows estimated: 128354269
		Stage: read PK and internal sort
Migration stage status: 31.04068%
		Rows completed: 39842159
		Rows estimated: 128354653
		Stage: read PK and internal sort
Migration stage status: 31.597143%
		Rows completed: 40556649
		Rows estimated: 128355421
		Stage: read PK and internal sort
Migration stage status: 32.167156%
		Rows completed: 41288415
		Rows estimated: 128355805
		Stage: read PK and internal sort
Migration stage status: 32.734234%
		Rows completed: 42016541
		Rows estimated: 128356573
		Stage: read PK and internal sort
Migration stage status: 33.285187%
		Rows completed: 42723982
		Rows estimated: 128357341
		Stage: read PK and internal sort
Migration stage status: 33.835575%
		Rows completed: 43430702
		Rows estimated: 128358109
		Stage: read PK and internal sort
Migration stage status: 34.385506%
		Rows completed: 44136848
		Rows estimated: 128358877
		Stage: read PK and internal sort
Migration stage status: 34.926308%
		Rows completed: 44831283
		Rows estimated: 128359645
		Stage: read PK and internal sort
Migration stage status: 35.412777%
		Rows completed: 45456124
		Rows estimated: 128360797
		Stage: read PK and internal sort
Migration stage status: 35.940243%
		Rows completed: 46133318
		Rows estimated: 128361181
		Stage: read PK and internal sort
Migration stage status: 36.49827%
		Rows completed: 46849887
		Rows estimated: 128361949
		Stage: read PK and internal sort
Migration stage status: 37.04007%
		Rows completed: 47545638
		Rows estimated: 128362717
		Stage: read PK and internal sort
Migration stage status: 37.60879%
		Rows completed: 48275955
		Rows estimated: 128363485
		Stage: read PK and internal sort
Migration stage status: 38.202763%
		Rows completed: 49038542
		Rows estimated: 128363869
		Stage: read PK and internal sort
Migration stage status: 38.79033%
		Rows completed: 49793065
		Rows estimated: 128364637
		Stage: read PK and internal sort
Migration stage status: 39.34335%
		Rows completed: 50503250
		Rows estimated: 128365405
		Stage: read PK and internal sort
Migration stage status: 39.88476%
		Rows completed: 51198546
		Rows estimated: 128366173
		Stage: read PK and internal sort
Migration stage status: 40.437458%
		Rows completed: 51908171
		Rows estimated: 128366557
		Stage: read PK and internal sort
Migration stage status: 40.99754%
		Rows completed: 52627449
		Rows estimated: 128367325
		Stage: read PK and internal sort
Migration stage status: 41.561268%
		Rows completed: 53351249
		Rows estimated: 128367709
		Stage: read PK and internal sort
Migration stage status: 42.119907%
		Rows completed: 54068686
		Rows estimated: 128368477
		Stage: read PK and internal sort
Migration stage status: 42.70012%
		Rows completed: 54813822
		Rows estimated: 128369245
		Stage: read PK and internal sort
Migration stage status: 43.262012%
		Rows completed: 55535452
		Rows estimated: 128370013
		Stage: read PK and internal sort
Migration stage status: 43.820805%
		Rows completed: 56253113
		Rows estimated: 128370781
		Stage: read PK and internal sort
Migration stage status: 44.36387%
		Rows completed: 56950418
		Rows estimated: 128371165
		Stage: read PK and internal sort
Migration stage status: 44.878025%
		Rows completed: 57610616
		Rows estimated: 128371549
		Stage: read PK and internal sort
Migration stage status: 45.396317%
		Rows completed: 58276302
		Rows estimated: 128372317
		Stage: read PK and internal sort
Migration stage status: 45.91871%
		Rows completed: 58947266
		Rows estimated: 128373085
		Stage: read PK and internal sort
Migration stage status: 46.422417%
		Rows completed: 59594423
		Rows estimated: 128374237
		Stage: read PK and internal sort
Migration stage status: 46.946144%
		Rows completed: 60266934
		Rows estimated: 128374621
		Stage: read PK and internal sort
Migration stage status: 47.50587%
		Rows completed: 60985848
		Rows estimated: 128375389
		Stage: read PK and internal sort
Migration stage status: 48.045837%
		Rows completed: 61679401
		Rows estimated: 128376157
		Stage: read PK and internal sort
Migration stage status: 48.542362%
		Rows completed: 62317010
		Rows estimated: 128376541
		Stage: read PK and internal sort
Migration stage status: 49.117077%
		Rows completed: 63054992
		Rows estimated: 128376925
		Stage: read PK and internal sort
Migration stage status: 49.67723%
		Rows completed: 63774676
		Rows estimated: 128378077
		Stage: read PK and internal sort
Migration stage status: 50.246475%
		Rows completed: 64505847
		Rows estimated: 128378845
		Stage: read PK and internal sort
Migration stage status: 50.76044%
		Rows completed: 65166059
		Rows estimated: 128379613
		Stage: read PK and internal sort
Migration stage status: 51.27417%
		Rows completed: 65825977
		Rows estimated: 128380381
		Stage: read PK and internal sort
Migration stage status: 51.821644%
		Rows completed: 66529022
		Rows estimated: 128380765
		Stage: read PK and internal sort
Migration stage status: 52.38247%
		Rows completed: 67249413
		Rows estimated: 128381533
		Stage: read PK and internal sort
Migration stage status: 52.923565%
		Rows completed: 67944492
		Rows estimated: 128382301
		Stage: read PK and internal sort
Migration stage status: 53.438915%
		Rows completed: 68606517
		Rows estimated: 128383069
		Stage: read PK and internal sort
Migration stage status: 53.915024%
		Rows completed: 69217967
		Rows estimated: 128383453
		Stage: read PK and internal sort
Migration stage status: 54.43589%
		Rows completed: 69887097
		Rows estimated: 128384221
		Stage: read PK and internal sort
Migration stage status: 54.987736%
		Rows completed: 70596211
		Rows estimated: 128385373
		Stage: read PK and internal sort
Migration stage status: 55.545807%
		Rows completed: 71312906
		Rows estimated: 128385757
		Stage: read PK and internal sort
Migration stage status: 56.099094%
		Rows completed: 72023679
		Rows estimated: 128386525
		Stage: read PK and internal sort
Migration stage status: 56.677757%
		Rows completed: 72767044
		Rows estimated: 128387293
		Stage: read PK and internal sort
Migration stage status: 39.248047%
		Rows completed: 78935481
		Rows estimated: 201119514
		Stage: merge sort
Migration stage status: 43.22773%
		Rows completed: 86939736
		Rows estimated: 201120282
		Stage: insert
Migration stage status: 47.29104%
		Rows completed: 95112231
		Rows estimated: 201121050
		Stage: merge sort
Migration stage status: 52.56531%
		Rows completed: 105720113
		Rows estimated: 201121434
		Stage: insert
Migration stage status: 57.485462%
		Rows completed: 115616026
		Rows estimated: 201122202
		Stage: merge sort
Migration stage status: 59.001446%
		Rows completed: 118665236
		Rows estimated: 201122586
		Stage: merge sort
Migration stage status: 60.57417%
		Rows completed: 121828802
		Rows estimated: 201123354
		Stage: merge sort
Migration stage status: 62.14664%
		Rows completed: 124991892
		Rows estimated: 201124122
		Stage: merge sort
Migration stage status: 65.31707%
		Rows completed: 131368898
		Rows estimated: 201124890
		Stage: insert
Migration stage status: 69.78821%
		Rows completed: 140362280
		Rows estimated: 201126042
		Stage: merge sort
Migration stage status: 74.87236%
		Rows completed: 150588113
		Rows estimated: 201126426
		Stage: insert
Migration stage status: 79.46122%
		Rows completed: 159818127
		Rows estimated: 201127194
		Stage: merge sort
Migration stage status: 85.31354%
		Rows completed: 171589060
		Rows estimated: 201127578
		Stage: insert
Migration stage status: 90.95488%
		Rows completed: 182936043
		Rows estimated: 201128346
		Stage: merge sort
Migration stage status: 97.062935%
		Rows completed: 195221817
		Rows estimated: 201129114
		Stage: insert
Migration stage status: 100.0%
		Rows completed: 198569576
		Rows estimated: 198569576
		Stage: flush
Migration stage status: 100.0%
		Rows completed: 198649155
		Rows estimated: 198649155
		Stage: flush
Migration stage status: 100.0%
		Rows completed: 198728226
		Rows estimated: 198728226
		Stage: flush
Migration stage status: 100.0%
		Rows completed: 198806739
		Rows estimated: 198806739
		Stage: flush
Migration stage status: 100.0%
		Rows completed: 198890571
		Rows estimated: 198890571
		Stage: flush
Migration stage status: 100.0%
		Rows completed: 198969062
		Rows estimated: 198969062
		Stage: flush
Migration stage status: 100.0%
		Rows completed: 199042715
		Rows estimated: 199042715
		Stage: flush
Migration stage status: 100.0%
		Rows completed: 199115507
		Rows estimated: 199115507
		Stage: flush
Migration stage status: 99.95606%
		Rows completed: 199172008
		Rows estimated: 199259560
		Stage: log apply table
Migration stage status: 99.95876%
		Rows completed: 199177768
		Rows estimated: 199259944
		Stage: log apply table
[10 Apr 2019 15:47] monty solomon 
mysql> show table status like 'forms'\G
*************************** 1. row ***************************
           Name: forms
         Engine: InnoDB
        Version: 10
     Row_format: Compressed
           Rows: 11547415
 Avg_row_length: 5385
    Data_length: 62184202240
Max_data_length: 0
   Index_length: 5439799296
      Data_free: 14680064
 Auto_increment: NULL
    Create_time: 2019-03-21 05:18:45
    Update_time: 2019-04-10 15:47:04
     Check_time: NULL
      Collation: utf8_general_ci
       Checksum: NULL
 Create_options: row_format=COMPRESSED KEY_BLOCK_SIZE=8
        Comment: 
1 row in set (0.02 sec)
[11 Apr 2019 19:25] monty solomon 
After upgrading to 5.7.23 the error changed to

Creating index 'FTS_DOC_ID_INDEX' required more than 'innodb_online_alter_log_max_size' bytes of modification log.

The database doesn't use any FULLTEXT indexes.
[11 Apr 2019 20:54] MySQL Verification Team 
Hi,

I don't see how to reproduce this issue?

thanks
Bogdan
[12 Apr 2019 19:22] monty solomon 
It fails repeatedly here but I don't know how to create an example you can reproduce.
[12 Apr 2019 20:14] MySQL Verification Team 
Hi,

> It fails repeatedly here but I don't know how to create an example you can reproduce.

for start you can give me create table, you gave only show table status since that would be a start position, creating random table and modifying column obviously don't reproduce your issue.

Did you check that table? Have you tried copying that table into other database and altering it to see if it would crash again (create table x like y; insert into x select * from y; alter table x...) as it's possible there's a table issue.

with the data provided, there's really nothing I can do

all best
Bogdan
[21 Apr 2019 1:17] MySQL Verification Team 
Hi,

mysql [localhost:5725] {msandbox} (test) > show table status like 'forms'\G
*************************** 1. row ***************************
           Name: forms
         Engine: InnoDB
        Version: 10
     Row_format: Compressed
           Rows: 12788454
 Avg_row_length: 99
    Data_length: 1272258560
Max_data_length: 0
   Index_length: 2566856704
      Data_free: 3670016
 Auto_increment: NULL
    Create_time: 2019-04-19 07:01:30
    Update_time: 2019-04-21 02:02:59
     Check_time: NULL
      Collation: utf8_general_ci
       Checksum: NULL
 Create_options: row_format=COMPRESSED KEY_BLOCK_SIZE=8
        Comment:
1 row in set (0.00 sec)

mysql [localhost:5725] {msandbox} (test) > ALTER TABLE forms   MODIFY COLUMN `formGuid` char(36) CHARACTER SET ascii COLLATE ascii_bin NOT NULL,   LOCK=NONE;
ERROR 1846 (0A000): LOCK=NONE is not supported. Reason: cannot silently convert NULL values, as required in this SQL_MODE. Try LOCK=SHARED.

What sql_mode are you using?
all best
bogdan

p.s. this might be duplicate of Bug #77097 but I'm not yet sure
[25 Apr 2019 2:34] monty solomon 
mysql> select @@SQL_MODE\G
*************************** 1. row ***************************
@@SQL_MODE: ONLY_FULL_GROUP_BY,NO_AUTO_VALUE_ON_ZERO,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
[25 Apr 2019 2:38] monty solomon 
I assume the ALTER will complete with a large enough value for innodb_online_alter_log_max_size.

I haven't tried that yet.
[25 Apr 2019 2:40] monty solomon 
I can also try using pt-online-schema-change since it will create a new table.
[6 May 2019 16:21] MySQL Verification Team 
I don't see how is this a bug :(

mysql [localhost:5725] {msandbox} (test) > set sql_mode='ONLY_FULL_GROUP_BY,NO_AUTO_VALUE_ON_ZERO,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION';
Query OK, 0 rows affected (0.01 sec)

mysql [localhost:5725] {msandbox} (test) > ALTER TABLE forms   MODIFY COLUMN `formGuid` char(36) CHARACTER SET ascii COLLATE ascii                 _bin NOT NULL,   LOCK=NONE;
Query OK, 0 rows affected (23 min 23.05 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql [localhost:5725] {msandbox} (test) > select @@version, @@innodb_online_alter_log_max_size;
+-----------+------------------------------------+
| @@version | @@innodb_online_alter_log_max_size |
+-----------+------------------------------------+
| 5.7.25    |                         1342177280 |
+-----------+------------------------------------+
1 row in set (0.00 sec)

of course, you have to have proper configured server for it to work properly but that's not a bug.

all best
Bogdan
[22 Jun 2020 2:44] Jie Zhou 
I figure out a way to repeat the bug. Refer to:
https://bugs.mysql.com/bug.php?id=99938