Bug #71104 error on database start activate crashing recovery.
Submitted: 6 Dec 2013 12:43 Modified: 10 Mar 2014 21:59
Reporter: massimo mico Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Errors Severity:S1 (Critical)
Version:5.7.3-m13 OS:Microsoft Windows (w2008 r2)
Assigned to: CPU Architecture:Any

[6 Dec 2013 12:43] massimo mico
Description:
i've installed 5.7.3 version of mysql (and use same configuration of previous 5.7.2 where everything ok) and when server start an error activate crashing recovery. 

i post log:
013-12-06T12:06:26.140880Z 0 [Note] Giving 0 client threads a chance to die gracefully
2013-12-06T12:06:26.141857Z 0 [Note] Shutting down slave threads
2013-12-06T12:06:26.143810Z 0 [Note] Forcefully disconnecting 0 remaining clients
2013-12-06T12:06:26.144786Z 0 [Note] Event Scheduler: Purging the queue. 0 events
2013-12-06T12:06:26.147716Z 0 [Note] Binlog end
2013-12-06T12:07:12.195550Z 0 [Note] Plugin 'FEDERATED' is disabled.
2013-12-06T12:07:12.199456Z 0 [Note] InnoDB: The InnoDB memory heap is disabled
2013-12-06T12:07:12.199456Z 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2013-12-06T12:07:12.202385Z 0 [Note] InnoDB: Uses system mutexes
2013-12-06T12:07:12.203362Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-12-06T12:07:12.209221Z 0 [Note] InnoDB: Number of pools: 1
2013-12-06T12:07:12.213127Z 0 [Note] InnoDB: Not using CPU crc32 instructions
2013-12-06T12:07:12.216056Z 0 [Note] InnoDB: Initializing buffer pool, total size = 1.0G, instances = 3
2013-12-06T12:07:12.405497Z 0 [Note] InnoDB: Completed initialization of buffer pool
2013-12-06T12:07:12.442604Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2013-12-06T12:07:12.460181Z 0 [Note] InnoDB: The log sequence numbers 87594636 and 87594636 in ibdata files do not match the log sequence number 88411279 in the ib_logfiles!
2013-12-06T12:07:12.463111Z 0 [Note] InnoDB: Database was not shutdown normally!
2013-12-06T12:07:12.464087Z 0 [Note] InnoDB: Starting crash recovery.
2013-12-06T12:07:12.465064Z 0 [Note] InnoDB: Reading tablespace information from the .ibd files...
2013-12-06T12:07:13.279465Z 0 [Note] InnoDB: Restoring possible half-written data pages 
2013-12-06T12:07:13.280441Z 0 [Note] InnoDB: from the doublewrite buffer...
2013-12-06T12:07:14.174915Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2013-12-06T12:07:14.177845Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2013-12-06T12:07:14.178821Z 0 [Note] InnoDB: Setting file ".\ibtmp1" size to 24 MB
2013-12-06T12:07:14.179798Z 0 [Note] InnoDB: Database physically writes the file full: wait ...
2013-12-06T12:07:14.558680Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2013-12-06T12:07:14.560633Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2013-12-06T12:07:14.693437Z 0 [Note] InnoDB: Waiting for purge to start
2013-12-06T12:07:14.777416Z 0 [Note] InnoDB: 5.7.3 started; log sequence number 88411279
2013-12-06T12:07:14.785228Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2013-12-06T12:07:14.787181Z 0 [Note] IPv6 is available.
2013-12-06T12:07:14.789134Z 0 [Note]   - '::' resolves to '::';
2013-12-06T12:07:14.790110Z 0 [Note] Server socket created on IP: '::'.
2013-12-06T12:07:14.802805Z 0 [Note] Event Scheduler: Loaded 0 events
2013-12-06T12:07:14.804758Z 0 [Note] C:\MySQL\bin\mysqld: ready for connections.
Version: '5.7.3-m13'  socket: ''  port: 3306  MySQL Community Server (GPL)

How to repeat:
on server start use this configuration:

my.ini:
[client]

port=3306

[mysqld]

port=3306
basedir="C:/MySQL/"
datadir="C:/MySQL/Data/"
tmpdir="C:/MySQL/temp/"
character-set-server=utf8

skip-external-locking

sql-mode="STRICT_TRANS_TABLES,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION"

max_connections=1000
key_buffer_size=25M
low_priority_updates=1
table_open_cache = 3000
back_log=150
query_cache_type=0
table_open_cache_instances=1
join_buffer_size = 96K
sort_buffer_size = 96K

innodb_log_buffer_size=8M
innodb_buffer_pool_size=1G
innodb_log_file_size=256M
innodb_temp_data_file_path=ibtmp1:24M:autoextend

#-------TEST----------------
explicit_defaults_for_timestamp
innodb_buffer_pool_instances=3
innodb_thread_concurrency=0
innodb_flush_log_at_trx_commit=2
innodb_max_dirty_pages_pct=50
innodb_use_native_aio=1
innodb_stats_persistent=1
innodb_spin_wait_delay=6
innodb_adaptive_flushing=1
innodb_flush_neighbors=0
innodb_purge_threads=1
innodb_adaptive_hash_index=0
performance_schema=off
innodb_checksum_algorithm=none
innodb_doublewrite=0
innodb_support_xa=0
innodb_file_format=Barracuda
innodb_file_per_table
[6 Dec 2013 14:56] MySQL Verification Team
Please attach the whole error file compressed. Thanks.
[6 Dec 2013 14:59] Peter Laursen
I think it is important how the 5.7.2 server was stopped as well as the installation method (using the "MySQL Instller" or some other method).

Obviously 5.7.2 was not shut down properly. This could be both a human error or a bug in an automated installer or a bug in MySQL 5.7.2 (what could then possibly also exist in 5.7.3).

Peter
(not a MySQL/Oracle person)
[6 Dec 2013 16:07] massimo mico
i've installed mysql 5.7.3 with clean unzip file and copied my.ini file in new mysql directory and next i've restored a dump file created with version 5.7.2. 

Isn't database corruption! because i've tested to make a full clean installation of 5.7.3 version and after start mysql with no restore dump of database, i receive the same error.

I think this is a bug on shutdown or start database procedure.

Thanks
[6 Dec 2013 16:11] massimo mico
LOG FILE MYSQL

Attachment: SERVER-2-1.zip (application/x-zip-compressed, text), 9.54 KiB.

[6 Dec 2013 16:24] Peter Laursen
Question are then: With what tool was the dump created?  

If you used 'mysqldump' what was then the full command? IMO it is interesting if --flush-logs and --single-transaction were used (or what similar options another tool has, if another tool was used.  Decent GUI tolls will have checkboxes or similar for the options). Some old GUI clients may not be fit for dumping InnoDB data (due to lack of proper options support). Not sure about phpMyAdmin.

The problem is with the dump itself. It is/was in an inconsistent state. MySQL 7.0.3 recovery does what it must: bring the database to a consistent state (including rolling back non-committed transactions)
[6 Dec 2013 16:37] massimo mico
hi Peter,

dump created with mysqldump on mysql 5.7.2 with the following line command:

mysqldump -u root -p --all-databases >c:\mysql\dump20131203.sql

but the problem occur also in full clean installation with no restore dump databases. 

Thanks
[6 Dec 2013 16:41] Peter Laursen
ok .. let Miguel or another MySQL supporter handle. 

If this error log occurs first time you start the server - and even before any user data are created, it looks weird.
[6 Dec 2013 17:08] Sveta Smirnova
Thank you for the feedback.

What is the actual file size of InnoDB log files?
[6 Dec 2013 17:10] massimo mico
Ok, thank Peter!

I precise that mysql server run on virtual machine enviroment, the virtual machine have a Windows 2008 R2 server installed, and the host machine have Windows 2012 server with Hyper-V role.

thanks
[6 Dec 2013 19:43] massimo mico
hi Sveta,

the actual size of innodb log file is 256M. I've tested also with 64M, 128M. 

Thanks
[9 Dec 2013 11:37] massimo mico
I think the bug is in shutdown procedure of InnoDB plugin, because in clean installation with no database restore, the server start and create file log, at first shutdown log are cut in shutdown plugin:
2013-12-07T11:19:14.512085Z 0 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'

after this no shutdown plugin is logged when server stop.

i add zip file with log of clean installation  to verify this.
[9 Dec 2013 11:38] massimo mico
LOG OF CLEAN NEW INSTALLATION 5.7.3

Attachment: CLEAN INST SERVER LOG.zip (application/x-zip-compressed, text), 1.88 KiB.

[10 Dec 2013 18:51] MySQL Verification Team
Something is wrong with your installation. There are no messages about plugins being shut down ... So, server can't find them, which is a consequence of bad installation ...
[10 Dec 2013 19:36] massimo mico
i've downloaded a Windows x64 version zip file, after i've unzip file in root folder and add in mysql directory MY.INI file and create a temp folder. This is my installation.
[11 Dec 2013 19:10] MySQL Verification Team
The crucial question is:

How do you shutdown MySQL server ????

If you shut it down with any other means except:

mysqladmin shutdown

then what you get is expected behavior !!! This is because you have this value:

innodb_flush_log_at_trx_commit=2

and because you can not have clean startup even if you would set all recovery features on.
[11 Dec 2013 20:00] massimo mico
I don't think this is the problem! Because i've a 5.7.2-m12 version installed in the same machine with same configuration and no problem occur in this version!
[11 Dec 2013 22:48] massimo mico
however i stop mysql with command "net stop mysql" (stop Windows service) is the same of mysqladmin shutdown, however i've same problem also i stop with mysqladmin and remove innodb_flush_log_at_trx_commit=2 in configuration file.
[17 Dec 2013 11:46] massimo mico
i think the bug is in mysqld.exe in shutdown procedure when MySql is installed as Windows service.
Infact, if i start server with command line mysqld and stop server with command mysqladmin shutdown, the server start and stop correctly with no error messages.
When i stop the server as Windows service with net stop Mysql command a shutdown procedure not activated shutdown of INNODB plugin. In log file i've only this:

2013-12-17T11:33:18.660914Z 0 [Note] c:\mysql\bin\mysqld: Normal shutdown

2013-12-17T11:33:18.663844Z 0 [Note] Giving 0 client threads a chance to die gracefully
2013-12-17T11:33:18.664820Z 0 [Note] Shutting down slave threads
2013-12-17T11:33:18.666773Z 0 [Note] Forcefully disconnecting 0 remaining clients
2013-12-17T11:33:18.667750Z 0 [Note] Event Scheduler: Purging the queue. 0 events
2013-12-17T11:33:18.670679Z 0 [Note] Binlog end
[19 Dec 2013 16:01] MySQL Verification Team
Thank you for the bug report. Verified on Windows 8.1.
[21 Dec 2013 9:44] massimo mico
thank you for verification.,
[10 Mar 2014 21:59] Paul DuBois
Noted in MySQL 5.7.5 changelog.

When MySQL runs as service on Windows, NTService.Stop() initiates
shutdown and exit events during shutdown. After a code reorganization
in MySQL 5.7.3, a call to clean_up() was missed, resulting in
initiation of crash recovery.