Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

cannot mark runaway query if most of the processing time on tidb side #51325

Closed
Tracked by #54434
nolouch opened this issue Feb 26, 2024 · 0 comments · Fixed by #54987
Closed
Tracked by #54434

cannot mark runaway query if most of the processing time on tidb side #51325

nolouch opened this issue Feb 26, 2024 · 0 comments · Fixed by #54987
Labels

Comments

@nolouch
Copy link
Member

nolouch commented Feb 26, 2024

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)


mysql> select * from information_schema.resource_groups;
+----------+------------+----------+-----------+----------------------------------+------------+
| NAME     | RU_PER_SEC | PRIORITY | BURSTABLE | QUERY_LIMIT                      | BACKGROUND |
+----------+------------+----------+-----------+----------------------------------+------------+
| default  | UNLIMITED  | MEDIUM   | YES       | NULL                             | NULL       |
| rg1      | 500        | MEDIUM   | NO        | EXEC_ELAPSED='10s', ACTION=KILL  | NULL       |
| rg2      | 500        | MEDIUM   | NO        | EXEC_ELAPSED='30s', ACTION=KILL  | NULL       |
| rg3      | 500        | MEDIUM   | NO        | EXEC_ELAPSED='1m0s', ACTION=KILL | NULL       |
+----------+------------+----------+-----------+----------------------------------+--------------


mysql> select count(*) from test.test1;
+----------+
| count(*) |
+----------+
| 10000000 |
+----------+
1 row in set (0.61 sec)

mysql> select count(*) from test.test2;
+----------+
| count(*) |
+----------+
| 10000000 |
+----------+
1 row in set (0.79 sec)


mysql> set resource group rg2;
mysql>  select count(*) from test.test1 t1, test.test2 t2;

2. What did you expect to see? (Required)

report error, the query will killed after 1m and the query will marked as runaway.

3. What did you see instead (Required)

no error, and the slow query info:

*************************** 1. row ***************************
                     INSTANCE: 172.20.12.53:10080
                         Time: 2024-02-26 10:06:02.496686
                 Txn_start_ts: 447981102749974535
                         User: root
                         Host: 172.20.12.53
                      Conn_ID: 750796370
                Session_alias:
             Exec_retry_count: 0
              Exec_retry_time: 0
                   Query_time: 874.752916407
                   Parse_time: 0.000144956
                 Compile_time: 0.000576323
                 Rewrite_time: 0.00019047
           Preproc_subqueries: 0
      Preproc_subqueries_time: 0
                Optimize_time: 0.000221586
                      Wait_TS: 0.000016797
                Prewrite_time: 0
    Wait_prewrite_binlog_time: 0
                  Commit_time: 0
           Get_commit_ts_time: 0
          Commit_backoff_time: 0
                Backoff_types:
            Resolve_lock_time: 0
        Local_latch_wait_time: 0
                   Write_keys: 0
                   Write_size: 0
              Prewrite_region: 0
                    Txn_retry: 0
                     Cop_time: 9.069416534
                 Process_time: 5.561180472
                    Wait_time: 0.039564512
                 Backoff_time: 0
                LockKeys_time: 0
                Request_count: 321
                   Total_keys: 10005441
                 Process_keys: 10005120
 Rocksdb_delete_skipped_count: 0
    Rocksdb_key_skipped_count: 10005120
Rocksdb_block_cache_hit_count: 19381
     Rocksdb_block_read_count: 28
      Rocksdb_block_read_byte: 2780646
                           DB: test
                  Index_names:
                  Is_internal: 0
                       Digest: 3836825468c0e3ab6ae83b8f3f2a9341e9b937565e740059b21ee0c4baab9a39
                        Stats: test2:447848644139024396[11000000;1000000],test1:447848644139024396[10000000;0]
                 Cop_proc_avg: 0.017324549
                 Cop_proc_p90: 0.028798486
                 Cop_proc_max: 0.064119483
                Cop_proc_addr: 172.20.12.52:20161
                 Cop_wait_avg: 0.000123253
                 Cop_wait_p90: 0.000157888
                 Cop_wait_max: 0.000777219
                Cop_wait_addr: 172.20.12.70:20161
                      Mem_max: 1563694950
                     Disk_max: 0
                     KV_total: 5.937441219
                     PD_total: 0.002410495
                Backoff_total: 0
     Write_sql_response_total: 0
                  Result_rows: 0
                     Warnings:
               Backoff_Detail:
                     Prepared: 0
                         Succ: 0
                IsExplicitTxn: 0
            IsWriteCacheTable: 0
              Plan_from_cache: 0
            Plan_from_binding: 0
             Has_more_results: 0
               Resource_group: rg1
            Request_unit_read: 6138.681872937518
           Request_unit_write: 0
            Time_queued_by_rc: 94.531057857
                         Plan: 	id                       	task     	estRows        	operator info                	actRows    	execution info                                                                                                                                                                                                                                                                                                                                                                                                                     	memory  	disk
	HashAgg_8                	root     	1              	funcs:count(1)->Column#7     	0          	time:14m34.7s, loops:1, partial_worker:{wall_time:14m34.747859099s, concurrency:5, task_num:20537108, tot_wait:37m8.750470668s, tot_exec:35m37.897897101s, tot_time:1h12m53.739014097s, max:14m34.747812638s, p95:14m34.747812638s}, final_worker:{wall_time:14m34.747870821s, concurrency:5, task_num:1, tot_wait:1h12m53.739021137s, tot_exec:20.085µs, tot_time:1h12m53.739060502s, max:14m34.747827344s, p95:14m34.747827344s}	165.3 KB	N/A
	└─HashJoin_11            	root     	110000000000000	CARTESIAN inner join         	21029998592	time:12m37.3s, loops:20537109, build_hash_table:{total:10s, fetch:9.04s, build:1.01s}                                                                                                                                                                                                                                                                                                                                              	1.46 GB 	0 Bytes
	  ├─TableReader_13(Build)	root     	10000000       	data:TableFullScan_12        	10000000   	time:9.05s, loops:9780, cop_task: {num: 305, max: 712.4ms, min: 740µs, avg: 328.1ms, p95: 655.1ms, max_proc_keys: 50144, p95_proc_keys: 50144, tot_proc: 5.54s, tot_wait: 34.1ms, rpc_num: 305, rpc_time: 1m40.1s, copr_cache_hit_ratio: 0.00, build_task_duration: 42.3µs, max_distsql_concurrency: 13}                                                                                                                         	2.30 MB 	N/A
	  │ └─TableFullScan_12   	cop[tikv]	10000000       	table:t1, keep order:false   	10000000   	tikv_task:{proc max:62ms, min:0s, avg: 17.4ms, p80:27ms, p95:29ms, iters:10977, tasks:305}, scan_detail: {total_process_keys: 10000000, total_process_keys_size: 270000000, total_keys: 10000305, get_snapshot_time: 16.7ms, rocksdb: {key_skipped_count: 10000000, block: {cache_hit_count: 19321}}}                                                                                                                              	N/A     	N/A
	  └─TableReader_15(Probe)	root     	11000000       	data:TableFullScan_14        	5120       	time:46.1ms, loops:5, cop_task: {num: 16, max: 44.3ms, min: 776.6µs, avg: 4.75ms, p95: 44.3ms, max_proc_keys: 480, p95_proc_keys: 480, tot_proc: 20.9ms, tot_wait: 5.5ms, rpc_num: 16, rpc_time: 75.7ms, copr_cache_hit_ratio: 0.00, build_task_duration: 2.59ms, max_distsql_concurrency: 10}                                                                                                                                    	69.0 KB 	N/A
	    └─TableFullScan_14   	cop[tikv]	11000000       	table:test2, keep order:false	5120       	tikv_task:{proc max:10ms, min:0s, avg: 1.19ms, p80:1ms, p95:10ms, iters:54, tasks:16}, scan_detail: {total_process_keys: 5120, total_process_keys_size: 138240, total_keys: 5136, get_snapshot_time: 4.88ms, rocksdb: {key_skipped_count: 5120, block: {cache_hit_count: 60, read_count: 28, read_byte: 2.65 MB, read_time: 11.4ms}}}                                                                                              	N/A     	N/A
                  Plan_digest: 74f124097a445931e9b79608e3ad390da42da617bdfd0700900e72807e19545d
                  Binary_plan: zRFICsgRCglIYXNoQWdnXzgS1Q0KCwEOeEpvaW5fMTESkAYKDlRhYmxlUmVhZGVyXzEzEosDChAFE/B9RnVsbFNjYW5fMTIhRUXixAFa4EEpAAAAANASY0EwgK3iBDgCQAJKDAoKCgR0ZXN0EgJ0MVIQa2VlcCBvcmRlcjpmYWxzZWqlAnRpa3ZfdGFzazp7cHJvYyBtYXg6NjJtcywgbWluOjBzLCBhdmc6IDE3LjRtcywgcDgwOjI3AR8UcDk1OjI5AQpkaXRlcnM6MTA5NzcsIHRhc2tzOjMwNX0sIHMBoXhkZXRhaWw6IHt0b3RhbF9wcm9jZXNzX2tleXM6IDEwCQEELCBGHgAgX3NpemU6IDI3CSMVJB06bDMwNSwgZ2V0X3NuYXBzaG90X3RpbWU6IDE2LjcBmmhyb2Nrc2RiOiB7a2V5X3NraXBwZWRfY291bnQufABAYmxvY2s6IHtjYWNoZV9oaXQVIyA5MzIxfX19cP8RAQQBeBEKMP8BGgEBISeOJPQieqY+fAEkAUABUhVkYXRhOj6uAQRaFgWjWDkuMDVzLCBsb29wczo5NzgwYpICY29wKYoYIHtudW06IAXeIZAMIDcxMil/WG1pbjogNzQwwrVzLCBhdmc6IDMyOC4xAewhkAwgNjU1CQ4IbWF4JWstLhQ1MDE0NCwBJEoWAAh0b3QFFhg6IDUuNTRzJYwgX3dhaXQ6IDM0CU8McnBjXxmUAQ4FxjggMW00MC4xcywgY29wcl85QCByYXRpbzogMC4htxBidWlsZAXaCF9kdQUaGG46IDQyLjMFxgGqbGRpc3RzcWxfY29uY3VycmVuY3k6IDEzfXDgo5MucgEEEqM+EwMINRKsRhMDIDQhmbLFi5v84SmXHBj7ZEEwgCg4YREMDwoNCmkRGAV0ZXN0MlJGFAMIxQJ0ShQDBDEwIWUhgAAwMXsIMS4xZQAMcDgwOjWDCShpEwg1NCxtEAQxNpIPAww1MTIwJX86KQMAX2kLEDEzODI0FSFpCAw1MTM2UgQDDDQuODgBs3IEAwlxYgADGDYwLCByZWF1MwQyOA0QCGJ5dGGbFC42NSBNQg0UTRIAMUGqajQDIAIhLGlb2Yy5qDadAWIyAwg0WhQFWgQ0NkmLaTMINWKJQjADCDE2LEFOFDogNDQuMwH7Ia4UIDc3Ni42RWplMAw0Ljc1ARxlLxUpNi4DCDQ4MEIsAwUUeSoIMjAuJfwBEmkrBDUuBVhhHGUqAY4BDQW9CCA3NYmSwigDCDIuNQVpAaNWJwMUMH1wkKgEnZgcIdX930+y5c4hYSw4u9cC2UIwgKDxq04lZFgUQ0FSVEVTSUFOIGlubmVyIGpvaW5aHQWmHDEybTM3LjNzkZgkMjA1MzcxMDliNmnDFGhhc2hfdMGSADqpzgQ6MWENEGZldGNogdKBPAUqVDoxLjAxc31w0tzB6QUhDSp0z4wzH0PFoAwAAPA/BYkYGGZ1bmNzOqWNMCgxKS0+Q29sdW1uIzetIhgxNG0zNC43FY1cMWKLA3BhcnRpYWxfd29ya2VyOnt3YWxsKWENLhw0Nzg1OTA5OYWSmUwANWmIAF8hmQ3VADhlaCm8NDM3bTguNzUwNDcwNjY4rQEYZXhlYzozNSESHDg5Nzg5NzEwgekh8SktOGgxMm01My43MzkwMTQwOQGqoa0ZigwxMjYzAU5Baz4WABR9LCBmaW56ywAMNzA4MgF0LhcFLssAADEdxC6PAAwyMTEzAY8IdG90CccUMjAuMDg1ZQUBFELAABQ2MDUwMnNpPhmqDDI3MzQh0zbAAAkWRH1whKoKeP///////////wEYAQ==
                    Prev_stmt:
                        Query: select count(*) from test.test1 t1, test.test2;
1 row in set (0.48 sec)

ERROR:
No query specified

4. What is your TiDB version? (Required)

@nolouch nolouch added type/bug The issue is confirmed as a bug. severity/major labels Feb 26, 2024
@nolouch nolouch changed the title cannot mark runaway query if most time proceed on tidb side cannot mark runaway query if most of the processing time o on tidb side Feb 26, 2024
@nolouch nolouch changed the title cannot mark runaway query if most of the processing time o on tidb side cannot mark runaway query if most of the processing time on tidb side Feb 26, 2024
@ti-chi-bot ti-chi-bot bot closed this as completed in d6dda3d Aug 12, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants