[MDEV-9377] Crash with signal 11 since last update (2 time in one month) Created: 2016-01-06  Updated: 2018-04-17  Resolved: 2018-04-17

Status: Closed
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 5.5.47, 10.0.25
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Aurélien Bras Assignee: Alice Sherepa
Resolution: Incomplete Votes: 0
Labels: need_feedback
Environment:

Debian Wheezy 7.9 on Xen guest

Attachments: File my.cnf    
Issue Links:
Duplicate
duplicates MDEV-9304 MariaDB crash with specific query Closed

 Description   

Hello,

Since upgrade to MariaDB 5.5.47 (5.5.47+maria-1~wheezy from 5.5.46+maria-1~wheezy) I have crash on only one MySQL server (9 servers with same production load/environement got the same update). I'm using InnoDB and MyISAM storage. RAM/CPU/DISK usage is normal before the crash.

I had only two crash in one month, and I cannot reproduce the bug by myself. It's a heavy loaded server so it's really difficult for me to activate debug mode.

That's all I have :

Jan 6 15:58:40 cl1-sql-tmp mysqld: 160106 15:58:40 [ERROR] mysqld got signal 11 ;
Jan 6 15:58:40 cl1-sql-tmp mysqld: This could be because you hit a bug. It is also possible that this binary
Jan 6 15:58:40 cl1-sql-tmp mysqld: or one of the libraries it was linked against is corrupt, improperly built,
Jan 6 15:58:40 cl1-sql-tmp mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.
Jan 6 15:58:40 cl1-sql-tmp mysqld:
Jan 6 15:58:40 cl1-sql-tmp mysqld: To report this bug, see http://kb.askmonty.org/en/reporting-bugs
Jan 6 15:58:40 cl1-sql-tmp mysqld:
Jan 6 15:58:40 cl1-sql-tmp mysqld: We will try our best to scrape up some info that will hopefully help
Jan 6 15:58:40 cl1-sql-tmp mysqld: diagnose the problem, but since we have already crashed,
Jan 6 15:58:40 cl1-sql-tmp mysqld: something is definitely wrong and this may fail.
Jan 6 15:58:40 cl1-sql-tmp mysqld:
Jan 6 15:58:40 cl1-sql-tmp mysqld: Server version: 5.5.47-MariaDB-1~wheezy
Jan 6 15:58:40 cl1-sql-tmp mysqld: key_buffer_size=2147483648
Jan 6 15:58:40 cl1-sql-tmp mysqld: read_buffer_size=4194304
Jan 6 15:58:40 cl1-sql-tmp mysqld: max_used_connections=176
Jan 6 15:58:40 cl1-sql-tmp mysqld: max_threads=502
Jan 6 15:58:40 cl1-sql-tmp mysqld: thread_count=6
Jan 6 15:58:40 cl1-sql-tmp mysqld: It is possible that mysqld could use up to
Jan 6 15:58:40 cl1-sql-tmp mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 6218475 K bytes of memory
Jan 6 15:58:40 cl1-sql-tmp mysqld: Hope that's ok; if not, decrease some variables in the equation.
Jan 6 15:58:40 cl1-sql-tmp mysqld:
Jan 6 15:58:40 cl1-sql-tmp mysqld: Thread pointer: 0x0x7efa3cce0000
Jan 6 15:58:40 cl1-sql-tmp mysqld: Attempting backtrace. You can use the following information to find out
Jan 6 15:58:40 cl1-sql-tmp mysqld: where mysqld died. If you see no messages after this, something went
Jan 6 15:58:40 cl1-sql-tmp mysqld: terribly wrong...
Jan 6 15:58:41 cl1-sql-tmp mysqld: stack_bottom = 0x7efa0504be40 thread_stack 0x48000
Jan 6 15:58:42 cl1-sql-tmp mysqld: (my_addr_resolve failure: fork)
Jan 6 15:58:42 cl1-sql-tmp mysqld: /usr/sbin/mysqld(my_print_stacktrace+0x2b) [0x7f0030f283eb]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /usr/sbin/mysqld(handle_fatal_signal+0x422) [0x7f0030b5d2f2]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /lib/x86_64-linux-gnu/libpthread.so.0(+0xf0a0) [0x7f00302520a0]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /usr/sbin/mysqld(st_join_table::cleanup()+0x43) [0x7f0030a569e3]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /usr/sbin/mysqld(JOIN::destroy()+0x2d0) [0x7f0030a59970]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /usr/sbin/mysqld(st_select_lex::cleanup()+0x2c) [0x7f0030aa9cac]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /usr/sbin/mysqld(mysql_select(THD*, Item**, TABLE_LIST, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*)+0x8d3) [0x7f0030a6b7b3]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /usr/sbin/mysqld(handle_select(THD*, LEX*, select_result*, unsigned long)+0x2c3) [0x7f0030a71df3]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /usr/sbin/mysqld(+0x399ab1) [0x7f0030a1aab1]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /usr/sbin/mysqld(mysql_execute_command(THD*)+0x1bcd) [0x7f0030a222fd]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /usr/sbin/mysqld(+0x3a5647) [0x7f0030a26647]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /usr/sbin/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0x1b51) [0x7f0030a28ad1]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /usr/sbin/mysqld(do_handle_one_connection(THD*)+0x22b) [0x7f0030adec2b]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /usr/sbin/mysqld(handle_one_connection+0x51) [0x7f0030adecb1]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50) [0x7f0030249b50]
Jan 6 15:58:42 cl1-sql-tmp mysqld: /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d) [0x7f002eb5795d]
Jan 6 15:58:42 cl1-sql-tmp mysqld:
Jan 6 15:58:42 cl1-sql-tmp mysqld: Trying to get some variables.
Jan 6 15:58:42 cl1-sql-tmp mysqld: Some pointers may be invalid and cause the dump to abort.
Jan 6 15:58:42 cl1-sql-tmp mysqld: Query (0x7efaec89f018): is an invalid pointer
Jan 6 15:58:42 cl1-sql-tmp mysqld: Connection ID (thread ID): 17204365
Jan 6 15:58:42 cl1-sql-tmp mysqld: Status: NOT_KILLED
Jan 6 15:58:42 cl1-sql-tmp mysqld:
Jan 6 15:58:42 cl1-sql-tmp mysqld: Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=off
Jan 6 15:58:42 cl1-sql-tmp mysqld:
Jan 6 15:58:42 cl1-sql-tmp mysqld: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
Jan 6 15:58:42 cl1-sql-tmp mysqld: information that should help you find out what is causing the crash.
Jan 6 15:58:43 cl1-sql-tmp mysqld_safe: Number of processes running now: 0
Jan 6 15:58:43 cl1-sql-tmp mysqld_safe: mysqld restarted

Thanks for your help.

Regards.

 Comments   
Comment by Elena Stepanova [ 2016-01-11 ]

profy,

Please attach your cnf file(s).

Did both crashes happen at approximately the same time of the day? Can it be that you have some process on this server (backup, maintenance, analytics, what not) that does not exist on other servers?

Do you happen to have server audit or slow log enabled? If you do, do they contain anything interesting around this time, or do they contain anything at all about connection 17204365 during that run? It may be not the query that caused the crash, but it might give you the idea what the connection was about, and what else it could be doing. Any guesses in regard to what kind of queries and on which tables this connection performed could be helpful.

Comment by Aurélien Bras [ 2016-01-11 ]

cnf file is now attached, there is no inclusion more.

This happen first time the december at 12h45 and the second time 16 january at 16h11, there was no special process when the crash happen and the server is exactly the same than the others.

It's a shared hosting with thousands users/databases, I cannot guess what can be the request.

I lost the log of the first crash.

Comment by Elena Stepanova [ 2016-01-26 ]

We have a bug with a very similar stacktrace (or even identical, it's hard to say with non-debug stack traces): MDEV-9304. Since we don't have much information about this one, I am going to assume for now that it's the same problem. I'm raising the priority of MDEV-9304 to make sure it gets fixed in the next 5.5 release, and closing this one as its duplicate. If you later find out that the fix for MDEV-9304 did not fix your problem, please feel free to comment, we'll re-open the issue and try to investigate it further.

Comment by Aurélien Bras [ 2016-02-23 ]

I updated to mariadb 5.5.48 (5.5.48+maria-1~wheezy) but I still have crash with same stacktrace.

Comment by Aurélien Bras [ 2016-03-24 ]

I still have crash, maybe more often since last update I have now a segfault in the log :

Mar 24 02:37:32 cl1-sql-tmp mysqld: 160324 2:37:32 [ERROR] mysqld got signal 11 ;
Mar 24 02:37:32 cl1-sql-tmp mysqld: This could be because you hit a bug. It is also possible that this binary
Mar 24 02:37:32 cl1-sql-tmp mysqld: or one of the libraries it was linked against is corrupt, improperly built,
Mar 24 02:37:32 cl1-sql-tmp mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.
Mar 24 02:37:32 cl1-sql-tmp mysqld:
Mar 24 02:37:32 cl1-sql-tmp mysqld: To report this bug, see http://kb.askmonty.org/en/reporting-bugs
Mar 24 02:37:32 cl1-sql-tmp mysqld:
Mar 24 02:37:32 cl1-sql-tmp mysqld: We will try our best to scrape up some info that will hopefully help
Mar 24 02:37:32 cl1-sql-tmp mysqld: diagnose the problem, but since we have already crashed,
Mar 24 02:37:32 cl1-sql-tmp mysqld: something is definitely wrong and this may fail.
Mar 24 02:37:32 cl1-sql-tmp mysqld:
Mar 24 02:37:32 cl1-sql-tmp mysqld: Server version: 5.5.48-MariaDB-1~wheezy
Mar 24 02:37:32 cl1-sql-tmp mysqld: key_buffer_size=2147483648
Mar 24 02:37:32 cl1-sql-tmp mysqld: read_buffer_size=4194304
Mar 24 02:37:32 cl1-sql-tmp mysqld: max_used_connections=222
Mar 24 02:37:32 cl1-sql-tmp mysqld: max_threads=502
Mar 24 02:37:32 cl1-sql-tmp mysqld: thread_count=16
Mar 24 02:37:32 cl1-sql-tmp mysqld: It is possible that mysqld could use up to
Mar 24 02:37:32 cl1-sql-tmp mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 6218475 K bytes of memory
Mar 24 02:37:32 cl1-sql-tmp mysqld: Hope that's ok; if not, decrease some variables in the equation.
Mar 24 02:37:32 cl1-sql-tmp mysqld:
Mar 24 02:37:32 cl1-sql-tmp mysqld: Thread pointer: 0x0x7f886f4b7000
Mar 24 02:37:32 cl1-sql-tmp mysqld: Attempting backtrace. You can use the following information to find out
Mar 24 02:37:32 cl1-sql-tmp mysqld: where mysqld died. If you see no messages after this, something went
Mar 24 02:37:32 cl1-sql-tmp mysqld: terribly wrong...
Mar 24 02:37:32 cl1-sql-tmp kernel: [18718547.198663] mysqld[30988]: segfault at ff0000003d ip 00007f8e2282b730 sp 00007f8c1d9b3dd0 error 4 in libgcc_s.so.1[7f8e2281c000+15000]

Comment by Aurélien Bras [ 2016-04-01 ]

I don't know how to re-open this bug issue, I hope I'm the only one concerned, and I will try an upgrade to MariaDB 10.0 next week to see if it's better. I will upgrade to another system too, to see if issue still persist. I will re-open a new bug if crash persist.

Comment by Elena Stepanova [ 2016-04-01 ]

Is it all that it writes to the log, no stack trace anymore? If there is, could you please paste it – is it identical to the previous one?

Comment by Aurélien Bras [ 2016-04-01 ]

I have no more crash since, but I have log from another crash (2016/2103) :

Mar 21 01:47:51 cl1-sql-tmp mysqld: 160321 1:47:51 [ERROR] mysqld got signal 11 ;
Mar 21 01:47:51 cl1-sql-tmp mysqld: This could be because you hit a bug. It is also possible that this binary
Mar 21 01:47:51 cl1-sql-tmp mysqld: or one of the libraries it was linked against is corrupt, improperly built,
Mar 21 01:47:51 cl1-sql-tmp mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.
Mar 21 01:47:51 cl1-sql-tmp mysqld:
Mar 21 01:47:51 cl1-sql-tmp mysqld: To report this bug, see http://kb.askmonty.org/en/reporting-bugs
Mar 21 01:47:51 cl1-sql-tmp mysqld:
Mar 21 01:47:51 cl1-sql-tmp mysqld: We will try our best to scrape up some info that will hopefully help
Mar 21 01:47:51 cl1-sql-tmp mysqld: diagnose the problem, but since we have already crashed,
Mar 21 01:47:51 cl1-sql-tmp mysqld: something is definitely wrong and this may fail.
Mar 21 01:47:51 cl1-sql-tmp mysqld:
Mar 21 01:47:51 cl1-sql-tmp mysqld: Server version: 5.5.48-MariaDB-1~wheezy
Mar 21 01:47:51 cl1-sql-tmp mysqld: key_buffer_size=2147483648
Mar 21 01:47:51 cl1-sql-tmp mysqld: read_buffer_size=4194304
Mar 21 01:47:51 cl1-sql-tmp mysqld: max_used_connections=207
Mar 21 01:47:51 cl1-sql-tmp mysqld: max_threads=502
Mar 21 01:47:51 cl1-sql-tmp mysqld: thread_count=15
Mar 21 01:47:51 cl1-sql-tmp mysqld: It is possible that mysqld could use up to
Mar 21 01:47:51 cl1-sql-tmp mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 6218475 K bytes of memory
Mar 21 01:47:51 cl1-sql-tmp mysqld: Hope that's ok; if not, decrease some variables in the equation.
Mar 21 01:47:51 cl1-sql-tmp mysqld:
Mar 21 01:47:51 cl1-sql-tmp mysqld: Thread pointer: 0x0x7fb12f1bc000
Mar 21 01:47:51 cl1-sql-tmp mysqld: Attempting backtrace. You can use the following information to find out
Mar 21 01:47:51 cl1-sql-tmp mysqld: where mysqld died. If you see no messages after this, something went
Mar 21 01:47:51 cl1-sql-tmp mysqld: terribly wrong...
Mar 21 01:47:51 cl1-sql-tmp kernel: [18456366.105732] mysqld[3694]: segfault at ff0000003d ip 00007fb6743f8730 sp 00007fb139692dd0 error 4 in libgcc_s.so.1[7fb6743e9000+15000]

Comment by Elena Stepanova [ 2016-04-01 ]

Right, it's the same stacktraceless output as above. You said you're getting crashes more often now, are they all like this?

Comment by Aurélien Bras [ 2016-04-01 ]

With hindsight, not really more often. Logs are always the sames.

Comment by Elena Stepanova [ 2016-04-06 ]

MDEV-9304 wasn't fixed in 5.5.48, it's still open; so, the possibility that this one is a duplicate of MDEV-9304 is still on the table. If it's so, upgrade to 10.0 won't help, because MDEV-9304 affects 10.0 too.

Comment by Aurélien Bras [ 2016-08-01 ]

Hello I have more information about the bug, two crash with identical requests, it's a sql injection, so it's not very beautiful, not sure it can be related to the other bug :

6202106 Query   SELECT `ville`.`nom` as ville_nom, `lib_ville`, `pays`.`nom` as pays_nom, `lib_pays`,`pays`.`couleur`,`ville`.`plan_gauche` FROM `ville`,`lib_ville`,`pays`,`lib_pays`,`musee` WHERE `musee`.`id_ville` = `ville`.`id_ville` AND `ville`.`id_pays` = `pays`.`id_pays` AND `ville`.`id_ville` = `lib_ville`.`id_ville` AND `pays`.`id_pays` = `lib_pays`.`id_pays` AND `musee`.`id_musee` = (/**/sElEcT 1 /**/fRoM(/**/sElEcT count(*),/**/cOnCaT((/**/sElEcT(/**/sElEcT /**/uNhEx(/**/hEx(/**/cOnCaT(0x217e21,0x4142433134355a5136324457514146504f4959434644,0x217e21)))) /**/fRoM information_schema./**/tAbLeS /**/lImIt 0,1),floor(rand(0)*2))x /**/fRoM information_schema./**/tAbLeS /**/gRoUp/**/bY x)a) AND `lib_ville`.`id_langue` = 1 AND `lib_pays`.`id_langue` = 1

and

SELECT * FROM `pays`,`ville` WHERE `pays`.`id_pays`=`ville`.`id_pays` and `ville`.`id_ville`=(/**/sElEcT 1 /**/fRoM(/**/sElEcT count(*),/**/cOnCaT((/**/sElEcT(/**/sElEcT /**/uNhEx(/**/hEx(/**/cOnCaT(0x217e21,0x4142433134355a5136324457514146504f4959434644,0x217e21)))) /**/fRoM information_schema./**/tAbLeS /**/lImIt 0,1),floor(rand(0)*2))x /**/fRoM information_schema./**/tAbLeS /**/gRoUp/**/bY x)a)

I tried to reproduce it without success, this request cannot be run, it complain about duplicate entry.

MariaDB version, I have now : 10.0.25-MariaDB-0+deb8u1

Comment by Alice Sherepa [ 2018-03-20 ]

Aurélien Bras, I can see that MDEV-9304 was fixed in 10.0.27. Is this issue still occurring? if the problem still exists, please let me know

Generated at Thu Feb 08 07:34:12 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.