[MDEV-10509] Excessive InnoDB logging on release server Created: 2016-08-07  Updated: 2017-04-17  Resolved: 2017-04-17

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.1
Fix Version/s: 10.1.23, 10.2.6

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: 10.2-ga

Issue Links:
Duplicate
is duplicated by MDEV-12322 MariaDB 10.1.19 - Error log - every 4... Closed
Relates
relates to MDEV-6812 Merge Kakao: Add global status variab... Closed
relates to MDEV-12512 Accurately report progress for ALTER ... Open
relates to MDEV-11027 InnoDB log recovery is too noisy Closed
Sprint: 10.2.5-1

 Description   

We are getting error logs from users which are flooded with this:

2016-08-02 17:16:56 139591697147648 [Note] InnoDB: Online DDL : Start merge-sorting index `IDX_MODIDATE` (2 / 3), estimated cost : 10.0000
 
2016-08-02 17:16:56 139591697147648 [Note] InnoDB: Online DDL : End of  merge-sorting index `IDX_MODIDATE` (2 / 3)
 
2016-08-02 17:16:56 139591697147648 [Note] InnoDB: Online DDL : Start building index `IDX_MODIDATE` (2 / 3), estimated cost : 15.0000
 
2016-08-02 17:16:56 139591697147648 [Note] InnoDB: Online DDL : End of building index `IDX_MODIDATE` (2 / 3)
 
2016-08-02 17:16:56 139591697147648 [Note] InnoDB: Online DDL : Completed
 
2016-08-02 17:16:56 139591697147648 [Note] InnoDB: Online DDL : Start merge-sorting index `IDX_CREATEDATE` (3 / 3), estimated cost : 10.0000
 
2016-08-02 17:16:56 139591697147648 [Note] InnoDB: Online DDL : End of  merge-sorting index `IDX_CREATEDATE` (3 / 3)
 
2016-08-02 17:16:56 139591697147648 [Note] InnoDB: Online DDL : Start building index `IDX_CREATEDATE` (3 / 3), estimated cost : 15.0000
 
2016-08-02 17:16:56 139591697147648 [Note] InnoDB: Online DDL : End of building index `IDX_CREATEDATE` (3 / 3)
 
2016-08-02 17:16:56 139591697147648 [Note] InnoDB: Online DDL : Completed
 
2016-08-03 11:18:37 139668872341248 [Note] InnoDB: Online DDL : Start
 
2016-08-03 11:18:37 139668872341248 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2016-08-03 11:18:37 139668872341248 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2016-08-03 11:18:37 139668872341248 [Note] InnoDB: Online DDL : Start merge-sorting index `idx_CREATEDATE1`--temporary-- (1 / 1), estimated cost : 20.0000
 
2016-08-03 11:18:37 139668872341248 [Note] InnoDB: Online DDL : End of  merge-sorting index `idx_CREATEDATE1`--temporary-- (1 / 1)
 
2016-08-03 11:18:37 139668872341248 [Note] InnoDB: Online DDL : Start building index `idx_CREATEDATE1`--temporary-- (1 / 1), estimated cost : 30.0000
 
2016-08-03 11:18:37 139668872341248 [Note] InnoDB: Online DDL : End of building index `idx_CREATEDATE1`--temporary-- (1 / 1)
 
2016-08-03 11:18:37 139668872341248 [Note] InnoDB: Online DDL : Start applying row log
 
2016-08-03 11:18:37 139668872341248 [Note] InnoDB: Online DDL : End of applying row log
 
2016-08-03 11:18:37 139668872341248 [Note] InnoDB: Online DDL : Completed
 
2016-08-03 11:18:48 139668872341248 [Note] InnoDB: Online DDL : Start
 
2016-08-03 11:18:48 139668872341248 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2016-08-03 11:18:48 139668872341248 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2016-08-03 11:18:48 139668872341248 [Note] InnoDB: Online DDL : Start merge-sorting index `idx_MODIDATE1`--temporary-- (1 / 1), estimated cost : 20.0000
 
2016-08-03 11:18:48 139668872341248 [Note] InnoDB: Online DDL : End of  merge-sorting index `idx_MODIDATE1`--temporary-- (1 / 1)
 
2016-08-03 11:18:48 139668872341248 [Note] InnoDB: Online DDL : Start building index `idx_MODIDATE1`--temporary-- (1 / 1), estimated cost : 30.0000
 
2016-08-03 11:18:48 139668872341248 [Note] InnoDB: Online DDL : End of building index `idx_MODIDATE1`--temporary-- (1 / 1)
 
2016-08-03 11:18:48 139668872341248 [Note] InnoDB: Online DDL : Start applying row log
 
2016-08-03 11:18:48 139668872341248 [Note] InnoDB: Online DDL : End of applying row log
 
2016-08-03 11:18:48 139668872341248 [Note] InnoDB: Online DDL : Completed
 
2016-08-03 11:19:34 139668872341248 [Note] InnoDB: Online DDL : Start
 
2016-08-03 11:19:34 139668872341248 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
 
2016-08-03 11:19:34 139668872341248 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
 
2016-08-03 11:19:34 139668872341248 [Note] InnoDB: Online DDL : Start merge-sorting index `idx_comp1`--temporary-- (1 / 1), estimated cost : 20.0000
 
2016-08-03 11:19:34 139668872341248 [Note] InnoDB: Online DDL : End of  merge-sorting index `idx_comp1`--temporary-- (1 / 1)
 
2016-08-03 11:19:34 139668872341248 [Note] InnoDB: Online DDL : Start building index `idx_comp1`--temporary-- (1 / 1), estimated cost : 30.0000
 
2016-08-03 11:19:34 139668872341248 [Note] InnoDB: Online DDL : End of building index `idx_comp1`--temporary-- (1 / 1)
 
2016-08-03 11:19:34 139668872341248 [Note] InnoDB: Online DDL : Start applying row log
 
2016-08-03 11:19:34 139668872341248 [Note] InnoDB: Online DDL : End of applying row log
 
2016-08-03 11:19:34 139668872341248 [Note] InnoDB: Online DDL : Completed

All of this is completely meaningless on the user side – even if they were interested in this kind of detail, the logging says nothing about the table which the operation was performed on, query, connection, account, etc. It is purely debug info, and should be logged as such.



 Comments   
Comment by Jan Lindström (Inactive) [ 2016-08-09 ]

I do not agree, this output tells a current phase and estimate how long the online alter table will still take as you can see the estimated cost. But it could be improved by adding a table etc information. This is not a debug info.

Comment by Elena Stepanova [ 2017-01-07 ]

We have had several discussions before, and I think we finally agreed that the logging would be moved to higher levels of log-warnings (above 2). Please do it.

The other option is, if you really think it's totally necessary to have all of this logged by default, create another InnoDB log file and put everything there.

We have already seen real-life customers' error logs where InnoDB would flood the error log with over 5,000 lines per second for continuous time. which is just crazy, nobody can find useful information there, it damages crash reporting, and it swiftly comes to the point when not only error logs aren't easily attachable/transferable, but it's going to affect the performance – the activity in error logs becomes comparable with the general log.. And of course, it has become even worse in 10.2.

Comment by Marko Mäkelä [ 2017-03-08 ]

I think that we should report progress via the native MariaDB interface instead of spamming the error log.
In 10.2, the InnoDB code to report progress via a similar interface already exists. It only needs to be tied to the proper interface. For 10.1, I think that we can backport the progress reporting changes from 10.2.

Comment by Marko Mäkelä [ 2017-03-08 ]

MDEV-6812 introduced server-wide status variables for monitoring ALTER TABLE…ALGORITHM=INPLACE progress. That feels wrong, because there can be multiple ALTER TABLE being executed concurrently.

Comment by Marko Mäkelä [ 2017-04-17 ]

As suggested by monty, I disabled the ALTER TABLE messages unless log_warnings is set to 3 or more. A proper fix will be done in MDEV-12512.

Generated at Thu Feb 08 07:42:46 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.