| Bug #81648 | Crash recovery in 5.7 is 2 times slower than in 5.6 | ||
|---|---|---|---|
| Submitted: | 30 May 2016 21:46 | Modified: | 14 Sep 2016 14:21 |
| Reporter: | Vadim Tkachenko | Email Updates: | |
| Status: | Duplicate | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S2 (Serious) |
| Version: | 5.7.12 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[30 May 2016 23:09]
Vadim Tkachenko
It seems that 5.7 going twice through scan phase In the middle of the log (the same as above) I see 2016-05-30T18:26:45.268993Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 514752205824 2016-05-30T18:26:45.502555Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 514757448704 2016-05-30T18:26:45.727362Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 514762691584 2016-05-30T18:26:45.968844Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 514767934464 2016-05-30T18:26:46.198174Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 514773177344 2016-05-30T18:26:46.424549Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 514778420224 >>>> 2016-05-30T18:26:48.320026Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 504334799872 2016-05-30T18:26:48.565615Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 504340042752 2016-05-30T18:26:48.828911Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 504345285632 2016-05-30T18:26:49.084489Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 504350528512 2016-05-30T18:26:49.341125Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 504355771392
[31 May 2016 0:07]
zhai weixiang
bug#80788 is related.
[2 Jun 2016 8:24]
MySQL Verification Team
Hello Vadim, Thank you for the report. Observed this with 5.7.12 build. Thanks, Umesh
[14 Sep 2016 14:21]
Thirunarayanan Balathandayuthapani
It is a duplicate of bug#80788.
Description: I am testing crash recovery in 5.7 and it appears two times slower than in 5.6. I am crashing server with kill -9 when there is about 10GB of uncheckpointed data There is log for crash recovery 5.6 2016-05-30 17:13:59 26295 [Note] InnoDB: from the doublewrite buffer... InnoDB: Doing recovery: scanned up to log sequence number 184996598784 ... InnoDB: Doing recovery: scanned up to log sequence number 195517028844 InnoDB: 87 transaction(s) which must be rolled back or cleaned up InnoDB: in total 898 row operations to undo InnoDB: Trx id counter is 10475264 2016-05-30 17:20:25 26295 [Note] InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percent: 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 InnoDB: Apply batch completed 2016-05-30 17:23:40 26295 [Note] InnoDB: 128 rollback segment(s) are active. 5.6 - about 10mins 5.7 2016-05-30T18:19:04.035978Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 504334603435 2016-05-30T18:19:04.243914Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 504339846144 ... 2016-05-30T18:35:36.104244Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 514865113030 2016-05-30T18:35:36.106714Z 0 [Note] InnoDB: Database was not shutdown normally! 2016-05-30T18:35:36.106724Z 0 [Note] InnoDB: Starting crash recovery. 2016-05-30T18:35:50.885045Z 0 [Note] InnoDB: 79 transaction(s) which must be rolled back or cleaned up in total 632 row operations to undo 2016-05-30T18:35:50.885085Z 0 [Note] InnoDB: Trx id counter is 112455424 2016-05-30T18:35:50.971742Z 0 [Note] InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percent: 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 2016-05-30T18:40:14.323329Z 0 [Note] InnoDB: Apply batch completed 5.7 - about 21 mins How to repeat: Start servers with huges log files, for example 15GB x 2 log files. Run write intensive workload, crash server when there is ~10GB of uncheckpointed data. Amount of uncheckpointed data you can see as mysql -e 'show engine innodb status\G' | awk ' BEGIN { } /Log sequence number/ {st=$4 } /Last checkpoint at/ { ed=$4; print (st-ed)/1024/1024 } ' It will show in MB Suggested fix: Return 5.6 crash recovery performance.