Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-10563

Crash during shutdown in Master_info_index::any_slave_sql_running (compiled with GCC v6)

Details

    • 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);

      Attachments

        Issue Links

          is caused by

          Bug - A problem which impairs or prevents the functions of the product. MDEV-6616 Server crashes in my_hash_first if shutdown is performed when FLUSH LOGS is running

          • Major - Major loss of function.
          • Closed
          is duplicated by

          Bug - A problem which impairs or prevents the functions of the product. MDEV-10612 main.shutdown failed in buildbot

          • Major - Major loss of function.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            cvicentiu Vicențiu Ciorbaru added a comment -

            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

            cvicentiu Vicențiu Ciorbaru added a comment - 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
            elenst Elena Stepanova added a comment -

            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)...

            elenst Elena Stepanova added a comment - 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)...
            serg Sergei Golubchik added a comment -

            ok to push

            serg Sergei Golubchik added a comment - ok to push
            cvicentiu Vicențiu Ciorbaru added a comment -

            Fixed with:
            4eb898bb1663ab470a07e8419de4aa14b5afc667

            cvicentiu Vicențiu Ciorbaru added a comment - Fixed with: 4eb898bb1663ab470a07e8419de4aa14b5afc667

            People

              cvicentiu Vicențiu Ciorbaru
              cvicentiu Vicențiu Ciorbaru
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.