[MDEV-10563] Crash during shutdown in Master_info_index::any_slave_sql_running (compiled with GCC v6) Created: 2016-08-15  Updated: 2016-12-01  Resolved: 2016-12-01

Status: Closed
Project: MariaDB Server
Component/s: Admin statements
Affects Version/s: 10.0, 10.1, 10.2
Fix Version/s: 10.0.27

Type: Bug Priority: Major
Reporter: Vicențiu Ciorbaru Assignee: Vicențiu Ciorbaru
Resolution: Fixed Votes: 0
Labels: debian, foundation, gcc6, packaging

Issue Links:
Duplicate
is duplicated by MDEV-10612 main.shutdown failed in buildbot Closed
Problem/Incident
is caused by MDEV-6616 Server crashes in my_hash_first if sh... Closed
Sprint: 10.1.17-1

 Description   

While packaging for Yakkety showed the following crash during mysql.shutdown

Thread 1 (Thread 0x7f5475f85700 (LWP 28787)):
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
 
#1  0x0000000000ab88ba in my_write_core (sig=sig@entry=11) at /home/vicentiu/Workspace/debian/mariadb-10.0/mysys/stacktrace.c:457
 
#2  0x00000000006eb6a2 in handle_fatal_signal (sig=11) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/signal_handler.cc:262
 
#3  <signal handler called>
 
#4  Master_info_index::any_slave_sql_running (this=0x0) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/rpl_mi.cc:1288
 
#5  0x00000000005290b1 in show_slaves_running (thd=<optimized out>, var=<optimized out>, buff=0x7f5475f821b0 "0") at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/mysqld.cc:7319
 
#6  0x0000000000602bbe in show_status_array (thd=thd@entry=0x7f546dadf008, wild=wild@entry=0x0, variables=0x7f54733fec50, value_type=value_type@entry=OPT_SESSION, status_var=status_var@entry=0x7f5475f83d40, prefix=prefix@entry=0xbf7436 "", table=0x7f546c00a020, ucase_names=false, cond=0x0) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_show.cc:3057
 
#7  0x000000000060746f in fill_status (thd=0x7f546dadf008, tables=0x7f546c019348, cond=<optimized out>) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_show.cc:7476
 
#8  0x000000000060cb9f in get_schema_tables_result (join=join@entry=0x7f546c019d30, executed_place=executed_place@entry=PROCESSED_BY_JOIN_EXEC) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_show.cc:8280
 
#9  0x00000000005f4ace in JOIN::exec_inner (this=this@entry=0x7f546c019d30) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_select.cc:2538
 
#10 0x00000000005f68a9 in JOIN::exec (this=0x7f546c019d30) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_select.cc:2373
 
#11 0x00000000005f375d in mysql_select (thd=thd@entry=0x7f546dadf008, rref_pointer_array=rref_pointer_array@entry=0x7f546dae31a8, tables=0x7f546c019348, wild_num=<optimized out>, fields=..., conds=<optimized out>, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2684619520, result=0x7f546c019d10, unit=0x7f546dae2840, select_lex=0x7f546dae2f30) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_select.cc:3308
 
#12 0x00000000005f40ef in handle_select (thd=thd@entry=0x7f546dadf008, lex=lex@entry=0x7f546dae2778, result=result@entry=0x7f546c019d10, setup_tables_done_option=setup_tables_done_option@entry=0) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_select.cc:361
 
#13 0x00000000005a1147 in execute_sqlcom_select (thd=thd@entry=0x7f546dadf008, all_tables=all_tables@entry=0x7f546c019348) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_parse.cc:5293
 
#14 0x00000000005ab62d in execute_show_status (all_tables=0x7f546c019348, thd=0x7f546dadf008) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_parse.cc:5314
 
#15 mysql_execute_command (thd=thd@entry=0x7f546dadf008) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_parse.cc:2492
 
#16 0x00000000005aefd0 in mysql_parse (thd=0x7f546dadf008, rawbuf=<optimized out>, length=11, parser_state=0x7f5475f84650) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_parse.cc:6574
 
#17 0x00000000005b0bed in dispatch_command (command=<optimized out>, thd=0x7f546dadf008, packet=<optimized out>, packet_length=<optimized out>) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_parse.cc:1308
 
#18 0x00000000005b164b in do_command (thd=<optimized out>) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_parse.cc:998
 
#19 0x0000000000662a0b in do_handle_one_connection (thd_arg=thd_arg@entry=0x7f546dadf008) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_connect.cc:1378
 
#20 0x0000000000662a58 in handle_one_connection (arg=arg@entry=0x7f546dadf008) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/sql_connect.cc:1293
 
#21 0x00000000008381e4 in pfs_spawn_thread (arg=0x7f547306d608) at /home/vicentiu/Workspace/debian/mariadb-10.0/storage/perfschema/pfs.cc:1860
 
#22 0x00007f54750cc6fa in start_thread (arg=0x7f5475f85700) at pthread_create.c:333
 
#23 0x00007f5473eaab5d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Notice how any_slave_sql_running has this pointer equal to NULL. When this crash happens, we have another thread executing:

Thread 3 (Thread 0x7f5475f3c700 (LWP 28791)):
 
#0  0x00007f5473ea0d13 in select () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x0000000000ab65db in my_sleep (m_seconds=m_seconds@entry=20000) at /home/vicentiu/Workspace/debian/mariadb-10.0/mysys/my_sleep.c:29
 
#2  0x000000000052d32d in close_connections () at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/mysqld.cc:1676
 
#3  kill_server (sig_ptr=0x0) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/mysqld.cc:1859
 
#4  0x000000000052d5ee in kill_server_thread (arg=arg@entry=0x7f5475fcdd9c) at /home/vicentiu/Workspace/debian/mariadb-10.0/sql/mysqld.cc:1887
 
#5  0x00000000008381e4 in pfs_spawn_thread (arg=0x7f546c425208) at /home/vicentiu/Workspace/debian/mariadb-10.0/storage/perfschema/pfs.cc:1860
 
#6  0x00007f54750cc6fa in start_thread (arg=0x7f5475f3c700) at pthread_create.c:333
 
#7  0x00007f5473eaab5d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

This happens when using gcc version 6. There is a difference in optimizations between gcc v5 and v6.

The relevant code is:

 
 
/**
 
   Master_info_index::any_slave_sql_running()
 
 
 
   The LOCK_active_mi must be held while calling this function.
 
 
 
   @return
 
   0            No Slave SQL thread is running
 
   #		Number of slave SQL thread running
 
*/
 
 
 
uint Master_info_index::any_slave_sql_running()
 
{
 
  uint count= 0;
 
  DBUG_ENTER("any_slave_sql_running");
 
  if (!this) // master_info_index is set to NULL on server shutdown
 
    DBUG_RETURN(count);
 
 
 
  for (uint i= 0; i< master_info_hash.records; ++i)
 
  {
 
    Master_info *mi= (Master_info *)my_hash_element(&master_info_hash, i);
 
    if (mi->rli.slave_running != MYSQL_SLAVE_NOT_RUN)
 
      count++;
 
  }
 
  DBUG_RETURN(count);
 
}

GCC V5 >>>>>>

1283:/home/vicentiu/Workspace/MariaDB/sql/rpl_mi.cc ****   uint count= 0;
 
1284:/home/vicentiu/Workspace/MariaDB/sql/rpl_mi.cc ****   DBUG_ENTER("any_slave_sql_running");
 
1285:/home/vicentiu/Workspace/MariaDB/sql/rpl_mi.cc ****   if (!this) // master_info_index is set to NULL on server shutdown
 
 4675              		.loc 1 1285 0
 
 4676 1fe0 4885FF   		testq	%rdi, %rdi
 
 4677 1fe3 0F84AF00 		je	.L397
 
 4677      0000
 
1282:/home/vicentiu/Workspace/MariaDB/sql/rpl_mi.cc ****   uint count= 0;

GCC V6 completely removes the if statement because in well defined C code this can never be NULL.

I have tested that this is true by adding a printf statement after the condition and it prints (nil).

printf("%p", this);



 Comments   
Comment by Vicențiu Ciorbaru [ 2016-08-16 ]

Hi Sergei, knielsen,

Please review a patch for this debian issue that will eventually hit us when we compile with GCC v6.

http://lists.askmonty.org/pipermail/commits/2016-August/009637.html

Thanks!
Vicentiu

Comment by Elena Stepanova [ 2016-08-24 ]

Adding a note to make the buildbot failure searchable in JIRA.

The problem makes main.shutdown fail in buildbot
http://buildbot.askmonty.org/buildbot/builders/kvm-deb-sid-x86/builds/2069/steps/test_4/logs/stdio

main.shutdown                            w1 [ fail ]  Found warnings/errors in server log file!
 
        Test ended at 2016-08-16 16:45:38
 
line
 
160816 16:45:37 [ERROR] mysqld got signal 11 ;
 
Attempting backtrace. You can use the following information to find out
 
160816 16:45:38 [ERROR] mysqld: Table './mysql/servers' is marked as crashed and should be repaired
 
160816 16:45:38 [Warning] Checking table:   './mysql/servers'
 
160816 16:45:38 [ERROR] mysql.servers: 1 client is using or hasn't closed the table properly
 
160816 16:45:38 [ERROR] mysqld: Table './mysql/user' is marked as crashed and should be repaired
 
160816 16:45:38 [Warning] Checking table:   './mysql/user'
 
160816 16:45:38 [ERROR] mysql.user: 1 client is using or hasn't closed the table properly
 
160816 16:45:38 [ERROR] mysqld: Table './mysql/db' is marked as crashed and should be repaired
 
160816 16:45:38 [Warning] Checking table:   './mysql/db'
 
160816 16:45:38 [ERROR] mysql.db: 1 client is using or hasn't closed the table properly
 
^ Found warnings in /dev/shm/var/1/log/mysqld.1.err
 
ok
 
 
 
 - saving '/dev/shm/var/1/log/main.shutdown/' to '/dev/shm/var/log/main.shutdown/'
 
 
 
Retrying test main.shutdown, attempt(2/3)...

Comment by Sergei Golubchik [ 2016-08-24 ]

ok to push

Comment by Vicențiu Ciorbaru [ 2016-12-01 ]

Fixed with:
4eb898bb1663ab470a07e8419de4aa14b5afc667

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