MySQL Bugs: #32918: Running sql-bench hits assertion with InnoDB

Bug #32918	Running sql-bench hits assertion with InnoDB
Submitted:	3 Dec 2007 0:08	Modified:	16 Nov 2009 11:51
Reporter:	Hakan Küçükyılmaz	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Optimizer	Severity:	S3 (Non-critical)
Version:	6.0.4 bk, 6.0-codebase bzr	OS:	Linux
Assigned to:	Olav Sandstå	CPU Architecture:	Any

Description:
Running sql-bench hits assertion with InnoDB. I tried debug and optimized build. (BUILD/compile-amd64-debug-max-no-ndb and BUILD/compile-amd64-max).

How to repeat:
Use latest source from mysql-6.0 tree and run sql-bench. In my.cnf I set
    default-storage-engine = InnoDB

then I run sql-bench like

hakan@lu0011:~/work/mysql/mysql-6.0/sql-bench$ ./run-all-tests --server=mysql   --fast   --log   --user=root   --hires   --socket=/tmp/mysql.sock

It ends with this assertion:
[New Thread 0x4410b950 (LWP 17258)]
 len 224; hex b8bc61afaa2a0000380109b4aa2a00000040bdb3aa2a00003e060000aa2a000003000000000000000200000000000000010000000000000000000000000000000000000000000000030000000000000000000000000000000100000000000000a24183b328010000452052454e414d4501000000000000008344510700000000bd3e62afaa2a0000030000000000000001000000000000001877c0b7aa2a000000000000000000003a0800000000000060e11177000000000200000000000000b82866afaa2a00005f6e616d653b0a45b83e62afaa2a00001100000000000000; asc   a  *  8    *   @   *  >    *                                                                   A  (   E RENAME         DQ      >b  *                   w   *          :       `  w             (f  *  _name; E >b  *          ;TRANSACTION 0 1972741, ACTIVE 1 sec, process no 16984, OS thread id 1141946704 fetching rows, thread declared inside InnoDB 489
mysql tables in use 2, locked 1
MySQL thread id 30015, query id 2281815 localhost root Sending data
select * from bench1 where (id3>=5 and id3<=10) or (id3>=1 and id3<=4)
071203  0:46:28  InnoDB: Assertion failure in thread 1141946704 in file btr/btr0pcur.c line 217
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
InnoDB: about forcing recovery.

Backtrace is:

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x4410b950 (LWP 17258)]
0x00002b784d211fd5 in raise () from /lib/libc.so.6
(gdb) bt
#0  0x00002b784d211fd5 in raise () from /lib/libc.so.6
#1  0x00002b784d213a30 in abort () from /lib/libc.so.6
#2  0x000000000091979f in btr_pcur_restore_position (latch_mode=1, cursor=0x2aaaaf6612b8,
    mtr=0x44108d50) at btr/btr0pcur.c:217
#3  0x00000000008fadbe in sel_restore_position_for_mysql (same_user_rec=0x44109210,
    latch_mode=16984, pcur=0x2aaaaf6612b8, moves_up=18446744073709551615, mtr=0x0)
    at row/row0sel.c:2970
#4  0x00000000008fc30a in row_search_for_mysql (buf=0x11f3f30 "", mode=2, prebuilt=0x2aaaaf6180b8,
    match_mode=0, direction=1) at row/row0sel.c:3621
#5  0x00000000008aa102 in ha_innobase::general_fetch (this=0x11f3c48, buf=0x11f3f30 "",
    direction=0, match_mode=4294967295) at handler/ha_innodb.cc:4363
#6  0x00000000008aa300 in ha_innobase::index_next (this=0x11f3c48, buf=0x11f3f30 "")
    at handler/ha_innodb.cc:4399
#7  0x000000000073365a in handler::read_range_next (this=0x11f3c48) at handler.cc:4209
#8  0x00000000008a7699 in ha_innobase::read_range_next (this=0x4258) at handler/ha_innodb.cc:8280
#9  0x000000000073285f in handler::multi_range_read_next (this=0x11f3c48, range_info=0x441093b8)
    at handler.cc:3472
#10 0x0000000000733f6c in DsMrr_impl::dsmrr_fill_buffer (this=0x11f3e88, h=0x11f3c48)
    at handler.cc:3670
#11 0x00000000007375af in DsMrr_impl::dsmrr_init (this=0x11f3e88, h=0x11f3c48, key=0x11f42b0,
    seq_funcs=0x441094c0, seq_init_param=0x2aaabf6f83f0, n_ranges=2, mode=4, buf=0x2aaabf709be8)
    at handler.cc:3597
#12 0x00000000008a77b4 in ha_innobase::multi_range_read_init (this=0x0, seq=0xffffffffffffffff,
    seq_init_param=0x8, n_ranges=11679512, mode=<value optimized out>, buf=<value optimized out>)
    at handler/ha_innodb.cc:8195

btr0pcur.c in InnoDB-5.1 (== InnoDB-6.0):

/******************************************************************
Restores the stored position of a persistent cursor bufferfixing the page and
obtaining the specified latches. If the cursor position was saved when the
(1) cursor was positioned on a user record: this function restores the position
to the last record LESS OR EQUAL to the stored record;
(2) cursor was positioned on a page infimum record: restores the position to
the last record LESS than the user record which was the successor of the page
infimum;
(3) cursor was positioned on the page supremum: restores to the first record
GREATER than the user record which was the predecessor of the supremum.
(4) cursor was positioned before the first or after the last in an empty tree:
restores to before first or after the last in the tree. */

ibool
btr_pcur_restore_position(
/*======================*/
                                        /* out: TRUE if the cursor position
                                        was stored when it was on a user record
                                        and it can be restored on a user record
                                        whose ordering fields are identical to
                                        the ones of the original user record */
        ulint           latch_mode,     /* in: BTR_SEARCH_LEAF, ... */
        btr_pcur_t*     cursor,         /* in: detached persistent cursor */
        mtr_t*          mtr)            /* in: mtr */
{
        dict_index_t*   index;
        page_t*         page;
        dtuple_t*       tuple;
        ulint           mode;
        ulint           old_mode;
        mem_heap_t*     heap;

        index = btr_cur_get_index(btr_pcur_get_btr_cur(cursor));

        if (UNIV_UNLIKELY(cursor->old_stored != BTR_PCUR_OLD_STORED)
            || UNIV_UNLIKELY(cursor->pos_state != BTR_PCUR_WAS_POSITIONED
                             && cursor->pos_state != BTR_PCUR_IS_POSITIONED)) {
                ut_print_buf(stderr, cursor, sizeof(btr_pcur_t));
                if (cursor->trx_if_known) {
                        trx_print(stderr, cursor->trx_if_known, 0);
                }

                ut_error;
        }

The assertion means that MySQL tries to re-read from a cursor whose position was never stored.

Maybe InnoDB contains some bad optimization and does not store the cusrsor position?

Or maybe MySQL in this special multi_range_read algorithm misuses a cursor? The code in 6.0 is completely new, I presume.

Assigning this complicated bug Inaam.

Calvin,

please try to determine what goes wrong here.

--Heikki

Reassign it to optimizer since the call stack clearly shows the path of DS-MRR. Also there are known crash bugs when using DS-MRR.

Please, try to repeat with a newer version, 6.0.6, and inform about the results.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

I can repeat the crash with current 6.0 sources.

Here is backtrace:

091006 15:35:07  InnoDB: ERROR: the age of the last checkpoint is 9434026,
InnoDB: which exceeds the log group capacity 9433498.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
091006 15:35:23  InnoDB: ERROR: the age of the last checkpoint is 9433601,
InnoDB: which exceeds the log group capacity 9433498.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
091006 15:35:39  InnoDB: ERROR: the age of the last checkpoint is 9433607,
InnoDB: which exceeds the log group capacity 9433498.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
091006 15:35:55  InnoDB: ERROR: the age of the last checkpoint is 9433918,
InnoDB: which exceeds the log group capacity 9433498.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
091006 15:36:11  InnoDB: ERROR: the age of the last checkpoint is 9926254,
InnoDB: which exceeds the log group capacity 9433498.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.
mysqld: mdl.cc:1027: bool MDL_ticket::upgrade_shared_lock_to_exclusive(): Assertion `m_type == MDL_SHARED_UPGRADABLE' failed.
091006 15:39:46 - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=16384
read_buffer_size=262144
max_used_connections=4
max_threads=151
thread_count=1
connection_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 50064 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x2aaab4000058
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x4dc990d8 thread_stack 0x20000
./libexec/mysqld(my_print_stacktrace+0x35) [0xb72d9c]
./libexec/mysqld(handle_segfault+0x2a7) [0x6c72bc]
/lib64/libpthread.so.0 [0x3429e0dd40]
/lib64/libc.so.6(gsignal+0x35) [0x3429230015]
/lib64/libc.so.6(abort+0x110) [0x3429231980]
/lib64/libc.so.6(__assert_fail+0xf6) [0x3429229726]
./libexec/mysqld(MDL_ticket::upgrade_shared_lock_to_exclusive()+0x125) [0x91efdd]
./libexec/mysqld(wait_while_table_is_used(THD*, TABLE*, ha_extra_function)+0x103) [0x7300cd]
./libexec/mysqld [0x8603b3]
./libexec/mysqld(mysql_optimize_table(THD*, TABLE_LIST*, st_ha_check_opt*)+0xc7) [0x861a01]
./libexec/mysqld(mysql_execute_command(THD*)+0x2fb4) [0x6dbd34]
./libexec/mysqld(mysql_parse(THD*, char const*, unsigned int, char const**)+0x293) [0x6e43aa]
./libexec/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0xaff) [0x6d6f84]
./libexec/mysqld(do_command(THD*)+0x25e) [0x6d61ee]
./libexec/mysqld(handle_one_connection+0x14c) [0x6d48d0]
/lib64/libpthread.so.0 [0x3429e061b5]
/lib64/libc.so.6(clone+0x6d) [0x34292cd39d]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x38637f0 = OPTIMIZE TABLE bench1
thd->thread_id=30018
thd->killed=NOT_KILLED
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

Not repeatable for me with mysql-6.0-codebase as well