*** glibc detected *** bin/mysqld: free(): corrupted unsorted chunks *** AT SHUTDOWN | handle_fatal_signal (sig=6) in _int_free (libc) from Events::deinit at sql/events.cc:930 | Also seen as corrupted double-linked list

Bug #1206065 reported by Roel Van de Paar on 2013-07-29
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server
High
Sergei Glushchenko
5.1
Undecided
Unassigned
5.5
High
Sergei Glushchenko
5.6
High
Sergei Glushchenko

Bug Description

Thread 56 (LWP 10273):
+bt
#0 0x000000341841188b in ?? () from /lib64/libgcc_s.so.1
#1 0x000000340c525d56 in dl_iterate_phdr () from /lib64/libc.so.6
#2 0x00000034184121a7 in _Unwind_Find_FDE () from /lib64/libgcc_s.so.1
#3 0x000000341840f5a3 in ?? () from /lib64/libgcc_s.so.1
#4 0x00000034184100b9 in _Unwind_Backtrace () from /lib64/libgcc_s.so.1
#5 0x000000340c4fe8fe in backtrace () from /lib64/libc.so.6
#6 0x00000000009897f5 in my_print_stacktrace (stack_bottom=0x0, thread_stack=262144) at /bzr/bug1191582_dbg/Percona-Server-5.6.12-rc60.4/mysys/stacktrace.c:224
#7 0x0000000000686c34 in handle_fatal_signal (sig=6) at /bzr/bug1191582_dbg/Percona-Server-5.6.12-rc60.4/sql/signal_handler.cc:166
#8 <signal handler called>
#9 0x000000340c4328a5 in raise () from /lib64/libc.so.6
#10 0x000000340c434085 in abort () from /lib64/libc.so.6
#11 0x000000340c4707b7 in __libc_message () from /lib64/libc.so.6
#12 0x000000340c4760e6 in malloc_printerr () from /lib64/libc.so.6
#13 0x000000340c478c13 in _int_free () from /lib64/libc.so.6
#14 0x00000000007ea1f0 in Events::deinit () at /bzr/bug1191582_dbg/Percona-Server-5.6.12-rc60.4/sql/events.cc:930
#15 0x00000000005a7c66 in close_connections () at /bzr/bug1191582_dbg/Percona-Server-5.6.12-rc60.4/sql/mysqld.cc:1438
#16 kill_server (sig_ptr=0x0) at /bzr/bug1191582_dbg/Percona-Server-5.6.12-rc60.4/sql/mysqld.cc:1614
#17 0x00000000005a821e in kill_server_thread (arg=<optimized out>) at /bzr/bug1191582_dbg/Percona-Server-5.6.12-rc60.4/sql/mysqld.cc:1642
#18 0x00000000009dd6c9 in pfs_spawn_thread (arg=0x7f9d24001ac0) at /bzr/bug1191582_dbg/Percona-Server-5.6.12-rc60.4/storage/perfschema/pfs.cc:1855
#19 0x000000340cc07851 in start_thread () from /lib64/libpthread.so.0
#20 0x000000340c4e890d in clone () from /lib64/libc.so.6

2013-07-29 12:15:46 9893 [Note] /ssd/Percona-Server-5.6.12-rc60.4-406-debug.Linux.x86_64/bin/mysqld: Normal shutdown
2013-07-29 12:15:46 9893 [Note] Giving 1 client threads a chance to die gracefully
09:15:46 UTC - mysqld got signal 6 ;
[...]
Thread pointer: 0x0

Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
summary: - *** glibc detected *** bin/mysqld: free(): corrupted unsorted chunks:
- 0x000000000321c4a0 *** | handle_fatal_signal (sig=6) in _int_free (libc)
- from Events::deinit at sql/events.cc:930
+ *** glibc detected *** bin/mysqld: free(): corrupted unsorted chunks:
+ 0x000000000321c4a0 *** AT SHUTDOWN | handle_fatal_signal (sig=6) in
+ _int_free (libc) from Events::deinit at sql/events.cc:930
description: updated
Roel Van de Paar (roel11) wrote :

This is a threadpool run and event scheduler might be related. Sergei, can you have a look if it's indeed threadpool-related?

Roel,

Can you check whether it still exists in lp:~sergei.glushchenko/percona-server/tp-fixes-summarized ?

Thanks

Roel -

Please let me know if you prefer to have tp-fixes-summarized merged to the QA branch for testing.

Roel Van de Paar (roel11) wrote :

Hi Laurynas, it was only a single occurrence afair, so merging tp-fixes-summarized may not help (at least as far as this bug goes), as it is very unlikely that I would run into it again. I terms of testing the branch specifically, can do if we believe it's fixed there (time required)?

Roel Van de Paar (roel11) wrote :

Sergei - due to time required, in terms of testing the branch specifically, can do if we believe it's fixed there. If it is somewhat unlikely that it is fixed, maybe code review may be a better first.

Roel Van de Paar (roel11) wrote :

Adding another occurrence. Seen again.

Roel Van de Paar (roel11) wrote :
tags: added: threadpool
Roel Van de Paar (roel11) wrote :

Thread 30 (LWP 15144):
+bt
#0 0x000000340c52606f in _dl_addr () from /lib64/libc.so.6
#1 0x000000340c4fee4c in backtrace_symbols_fd () from /lib64/libc.so.6
#2 0x00000000009898c8 in my_print_stacktrace (stack_bottom=0x7f523b8f6b68 "\240\n@\001", thread_stack=262144) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/mysys/stacktrace.c:237
#3 0x0000000000686c84 in handle_fatal_signal (sig=6) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/signal_handler.cc:166
#4 <signal handler called>
#5 0x000000340c4328a5 in raise () from /lib64/libc.so.6
#6 0x000000340c434085 in abort () from /lib64/libc.so.6
#7 0x000000340c4707b7 in __libc_message () from /lib64/libc.so.6
#8 0x000000340c4760e6 in malloc_printerr () from /lib64/libc.so.6
#9 0x000000340c478c13 in _int_free () from /lib64/libc.so.6
#10 0x0000000000983c46 in my_free (ptr=0x36d59e0) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/mysys/my_malloc.c:137
#11 0x0000000000968942 in delete_dynamic (array=0x36db718) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/mysys/array.c:308
#12 0x000000000096ae0c in my_hash_free (hash=0x36db6f0) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/mysys/hash.c:138
#13 0x00000000006e87ad in THD::cleanup (this=0x36db150) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_class.cc:1686
#14 0x00000000006e8ac8 in THD::release_resources (this=0x36db150) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/sql_class.cc:1742
#15 0x00000000007d6a2c in threadpool_remove_connection (thd=0x36db150) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/threadpool_common.cc:250
#16 0x00000000007d941f in connection_abort (connection=0x379ab10) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/threadpool_unix.cc:1276
#17 handle_event (connection=0x379ab10) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/threadpool_unix.cc:1477
#18 worker_main (param=0x1506c00 <all_groups+512>) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/sql/threadpool_unix.cc:1519
#19 0x00000000009dd7a9 in pfs_spawn_thread (arg=0x7f52200167d0) at /bzr/5.6-QA_dbg/Percona-Server-5.6.12-rc60.4/storage/perfschema/pfs.cc:1855
#20 0x000000340cc07851 in start_thread () from /lib64/libpthread.so.0
#21 0x000000340c4e890d in clone () from /lib64/libc.so.6

Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :

What happened here is concurrent vio_shutdown and vio_delete. So shutdown read from/write to memory which already has been released. Here is how it looks:

==30550== Thread 35:
==30550== Invalid read of size 4
==30550== at 0x8A70199: vio_shutdown (viosocket.c:468)
==30550== by 0x84AB73C: tp_post_kill_notification(THD*) (threadpool_unix.cc:1298)
==30550== by 0x81FFCE8: close_connections() (mysqld.cc:1420)
==30550== by 0x8200318: kill_server(void*) (mysqld.cc:1614)
==30550== by 0x8200368: kill_server_thread (mysqld.cc:1642)
==30550== by 0x87255B3: pfs_spawn_thread (pfs.cc:1855)
==30550== by 0x4A9851: start_thread (in /lib/libpthread-2.5.so)
==30550== by 0x413A8D: clone (in /lib/libc-2.5.so)
==30550== Address 0x1ab97444 is 4 bytes inside a block of size 396 free'd
==30550== at 0x400579D: free (vg_replace_malloc.c:325)
==30550== by 0x86AFA7E: my_free (my_malloc.c:137)
==30550== by 0x8A6F37D: vio_delete (vio.c:349)
==30550== by 0x837E07D: THD::release_resources() (sql_class.cc:1733)
==30550== by 0x84A970D: threadpool_remove_connection(THD*) (threadpool_common.cc:250)
==30550== by 0x84AB56D: connection_abort(connection_t*) (threadpool_unix.cc:1276)
==30550== by 0x84ACA8F: handle_event(connection_t*) (threadpool_unix.cc:1477)
==30550== by 0x84ACC89: worker_main(void*) (threadpool_unix.cc:1519)
==30550== by 0x87255B3: pfs_spawn_thread (pfs.cc:1855)
==30550== by 0x4A9851: start_thread (in /lib/libpthread-2.5.so)
==30550== by 0x413A8D: clone (in /lib/libc-2.5.so)

It's not fixed in lp:~sergei.glushchenko/percona-server/tp-fixes-summarized, but is very unlikely to hit there.
Starting to work on th fix.

Roel Van de Paar (roel11) wrote :

This was also seen as:

*** glibc detected *** /sde/Percona-Server-5.6.12-rc60.4-410-debug.Linux.x86_64/bin/mysqld: corrupted double-linked list: 0x00000000021fc990 ***

Adding analysis files below

Roel Van de Paar (roel11) wrote :
summary: - *** glibc detected *** bin/mysqld: free(): corrupted unsorted chunks:
- 0x000000000321c4a0 *** AT SHUTDOWN | handle_fatal_signal (sig=6) in
- _int_free (libc) from Events::deinit at sql/events.cc:930
+ *** glibc detected *** bin/mysqld: free(): corrupted unsorted chunks ***
+ AT SHUTDOWN | handle_fatal_signal (sig=6) in _int_free (libc) from
+ Events::deinit at sql/events.cc:930 | Also seen as corrupted double-
+ linked list
Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
tags: added: 56qual
tags: added: tp
removed: threadpool

No longer affects 5.6, was fixed with lp:~sergei.glushchenko/percona-server/5.6-ps-bug1194097 merged.

In 5.5 might not be reproducible (see comments on https://mariadb.atlassian.net/browse/MDEV-4889)

Sergei -

Can you close this bug as a duplicate of the correct bug? Is it bug 1201681?

To post a comment you must log in.