MySQL Bugs: #99582: Reduce logging of new doublewrite buffer initialisation which is confusing

Bug #99582	Reduce logging of new doublewrite buffer initialisation which is confusing
Submitted:	15 May 2020 8:43	Modified:	18 May 2020 6:09
Reporter:	Simon Mudd (OCA)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S4 (Feature request)
Version:	8.0.20, 8.0.24	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	change management, documentation, doublewrite, legacy.monitoring

Description:
Spinning up 8.0.20 it shows:

2020-05-15T08:28:17.758967Z 1 [Note] [MY-011920] [InnoDB] Legacy doublewrite buffer not found: creating new
2020-05-15T08:28:17.761713Z 0 [Note] [MY-011950] [InnoDB] Resetting invalid page [page id: space=0, page number=24] type 20 to 13 when flushing.
...
2020-05-15T08:28:17.868711Z 0 [Note] [MY-011950] [InnoDB] Resetting invalid page [page id: space=0, page number=176] type 20 to 13 when flushing.
2020-05-15T08:28:17.874089Z 1 [Note] [MY-011924] [InnoDB] Legacy atomic write buffer created

There are 160 lines of logging for this action.

How to repeat:
Initialise a new mysqld instance using:

mysqld --initialize  --user=_mysql

I'm not sure if this is related to the specific configuration that I put on the server. This was for use on a laptop for testing so I can provide the my.cnf file if that might clarify.

Suggested fix:
 I know there are changes related to the double write buffer in 8.0.20 but I don' think that this amount of logging is necessary.

Suggestion: Reduce the logging to show less information or to summarise it better.

Also I'm confused. this is a completely fresh install. If there's a legacy double-write buffer and a new one and the system notices that this is a fresh install it seems from logging that it's building the legacy one and not using the new one. Why?

2020-05-15T08:28:17.758967Z 1 [Note] [MY-011920] [InnoDB] Legacy doublewrite buffer not found: creating new
2020-05-15T08:28:17.761713Z 0 [Note] [MY-011950] [InnoDB] Resetting invalid page [page id: space=0, page number=24] type 20 to 13 when flushing.
...
2020-05-15T08:28:17.868711Z 0 [Note] [MY-011950] [InnoDB] Resetting invalid page [page id: space=0, page number=176] type 20 to 13 when flushing.
2020-05-15T08:28:17.874089Z 1 [Note] [MY-011924] [InnoDB] Legacy atomic write buffer created

Looking at the datadir I see the new double write files:
-rw-r-----    1 _mysql  _mysql     196608 May 15 10:28 #ib_16384_0.dblwr
-rw-r-----    1 _mysql  _mysql    8585216 May 15 10:28 #ib_16384_1.dblwr

So to me the logging is confusing. If this is building a new double-write buffer why did it create the legacy one unless that's needed. While probably unimportant functionally better logging here would help and make things clearer.

The documentation https://dev.mysql.com/doc/refman/8.0/en/innodb-doublewrite-buffer.html doesn't really answer these questions either.

I'm assuming that on initialisation there are 2 options: you have to build both double-write buffers for compatibility (but in theory you can't now downgrade minor versions of 8.0 so this doesn't seem to be needed?) in which case indicate this:
* initialising legacy doublewrite buffer
* initialising new doublewrite buffer
Then log which one is being used (probably the new one)?

This also leads to a number of questions. The doublewrite buffer now has 3 settings. the directory, the number of files and the number of pages in each file.

These settings are indicated to be static which is mainly fine but are they static forever?  The documentation does not mention this.

Trying to change the values and restarting mysqld seems to indicate they are dynamci:

2020-05-15T09:14:13.181221Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_0.dblwr' for doublewrite
2020-05-15T09:14:13.187487Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_1.dblwr' for doublewrite
2020-05-15T09:14:13.199996Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_2.dblwr' for doublewrite
2020-05-15T09:14:13.205271Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_3.dblwr' for doublewrite
2020-05-15T09:14:13.245571Z 1 [Note] [MY-013566] [InnoDB] Double write buffer files: 4
2020-05-15T09:14:13.245742Z 1 [Note] [MY-013565] [InnoDB] Double write buffer pages per instance: 128
2020-05-15T09:14:13.246061Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_0.dblwr' for doublewrite
2020-05-15T09:14:13.246360Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_1.dblwr' for doublewrite
2020-05-15T09:14:13.246717Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_2.dblwr' for doublewrite
2020-05-15T09:14:13.247037Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_3.dblwr' for doublewrite

And reducing the value appears to change the file when it's used (so shows initially only a single file changing when I reduce the files to 2 and the number of pages down again):

...
2020-05-15T09:17:26.779605Z 1 [Note] [MY-012535] [InnoDB] Apply batch completed!
2020-05-15T09:17:26.780269Z 1 [Note] [MY-013548] [InnoDB] ./#ib_16384_0.dblwr size reduced to 1572864 bytes from 4194304 bytes
2020-05-15T09:17:26.781375Z 1 [Note] [MY-013252] [InnoDB] Using undo tablespace './undo_001'.
...

This will leave the old doublewrite files around which would need to be cleaned up.

Clarifying these points may be good in the docs as the documentation indicates that these new settings provide better flexibility for the user if needed but it's likely that these are settings which won't be touched very frequently so people won't be sure how they can be adjusted if this is wanted.

A final question that also arises is "When might I need to make changes to the doublewrite buffer?" and to answer that some comments on what to look for in the different performance_schema or server metrics might be good.   Then we can use these metrics to identify is changes to the settings may be appropriate.

So thanks for also considering adding more documentation to clarify these points.

Finally if you're going to log something about the doublewrite buffer on startup consider showing the settings used:

2020-05-15T08:28:17.758967Z 1 [Note] [MY-011920] [InnoDB] Doublewrite buffer configuration: 2 files, 64 pages in directory /data/mysql/instance1.

Also I notice:

+------------------------------+-------+
| Variable_name                | Value |
+------------------------------+-------+
| innodb_buffer_pool_instances | 1     |
+------------------------------+-------+
1 row in set (0.01 sec)

root@usher0db-1016 [(none)]> show global variables like '%doublewrite%';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| innodb_doublewrite            | ON    |
| innodb_doublewrite_batch_size | 0     |
| innodb_doublewrite_dir        |       |
| innodb_doublewrite_files      | 4     |
| innodb_doublewrite_pages      | 32    |
+-------------------------------+-------+
5 rows in set (0.02 sec)

The startup was quite happy about this:

2020-05-15T11:28:09.060709Z 1 [Note] [MY-013548] [InnoDB] ./#ib_16384_0.dblwr size reduced to 1048576 bytes from 1572864 bytes
2020-05-15T11:28:09.061508Z 1 [Note] [MY-013548] [InnoDB] ./#ib_16384_1.dblwr size reduced to 5242880 bytes from 9961472 bytes
2020-05-15T11:28:09.062691Z 1 [Note] [MY-013548] [InnoDB] ./#ib_16384_2.dblwr size reduced to 1048576 bytes from 4194304 bytes
2020-05-15T11:28:09.063412Z 1 [Note] [MY-013548] [InnoDB] ./#ib_16384_3.dblwr size reduced to 5242880 bytes from 8388608 bytes

Yet it contradicts the wording in the url posted earlier in this bug report:

"At a minimum, there are two doublewrite files. The maximum number of doublewrite files is two times the number of buffer pool instances. (The number of buffer pool instances is controlled by the innodb_buffer_pool_instances variable.)"

I have 1 buffer pool instance and 4 doublewrite buffer files.  I guess the docs need to be updated unless maybe 2 of these files won't actually be used?

Adjust tags

Hello Simon,

Thank you for the report and feedback.
Observed this during initialization when --log-error-verbosity was set to 3.

regards,
Umesh

Hi,

I just checked https://dev.mysql.com/doc/refman/8.0/en/server-system-variables.html#sysvar_log_error_verb... 

I hadn't realised that this default value had been changed as I was aware of the value for 5.7 being 3 by default 

https://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html#sysvar_log_error_verb...

So that would reduce some  logging in 8.0 and the new doublewrite buffer is only in 8.0.

Having said that getting the right amount of logging for all logging provided by mysqld is hard. I'm aware of the options which now allow me to optionally change logging which was introduced in 8.0 but that's still awkward to manage on initial startup, something I have reported directly to Oracle staff.

So perhaps my comments about the "verbose logging" for the initial startup may be overstated. I do however, think there are several other issues which are related to this new functionality and logging which still could be improved and I stand by those comments.

Thanks for listening.

Simon, if you don't want these messages, you can just add to your my.cnf:

[mysqld]
log-error-suppression-list="MY-011950"

I still think logging could be adjusted somewhat and that would be better.

There is also an issue with documentation should be resolved too.  This is typical of a new feature.

Is it better to open a second bug report for say the documentation or are the things that are described here clear enough?

Since there don't appear to be any bugs I'll change the severity to S4 FR.

Simon, you guessed right, since it's a new feature and my preference is generally to print more rather than less and I agree that to log too many (trace) messages are useless to the end user and are unnecessary clutter. Usually such messages are trimmed down or removed altogether after a minor release or two. Testing internally is not the same as testing done by users with realistic loads and use cases etc. Core files are not always available and neither do users run debug versions of the code besides races etc. are mostly detected in optimized code.

I'm open to suggestions as I was going to remove them altogether after I saw your bug. I agree that once things stabilize it's better to print something on which the end user can take some action or print just enough trace messages so that the end user can  verify whether the server is misconfigured etc.

MySQL lacks a trace facility and so [Info] is abused a little and used like trace messages.

Regarding dblwr file life cycle. I wasn't keen to delete the unused files initially. Since then I've changed my mind. I think we can remove all of them within InnoDB on a clean shutdown.