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

Crash in rollback of a recovered INSERT transaction after upgrade

Details

    Description

      2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Completed initialization of buffer pool
      		 
      2017-08-10 17:48:57 140404724037376 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      		 
      2017-08-10 17:48:57 140405466861632 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
      		 
      2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Trx id counter is 7424
      		 
      2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Upgrading redo log: 2*50331648 bytes; LSN=9779797
      		 
      2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Starting to delete and rewrite log files.
      		 
      2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Setting log file ./ib_logfile101 size to 50331648 bytes
      		 
      2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Setting log file ./ib_logfile1 size to 50331648 bytes
      		 
      2017-08-10 17:48:58 140405466861632 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
      		 
      2017-08-10 17:48:58 140405466861632 [Note] InnoDB: New log files created, LSN=9779797
      		 
      2017-08-10 17:48:58 140404715644672 [Note] InnoDB: Starting in background the rollback of recovered transactions
      		 
      2017-08-10 17:48:58 140405466861632 [Note] InnoDB: 128 out of 128 rollback segments are active.
      		 
      2017-08-10 17:48:58 140404715644672 [Note] InnoDB: Rolling back trx with id 6568, 1 rows to undo
      		 
      2017-08-10 17:48:58 140405466861632 [Note] InnoDB: Creating shared tablespace for temporary tables
      		 
      2017-08-10 17:48:58 140405466861632 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
      		 
      mysqld: /data/src/10.3/storage/innobase/trx/trx0trx.cc:1918: void trx_commit_low(trx_t*, mtr_t*): Assertion `!mtr == !trx->has_logged()' failed.
      		 
      170810 17:48:58 [ERROR] mysqld got signal 6 ;

      10.3 73297f532fba89e33785460448e93f87478c2505

      		 
      #3  0x00007f3ff87f7ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
      		 
      #4  0x0000565165cfad75 in trx_commit_low (trx=0x7f3ff5406878, mtr=0x7f3fce337470) at /data/src/10.3/storage/innobase/trx/trx0trx.cc:1918
      		 
      #5  0x0000565165cfafcc in trx_commit (trx=0x7f3ff5406878) at /data/src/10.3/storage/innobase/trx/trx0trx.cc:2018
      		 
      #6  0x0000565165cee5c2 in trx_rollback_finish (trx=0x7f3ff5406878) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:1147
      		 
      #7  0x0000565165cecf5b in trx_rollback_active (trx=0x7f3ff5406878) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:689
      		 
      #8  0x0000565165ced427 in trx_rollback_resurrected (trx=0x7f3ff5406878, all=1) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:773
      		 
      #9  0x0000565165ced6d6 in trx_rollback_or_clean_recovered (all=1) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:841
      		 
      #10 0x0000565165ced889 in trx_rollback_or_clean_all_recovered (arg=0x0) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:881
      		 
      #11 0x00007f3ffa73c494 in start_thread (arg=0x7f3fce338700) at pthread_create.c:333
      		 
      #12 0x00007f3ff88b493f in clone () from /lib/x86_64-linux-gnu/libc.so.6

      The attached datadir was created as a part of MDEV-13269 workflow.

      • 10.2 server (86f9b7714791) was started with --innodb-change-buffering=none --innodb-page-size=8K --innodb-compression-algorithm=zlib, otherwise defaults;
      • a number of tables was created and concurrent DML was executed in 4 threads for about a minute;
      • the server was SIGKILL-ed;
      • the server was started again with the same options plus --innodb-force-recovery=3;
      • the server was shut down normally.

      Now, to reproduce the reported assertion failure, start 10.3 server on the provided datadir with --innodb-change-buffering=none --innodb-page-size=8K --innodb-compression-algorithm=zlib, the failure happens upon startup.

      10.2 starts all right on this datadir.

      Note: in the initial scenario, there was an intermediate step when the 10.3 server is started on the datadir with --innodb-read-only and then gets shut down normally. It starts all right, but the step does not change the outcome when the server is finally restarted in a normal mode, so it's omitted above.

      Attachments

        1. data.tar.gz
          5.91 MB
        2. threads1
          24 kB

        Issue Links

          is caused by

          Task - A task that needs to be done. MDEV-12288 Reset DB_TRX_ID when the history is removed, to speed up MVCC

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

          Task - A task that needs to be done. MDEV-13269 Upgrade tests for InnoDB undo log

          • Major - Major loss of function.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            elenst Elena Stepanova created issue -
            elenst Elena Stepanova made changes -
            Field Original Value New Value
            Assignee Elena Stepanova [ elenst ] Marko Mäkelä [ marko ]
            Description {noformat}
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Completed initialization of buffer pool
            2017-08-10 17:48:57 140404724037376 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Trx id counter is 7424
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Upgrading redo log: 2*50331648 bytes; LSN=9779797
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Starting to delete and rewrite log files.
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Setting log file ./ib_logfile101 size to 50331648 bytes
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Setting log file ./ib_logfile1 size to 50331648 bytes
            2017-08-10 17:48:58 140405466861632 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
            2017-08-10 17:48:58 140405466861632 [Note] InnoDB: New log files created, LSN=9779797
            2017-08-10 17:48:58 140404715644672 [Note] InnoDB: Starting in background the rollback of recovered transactions
            2017-08-10 17:48:58 140405466861632 [Note] InnoDB: 128 out of 128 rollback segments are active.
            2017-08-10 17:48:58 140404715644672 [Note] InnoDB: Rolling back trx with id 6568, 1 rows to undo
            2017-08-10 17:48:58 140405466861632 [Note] InnoDB: Creating shared tablespace for temporary tables
            2017-08-10 17:48:58 140405466861632 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
            mysqld: /data/src/10.3/storage/innobase/trx/trx0trx.cc:1918: void trx_commit_low(trx_t*, mtr_t*): Assertion `!mtr == !trx->has_logged()' failed.
            170810 17:48:58 [ERROR] mysqld got signal 6 ;
            {noformat}
            {noformat:title=10.3 73297f532fba89e33785460448e93f87478c2505}
            #3 0x00007f3ff87f7ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
            #4 0x0000565165cfad75 in trx_commit_low (trx=0x7f3ff5406878, mtr=0x7f3fce337470) at /data/src/10.3/storage/innobase/trx/trx0trx.cc:1918
            #5 0x0000565165cfafcc in trx_commit (trx=0x7f3ff5406878) at /data/src/10.3/storage/innobase/trx/trx0trx.cc:2018
            #6 0x0000565165cee5c2 in trx_rollback_finish (trx=0x7f3ff5406878) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:1147
            #7 0x0000565165cecf5b in trx_rollback_active (trx=0x7f3ff5406878) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:689
            #8 0x0000565165ced427 in trx_rollback_resurrected (trx=0x7f3ff5406878, all=1) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:773
            #9 0x0000565165ced6d6 in trx_rollback_or_clean_recovered (all=1) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:841
            #10 0x0000565165ced889 in trx_rollback_or_clean_all_recovered (arg=0x0) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:881
            #11 0x00007f3ffa73c494 in start_thread (arg=0x7f3fce338700) at pthread_create.c:333
            #12 0x00007f3ff88b493f in clone () from /lib/x86_64-linux-gnu/libc.so.6
            {noformat}

            The attached datadir was created as a part of MDEV-13269 workflow.

            - 10.2 server (86f9b7714791) was started with {{\-\-innodb-change-buffering=none \-\-innodb-page-size=8K \-\-innodb-compression-algorithm=zlib}}, otherwise defaults;
            - a number of tables was created and concurrent DML was executed in 4 threads for about a minute;
            - the server was SIGKILL-ed;
            - the server was started again with the same options plus {{\-\-innodb-force-recovery=3}};
            - the server was shut down normally.

            Now, to reproduce the reported assertion failure, start 10.3 server on the provided datadir with {{\-\-innodb-change-buffering=none \-\-innodb-page-size=8K \-\-innodb-compression-algorithm=zlib}}, the failure happens upon startup.

            _Note: in the initial scenario, there was an intermediate step when the 10.3 server is started on the datadir with {{--innodb-read-only}} and then gets shut down normally. It starts all right, but the step does not change the outcome when the server is finally restarted in a normal mode, so it's omitted above._             		{noformat}
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Completed initialization of buffer pool
            2017-08-10 17:48:57 140404724037376 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Trx id counter is 7424
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Upgrading redo log: 2*50331648 bytes; LSN=9779797
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Starting to delete and rewrite log files.
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Setting log file ./ib_logfile101 size to 50331648 bytes
            2017-08-10 17:48:57 140405466861632 [Note] InnoDB: Setting log file ./ib_logfile1 size to 50331648 bytes
            2017-08-10 17:48:58 140405466861632 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
            2017-08-10 17:48:58 140405466861632 [Note] InnoDB: New log files created, LSN=9779797
            2017-08-10 17:48:58 140404715644672 [Note] InnoDB: Starting in background the rollback of recovered transactions
            2017-08-10 17:48:58 140405466861632 [Note] InnoDB: 128 out of 128 rollback segments are active.
            2017-08-10 17:48:58 140404715644672 [Note] InnoDB: Rolling back trx with id 6568, 1 rows to undo
            2017-08-10 17:48:58 140405466861632 [Note] InnoDB: Creating shared tablespace for temporary tables
            2017-08-10 17:48:58 140405466861632 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
            mysqld: /data/src/10.3/storage/innobase/trx/trx0trx.cc:1918: void trx_commit_low(trx_t*, mtr_t*): Assertion `!mtr == !trx->has_logged()' failed.
            170810 17:48:58 [ERROR] mysqld got signal 6 ;
            {noformat}
            {noformat:title=10.3 73297f532fba89e33785460448e93f87478c2505}
            #3 0x00007f3ff87f7ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
            #4 0x0000565165cfad75 in trx_commit_low (trx=0x7f3ff5406878, mtr=0x7f3fce337470) at /data/src/10.3/storage/innobase/trx/trx0trx.cc:1918
            #5 0x0000565165cfafcc in trx_commit (trx=0x7f3ff5406878) at /data/src/10.3/storage/innobase/trx/trx0trx.cc:2018
            #6 0x0000565165cee5c2 in trx_rollback_finish (trx=0x7f3ff5406878) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:1147
            #7 0x0000565165cecf5b in trx_rollback_active (trx=0x7f3ff5406878) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:689
            #8 0x0000565165ced427 in trx_rollback_resurrected (trx=0x7f3ff5406878, all=1) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:773
            #9 0x0000565165ced6d6 in trx_rollback_or_clean_recovered (all=1) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:841
            #10 0x0000565165ced889 in trx_rollback_or_clean_all_recovered (arg=0x0) at /data/src/10.3/storage/innobase/trx/trx0roll.cc:881
            #11 0x00007f3ffa73c494 in start_thread (arg=0x7f3fce338700) at pthread_create.c:333
            #12 0x00007f3ff88b493f in clone () from /lib/x86_64-linux-gnu/libc.so.6
            {noformat}

            The attached datadir was created as a part of MDEV-13269 workflow.

            - 10.2 server (86f9b7714791) was started with {{\-\-innodb-change-buffering=none \-\-innodb-page-size=8K \-\-innodb-compression-algorithm=zlib}}, otherwise defaults;
            - a number of tables was created and concurrent DML was executed in 4 threads for about a minute;
            - the server was SIGKILL-ed;
            - the server was started again with the same options plus {{\-\-innodb-force-recovery=3}};
            - the server was shut down normally.

            Now, to reproduce the reported assertion failure, start 10.3 server on the provided datadir with {{\-\-innodb-change-buffering=none \-\-innodb-page-size=8K \-\-innodb-compression-algorithm=zlib}}, the failure happens upon startup.

            10.2 starts all right on this datadir.

            _Note: in the initial scenario, there was an intermediate step when the 10.3 server is started on the datadir with {{--innodb-read-only}} and then gets shut down normally. It starts all right, but the step does not change the outcome when the server is finally restarted in a normal mode, so it's omitted above._
            marko Marko Mäkelä made changes -
            marko Marko Mäkelä made changes -
            Summary Assertion `!mtr == !trx->has_logged()' failed in trx_commit_low(trx_t*, mtr_t*) Crash in rollback of a recovered INSERT transaction after upgrade
            marko Marko Mäkelä made changes -
            Affects Version/s 10.3.1 [ 22532 ]
            Affects Version/s 10.3 [ 22126 ]
            marko Marko Mäkelä made changes -
            Status Open [ 1 ] Confirmed [ 10101 ]
            marko Marko Mäkelä made changes -
            Status Confirmed [ 10101 ] In Progress [ 3 ]
            marko Marko Mäkelä made changes -
            issue.field.resolutiondate 2017-08-11 10:02:17.0 2017-08-11 10:02:17.425
            marko Marko Mäkelä made changes -
            Fix Version/s 10.3.1 [ 22532 ]
            Fix Version/s 10.3 [ 22126 ]
            Resolution Fixed [ 1 ]
            Status In Progress [ 3 ] Closed [ 6 ]
            elenst Elena Stepanova made changes -
            serg Sergei Golubchik made changes -
            Workflow MariaDB v3 [ 81992 ] MariaDB v4 [ 152593 ]

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              2 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.