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.
{"report":{"fcp":899.7999999523163,"ttfb":142.29999995231628,"pageVisibility":"visible","entityId":59344,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":1,"journeyId":"51366c15-9bdf-47fe-ac7f-575d3c08d4d2","navigationType":0,"readyForUser":984.8999999761581,"redirectCount":0,"resourceLoadedEnd":1005.8999999761581,"resourceLoadedStart":147,"resourceTiming":[{"duration":64.39999997615814,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2bu7/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":147,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":147,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":211.39999997615814,"responseStart":0,"secureConnectionStart":0},{"duration":64.29999995231628,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2bu7/820016/12ta74/8679b4946efa1a0bb029a3a22206fb5d/_/download/contextbatch/css/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true","startTime":147.20000004768372,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":147.20000004768372,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":211.5,"responseStart":0,"secureConnectionStart":0},{"duration":261.90000009536743,"initiatorType":"script","name":"https://jira.mariadb.org/s/fbf975c0cce4b1abf04784eeae9ba1f4-CDN/lu2bu7/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":147.29999995231628,"connectEnd":147.29999995231628,"connectStart":147.29999995231628,"domainLookupEnd":147.29999995231628,"domainLookupStart":147.29999995231628,"fetchStart":147.29999995231628,"redirectEnd":0,"redirectStart":0,"requestStart":147.29999995231628,"responseEnd":409.2000000476837,"responseStart":409.2000000476837,"secureConnectionStart":147.29999995231628},{"duration":380.60000002384186,"initiatorType":"script","name":"https://jira.mariadb.org/s/099b33461394b8015fc36c0a4b96e19f-CDN/lu2bu7/820016/12ta74/8679b4946efa1a0bb029a3a22206fb5d/_/download/contextbatch/js/jira.browse.project,project.issue.navigator,jira.view.issue,jira.general,jira.global,atl.general,-_super/batch.js?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&locale=en&slack-enabled=true","startTime":151.79999995231628,"connectEnd":151.79999995231628,"connectStart":151.79999995231628,"domainLookupEnd":151.79999995231628,"domainLookupStart":151.79999995231628,"fetchStart":151.79999995231628,"redirectEnd":0,"redirectStart":0,"requestStart":151.79999995231628,"responseEnd":532.3999999761581,"responseStart":532.3999999761581,"secureConnectionStart":151.79999995231628},{"duration":384.39999997615814,"initiatorType":"script","name":"https://jira.mariadb.org/s/94c15bff32baef80f4096a08aceae8bc-CDN/lu2bu7/820016/12ta74/c92c0caa9a024ae85b0ebdbed7fb4bd7/_/download/contextbatch/js/atl.global,-_super/batch.js?locale=en","startTime":151.89999997615814,"connectEnd":151.89999997615814,"connectStart":151.89999997615814,"domainLookupEnd":151.89999997615814,"domainLookupStart":151.89999997615814,"fetchStart":151.89999997615814,"redirectEnd":0,"redirectStart":0,"requestStart":151.89999997615814,"responseEnd":536.2999999523163,"responseStart":536.2999999523163,"secureConnectionStart":151.89999997615814},{"duration":384.7999999523163,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-en/jira.webresources:calendar-en.js","startTime":152,"connectEnd":152,"connectStart":152,"domainLookupEnd":152,"domainLookupStart":152,"fetchStart":152,"redirectEnd":0,"redirectStart":0,"requestStart":152,"responseEnd":536.7999999523163,"responseStart":536.7999999523163,"secureConnectionStart":152},{"duration":385,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-localisation-moment/jira.webresources:calendar-localisation-moment.js","startTime":152.10000002384186,"connectEnd":152.10000002384186,"connectStart":152.10000002384186,"domainLookupEnd":152.10000002384186,"domainLookupStart":152.10000002384186,"fetchStart":152.10000002384186,"redirectEnd":0,"redirectStart":0,"requestStart":152.10000002384186,"responseEnd":537.1000000238419,"responseStart":537.1000000238419,"secureConnectionStart":152.10000002384186},{"duration":385.40000009536743,"initiatorType":"link","name":"https://jira.mariadb.org/s/b04b06a02d1959df322d9cded3aeecc1-CDN/lu2bu7/820016/12ta74/a2ff6aa845ffc9a1d22fe23d9ee791fc/_/download/contextbatch/css/jira.global.look-and-feel,-_super/batch.css","startTime":152.29999995231628,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":152.29999995231628,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":537.7000000476837,"responseStart":0,"secureConnectionStart":0},{"duration":385.2000000476837,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":152.39999997615814,"connectEnd":152.39999997615814,"connectStart":152.39999997615814,"domainLookupEnd":152.39999997615814,"domainLookupStart":152.39999997615814,"fetchStart":152.39999997615814,"redirectEnd":0,"redirectStart":0,"requestStart":152.39999997615814,"responseEnd":537.6000000238419,"responseStart":537.6000000238419,"secureConnectionStart":152.39999997615814},{"duration":385.5,"initiatorType":"link","name":"https://jira.mariadb.org/s/3ac36323ba5e4eb0af2aa7ac7211b4bb-CDN/lu2bu7/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/css/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.css?jira.create.linked.issue=true","startTime":152.5,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":152.5,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":538,"responseStart":0,"secureConnectionStart":0},{"duration":385.60000002384186,"initiatorType":"script","name":"https://jira.mariadb.org/s/3339d87fa2538a859872f2df449bf8d0-CDN/lu2bu7/820016/12ta74/d176f0986478cc64f24226b3d20c140d/_/download/contextbatch/js/com.atlassian.jira.projects.sidebar.init,-_super,-project.issue.navigator,-jira.view.issue/batch.js?jira.create.linked.issue=true&locale=en","startTime":152.60000002384186,"connectEnd":152.60000002384186,"connectStart":152.60000002384186,"domainLookupEnd":152.60000002384186,"domainLookupStart":152.60000002384186,"fetchStart":152.60000002384186,"redirectEnd":0,"redirectStart":0,"requestStart":152.60000002384186,"responseEnd":538.2000000476837,"responseStart":538.1000000238419,"secureConnectionStart":152.60000002384186},{"duration":492.39999997615814,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-js/jira.webresources:bigpipe-js.js","startTime":158.89999997615814,"connectEnd":158.89999997615814,"connectStart":158.89999997615814,"domainLookupEnd":158.89999997615814,"domainLookupStart":158.89999997615814,"fetchStart":158.89999997615814,"redirectEnd":0,"redirectStart":0,"requestStart":158.89999997615814,"responseEnd":651.2999999523163,"responseStart":651.2999999523163,"secureConnectionStart":158.89999997615814},{"duration":738.3000000715256,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2bu7/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-init/jira.webresources:bigpipe-init.js","startTime":163.89999997615814,"connectEnd":163.89999997615814,"connectStart":163.89999997615814,"domainLookupEnd":163.89999997615814,"domainLookupStart":163.89999997615814,"fetchStart":163.89999997615814,"redirectEnd":0,"redirectStart":0,"requestStart":163.89999997615814,"responseEnd":902.2000000476837,"responseStart":902.2000000476837,"secureConnectionStart":163.89999997615814},{"duration":89.19999992847443,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":562.7000000476837,"connectEnd":562.7000000476837,"connectStart":562.7000000476837,"domainLookupEnd":562.7000000476837,"domainLookupStart":562.7000000476837,"fetchStart":562.7000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":562.7000000476837,"responseEnd":651.8999999761581,"responseStart":651.8999999761581,"secureConnectionStart":562.7000000476837},{"duration":187.5,"initiatorType":"link","name":"https://jira.mariadb.org/s/d5715adaadd168a9002b108b2b039b50-CDN/lu2bu7/820016/12ta74/be4b45e9cec53099498fa61c8b7acba4/_/download/contextbatch/css/jira.project.sidebar,-_super,-project.issue.navigator,-jira.general,-jira.browse.project,-jira.view.issue,-jira.global,-atl.general,-com.atlassian.jira.projects.sidebar.init/batch.css?agile_global_admin_condition=true&jag=true&jira.create.linked.issue=true&slack-enabled=true","startTime":818.3999999761581,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":818.3999999761581,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":1005.8999999761581,"responseStart":0,"secureConnectionStart":0}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":4,"responseStart":143,"responseEnd":164,"domLoading":146,"domInteractive":1049,"domContentLoadedEventStart":1049,"domContentLoadedEventEnd":1096,"domComplete":1822,"loadEventStart":1822,"loadEventEnd":1823,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1027.8999999761581},{"name":"bigPipe.sidebar-id.end","time":1028.6000000238419},{"name":"bigPipe.activity-panel-pipe-id.start","time":1028.7999999523163},{"name":"bigPipe.activity-panel-pipe-id.end","time":1031.1000000238419},{"name":"activityTabFullyLoaded","time":1108.6000000238419}],"measures":[],"correlationId":"9c84a4d7fbb8e9","effectiveType":"4g","downlink":9.7,"rtt":0,"serverDuration":78,"dbReadsTimeInMs":9,"dbConnsTimeInMs":15,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}