server crash in main.percona_query_response_time-stored and main.percona_query_response_time-replication

[Alexey Kopytov]

I see the following failure in Jenkins which has seemingly not been reported yet:

http://jenkins.percona.com/view/Percona%20Server%205.1/job/percona-server-5.1-trunk/BUILD_TYPE=debug-no-Werror,Host=ubuntu-lucid-32bit/30/console

main.percona_query_response_time-stored w2 [ fail ]
        Test ended at 2011-06-28 14:45:46

CURRENT_TEST: main.percona_query_response_time-stored
mysqltest: At line 31: query 'SELECT test_f()' failed: 2013: Lost connection to MySQL server during query

The result from queries just before the failure was:
< snip >
    512.000000
   1024.000000
   2048.000000
   4096.000000
   8192.000000
  16384.000000
  32768.000000
  65536.000000
 131072.000000
 262144.000000
 524288.000000
 1048576.00000
 2097152.00000
 4194304.00000
 8388608.00000
TOO LONG
SET GLOBAL ENABLE_QUERY_RESPONSE_TIME_STATS=1;
SELECT test_f();
test_f()
Hello, world!

More results from queries before failure can be found in /mnt/workspace/percona-server-5.1-trunk/BUILD_TYPE/debug-no-Werror/Host/ubuntu-lucid-32bit/Percona-Server-5.1.57-rel12.8/mysql-test/var/2/log/percona_query_response_time-stored.log

Server [mysqld.1 - pid: 21158, winpid: 21158, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
110628 17:45:46 - mysqld got signal 11 ;
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=1048576
read_buffer_size=131072
max_used_connections=1
max_threads=151
threads_connected=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 60042 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0xb69245c0
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 = 0xb6b0736c thread_stack 0x30000
/mnt/workspace/percona-server-5.1-trunk/BUILD_TYPE/debug-no-Werror/Host/ubuntu-lucid-32bit/Percona-Server-5.1.57-rel12.8/sql/mysqld(my_print_stacktrace+0x22) [0x85449fc]
/mnt/workspace/percona-server-5.1-trunk/BUILD_TYPE/debug-no-Werror/Host/ubuntu-lucid-32bit/Percona-Server-5.1.57-rel12.8/sql/mysqld(handle_segfault+0x28a) [0x820184f]
[0xb77ae400]
/mnt/workspace/percona-server-5.1-trunk/BUILD_TYPE/debug-no-Werror/Host/ubuntu-lucid-32bit/Percona-Server-5.1.57-rel12.8/sql/mysqld(log_slow_statement(THD*)+0x1c7) [0x82100be]
/mnt/workspace/percona-server-5.1-trunk/BUILD_TYPE/debug-no-Werror/Host/ubuntu-lucid-32bit/Percona-Server-5.1.57-rel12.8/sql/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0x1a76) [0x821f150]
/mnt/workspace/percona-server-5.1-trunk/BUILD_TYPE/debug-no-Werror/Host/ubuntu-lucid-32bit/Percona-Server-5.1.57-rel12.8/sql/mysqld(do_command(THD*)+0x2d9) [0x821f6ea]
/mnt/workspace/percona-server-5.1-trunk/BUILD_TYPE/debug-no-Werror/Host/ubuntu-lucid-32bit/Percona-Server-5.1.57-rel12.8/sql/mysqld(handle_one_connection+0x553) [0x820dad2]
/lib/tls/i686/nosegneg/libpthread.so.0(+0x5985) [0xb778c985]
/lib/tls/i686/nosegneg/libc.so.6(clone+0x5e) [0xb755113e]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x9b839b0): SELECT test_f()
Connection ID (thread ID): 2277
Status: 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.
Writing a core file
----------SERVER LOG END-------------

 - saving '/mnt/workspace/percona-server-5.1-trunk/BUILD_TYPE/debug-no-Werror/Host/ubuntu-lucid-32bit/Percona-Server-5.1.57-rel12.8/mysql-test/var/2/log/main.percona_query_response_time-stored/' to '/mnt/workspace/percona-server-5.1-trunk/BUILD_TYPE/debug-no-Werror/Host/ubuntu-lucid-32bit/Percona-Server-5.1.57-rel12.8/mysql-test/var/log/main.percona_query_response_time-stored/'
 - found 'core' (0/5)

Trying 'dbx' to get a backtrace

Trying 'gdb' to get a backtrace
Guessing that core was generated by '/mnt/workspace/percona-server-5.1-trunk/BUILD_TYPE/debug-no-Werror/Host/ubuntu-lucid-32bit/Percona-Server-5.1.57-rel12.8/sql/mysqld'
Output from gdb follows. The first stack trace is from the failing thread.
The following stack traces are from all threads (so the failing one is
duplicated).
--------------------------
[New Thread 13523]
[New Thread 21159]
[New Thread 21163]

warning: Can't read pathname for load map: Input/output error.
Core was generated by `/mnt/workspace/percona-server-5.1-trunk/BUILD_TYPE/debug-no-Werror/Host/ubuntu-'.
Program terminated with signal 11, Segmentation fault.
#0 0xb77ae424 in __kernel_vsyscall ()
#0 0xb77ae424 in __kernel_vsyscall ()
#1 0xb7792123 in __pthread_kill (threadid=3065019248, signo=11)
    at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:64
#2 0x085449d4 in my_write_core (sig=11) at stacktrace.c:426
#3 0x08201a47 in handle_segfault (sig=11) at mysqld.cc:2660
#4 <signal handler called>
#5 0x08230e07 in my_atomic_cas64 (query_time=1112647)
    at ../include/my_atomic.h:203
#6 my_atomic_add64 (query_time=1112647) at ../include/my_atomic.h:211
#7 query_response_time::time_collector::collect (query_time=1112647)
    at query_response_time.cc:201
#8 query_response_time::collector::collect (query_time=1112647)
    at query_response_time.cc:264
#9 query_response_time_collect (query_time=1112647)
    at query_response_time.cc:306
#10 0x082100be in log_slow_statement (thd=0xb69245c0) at sql_parse.cc:1780
#11 0x0821f150 in dispatch_command (command=COM_QUERY, thd=0xb69245c0,
    packet=0xb6926509 "", packet_length=15) at sql_parse.cc:1701
#12 0x0821f6ea in do_command (thd=0xb69245c0) at sql_parse.cc:903
#13 0x0820dad2 in handle_one_connection (arg=0xb69245c0)
    at sql_connect.cc:1898
#14 0xb778c985 in start_thread (arg=0xb6b07b70) at pthread_create.c:300
#15 0xb755113e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Thread 3 (Thread 21163):
#0 0xb77ae424 in __kernel_vsyscall ()
#1 0xb779522d in do_sigwait (set=0xb6b9a350, sig=<value optimized out>)
    at ../nptl/sysdeps/unix/sysv/linux/../../../../../sysdeps/unix/sysv/linux/sigwait.c:63
#2 0xb77952d0 in __sigwait (set=0xb6b9a2bc, sig=0xb6b9a350)
    at ../nptl/sysdeps/unix/sysv/linux/../../../../../sysdeps/unix/sysv/linux/sigwait.c:100
#3 0x082013af in signal_hand (arg=0x0) at mysqld.cc:2854
#4 0xb778c985 in start_thread (arg=0xb6b9ab70) at pthread_create.c:300
#5 0xb755113e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Thread 2 (Thread 21159):
#0 0xb77ae424 in __kernel_vsyscall ()
#1 0xb7542ab6 in *__GI___poll (fds=0xb75daff4, nfds=2, timeout=-1)
    at ../sysdeps/unix/sysv/linux/poll.c:87
#2 0x082067a3 in handle_connections_sockets (arg=0x0) at mysqld.cc:5311
#3 0x0820894c in main (argc=9, argv=0xbfc04a14) at mysqld.cc:4769

Thread 1 (Thread 13523):
#0 0xb77ae424 in __kernel_vsyscall ()
#1 0xb7792123 in __pthread_kill (threadid=3065019248, signo=11)
    at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:64
#2 0x085449d4 in my_write_core (sig=11) at stacktrace.c:426
#3 0x08201a47 in handle_segfault (sig=11) at mysqld.cc:2660
#4 <signal handler called>
#5 0x08230e07 in my_atomic_cas64 (query_time=1112647)
    at ../include/my_atomic.h:203
#6 my_atomic_add64 (query_time=1112647) at ../include/my_atomic.h:211
#7 query_response_time::time_collector::collect (query_time=1112647)
    at query_response_time.cc:201
#8 query_response_time::collector::collect (query_time=1112647)
    at query_response_time.cc:264
#9 query_response_time_collect (query_time=1112647)
    at query_response_time.cc:306
#10 0x082100be in log_slow_statement (thd=0xb69245c0) at sql_parse.cc:1780
#11 0x0821f150 in dispatch_command (command=COM_QUERY, thd=0xb69245c0,
    packet=0xb6926509 "", packet_length=15) at sql_parse.cc:1701
#12 0x0821f6ea in do_command (thd=0xb69245c0) at sql_parse.cc:903
#13 0x0820dad2 in handle_one_connection (arg=0xb69245c0)
    at sql_connect.cc:1898
#14 0xb778c985 in start_thread (arg=0xb6b07b70) at pthread_create.c:300
#15 0xb755113e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

[Alexey Kopytov (akopytov)]

main.percona_query_response_time-replication fails with the same backtrace.

[Oleg Tsarev (tsarev)]

Confirmed. Looks like to bug in my_atomic_cas for 64 bit int on 32 bit platform.

[Oleg Tsarev (tsarev)]

http://jenkins.percona.com/view/Percona%20Server%205.1/job/percona-server-5.1-param/61/BUILD_TYPE=debug-no-Werror,Host=ubuntu-lucid-32bit/consoleText

[Laurynas Biveinis (laurynas-biveinis)]

I believe this is an issue with 64-bit CAS implementation on IA32 systems. Here is the relevant code from include/atomic/x86_gcc.h:

  asm volatile ("push %%ebx;"
                "movl (%%ecx), %%ebx;"
                "movl 4(%%ecx), %%ecx;"
                LOCK_prefix "; cmpxchg8b %0;"
                "setz %2; pop %%ebx"
                : "=m" (*a), "+A" (*cmp), "=c" (ret)
                : "c" (&set), "m" (*a)
                : "memory", "esp")

There are following issues that make it easy for GCC to break this code by optimization:
- The zero-th operand is marked as output-only, but it is an input-output one: CMPXCHG8B reads the memory pointed to it, and also sets EDX:EAX if the operand and EDX:EAX are non-equal. It is also an output operand: the instruction sets it to ECX:EBX.
- The code probably tried to say that zero-th operand is also an input one by specifying it as the 4th operand ("m" (*a)), but this fails, because GCC does not guarantee putting the input and output operands referenced by the same C expression at the same location. Also this operand is not referenced in the assembly at all.

While we are at it, there are following issues that make the resulting code suboptimal:
- "volatile" is not needed as all the output operands are specified fully (i.e. no undescribed side-effects in the assembly);
- Saving EBX in the code is not required, just tell GCC that the code clobbers EBX and GCC will handle this;
- No need to force using ECX for input &set and output ret;
- Clobber "memory" is redundant as the code does not access memory in a way undescribed by constraints;
- Clobber "esp", I fail to understand its point at all.

The rewritten code:

    int32 val_for_ebx= (set & 0xFFFFFFFF);
    int32 val_for_ecx= set >> 32;
    asm (LOCK_prefix "; cmpxchg8b %0;"
         "setz %1"
         : "+m" (*a), "=g" (ret), "+A" (*cmp)
         : "b" (val_for_ebx), "c" (val_for_ecx)
         : "flags")

Note that this is similar to
http://bugs.mysql.com/bug.php?id=52419 and
http://lists.mysql.com/commits/118512

but in fact the original bug there was that ebx operand had a wrong constraint (memory, failing because it is stack pointer-relative) when it should have been directly EBX register.

Before and after dissasambly (note the new version is shorter):

   0x08231070 <+219>: mov %esi,-0x30(%ebp)
   0x08231073 <+222>: mov %ebx,-0x2c(%ebp)
   0x08231076 <+225>: mov %edi,%ebx
   0x08231078 <+227>: mov (%edi),%eax
   0x0823107a <+229>: mov 0x4(%edi),%edx
   0x0823107d <+232>: lea -0x20(%ebp),%ecx
   0x08231080 <+235>: mov %ecx,-0x3c(%ebp)
   0x08231083 <+238>: mov -0x30(%ebp),%esi
   0x08231086 <+241>: mov -0x2c(%ebp),%edi
   0x08231089 <+244>: add %eax,%esi
   0x0823108b <+246>: adc %edx,%edi
   0x0823108d <+248>: mov %esi,-0x20(%ebp)
   0x08231090 <+251>: mov %edi,-0x1c(%ebp)
   0x08231093 <+254>: mov -0x3c(%ebp),%ecx
   0x08231096 <+257>: push %ebx
   0x08231097 <+258>: mov (%ecx),%ebx
  ...

[Laurynas Biveinis (laurynas-biveinis)]

Oh, the original code also failed to specify that it clobbers EFLAGS.

[Laurynas Biveinis (laurynas-biveinis)]

Apparently GCC is unable to spill EBX around the assembly in case of PIC. Fixed code is

    int32 val_for_ebx= set & 0xFFFFFFFF; \
    int32 val_for_ecx= set >> 32; \
    int32 saved_ebx; \
    asm ("movl %%ebx, %3;" \
         "movl %4, %%ebx;" \
         LOCK_prefix "; cmpxchg8b %0;" \
         "setz %1;" \
         "movl %%edi, %%ebx" \
         : "+m" (*a), "=g" (ret), "+A" (*cmp), "=g" (saved_ebx) \
         : "g" (val_for_ebx), "c" (val_for_ecx) \
         : "flags")

Also relevant is http://lists.mysql.com/commits/113160

[Laurynas Biveinis (laurynas-biveinis)]

The same buggy code is used for 5.5 too. Will fix it there too, but setting prio only to medium as no actual test failures have been observed yet.

[Davi Arnaut (davi)]

Hum, saw this as a question on stackoverflow.com. For what it's worth, the volatile and memory clobber are used because all the atomic functions must imply barriers. The stack pointer is clobbered to prevent GCC from using variables as a offset from it. Clobbering flags is not necessary, already implied.

[Laurynas Biveinis (laurynas-biveinis)]

Davi -

According to the GCC manual http://gcc.gnu.org/onlinedocs/gcc-4.6.1/gcc/Extended-Asm.html#Extended-Asm , "memory" clobber is: "If your assembler instructions access memory in an unpredictable fashion, add `memory' to the list of clobbered registers. This will cause GCC to not keep memory values cached in registers across the assembler instruction and not optimize stores or loads to that memory." This implies memory barrier, but also the key is "unpredictable fashion". When the inputs and outputs are completely described (i.e. no unpredictable pointer dereferences), and the variables in question are marked volatile, I don't think anything extra is achieved by adding memory clobber.

Re. volatile, the next sentence in the manual reads "You will also want to add the volatile keyword if the memory affected is not listed in the inputs or outputs of the asm, as the `memory' clobber does not count as a side-effect of the asm." Again, this is important if the memory is not listed in the inputs/outputs, and not if it is. Moreover, the manual says "If an asm has output operands, GCC assumes for optimization purposes the instruction has no side effects except to change the output operands. This does not mean instructions with a side effect cannot be used, but you must be careful, because the compiler may eliminate them if the output operands aren't used, or move them out of loops, or replace two with one if they constitute a common subexpression. [...] You can prevent an asm instruction from being deleted by writing the keyword volatile after the asm." This implies that volatile is used for data flow analysis decisions, which again shouldn't matter if the asm inputs and outputs are fully described, as it is visible to DF anyway.

In any case "memory" and "volatile" do not hurt even if not necessary, and what actually hurts are the 0th and 4th operand description errors in my analysis above.

Regarding my other points above, I was wrong about EBX (specifying that it is clobbered will not stop GCC from using it, also will cause GCC errors about impossible reloads quite often), and now I see the point about specifying ESP clobber - although after EBX experience I'm not sure if GCC honors it or if it just works silently since GCC (as opposed to ICC) does not use ESP much anyway for addressing.

The final code we are going with is in the SO answer. I will submit a bug report upstream once we test it some more and are confident in it. GCC inline asm is tricky and even after "best efforts" I do not claim to have a full understanding of it.

[Davi Arnaut (davi)]

Laurynas,

The usage volatile and memory in this case have very little to do with the asm block itself, inputs/outputs or its side-effects, it's mainly about the context in which it is used. If the atomic intrinsic is being used to implement a locking primitive (e.g. a spinlock), which is the case in MySQL, it's is important to prevent the compiler from reordering across the locked region and to synchronize memory access around it.

[Laurynas Biveinis (laurynas-biveinis)]

Davi -

I made an incorrect assumption that atomic ops are used with volatile vars only. Which is not the case, and then the compiler scheduling barrier is obviously necessary. Thank you.

[Laurynas Biveinis (laurynas-biveinis)]

See bug 1177682.

[Shahriyar Rzayev (rzayev-sehriyar)]

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