Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-10509

Excessive InnoDB logging on release server

Details

    • 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.

      Attachments

        Issue Links

          is duplicated by

          Bug - A problem which impairs or prevents the functions of the product. MDEV-12322 MariaDB 10.1.19 - Error log - every 4 seconds error message "clustered index of the table and create temporary files"

          • Major - Major loss of function.
          • Closed
          relates to

          Task - A task that needs to be done. MDEV-6812 Merge Kakao: Add global status variables which tell you the progress of inplace alter table and row log buffer usage

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-12512 Accurately report progress for ALTER TABLE...ALGORITHM=INPLACE

          • Major - Major loss of function.
          • Open

          Bug - A problem which impairs or prevents the functions of the product. MDEV-11027 InnoDB log recovery is too noisy

          • Major - Major loss of function.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            jplindst Jan Lindström (Inactive) added a comment -

            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.

            jplindst Jan Lindström (Inactive) added a comment - 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.
            elenst Elena Stepanova added a comment - - edited

            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.

            elenst Elena Stepanova added a comment - - edited 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.
            marko Marko Mäkelä added a comment -

            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.

            marko Marko Mäkelä added a comment - 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.
            marko Marko Mäkelä added a comment -

            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.

            marko Marko Mäkelä added a comment - 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.
            marko Marko Mäkelä added a comment -

            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.

            marko Marko Mäkelä added a comment - 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 .

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.