Uploaded image for project: 'Percona Server'
  1. Percona Server
  2. PS-5442

Intermittent sql/log.cc:1479: bool Query_logger::slow_log_write(THD*, const char*, size_t): Assertion `thd->enable_slow_log && opt_slow_log' failed.

    Details

      Description

      On 5.7, innodb.percona_log_slow_innodb crashes intermittently on debug:

      [ 85%] innodb.percona_log_slow_innodb           w8 [ fail ]
              Test ended at 2019-02-26 18:33:43
      
      CURRENT_TEST: innodb.percona_log_slow_innodb
      mysqltest: At line 105: query 'SET @saved_slow_query_log = @@GLOBAL.slow_query_log' failed: 2006: MySQL server has gone away
      ...
      mysqld: /tmp/ps/sql/log.cc:1479: bool Query_logger::slow_log_write(THD*, const char*, size_t): Assertion `thd->enable_slow_log && opt_slow_log' failed.
      18:33:42 UTC - mysqld got signal 6 ;
      ...
      #7  0x00007f19e34d8412 in __GI___assert_fail (assertion=0x5610d6728d78 "thd->enable_slow_log && opt_slow_log", file=0x5610d6728542 "/tmp/ps/sql/log.cc", line=1479, function=0x5610d67294e0 <Query_logger::slow_log_write(THD*, char const*, unsigned long)::__PRETTY_FUNCTION__> "bool Query_logger::slow_log_write(THD*, const char*, size_t)") at assert.c:101
      #8  0x00005610d5b0c1e0 in Query_logger::slow_log_write (this=0x5610d7500680 <query_logger>, thd=0x7f19cac19000, query=0x7f19cac27030 "COMMIT", query_length=6) at /tmp/ps/sql/log.cc:1479
      #9  0x00005610d5b0d9b4 in log_slow_do (thd=0x7f19cac19000) at /tmp/ps/sql/log.cc:1993
      #10 0x00005610d5b0d9e4 in log_slow_statement (thd=0x7f19cac19000) at /tmp/ps/sql/log.cc:2000
      #11 0x00005610d5c22268 in dispatch_command (thd=0x7f19cac19000, com_data=0x7f19e5d37d80, command=COM_QUERY) at /tmp/ps/sql/sql_parse.cc:1978
      #12 0x00005610d5c1f9a0 in do_command (thd=0x7f19cac19000) at /tmp/ps/sql/sql_parse.cc:1053
      #13 0x00005610d5d6490a in handle_connection (arg=0x7f19d9a5c640) at /tmp/ps/sql/conn_handler/connection_handler_per_thread.cc:318
      #14 0x00005610d605e02c in pfs_spawn_thread (arg=0x7f19de7b8120) at /tmp/ps/storage/perfschema/pfs.cc:2190
      #15 0x00007f19e552f6db in start_thread (arg=0x7f19e5d38700) at pthread_create.c:463
      #16 0x00007f19e35c988f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

      Two things wrong with that assert:
      1) Two conditions tested through conjunction, no indication which part failed
      2) opt_slow_log test is racy with other threads updating this variable after the current thread has already made the decision to log

        Smart Checklist

          Attachments

            Activity

              People

              • Assignee:
                laurynas.biveinis Laurynas Biveinis
                Reporter:
                laurynas.biveinis Laurynas Biveinis
              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - Not Specified
                  Not Specified
                  Logged:
                  Time Spent - 37 minutes
                  37m