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

LP:613418 - (M)aria recovery failure: ma_key_recover.c:981: _ma_apply_redo_index: Assertion `check_page_length == page_length' failed.

        Details

        • Type: Bug
        • Status: Closed
        • Priority: Major
        • Resolution: Fixed
        • Affects Version/s: None
        • Fix Version/s: None
        • Component/s: None
        • Labels:

          Description

          When recovering from the rqg_maria_varchar test, which uses random DML statements with lengthy strings and multibyte character sets, (M)aria failed as follows:

          1. 2010-08-04T13:18:55 recovered pages: 0% 10% 20% 30% 40% 50% 60% 70% 80% 90%mysqld: ma_key_recover.c:981: _ma_apply_redo_index: Assertion `check_page_length == page_length' failed.
          2. 2010-08-04T13:18:55 100804 13:18:55 [ERROR] mysqld got signal 6 ;
          3. 2010-08-04T13:18:55 Recovery has apparently crashed.
          4. 2010-08-04T13:18:55 This could be because you hit a bug. It is also possible that this binary
          5. 2010-08-04T13:18:55 or one of the libraries it was linked against is corrupt, improperly built,
          6. 2010-08-04T13:18:55 Log message 'or one of the libraries it was linked against is corrupt, improperly built,' indicates database corruption
          7. 2010-08-04T13:18:55 or misconfigured. This error can also be caused by malfunctioning hardware.
          8. 2010-08-04T13:18:55 We will try our best to scrape up some info that will hopefully help diagnose
          9. 2010-08-04T13:18:55 the problem, but since we have already crashed, something is definitely wrong
          10. 2010-08-04T13:18:55 and this may fail.
          11. 2010-08-04T13:18:55
          12. 2010-08-04T13:18:55 key_buffer_size=0
          13. 2010-08-04T13:18:55 read_buffer_size=131072
          14. 2010-08-04T13:18:55 max_used_connections=0
          15. 2010-08-04T13:18:55 max_threads=153
          16. 2010-08-04T13:18:55 threads_connected=0
          17. 2010-08-04T13:18:55 It is possible that mysqld could use up to
          18. 2010-08-04T13:18:55 key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 334854 K
          19. 2010-08-04T13:18:55 bytes of memory
          20. 2010-08-04T13:18:55 Hope that's ok; if not, decrease some variables in the equation.
          21. 2010-08-04T13:18:55
          22. 2010-08-04T13:18:55 thd: 0x0
          23. 2010-08-04T13:18:55 Attempting backtrace. You can use the following information to find out
          24. 2010-08-04T13:18:55 where mysqld died. If you see no messages after this, something went
          25. 2010-08-04T13:18:55 terribly wrong...
          26. 2010-08-04T13:18:55 stack_bottom = (nil) thread_stack 0x48000
          27. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld(my_print_stacktrace+0x35) [0xb9375f]
          28. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld(handle_segfault+0x2ee) [0x6716bb]
          29. 2010-08-04T13:18:55 Recovery has apparently crashed.
          30. 2010-08-04T13:18:55 /lib64/libpthread.so.0() [0x307ba0f440]
          31. 2010-08-04T13:18:55 /lib64/libc.so.6(gsignal+0x35) [0x307b6329c5]
          32. 2010-08-04T13:18:55 /lib64/libc.so.6(abort+0x175) [0x307b6341a5]
          33. 2010-08-04T13:18:55 /lib64/libc.so.6(__assert_fail+0xf5) [0x307b62b945]
          34. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld(_ma_apply_redo_index+0xaf8) [0x982fe7]
          35. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld() [0x9ee6de]
          36. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld() [0x9ec155]
          37. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld() [0x9f0e38]
          38. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld(maria_apply_log+0x234) [0x9ebb15]
          39. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld(maria_recovery_from_log+0x10e) [0x9eb868]
          40. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld() [0x96ad38]
          41. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld(ha_initialize_handlerton(st_plugin_int*)+0xb5) [0x7c3bbc]
          42. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld() [0x8920a7]
          43. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld(plugin_init(int*, char**, int)+0x628) [0x89294e]
          44. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld() [0x6740a9]
          45. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld(main+0x259) [0x674bd5]
          46. 2010-08-04T13:18:55 /lib64/libc.so.6(__libc_start_main+0xfd) [0x307b61ec5d]
          47. 2010-08-04T13:18:55 /home/buildbot/rqg-buildbot-slave/rqg-perpush-mariaengine/build/mysql-test//../sql/mysqld() [0x57dcb9]

          The core, binary and such will be uploaded shortly.

            Gliffy Diagrams

              Attachments

                Activity

                Ascending order - Click to sort in descending order
                7 older comments
                Hide
                Permalink
                philipstoev Philip Stoev added a comment -

                Re: (M)aria recovery failure: ma_key_recover.c:981: _ma_apply_redo_index: Assertion `check_page_length == page_length' failed.
                This is still repeatable with

                revision-id: monty@askmonty.org-20100907165839-hbgfbzsuytbxtzn2
                date: 2010-09-07 19:58:39 +0300
                build-date: 2010-09-09 10:42:24 +0300
                revno: 2924
                branch-nick: 5.1

                maria_read_log reports:

                The transaction log starts from lsn (1,0x2007)
                TRACE of the last maria_read_log
                /home/buildbot/rqg-buildbot-slave/rqg-weekend/build/mysql-test//../storage/maria/maria_read_log: Maria engine: starting recovery
                recovered pages: 0%maria_read_log: ma_key_recover.c:1062: _ma_apply_redo_index: Assertion `check_page_length == page_length' failed.

                Show
                philipstoev Philip Stoev added a comment - Re: (M)aria recovery failure: ma_key_recover.c:981: _ma_apply_redo_index: Assertion `check_page_length == page_length' failed. This is still repeatable with revision-id: monty@askmonty.org-20100907165839-hbgfbzsuytbxtzn2 date: 2010-09-07 19:58:39 +0300 build-date: 2010-09-09 10:42:24 +0300 revno: 2924 branch-nick: 5.1 maria_read_log reports: The transaction log starts from lsn (1,0x2007) TRACE of the last maria_read_log /home/buildbot/rqg-buildbot-slave/rqg-weekend/build/mysql-test//../storage/maria/maria_read_log: Maria engine: starting recovery recovered pages: 0%maria_read_log: ma_key_recover.c:1062: _ma_apply_redo_index: Assertion `check_page_length == page_length' failed.
                Hide
                Permalink
                philipstoev Philip Stoev added a comment -

                Re: (M)aria recovery failure: ma_key_recover.c:981: _ma_apply_redo_index: Assertion `check_page_length == page_length' failed.
                Latest RQG command line that produced the problem

                1. 2010-09-09T07:46:51 # /home/buildbot/randgen/runall.pl \
                2. 2010-09-09T07:46:51 # --queries=1M \
                3. 2010-09-09T07:46:51 # --engine=Maria \
                4. 2010-09-09T07:46:51 # -mysqld=-log-output=file \
                5. 2010-09-09T07:46:51 # -mysqld=-maria_log_purge_type=at_flush \
                6. 2010-09-09T07:46:51 # --reporters=ErrorLog,Backtrace,Recovery,Shutdown \
                7. 2010-09-09T07:46:51 # --duration=30 \
                8. 2010-09-09T07:46:51 # --threads=1 \
                9. 2010-09-09T07:46:51 # --rows=1 \
                10. 2010-09-09T07:46:51 # --mask-level=2 \
                11. 2010-09-09T07:46:51 # -mysqld=-loose-maria-group-commit=soft \
                12. 2010-09-09T07:46:51 # -mysqld=-loose-maria_group_commit_interval=100 \
                13. 2010-09-09T07:46:51 # -mysqld=-maria-checkpoint-interval=120 \
                14. 2010-09-09T07:46:51 # -mysqld=-maria-block-size=16K \
                15. 2010-09-09T07:46:51 # --grammar=conf/engines/varchar.yy \
                16. 2010-09-09T07:46:51 # --gendata=conf/engines/varchar.zz \
                17. 2010-09-09T07:46:51 # --mask=62443 \
                18. 2010-09-09T07:46:51 # --queries=100000000 \
                19. 2010-09-09T07:46:51 # --mask=62443 \
                20. 2010-09-09T07:46:51 # --basedir=. \
                21. 2010-09-09T07:46:51 # --seed=time \
                22. 2010-09-09T07:46:51 # --vardir=/home/buildbot/rqg-buildbot-slave/rqg-weekend/vardir-maria_recovery_weekend/current
                Show
                philipstoev Philip Stoev added a comment - Re: (M)aria recovery failure: ma_key_recover.c:981: _ma_apply_redo_index: Assertion `check_page_length == page_length' failed. Latest RQG command line that produced the problem 2010-09-09T07:46:51 # /home/buildbot/randgen/runall.pl \ 2010-09-09T07:46:51 # --queries=1M \ 2010-09-09T07:46:51 # --engine=Maria \ 2010-09-09T07:46:51 # - mysqld= -log-output=file \ 2010-09-09T07:46:51 # - mysqld= -maria_log_purge_type=at_flush \ 2010-09-09T07:46:51 # --reporters=ErrorLog,Backtrace,Recovery,Shutdown \ 2010-09-09T07:46:51 # --duration=30 \ 2010-09-09T07:46:51 # --threads=1 \ 2010-09-09T07:46:51 # --rows=1 \ 2010-09-09T07:46:51 # --mask-level=2 \ 2010-09-09T07:46:51 # - mysqld= -loose-maria-group-commit=soft \ 2010-09-09T07:46:51 # - mysqld= -loose-maria_group_commit_interval=100 \ 2010-09-09T07:46:51 # - mysqld= -maria-checkpoint-interval=120 \ 2010-09-09T07:46:51 # - mysqld= -maria-block-size=16K \ 2010-09-09T07:46:51 # --grammar=conf/engines/varchar.yy \ 2010-09-09T07:46:51 # --gendata=conf/engines/varchar.zz \ 2010-09-09T07:46:51 # --mask=62443 \ 2010-09-09T07:46:51 # --queries=100000000 \ 2010-09-09T07:46:51 # --mask=62443 \ 2010-09-09T07:46:51 # --basedir=. \ 2010-09-09T07:46:51 # --seed=time \ 2010-09-09T07:46:51 # --vardir=/home/buildbot/rqg-buildbot-slave/rqg-weekend/vardir-maria_recovery_weekend/current
                Hide
                Permalink
                monty Michael Widenius added a comment -

                Re: (M)aria recovery failure: ma_key_recover.c:981: _ma_apply_redo_index: Assertion `check_page_length == page_length' failed.
                I run the test case but it failed with failures from maria_read_log like:

                WARNING: Aria engine currently logs no records about insertion of data by ALTER TABLE and CREATE SELECT, as they are not necessary for recovery; present applying of log records to table './test/table1_maria_varchar_1024_not_null.MAI' may well not work

                There is one cases when maria_read_log can't recreate all data. This is when one is doing inserting into the table with a bulk insert and then creating the index with repair. This happens in the following cases:

                • Insert many values into an empty table
                • INSERT ... SELECT into an empty table
                • ALTER TABLE

                From recovery point of few things are safe as the recovery log will log an undo entry that will restore the table to it's empty state if the bulk insert failed and if it succeeded the undo entry will be ignored.

                Running maria_read_log on crashed data should work as everything before the checkpoint will be ignored and on bulk insert we have a check that the table is up to date.

                One can force Aria to never do bulk insert, in which case maria_read_log should work. This is done by starting mysqld with the --safe-mode option.

                With the --safe-mode option I was not able to repeat the problem.

                I downloaded var-bug613418-2.zip, but maria_read_log -a -s worked perfectly in the master-data directory.
                I then copied the maria_* and test/* from master-data to a MariaDB 5.1 installation and start MariaDB; The recovery worked without any problems.

                How can I repeat the problem with the test file ?
                What was the error message you got?

                Show
                monty Michael Widenius added a comment - Re: (M)aria recovery failure: ma_key_recover.c:981: _ma_apply_redo_index: Assertion `check_page_length == page_length' failed. I run the test case but it failed with failures from maria_read_log like: WARNING: Aria engine currently logs no records about insertion of data by ALTER TABLE and CREATE SELECT, as they are not necessary for recovery; present applying of log records to table './test/table1_maria_varchar_1024_not_null.MAI' may well not work There is one cases when maria_read_log can't recreate all data. This is when one is doing inserting into the table with a bulk insert and then creating the index with repair. This happens in the following cases: Insert many values into an empty table INSERT ... SELECT into an empty table ALTER TABLE From recovery point of few things are safe as the recovery log will log an undo entry that will restore the table to it's empty state if the bulk insert failed and if it succeeded the undo entry will be ignored. Running maria_read_log on crashed data should work as everything before the checkpoint will be ignored and on bulk insert we have a check that the table is up to date. One can force Aria to never do bulk insert, in which case maria_read_log should work. This is done by starting mysqld with the --safe-mode option. With the --safe-mode option I was not able to repeat the problem. I downloaded var-bug613418-2.zip, but maria_read_log -a -s worked perfectly in the master-data directory. I then copied the maria_* and test/* from master-data to a MariaDB 5.1 installation and start MariaDB; The recovery worked without any problems. How can I repeat the problem with the test file ? What was the error message you got?
                Hide
                Permalink
                monty Michael Widenius added a comment -

                Re: (M)aria recovery failure: ma_key_recover.c:981: _ma_apply_redo_index: Assertion `check_page_length == page_length' failed.
                Closed as we haven't seen this issue in over a month (probably fixed)

                Show
                monty Michael Widenius added a comment - Re: (M)aria recovery failure: ma_key_recover.c:981: _ma_apply_redo_index: Assertion `check_page_length == page_length' failed. Closed as we haven't seen this issue in over a month (probably fixed)
                Hide
                Permalink
                ratzpo Rasmus Johansson added a comment -

                Launchpad bug id: 613418

                Show
                ratzpo Rasmus Johansson added a comment - Launchpad bug id: 613418

                  People

                  • Assignee:
                    monty Michael Widenius
                    Reporter:
                    philipstoev Philip Stoev
                  • Votes:
                    0 Vote for this issue
                    Watchers:
                    0 Start watching this issue

                    Dates

                    • Created:
                      Updated:
                      Resolved: