Assertion failure with Query_cache on debug build + --debug option

[Raghavendra D Prabhu]

Hit this assertion when running UNIV_DEBUG enabled binary (tested with both 5.5.27 and trunk PS).

===================================================

mysqld: /media/Vone/Percona-Server-5.5.27-rel28.0/sql/sql_cache.cc:1234: void Query_cache::end_of_result(THD*): Assertion `0' failed.

Program received signal SIGABRT, Aborted.
[Switching to Thread 0x7fffc422f700 (LWP 3651)]
0x00007ffff6185fa5 in raise () from /lib/libc.so.6
(gdb) bt
#0 0x00007ffff6185fa5 in raise () from /lib/libc.so.6
#1 0x00007ffff6187428 in abort () from /lib/libc.so.6
#2 0x00007ffff617f002 in __assert_fail_base () from /lib/libc.so.6
#3 0x00007ffff617f0b2 in __assert_fail () from /lib/libc.so.6
bt ful#4 0x0000000000568484 in Query_cache::end_of_result (this=0xf0aec0 <query_cache>, thd=0x24b7cc0) at /media/Vone/Percona-Server-5.5.27-rel28.0/sql/sql_cache.cc:1234
#5 0x000000000059deec in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x24b7cc0, packet=packet@entry=0x24a80f1 "", packet_length=packet_length@entry=35) at /media/Vone/Percona-Server-5.5.27-rel28.0/sql/sql_parse.cc:1433
#6 0x000000000059e73f in do_command (thd=0x24b7cc0) at /media/Vone/Percona-Server-5.5.27-rel28.0/sql/sql_parse.cc:788
#7 0x0000000000648041 in do_handle_one_connection (thd_arg=thd_arg@entry=0x24afdf0) at /media/Vone/Percona-Server-5.5.27-rel28.0/sql/sql_connect.cc:1484
#8 0x0000000000648137 in handle_one_connection (arg=0x24afdf0) at /media/Vone/Percona-Server-5.5.27-rel28.0/sql/sql_connect.cc:1391
#9 0x00007ffff7bc6e0f in start_thread () from /lib/libpthread.so.0
#10 0x00007ffff623504d in clone () from /lib/libc.so.6
(gdb) bt full
#0 0x00007ffff6185fa5 in raise () from /lib/libc.so.6
No symbol table info available.
#1 0x00007ffff6187428 in abort () from /lib/libc.so.6
No symbol table info available.
#2 0x00007ffff617f002 in __assert_fail_base () from /lib/libc.so.6
No symbol table info available.
#3 0x00007ffff617f0b2 in __assert_fail () from /lib/libc.so.6
No symbol table info available.
#4 0x0000000000568484 in Query_cache::end_of_result (this=0xf0aec0 <query_cache>, thd=0x24b7cc0) at /media/Vone/Percona-Server-5.5.27-rel28.0/sql/sql_cache.cc:1234
        header = 0x7fffee007058
        last_result_block = <optimized out>
        allign_size = <optimized out>
        len = <optimized out>
        query_cache_tls = 0x24b7ee8
        limit_found_rows = 1
        __PRETTY_FUNCTION__ = "void Query_cache::end_of_result(THD*)"
        __FUNCTION__ = "end_of_result"
        query_block = 0x7fffee007000
        _db_stack_frame_ = {func = 0xa5e22e "dispatch_command", file = 0xa5e498 "/media/Vone/Percona-Server-5.5.27-rel28.0/sql/sql_parse.cc", level = 2147483651, prev = 0x7fffc422e640}
#5 0x000000000059deec in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x24b7cc0, packet=packet@entry=0x24a80f1 "", packet_length=packet_length@entry=35) at /media/Vone/Percona-Server-5.5.27-rel28.0/sql/sql_parse.cc:1433
        net = 0x24b7ef0
        __PRETTY_FUNCTION__ = "bool dispatch_command(enum_server_command, THD*, char*, uint)"
        __FUNCTION__ = "dispatch_command"
        error = false
        _db_stack_frame_ = {func = 0xa5e2d6 "do_command", file = 0xa5e498 "/media/Vone/Percona-Server-5.5.27-rel28.0/sql/sql_parse.cc", level = 2147483650, prev = 0x7fffc422ede0}
#6 0x000000000059e73f in do_command (thd=0x24b7cc0) at /media/Vone/Percona-Server-5.5.27-rel28.0/sql/sql_parse.cc:788
        return_value = <optimized out>
        packet = 0x24a80f0 "\001"
        packet_length = 36
        net = 0x24b7ef0
        command = COM_QUERY
        __PRETTY_FUNCTION__ = "bool do_command(THD*)"
        _db_stack_frame_ = {func = 0xb51c91 "?func", file = 0xb51c97 "?file", level = 2147483649, prev = 0x0}
#7 0x0000000000648041 in do_handle_one_connection (thd_arg=thd_arg@entry=0x24afdf0) at /media/Vone/Percona-Server-5.5.27-rel28.0/sql/sql_connect.cc:1484
        rc = <optimized out>
        create_user = true
        thd = 0x24b7cc0
#8 0x0000000000648137 in handle_one_connection (arg=0x24afdf0) at /media/Vone/Percona-Server-5.5.27-rel28.0/sql/sql_connect.cc:1391
        thd = 0x24afdf0
#9 0x00007ffff7bc6e0f in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#10 0x00007ffff623504d in clone () from /lib/libc.so.6
No symbol table info available.

================================================================

The my.cnf is http://sprunge.us/FAfX

To reproduce: start mysqld as mysqld --user=mysql --debug (with above my.cnf) and run sysbench or some load, and wait for it to crash on signal 6.

[Laurynas Biveinis (laurynas-biveinis)]

I wonder if the crashing workload could be minimized? Does sysbench load depend on multiple client connections?

[Alexey Kopytov (akopytov)]

Could not repeat on OSX with a debug PS 5.5.27 binary started with --debug --query_cache_size=32M --query_cache_type=1 and both single- and multi-threaded sysbench OLTP test. What was the sysbench command line?

[Raghavendra D Prabhu (raghavendra-prabhu)]

@Alexey,

It didn't take long for crash to happen. Just starting sysbench run crashed it.

Details:

my.cnf -- http://sprunge.us/STiQ

Sysbench:

sysbench --test=./oltp.lua --db-driver=mysql --mysql-engine-trx=yes --mysql-table-engine=innodb --mysql-user=root --mysql-password=test --oltp-table-size=5000 --num-threads=4 run

(but any sysbench should crash it I believe).

Tested with both 5.5.27-28.1 and PS 5.5 bzr head.

[Alexey Kopytov (akopytov)]

Thanks, I can reproduce the crash with both MySQL 5.5 and PS 5.5 and the sysbench command line you have provided. For some reasons, sysbench 0.4 with similar options does not crash the server.

[Alexey Kopytov (akopytov)]

No, I spoke too soon. sysbench 0.4 crashes the server just as well with the following command line:

sysbench --test=oltp --oltp-table-size=5000 --num-threads=4 run

[Alexey Kopytov (akopytov)]

It looks like --debug has something to do with it. I could not reproduce it with --debug removed.

[Raghavendra D Prabhu (raghavendra-prabhu)]

Ah, yes, I wanted to stress --debug part in the description since the crash is reproduceable only with that.

Regarding why it hits on --debug only, that is interesting.

However,

    if (header->result() == 0)
    {
      DBUG_PRINT("error", ("End of data with no result blocks; "
                           "Query '%s' removed from cache.", header->query()));
      /*
        Extra safety: empty result should not happen in the normal call
        to this function. In the release version that query should be ignored
        and removed from QC.
      */
      DBUG_ASSERT(0); ----------------> This is where it is crashing.
      free_query(query_block);
      unlock();
      DBUG_VOID_RETURN;
    }

Even though DBUG_PRINT is hit only when --debug is enabled I wonder how it changes the control flow if not present.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1935