[MDEV-5308] Crash when running with slow_query_log=1 Created: 2013-11-18  Updated: 2013-11-26  Resolved: 2013-11-26

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.0.5
Fix Version/s: 10.0.7

Type: Bug Priority: Critical
Reporter: Torsten Krah Assignee: Sergei Petrunia
Resolution: Fixed Votes: 0
Labels: None
Environment:

Linux 64 Bit, Ubuntu Saucy



 Description   

Hi,

did upgrade from 5.5.33a to 10.0.5 today.
Upgrade did crash several times - but it did always crash when running "mysql_upgrade" at stage 3/3:

Phase 3/3: Running 'mysql_fix_privilege_tables'...

Crash

Stacktrace does show this:

Nov 18 16:22:21 thorstenknbl1 mysqld: 131118 16:22:21 [ERROR] mysqld got signal 11 ;
Nov 18 16:22:21 thorstenknbl1 mysqld: This could be because you hit a bug. It is also possible that this binary
Nov 18 16:22:21 thorstenknbl1 mysqld: or one of the libraries it was linked against is corrupt, improperly built,
Nov 18 16:22:21 thorstenknbl1 mysqld: or misconfigured. This error can also be caused by malfunctioning hardware.
Nov 18 16:22:21 thorstenknbl1 mysqld: 
Nov 18 16:22:21 thorstenknbl1 mysqld: To report this bug, see http://kb.askmonty.org/en/reporting-bugs
Nov 18 16:22:21 thorstenknbl1 mysqld: 
Nov 18 16:22:21 thorstenknbl1 mysqld: We will try our best to scrape up some info that will hopefully help
Nov 18 16:22:21 thorstenknbl1 mysqld: diagnose the problem, but since we have already crashed, 
Nov 18 16:22:21 thorstenknbl1 mysqld: something is definitely wrong and this may fail.
Nov 18 16:22:21 thorstenknbl1 mysqld: 
Nov 18 16:22:21 thorstenknbl1 mysqld: Server version: 10.0.5-MariaDB-log
Nov 18 16:22:21 thorstenknbl1 mysqld: key_buffer_size=67108864
Nov 18 16:22:21 thorstenknbl1 mysqld: read_buffer_size=524288
Nov 18 16:22:21 thorstenknbl1 mysqld: max_used_connections=1
Nov 18 16:22:21 thorstenknbl1 mysqld: max_threads=501
Nov 18 16:22:21 thorstenknbl1 mysqld: thread_count=1
Nov 18 16:22:21 thorstenknbl1 mysqld: It is possible that mysqld could use up to 
Nov 18 16:22:21 thorstenknbl1 mysqld: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 580639 K  bytes of memory
Nov 18 16:22:21 thorstenknbl1 mysqld: Hope that's ok; if not, decrease some variables in the equation.
Nov 18 16:22:21 thorstenknbl1 mysqld: 
Nov 18 16:22:21 thorstenknbl1 mysqld: Thread pointer: 0x0x7f4ee0264008
Nov 18 16:22:21 thorstenknbl1 mysqld: Attempting backtrace. You can use the following information to find out
Nov 18 16:22:21 thorstenknbl1 mysqld: where mysqld died. If you see no messages after this, something went
Nov 18 16:22:21 thorstenknbl1 mysqld: terribly wrong...
Nov 18 16:22:21 thorstenknbl1 mysqld: stack_bottom = 0x7f4f7b5e3cc8 thread_stack 0x48000
Nov 18 16:22:21 thorstenknbl1 mysqld: mysys/stacktrace.c:247(my_print_stacktrace)[0xb78f2b]
Nov 18 16:22:21 thorstenknbl1 mysqld: sql/signal_handler.cc:153(handle_fatal_signal)[0x70ce68]
Nov 18 16:22:21 thorstenknbl1 mysqld: ??:0(??)[0x7f4f7d75dbb0]
Nov 18 16:22:21 thorstenknbl1 mysqld: psi/mysql_thread.h:662(inline_mysql_mutex_lock)[0x6b6a1a]
Nov 18 16:22:21 thorstenknbl1 mysqld: sql/sql_explain.cc:35(Explain_query::~Explain_query())[0x69aa30]
Nov 18 16:22:21 thorstenknbl1 mysqld: sql/sql_explain.cc:938(delete_explain_query(LEX*))[0x69bf8d]
Nov 18 16:22:21 thorstenknbl1 mysqld: sql/sql_parse.cc:1767(log_slow_statement)[0x5c39f9]
Nov 18 16:22:21 thorstenknbl1 mysqld: sql/threadpool_common.cc:232(threadpool_process_request(THD*))[0x6b6387]
Nov 18 16:22:21 thorstenknbl1 mysqld: sql/threadpool_unix.cc:1444(handle_event)[0x6e227d]
Nov 18 16:22:21 thorstenknbl1 mysqld: perfschema/pfs.cc:1856(pfs_spawn_thread)[0xa2c460]
Nov 18 16:22:21 thorstenknbl1 mysqld: ??:0(??)[0x7f4f7d755f6e]
Nov 18 16:22:21 thorstenknbl1 mysqld: ??:0(??)[0x7f4f7ce789cd]
Nov 18 16:22:21 thorstenknbl1 mysqld: 
Nov 18 16:22:21 thorstenknbl1 mysqld: Trying to get some variables.
Nov 18 16:22:21 thorstenknbl1 mysqld: Some pointers may be invalid and cause the dump to abort.
Nov 18 16:22:21 thorstenknbl1 mysqld: Query (0x7f4ecd82d020): is an invalid pointer
Nov 18 16:22:21 thorstenknbl1 mysqld: Connection ID (thread ID): 6
Nov 18 16:22:21 thorstenknbl1 mysqld: Status: NOT_KILLED
Nov 18 16:22:21 thorstenknbl1 mysqld: 
Nov 18 16:22:21 thorstenknbl1 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,exists_to_in=off
Nov 18 16:22:21 thorstenknbl1 mysqld: 
Nov 18 16:22:21 thorstenknbl1 mysqld: The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
Nov 18 16:22:21 thorstenknbl1 mysqld: information that should help you find out what is causing the crash.

As i saw log_slow statement in the trace, i'll remove all my slow query log stuff from the config and upgrade went fine, no crash.

So slow query log is broken in 10.0.5 at the moment.

config was:

slow_query_log = 1
log_slow_rate_limit = 1000
log-queries-not-using-indexes



 Comments   
Comment by Elena Stepanova [ 2013-11-18 ]

Thanks for reporting this.

slow_query_log does not get along with log_slow_rate_limit.

Test case:

SET log_slow_rate_limit=1000;
SET GLOBAL slow_query_log=1;
SET long_query_time=0.000001;

SELECT 1;

  1. end of test case

sql/sql_parse.cc:994: bool do_command(THD*): Assertion `!thd->apc_target.is_enabled()' failed.
131118 19:47:04 [ERROR] mysqld got signal 6 ;

#6 0x00007faf2d5140ee in __assert_fail_base (fmt=<optimized out>, assertion=0xfdc5fa "!thd->apc_target.is_enabled()", file=0xfdc428 "/home/elenst/bzr/10.0/sql/sql_parse.cc", line=<optimized out>, function=<optimized out>) at assert.c:94
#7 0x00007faf2d514192 in _GI__assert_fail (assertion=0xfdc5fa "!thd->apc_target.is_enabled()", file=0xfdc428 "/home/elenst/bzr/10.0/sql/sql_parse.cc", line=994, function=0xfddf70 "bool do_command(THD*)") at assert.c:103
#8 0x0000000000644e4a in do_command (thd=0x7faf27341070) at /home/elenst/bzr/10.0/sql/sql_parse.cc:994
#9 0x0000000000763fd9 in do_handle_one_connection (thd_arg=0x7faf27341070) at /home/elenst/bzr/10.0/sql/sql_connect.cc:1379
#10 0x0000000000763d2c in handle_one_connection (arg=0x7faf27341070) at /home/elenst/bzr/10.0/sql/sql_connect.cc:1293
#11 0x00000000009ffd8f in pfs_spawn_thread (arg=0x7faf26644df0) at /home/elenst/bzr/10.0/storage/perfschema/pfs.cc:1853
#12 0x00007faf2e0bee9a in start_thread (arg=0x7faf2f156700) at pthread_create.c:308
#13 0x00007faf2d5d93fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112

Comment by Sergei Petrunia [ 2013-11-21 ]

Fix pushed into 10.0-base

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