Uploaded image for project: 'Percona Server for MySQL'
  1. Percona Server for MySQL
  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

      Attachments

        Activity

          People

            laurynas.biveinis Laurynas Biveinis (Inactive)
            laurynas.biveinis Laurynas Biveinis (Inactive)
            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

                Smart Checklist