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

Recovery failure : loop of Read redo log up to LSN

Details

    Description

      Hello,

      I think I've just encountered a bug with the latest version of mariadb-server-10.3.

      After a power failure mariadb start a crash recovery but it seems to loop on the same LSN for ever.

      To fix it I uninstall everythning and install v10.3.21.
      The crash recovery just run fine.

      Version: '10.3.22-MariaDB-0+deb10u1-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Debian 10
      		 
      2020-02-25 23:46:30 0 [Note] InnoDB: Buffer pool(s) load completed at 200225 23:46:30
      		 
      2020-02-26 20:31:14 0 [Note] InnoDB: Using Linux native AIO
      		 
      2020-02-26 20:31:14 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      		 
      2020-02-26 20:31:14 0 [Note] InnoDB: Uses event mutexes
      		 
      2020-02-26 20:31:14 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
      		 
      2020-02-26 20:31:14 0 [Note] InnoDB: Number of pools: 1
      		 
      2020-02-26 20:31:14 0 [Note] InnoDB: Using SSE2 crc32 instructions
      		 
      2020-02-26 20:31:14 0 [Note] InnoDB: Initializing buffer pool, total size = 3G, instances = 3, chunk size = 128M
      		 
      2020-02-26 20:31:15 0 [Note] InnoDB: Completed initialization of buffer pool
      		 
      2020-02-26 20:31:15 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      		 
      2020-02-26 20:31:15 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=3388965427
      		 
      2020-02-26 20:31:30 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:31:45 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:32:00 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:32:15 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:32:30 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:32:45 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:33:00 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:33:15 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:33:30 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:33:45 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:34:00 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:34:15 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:34:30 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:34:45 0 [Note] InnoDB: Read redo log up to LSN=3388965888
      		 
      2020-02-26 20:35:00 0 [Note] InnoDB: Read redo log up to LSN=3388965888

      mariad configuration:

      [mysqld]
      		 
       
      		 
      skip-name-resolve
      		 
       
      		 
      query_cache_type        	= 0
      		 
      query_cache_size		= 0
      		 
       
      		 
      innodb_io_capacity		= 3000
      		 
      innodb_buffer_pool_size		= 3G
      		 
      innodb_buffer_pool_instances	= 3
      		 
      innodb_flush_method		= O_DIRECT
      		 
       
      		 
      # Logs
      		 
      log-error			= /var/log/mysql/error.log
      		 
      slow_query_log			= 1
      		 
      slow_query_log_file		= /var/log/mysql/mysql-slow.log
      		 
      long_query_time			= 5

      Attachments

        Issue Links

          is caused by

          Bug - A problem which impairs or prevents the functions of the product. MDEV-19176 Do not run out of InnoDB buffer pool during recovery

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

          Bug - A problem which impairs or prevents the functions of the product. MDEV-22512 innodb_zip.recover, innodb_gis.types failed in buildbot with server failing to restart

          • Major - Major loss of function.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            View 13 older comments
            marko Marko Mäkelä added a comment -

            We were very busy with 10.5 development, but thiru will take a look at the new upload soon.

            marko Marko Mäkelä added a comment - We were very busy with 10.5 development, but thiru will take a look at the new upload soon.
            thiru Thirunarayanan Balathandayuthapani added a comment - - edited

            I used the latest uploaded ib_logfile* to start the server for the following builds:

            mariadb-10.3.22 debug built from source

            		 
            2020-03-13 15:48:48 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
            		 
            innodb_init: ib_log: checkpoint 155950 at 4174599553 found
            		 
            innodb_init: ib_log: checkpoint 155949 at 4174599424 found
            		 
            2020-03-13 15:48:48 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4174599553
            		 
            recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(4174599553) read at 4174599562
            		 
            recv_group_scan_log_recs: ib_log: scan 4174599562 completed
            		 
            recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(4174599553) reread at 4174599562
            		 
            recv_group_scan_log_recs: ib_log: scan 4174599562 completed
            		 
            innodb_init: ib_log: checkpoint 155951 at 4174599553 written
            		 
            innodb_init: ib_log: MLOG_CHECKPOINT(4174599553) written at 4174599571
            		 
            innodb_init: ib_log: apply completed

            mariadb-10.3.22 release built from source

            		 
            2020-03-13 18:05:49 0 [Note] InnoDB: Using SSE2 crc32 instructions
            		 
            2020-03-13 18:05:49 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
            		 
            2020-03-13 18:05:49 0 [Note] InnoDB: Completed initialization of buffer pool
            		 
            2020-03-13 18:05:49 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
            		 
            2020-03-13 18:05:49 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4174599553
            		 
            2020-03-13 18:05:49 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
            		 
            2020-03-13 18:05:49 0 [Note] InnoDB: Creating shared tablespace for temporary tables
            		 
            2020-03-13 18:05:49 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
            		 
            2020-03-13 18:05:49 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
            		 
            2020-03-13 18:05:49 0 [Note] InnoDB: Waiting for purge to start
            		 
            2020-03-13 18:05:49 0 [Note] InnoDB: 10.3.22 started; log sequence number 4174599562; transaction id 21
            		 
            2020-03-13 18:05:49 0 [Note] InnoDB: Loading buffer pool(s) from /home/thiru/mariarepo/10.3/MDEV-21826/bld_MDEV-21826-rel/data/ib_buffer_pool
            		 
            2020-03-13 18:05:49 0 [Note] Plugin 'FEEDBACK' is disabled.
            		 
            2020-03-13 18:05:49 0 [Note] InnoDB: Buffer pool(s) load completed at 200313 18:05:49

            mariadb-10.3.22-buster_all.deb

            		 
            - Unit mariadb.service has begun starting up.
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] /usr/sbin/mysqld (mysqld 10.3.22-MariaDB-1:10.3.22+maria~bionic) starting as p
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Using Linux native AIO
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Uses event mutexes
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Number of pools: 1
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Using SSE2 crc32 instructions
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Completed initialization of buffer pool
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priori
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4174599553
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Creating shared tablespace for temporary tables
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file ful
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: 10.3.22 started; log sequence number 4174599562; transaction id 21
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] Plugin 'FEEDBACK' is disabled.
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
            		 
            Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Buffer pool(s) load completed at 2003

            Recovery didn't show up any issue for the given ib_logfile* files.
            Can you provide ssh access to the environment where the issue can be repeated ? Thanks neimad

            thiru Thirunarayanan Balathandayuthapani added a comment - - edited I used the latest uploaded ib_logfile* to start the server for the following builds: mariadb-10.3.22 debug built from source 2020-03-13 15:48:48 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). innodb_init: ib_log: checkpoint 155950 at 4174599553 found innodb_init: ib_log: checkpoint 155949 at 4174599424 found 2020-03-13 15:48:48 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4174599553 recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(4174599553) read at 4174599562 recv_group_scan_log_recs: ib_log: scan 4174599562 completed recv_group_scan_log_recs: ib_log: MLOG_CHECKPOINT(4174599553) reread at 4174599562 recv_group_scan_log_recs: ib_log: scan 4174599562 completed innodb_init: ib_log: checkpoint 155951 at 4174599553 written innodb_init: ib_log: MLOG_CHECKPOINT(4174599553) written at 4174599571 innodb_init: ib_log: apply completed mariadb-10.3.22 release built from source 2020-03-13 18:05:49 0 [Note] InnoDB: Using SSE2 crc32 instructions 2020-03-13 18:05:49 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M 2020-03-13 18:05:49 0 [Note] InnoDB: Completed initialization of buffer pool 2020-03-13 18:05:49 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 2020-03-13 18:05:49 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4174599553 2020-03-13 18:05:49 0 [Note] InnoDB: 128 out of 128 rollback segments are active. 2020-03-13 18:05:49 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2020-03-13 18:05:49 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2020-03-13 18:05:49 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2020-03-13 18:05:49 0 [Note] InnoDB: Waiting for purge to start 2020-03-13 18:05:49 0 [Note] InnoDB: 10.3.22 started; log sequence number 4174599562; transaction id 21 2020-03-13 18:05:49 0 [Note] InnoDB: Loading buffer pool(s) from /home/thiru/mariarepo/10.3/MDEV-21826/bld_MDEV-21826-rel/data/ib_buffer_pool 2020-03-13 18:05:49 0 [Note] Plugin 'FEEDBACK' is disabled. 2020-03-13 18:05:49 0 [Note] InnoDB: Buffer pool(s) load completed at 200313 18:05:49 mariadb-10.3.22-buster_all.deb - Unit mariadb.service has begun starting up. Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] /usr/sbin/mysqld (mysqld 10.3.22-MariaDB-1:10.3.22+maria~bionic) starting as p Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Using Linux native AIO Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Uses event mutexes Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Number of pools: 1 Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Using SSE2 crc32 instructions Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Completed initialization of buffer pool Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priori Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4174599553 Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: 128 out of 128 rollback segments are active. Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Creating shared tablespace for temporary tables Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file ful Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: 10.3.22 started; log sequence number 4174599562; transaction id 21 Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] Plugin 'FEEDBACK' is disabled. Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool Mar 13 18:57:20 thiru-ThinkPad-T480 mysqld[21823]: 2020-03-13 18:57:20 0 [Note] InnoDB: Buffer pool(s) load completed at 2003 Recovery didn't show up any issue for the given ib_logfile* files. Can you provide ssh access to the environment where the issue can be repeated ? Thanks neimad
            thiru Thirunarayanan Balathandayuthapani added a comment -

            Thanks neimad. I can repeat the issue now.

            thiru Thirunarayanan Balathandayuthapani added a comment - Thanks neimad . I can repeat the issue now.
            marko Marko Mäkelä added a comment -

            neimad, the bug can be worked around by setting innodb_buffer_pool_instances=1. The MDEV-19176 fix included a bogus condition that we missed not only in code review but also in our internal testing, because we usually run tests with random input using rather small buffer pool sizes. For the record, MariaDB 10.5 would not be affected by this, because MDEV-15058 removed multiple buffer pool instances.

            marko Marko Mäkelä added a comment - neimad , the bug can be worked around by setting innodb_buffer_pool_instances=1 . The MDEV-19176 fix included a bogus condition that we missed not only in code review but also in our internal testing, because we usually run tests with random input using rather small buffer pool sizes. For the record, MariaDB 10.5 would not be affected by this, because MDEV-15058 removed multiple buffer pool instances.
            mleich Matthias Leich added a comment -

            I was able to replay the problem on origin/10.2 ab0034a78966f3e9f76cf332744fdc54ef10f8c1 2020-03-17T16:28:16+02:00 with RQG

            • innodb_buffer_pool_instances=3 replay
              innodb_buffer_pool_instances=1 never a replay
            • running DDL within the RQG grammar is not required.

            No replay + no unknown bad effect on origin/10.2 09e8707d90a8a73887fd4f22b64df43ff4669556 2020-03-18T15:25:28+05:30

            mleich Matthias Leich added a comment - I was able to replay the problem on origin/10.2 ab0034a78966f3e9f76cf332744fdc54ef10f8c1 2020-03-17T16:28:16+02:00 with RQG innodb_buffer_pool_instances=3 replay innodb_buffer_pool_instances=1 never a replay running DDL within the RQG grammar is not required. No replay + no unknown bad effect on origin/10.2 09e8707d90a8a73887fd4f22b64df43ff4669556 2020-03-18T15:25:28+05:30

            People

              thiru Thirunarayanan Balathandayuthapani
              neimad Damien BRS
              Votes:
              0 Vote for this issue
              Watchers:
              7 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.