main.percona_innodb_doublewrite_file fails on 12.4, CentOS 5, 64 bit

Bug #690144 reported by Aleksandr Kuzminsky
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
High
Unassigned

Bug Description

main.percona_innodb_doublewrite_file [ fail ]
        Test ended at 2010-12-14 03:10:45

Server log is:
101214 14:10:44 [Warning] '--default-character-set' is deprecated and will be removed in a future release. Please use '--character-set-server' instead.
101214 14:10:44 [Note] Flashcache bypass: disabled
101214 14:10:44 [Note] Flashcache setup error is : open flash device failed

InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3
InnoDB: The first specified data file ./ibdata1 did not exist:
InnoDB: a new database to be created!
101214 14:10:44 InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Notice: innodb_doublewrite_file is specified.
InnoDB: This is for expert only. Don't use if you don't understand what is it 'WELL'.
InnoDB: ### Don't specify older file than the last checkpoint ###
InnoDB: otherwise the older doublewrite buffer will break your data during recovery!
101214 14:10:44 InnoDB: Doublewrite buffer file ib_doublewrite did not exist: new to be created
101214 14:10:44 InnoDB: Setting file ib_doublewrite size to 9 MB
InnoDB: Database physically writes the file full: wait...
101214 14:10:44 InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
101214 14:10:45 InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Doublewrite buffer not found in the doublewrite file: creating new
101214 14:10:45 - 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=0
max_threads=151
threads_connected=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 60646 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x0
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 = (nil) thread_stack 0x40000
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld(my_print_stacktrace+0x2e)[0x868f3e]
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld(handle_segfault+0x322)[0x5b1732]
/lib64/libpthread.so.0[0x3c7860e7c0]
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld[0x74fc24]
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld[0x803e4c]
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld[0x80d265]
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld[0x7a3af6]
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld[0x79314d]
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld[0x72518f]
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x31)[0x691b71]
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld[0x70e5fd]
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld(_Z11plugin_initPiPPci+0x73a)[0x710daa]
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld[0x5b36df]
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld(main+0x7f9)[0x5b4c59]
/lib64/libc.so.6(__libc_start_main+0xf4)[0x3586c1d994]
/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/sql/mysqld[0x4fd8d9]
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

Failed to start mysqld.1

 - saving '/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/mysql-test/var/log/main.percona_innodb_doublewrite_file/' to '/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/mysql-test/var/log/main.percona_innodb_doublewrite_file/'
 - found 'core.11723' (0/5)

Trying 'dbx' to get a backtrace

Trying 'gdb' to get a backtrace
Guessing that core was generated by '/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Server/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).
--------------------------
Core was generated by `/mnt/data1/home/buildbot/slaves/percona-server-51-12/full_test/build/Percona-Se'.
Program terminated with signal 11, Segmentation fault.
[New process 11723]
[New process 11734]
[New process 11733]
[New process 11732]
[New process 11731]
[New process 11730]
[New process 11729]
[New process 11728]
[New process 11727]
[New process 11726]
[New process 11725]
#0 0x0000003c7860b9b2 in pthread_kill () from /lib64/libpthread.so.0
#0 0x0000003c7860b9b2 in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000005b1765 in handle_segfault (sig=11) at mysqld.cc:2650
#2 <signal handler called>
#3 mtr_read_ulint (ptr=0x18 <Address 0x18 out of bounds>, type=1,
    mtr=0x7fffcc9b6040) at ./include/mach0data.ic:54
#4 0x0000000000803e4c in fsp_reserve_free_extents (n_reserved=0x7fffcc9b5f70,
    space=4294967264, n_ext=2, alloc_type=<value optimized out>,
    mtr=0x7fffcc9b6040) at fsp/fsp0fsp.c:414
#5 0x000000000080d265 in fseg_create_general (space=4294967264,
    page=<value optimized out>, byte_offset=16184, has_done_reservation=0,
    mtr=0x7fffcc9b6040) at fsp/fsp0fsp.c:2315
#6 0x00000000007a3af6 in trx_sys_create_doublewrite_buf ()
    at trx/trx0sys.c:448
#7 0x000000000079314d in innobase_start_or_create_for_mysql ()
    at srv/srv0start.c:1655
#8 0x000000000072518f in innobase_init (p=<value optimized out>)
    at handler/ha_innodb.cc:2478
#9 0x0000000000691b71 in ha_initialize_handlerton (plugin=0x11d83500)
    at handler.cc:435
#10 0x000000000070e5fd in plugin_initialize (plugin=0x11d83500)
    at sql_plugin.cc:1019
#11 0x0000000000710daa in plugin_init (argc=0xdad790, argv=0x11d544d8,
    flags=<value optimized out>) at sql_plugin.cc:1246
#12 0x00000000005b36df in init_server_components () at mysqld.cc:4056
#13 0x00000000005b4c59 in main (argc=<value optimized out>,
    argv=<value optimized out>) at mysqld.cc:4629

Thread 11 (process 11725):
#0 0x0000003c7860ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1 0x0000000000754ff5 in os_event_wait_low (event=0x1217f700,
    reset_sig_count=<value optimized out>) at os/os0sync.c:402
#2 0x0000000000753c6d in os_aio_simulated_handle (global_segment=0,
    message1=0x41b2b108, message2=0x41b2b100, type=0x41b2b0f8)
    at os/os0file.c:4324
#3 0x00000000007f9e47 in fil_aio_wait (segment=0) at fil/fil0fil.c:5023
#4 0x0000000000792081 in io_handler_thread (arg=<value optimized out>)
    at srv/srv0start.c:474
#5 0x0000003c786064a7 in start_thread () from /lib64/libpthread.so.0
#6 0x0000003586cd3c2d in clone () from /lib64/libc.so.6

Thread 10 (process 11726):
#0 0x0000003c7860ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1 0x0000000000754ff5 in os_event_wait_low (event=0x1217f780,
    reset_sig_count=<value optimized out>) at os/os0sync.c:402
#2 0x0000000000753c6d in os_aio_simulated_handle (global_segment=1,
    message1=0x41070108, message2=0x41070100, type=0x410700f8)
    at os/os0file.c:4324
#3 0x00000000007f9e47 in fil_aio_wait (segment=1) at fil/fil0fil.c:5023
#4 0x0000000000792081 in io_handler_thread (arg=<value optimized out>)
    at srv/srv0start.c:474
#5 0x0000003c786064a7 in start_thread () from /lib64/libpthread.so.0
#6 0x0000003586cd3c2d in clone () from /lib64/libc.so.6

Thread 9 (process 11727):
#0 0x0000003c7860ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1 0x0000000000754ff5 in os_event_wait_low (event=0x1217f800,
    reset_sig_count=<value optimized out>) at os/os0sync.c:402
#2 0x0000000000753c6d in os_aio_simulated_handle (global_segment=2,
    message1=0x4252c108, message2=0x4252c100, type=0x4252c0f8)
    at os/os0file.c:4324
#3 0x00000000007f9e47 in fil_aio_wait (segment=2) at fil/fil0fil.c:5023
#4 0x0000000000792081 in io_handler_thread (arg=<value optimized out>)
    at srv/srv0start.c:474
#5 0x0000003c786064a7 in start_thread () from /lib64/libpthread.so.0
#6 0x0000003586cd3c2d in clone () from /lib64/libc.so.6

Thread 8 (process 11728):
#0 0x0000003c7860ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1 0x0000000000754ff5 in os_event_wait_low (event=0x1217f880,
    reset_sig_count=<value optimized out>) at os/os0sync.c:402
#2 0x0000000000753c6d in os_aio_simulated_handle (global_segment=3,
    message1=0x42f2d108, message2=0x42f2d100, type=0x42f2d0f8)
    at os/os0file.c:4324
#3 0x00000000007f9e47 in fil_aio_wait (segment=3) at fil/fil0fil.c:5023
#4 0x0000000000792081 in io_handler_thread (arg=<value optimized out>)
    at srv/srv0start.c:474
#5 0x0000003c786064a7 in start_thread () from /lib64/libpthread.so.0
#6 0x0000003586cd3c2d in clone () from /lib64/libc.so.6

Thread 7 (process 11729):
#0 0x0000003c7860ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1 0x0000000000754ff5 in os_event_wait_low (event=0x1217f900,
    reset_sig_count=<value optimized out>) at os/os0sync.c:402
#2 0x0000000000753c6d in os_aio_simulated_handle (global_segment=4,
    message1=0x4392e108, message2=0x4392e100, type=0x4392e0f8)
    at os/os0file.c:4324
#3 0x00000000007f9e47 in fil_aio_wait (segment=4) at fil/fil0fil.c:5023
#4 0x0000000000792081 in io_handler_thread (arg=<value optimized out>)
    at srv/srv0start.c:474
#5 0x0000003c786064a7 in start_thread () from /lib64/libpthread.so.0
#6 0x0000003586cd3c2d in clone () from /lib64/libc.so.6

Thread 6 (process 11730):
#0 0x0000003c7860ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1 0x0000000000754ff5 in os_event_wait_low (event=0x1217f980,
    reset_sig_count=<value optimized out>) at os/os0sync.c:402
#2 0x0000000000753c6d in os_aio_simulated_handle (global_segment=5,
    message1=0x4432f108, message2=0x4432f100, type=0x4432f0f8)
    at os/os0file.c:4324
#3 0x00000000007f9e47 in fil_aio_wait (segment=5) at fil/fil0fil.c:5023
#4 0x0000000000792081 in io_handler_thread (arg=<value optimized out>)
    at srv/srv0start.c:474
#5 0x0000003c786064a7 in start_thread () from /lib64/libpthread.so.0
#6 0x0000003586cd3c2d in clone () from /lib64/libc.so.6

Thread 5 (process 11731):
#0 0x0000003c7860ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1 0x0000000000754ff5 in os_event_wait_low (event=0x1217fa00,
    reset_sig_count=<value optimized out>) at os/os0sync.c:402
#2 0x0000000000753c6d in os_aio_simulated_handle (global_segment=6,
    message1=0x44d30108, message2=0x44d30100, type=0x44d300f8)
    at os/os0file.c:4324
#3 0x00000000007f9e47 in fil_aio_wait (segment=6) at fil/fil0fil.c:5023
#4 0x0000000000792081 in io_handler_thread (arg=<value optimized out>)
    at srv/srv0start.c:474
#5 0x0000003c786064a7 in start_thread () from /lib64/libpthread.so.0
#6 0x0000003586cd3c2d in clone () from /lib64/libc.so.6

Thread 4 (process 11732):
#0 0x0000003c7860ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1 0x0000000000754ff5 in os_event_wait_low (event=0x1217fa80,
    reset_sig_count=<value optimized out>) at os/os0sync.c:402
#2 0x0000000000753c6d in os_aio_simulated_handle (global_segment=7,
    message1=0x45731108, message2=0x45731100, type=0x457310f8)
    at os/os0file.c:4324
#3 0x00000000007f9e47 in fil_aio_wait (segment=7) at fil/fil0fil.c:5023
#4 0x0000000000792081 in io_handler_thread (arg=<value optimized out>)
    at srv/srv0start.c:474
#5 0x0000003c786064a7 in start_thread () from /lib64/libpthread.so.0
#6 0x0000003586cd3c2d in clone () from /lib64/libc.so.6

Thread 3 (process 11733):
#0 0x0000003c7860ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1 0x0000000000754ff5 in os_event_wait_low (event=0x1217fb00,
    reset_sig_count=<value optimized out>) at os/os0sync.c:402
#2 0x0000000000753c6d in os_aio_simulated_handle (global_segment=8,
    message1=0x46132108, message2=0x46132100, type=0x461320f8)
    at os/os0file.c:4324
#3 0x00000000007f9e47 in fil_aio_wait (segment=8) at fil/fil0fil.c:5023
#4 0x0000000000792081 in io_handler_thread (arg=<value optimized out>)
    at srv/srv0start.c:474
#5 0x0000003c786064a7 in start_thread () from /lib64/libpthread.so.0
#6 0x0000003586cd3c2d in clone () from /lib64/libc.so.6

Thread 2 (process 11734):
#0 0x0000003c7860ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
#1 0x0000000000754ff5 in os_event_wait_low (event=0x1217fb80,
    reset_sig_count=<value optimized out>) at os/os0sync.c:402
#2 0x0000000000753c6d in os_aio_simulated_handle (global_segment=9,
    message1=0x46b33108, message2=0x46b33100, type=0x46b330f8)
    at os/os0file.c:4324
#3 0x00000000007f9e47 in fil_aio_wait (segment=9) at fil/fil0fil.c:5023
#4 0x0000000000792081 in io_handler_thread (arg=<value optimized out>)
    at srv/srv0start.c:474
#5 0x0000003c786064a7 in start_thread () from /lib64/libpthread.so.0
#6 0x0000003586cd3c2d in clone () from /lib64/libc.so.6

Thread 1 (process 11723):
#0 0x0000003c7860b9b2 in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000005b1765 in handle_segfault (sig=11) at mysqld.cc:2650
#2 <signal handler called>
#3 mtr_read_ulint (ptr=0x18 <Address 0x18 out of bounds>, type=1,
    mtr=0x7fffcc9b6040) at ./include/mach0data.ic:54
#4 0x0000000000803e4c in fsp_reserve_free_extents (n_reserved=0x7fffcc9b5f70,
    space=4294967264, n_ext=2, alloc_type=<value optimized out>,
    mtr=0x7fffcc9b6040) at fsp/fsp0fsp.c:414
#5 0x000000000080d265 in fseg_create_general (space=4294967264,
    page=<value optimized out>, byte_offset=16184, has_done_reservation=0,
    mtr=0x7fffcc9b6040) at fsp/fsp0fsp.c:2315
#6 0x00000000007a3af6 in trx_sys_create_doublewrite_buf ()
    at trx/trx0sys.c:448
#7 0x000000000079314d in innobase_start_or_create_for_mysql ()
    at srv/srv0start.c:1655
#8 0x000000000072518f in innobase_init (p=<value optimized out>)
    at handler/ha_innodb.cc:2478
#9 0x0000000000691b71 in ha_initialize_handlerton (plugin=0x11d83500)
    at handler.cc:435
#10 0x000000000070e5fd in plugin_initialize (plugin=0x11d83500)
    at sql_plugin.cc:1019
#11 0x0000000000710daa in plugin_init (argc=0xdad790, argv=0x11d544d8,
    flags=<value optimized out>) at sql_plugin.cc:1246
#12 0x00000000005b36df in init_server_components () at mysqld.cc:4056
#13 0x00000000005b4c59 in main (argc=<value optimized out>,
    argv=<value optimized out>) at mysqld.cc:4629

Retrying test main.percona_innodb_doublewrite_file, attempt(2/3)...

Related branches

Changed in percona-server:
milestone: none → 5.1.53-12.4
importance: Undecided → High
Changed in percona-server:
assignee: nobody → Yasufumi Kinoshita (yasufumi-kinoshita)
status: New → Fix Committed
Changed in percona-server:
status: Fix Committed → Fix Released
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.