Type:
Priority:
Resolution:
Fixed
ANALYZE FORMAT=JSON shows r_total_time_ms. This is the time spent executing the query. It doesn't include the time spent doing query optimization.
Here's an example: The query execution takes 30 seconds, and I've stopped it in the optimizer for 50 seconds:
MariaDB [j1]> analyze format=json select sleep(10) from t1 where a<=3;
| ANALYZE | {
"query_block": {
"select_id": 1,
"r_loops": 1,
"r_total_time_ms": 30056.17521,
"nested_loop": [
{
"table": {
"table_name": "t1",
"access_type": "ALL",
"r_loops": 1,
"rows": 1000,
"r_rows": 1000,
"r_table_time_ms": 9.739445325,
"r_other_time_ms": 30046.39758,
"filtered": 100,
"r_filtered": 0.3,
"attached_condition": "t1.a <= 3"
}
}
]
}
} |
1 row in set (1 min 20.511 sec)
Note the client show the query took 1 min 20 sec, while query_block.r_total_time_ms=20 sec.
In some cases, query optimization itself can take a while, so we should report that time as well.
Note
Starting from 10.9, there is SHOW ANALYZE FORMAT=JSON . It has r_query_time_in_progress_ms which counts the query execution time from the start of the query.
MariaDB [j1]> show analyze format=json for 6;
| {
"r_query_time_in_progress_ms": 60499,
"query_block": {
"select_id": 1,
"r_loops": 1,
"nested_loop": [
{
"table": {
"table_name": "t1",
"access_type": "ALL",
"r_loops": 1,
"rows": 1000,
"r_rows": 1,
"r_table_time_ms": 0.156016501,
"r_other_time_ms": 0,
"filtered": 100,
"r_filtered": 100,
"attached_condition": "t1.a <= 3"
}
}
]
}
} |
Let's define "query optimization time" as the time spent between the calls to Explain_query::Explain_query() and Explain_query::query_plan_ready() .
Time can be tracked by using an Exec_time_tracker object. Make it a member of Explain_query.
Do not track the time if the statement is not an ANALYZE statement (like it's done in other counters).
JSON to be emitted:
"query_optimization": { "r_total_time_ms": NNNN.NNN }
{"report":{"fcp":994.7000000476837,"ttfb":277.30000019073486,"pageVisibility":"visible","entityId":112156,"key":"jira.project.issue.view-issue","isInitial":true,"threshold":1000,"elementTimings":{},"userDeviceMemory":8,"userDeviceProcessors":64,"apdex":0.5,"journeyId":"7b5795b4-ea4b-4e19-ad04-bc781b949560","navigationType":0,"readyForUser":1083.4000000953674,"redirectCount":0,"resourceLoadedEnd":774.6000001430511,"resourceLoadedStart":283.30000019073486,"resourceTiming":[{"duration":167.5,"initiatorType":"link","name":"https://jira.mariadb.org/s/2c21342762a6a02add1c328bed317ffd-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/css/_super/batch.css","startTime":283.30000019073486,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":283.30000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":450.80000019073486,"responseStart":0,"secureConnectionStart":0},{"duration":167.5,"initiatorType":"link","name":"https://jira.mariadb.org/s/7ebd35e77e471bc30ff0eba799ebc151-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/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&whisper-enabled=true","startTime":283.60000014305115,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":283.60000014305115,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":451.10000014305115,"responseStart":0,"secureConnectionStart":0},{"duration":196.39999985694885,"initiatorType":"script","name":"https://jira.mariadb.org/s/0917945aaa57108d00c5076fea35e069-CDN/lu2cib/820016/12ta74/0a8bac35585be7fc6c9cc5a0464cd4cf/_/download/contextbatch/js/_super/batch.js?locale=en","startTime":283.80000019073486,"connectEnd":283.80000019073486,"connectStart":283.80000019073486,"domainLookupEnd":283.80000019073486,"domainLookupStart":283.80000019073486,"fetchStart":283.80000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":283.80000019073486,"responseEnd":480.2000000476837,"responseStart":480.2000000476837,"secureConnectionStart":283.80000019073486},{"duration":257.5,"initiatorType":"script","name":"https://jira.mariadb.org/s/2d8175ec2fa4c816e8023260bd8c1786-CDN/lu2cib/820016/12ta74/494e4c556ecbb29f90a3d3b4f09cb99c/_/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&whisper-enabled=true","startTime":283.90000009536743,"connectEnd":283.90000009536743,"connectStart":283.90000009536743,"domainLookupEnd":283.90000009536743,"domainLookupStart":283.90000009536743,"fetchStart":283.90000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":283.90000009536743,"responseEnd":541.4000000953674,"responseStart":541.4000000953674,"secureConnectionStart":283.90000009536743},{"duration":261.2000000476837,"initiatorType":"script","name":"https://jira.mariadb.org/s/a9324d6758d385eb45c462685ad88f1d-CDN/lu2cib/820016/12ta74/c92c0caa9a024ae85b0ebdbed7fb4bd7/_/download/contextbatch/js/atl.global,-_super/batch.js?locale=en","startTime":284.2000000476837,"connectEnd":284.2000000476837,"connectStart":284.2000000476837,"domainLookupEnd":284.2000000476837,"domainLookupStart":284.2000000476837,"fetchStart":284.2000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":284.2000000476837,"responseEnd":545.4000000953674,"responseStart":545.4000000953674,"secureConnectionStart":284.2000000476837},{"duration":261.40000009536743,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-en/jira.webresources:calendar-en.js","startTime":284.40000009536743,"connectEnd":284.40000009536743,"connectStart":284.40000009536743,"domainLookupEnd":284.40000009536743,"domainLookupStart":284.40000009536743,"fetchStart":284.40000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":284.40000009536743,"responseEnd":545.8000001907349,"responseStart":545.8000001907349,"secureConnectionStart":284.40000009536743},{"duration":261.80000019073486,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:calendar-localisation-moment/jira.webresources:calendar-localisation-moment.js","startTime":284.5,"connectEnd":284.5,"connectStart":284.5,"domainLookupEnd":284.5,"domainLookupStart":284.5,"fetchStart":284.5,"redirectEnd":0,"redirectStart":0,"requestStart":284.5,"responseEnd":546.3000001907349,"responseStart":546.3000001907349,"secureConnectionStart":284.5},{"duration":339.90000009536743,"initiatorType":"link","name":"https://jira.mariadb.org/s/b04b06a02d1959df322d9cded3aeecc1-CDN/lu2cib/820016/12ta74/a2ff6aa845ffc9a1d22fe23d9ee791fc/_/download/contextbatch/css/jira.global.look-and-feel,-_super/batch.css","startTime":284.7000000476837,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":284.7000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":624.6000001430511,"responseStart":0,"secureConnectionStart":0},{"duration":262,"initiatorType":"script","name":"https://jira.mariadb.org/rest/api/1.0/shortcuts/820016/47140b6e0a9bc2e4913da06536125810/shortcuts.js?context=issuenavigation&context=issueaction","startTime":284.80000019073486,"connectEnd":284.80000019073486,"connectStart":284.80000019073486,"domainLookupEnd":284.80000019073486,"domainLookupStart":284.80000019073486,"fetchStart":284.80000019073486,"redirectEnd":0,"redirectStart":0,"requestStart":284.80000019073486,"responseEnd":546.8000001907349,"responseStart":546.8000001907349,"secureConnectionStart":284.80000019073486},{"duration":339.80000019073486,"initiatorType":"link","name":"https://jira.mariadb.org/s/3ac36323ba5e4eb0af2aa7ac7211b4bb-CDN/lu2cib/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":285,"connectEnd":0,"connectStart":0,"domainLookupEnd":0,"domainLookupStart":0,"fetchStart":285,"redirectEnd":0,"redirectStart":0,"requestStart":0,"responseEnd":624.8000001907349,"responseStart":0,"secureConnectionStart":0},{"duration":262.2000000476837,"initiatorType":"script","name":"https://jira.mariadb.org/s/5d5e8fe91fbc506585e83ea3b62ccc4b-CDN/lu2cib/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":285.2000000476837,"connectEnd":285.2000000476837,"connectStart":285.2000000476837,"domainLookupEnd":285.2000000476837,"domainLookupStart":285.2000000476837,"fetchStart":285.2000000476837,"redirectEnd":0,"redirectStart":0,"requestStart":285.2000000476837,"responseEnd":547.4000000953674,"responseStart":547.4000000953674,"secureConnectionStart":285.2000000476837},{"duration":404.59999990463257,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-js/jira.webresources:bigpipe-js.js","startTime":286.40000009536743,"connectEnd":286.40000009536743,"connectStart":286.40000009536743,"domainLookupEnd":286.40000009536743,"domainLookupStart":286.40000009536743,"fetchStart":286.40000009536743,"redirectEnd":0,"redirectStart":0,"requestStart":286.40000009536743,"responseEnd":691,"responseStart":691,"secureConnectionStart":286.40000009536743},{"duration":488.10000014305115,"initiatorType":"script","name":"https://jira.mariadb.org/s/d41d8cd98f00b204e9800998ecf8427e-CDN/lu2cib/820016/12ta74/1.0/_/download/batch/jira.webresources:bigpipe-init/jira.webresources:bigpipe-init.js","startTime":286.5,"connectEnd":286.5,"connectStart":286.5,"domainLookupEnd":286.5,"domainLookupStart":286.5,"fetchStart":286.5,"redirectEnd":0,"redirectStart":0,"requestStart":286.5,"responseEnd":774.6000001430511,"responseStart":774.6000001430511,"secureConnectionStart":286.5},{"duration":66.89999985694885,"initiatorType":"xmlhttprequest","name":"https://jira.mariadb.org/rest/webResources/1.0/resources","startTime":637.6000001430511,"connectEnd":637.6000001430511,"connectStart":637.6000001430511,"domainLookupEnd":637.6000001430511,"domainLookupStart":637.6000001430511,"fetchStart":637.6000001430511,"redirectEnd":0,"redirectStart":0,"requestStart":637.6000001430511,"responseEnd":704.5,"responseStart":704.5,"secureConnectionStart":637.6000001430511}],"fetchStart":0,"domainLookupStart":0,"domainLookupEnd":0,"connectStart":0,"connectEnd":0,"requestStart":111,"responseStart":277,"responseEnd":278,"domLoading":280,"domInteractive":1145,"domContentLoadedEventStart":1145,"domContentLoadedEventEnd":1195,"domComplete":2769,"loadEventStart":2769,"loadEventEnd":2770,"userAgent":"Mozilla/5.0 AppleWebKit/537.36 (KHTML, like Gecko; compatible; ClaudeBot/1.0; +claudebot@anthropic.com)","marks":[{"name":"bigPipe.sidebar-id.start","time":1125.6000001430511},{"name":"bigPipe.sidebar-id.end","time":1126.5},{"name":"bigPipe.activity-panel-pipe-id.start","time":1126.7000000476837},{"name":"bigPipe.activity-panel-pipe-id.end","time":1129.3000001907349},{"name":"activityTabFullyLoaded","time":1207.2000000476837}],"measures":[],"correlationId":"abe2ce90652ecc","effectiveType":"4g","downlink":9.6,"rtt":0,"serverDuration":96,"dbReadsTimeInMs":12,"dbConnsTimeInMs":21,"applicationHash":"9d11dbea5f4be3d4cc21f03a88dd11d8c8687422","experiments":[]}}
Task
Critical
MDEV-29572 Time reported as spent in optimizer exceeds total query time
