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

Queries executed by event scheduler are written to slow log incorrectly or not written at all

    Details

    • Sprint:
      5.5.54

      Description

      Found on stackoverflow:
      http://stackoverflow.com/questions/41099516/huge-time-in-slow-query-log-mariadb

      Slow queries are not written to the slow log when they are executed via events.
      Queries not using indexes are written to the slow log (if the corresponding option is set), but the timestamp and query execution time are corrupt.

      Test case

      set @event_scheduler.save= @@global.event_scheduler;
      set @log_queries_not_using_indexes.save= @@global.log_queries_not_using_indexes;
      set @slow_query_log.save= @@global.slow_query_log;
       
      set global event_scheduler= on;
      set global slow_query_log= on;
      set global log_queries_not_using_indexes= on;
      --let $slowlog = `SELECT @@slow_query_log_file`
       
      create table t1 (i int);
      insert into t1 values (0),(0);
      create event ev on schedule at CURRENT_TIMESTAMP + INTERVAL 1 second do update t1 set i=1;
      sleep 2;
      --echo # 
      --echo # Queries not using indexes are logged, but time is off:
      --echo #
      --cat_file $slowlog
      --echo
       
      set global log_queries_not_using_indexes= off;
      set global long_query_time=0.2;
      set global event_scheduler=off;
      set global event_scheduler=on;
       
      --echo
      --echo #
      --echo # Slow queries are not logged at all:
      --echo #
      create event ev on schedule at CURRENT_TIMESTAMP + INTERVAL 1 second do update t1 set i=sleep(0.5);
      sleep 2;
      --cat_file $slowlog
      --echo
       
      drop table t1;
       
      set global event_scheduler= @event_scheduler.save;
      set global log_queries_not_using_indexes= @log_queries_not_using_indexes.save;
      set global slow_query_log= @slow_query_log.save;
      set global long_query_time= @@session.long_query_time;
      

      Log contents:

      /data/src/5.5-bug/sql/mysqld, Version: 5.5.54-MariaDB-debug (Source distribution). started with:
      Tcp port: 16000  Unix socket: /data/src/5.5-bug/mysql-test/var/tmp/mysqld.1.sock
      Time                 Id Command    Argument
      # Time: 571004 12:33:04
      # User@Host: root[root] @ localhost [localhost]
      # Thread_id: 4  Schema: test  QC_hit: No
      # Query_time: 11936127050132.482422  Lock_time: 0.002233  Rows_sent: 0  Rows_examined: 2
      use test;
      SET timestamp=11937608616784;
      update t1 set i=1;
      

      Only the first query was written, and Query_time and timestamp show huge values.

      Not reproducible on MySQL 5.5-5.7 – either it's been fixed there, or the problem was introduced in MariaDB.

        Attachments

          Activity

            People

            • Assignee:
              serg Sergei Golubchik
              Reporter:
              elenst Elena Stepanova
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: