| Bug #78960 | Unclear note "InnoDB: not started" in the error log | ||
|---|---|---|---|
| Submitted: | 26 Oct 2015 8:34 | Modified: | 20 Nov 2015 14:39 |
| Reporter: | Valeriy Kravchuk | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S3 (Non-critical) |
| Version: | 5.7.9, 5.7.10 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | buf_load_status, buf_resize_status, error log, innodb, note | ||
[26 Oct 2015 8:41]
MySQL Verification Team
Hello Valeriy, Thank you for the bug report. Verified as described with 5.7.10 build. Thanks, Umesh
[26 Oct 2015 8:42]
MySQL Verification Team
// 5.7.10 - extract from error log . . 2015-10-26T08:38:30.479964Z 0 [Note] InnoDB: Waiting for purge to start 2015-10-26T08:38:30.530091Z 0 [Note] InnoDB: 5.7.10 started; log sequence number 2484914 2015-10-26T08:38:30.530285Z 0 [Note] InnoDB: Loading buffer pool(s) from /export/umesh/server/mysql-advanced-5.7.10/78960/ib_buffer_pool 2015-10-26T08:38:30.530378Z 0 [Note] InnoDB: not started 2015-10-26T08:38:30.530548Z 0 [Note] Plugin 'FEDERATED' is disabled. 2015-10-26T08:38:30.532305Z 0 [Note] InnoDB: Buffer pool(s) load completed at 151026 9:38:30 2015-10-26T08:38:30.533574Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them. 2015-10-26T08:38:30.533594Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory. 2015-10-26T08:38:30.556956Z 0 [Warning] CA certificate ca.pem is self signed. 2015-10-26T08:38:30.557010Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory. 2015-10-26T08:38:30.557127Z 0 [Note] Server hostname (bind-address): '*'; port: 15000 2015-10-26T08:38:30.557192Z 0 [Note] IPv6 is available. 2015-10-26T08:38:30.557206Z 0 [Note] - '::' resolves to '::'; 2015-10-26T08:38:30.557213Z 0 [Note] Server socket created on IP: '::'. 2015-10-26T08:38:30.567419Z 0 [Note] Event Scheduler: Loaded 0 events 2015-10-26T08:38:30.567617Z 0 [Note] bin/mysqld: ready for connections. Version: '5.7.10-enterprise-commercial-advanced' socket: '/tmp/mysql_ushastry.sock' port: 15000 MySQL Enterprise Server - Advanced Edition (Commercial) [umshastr@hod04]/export/umesh/server/mysql-advanced-5.7.10: cat docs/INFO_SRC commit: ec8eea3eb451866b70e25331d6d278125127b82c date: 2015-10-26 03:21:28 +0100 build-date: 2015-10-26 03:35:04 +0100 short: ec8eea3 branch: mysql-5.7 MySQL source 5.7.10
[20 Nov 2015 14:39]
Daniel Price
Posted by developer: Fixed as of the upcoming 5.7.11, 5.8.0 release, and here's the changelog entry: InnoDB startup messages related to dumping and loading of the buffer pool were improved. Thank you for the bug report.
Description: I've noted the following sequence of messages in the error log during MySQL 5.7.9 startup: ... 2015-10-26T08:09:24.712465Z 0 [Note] InnoDB: 5.7.9 started; log sequence number 8059019 2015-10-26T08:09:24.712737Z 0 [Note] InnoDB: Loading buffer pool(s) from /home/openxs/dbs/5.7/data/ib_buffer_pool 2015-10-26T08:09:24.712775Z 0 [Note] InnoDB: not started 2015-10-26T08:09:24.712894Z 0 [Note] Plugin 'FEDERATED' is disabled. 2015-10-26T08:09:24.715124Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key 2015-10-26T08:09:24.715600Z 0 [Note] Server hostname (bind-address): '*'; port: 3306 2015-10-26T08:09:24.715702Z 0 [Note] IPv6 is available. 2015-10-26T08:09:24.715718Z 0 [Note] - '::' resolves to '::'; 2015-10-26T08:09:24.715731Z 0 [Note] Server socket created on IP: '::'. 2015-10-26T08:09:24.716211Z 0 [Note] InnoDB: Buffer pool(s) load completed at 151026 10:09:24 2015-10-26T08:09:24.754209Z 0 [Note] Event Scheduler: Loaded 0 events 2015-10-26T08:09:24.754408Z 0 [Note] /home/openxs/dbs/5.7/bin/mysqld: ready for connections. Version: '5.7.9' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL) Note that first it says InnoDB 5.7.9 is started, then it says "InnoDB: not started". What does it mean, what is not started at the moment? Quick search in the code ended up with 3 possible cases when this kind of message may appear: storage/innobase/buf/buf0buf.cc:2959: buf_resize_status("not started"); storage/innobase/buf/buf0dump.cc:744: buf_dump_status(STATUS_VERBOSE, "not started"); storage/innobase/buf/buf0dump.cc:745: buf_load_status(STATUS_VERBOSE, "not started"); and based on the context I'd say that probably it was the load of buffer pool that was not started, but I have two questions then: 1. Why we do not say explicitly was was "not started"? 2. Why we need to know it was "not started"? Maybew we should just say that we are starting it, if timestamp of this event is important? How to repeat: Start MySQL 5.7.9 and read messages in the error log carefully. Try to understand what this one: 2015-10-26T08:09:24.712775Z 0 [Note] InnoDB: not started is about. Suggested fix: Please, make these notes more clear and specific, instead of looking scary and/or obscure and/or useless.