适用范围

OCEANBASE V3.2.4

问题概述

在分析OB性能问题、正在执行的慢SQL时，发现有些SQL在PROCESSLIST中显示执行时间超过100秒，但gv$plan_cache_Plan_stat,gv$sql_audit中记录的执行时长不到1秒。

问题原因

processlist中的time只能说明会话活动时长(或者状态变化时长）,并不是当前SQL执行时长。

测试验证

1. 跑一个PLSQL块，循环执行一条SQL。

declare
c number;
begin
for i in 1..1000000
loop
select count(*) into c from dba_objects;
end loop;
end;
/

2. 通过processlist观察time列时长超过100秒

MySQL [oceanbase]> select 'slowsqltag', svr_ip,user,ifnull(sql_id,'') sql_id,round(avg(time)) avgtime ,round(max(time)) maxtime,count(*) cnt,trace_id,info  from oceanbase.__all_virtual_processlist where tenant>'sys' and sql_id<>'' and time>3 group by user,sql_id order by count(*) desc limit 20;
+------------+---------------+------+----------------------------------+---------+---------+------+-----------------------------------+------------------------------------------+
| slowsqltag | svr_ip        | user | sql_id                           | avgtime | maxtime | cnt  | trace_id                          | info                                     |
+------------+---------------+------+----------------------------------+---------+---------+------+-----------------------------------+------------------------------------------+
| slowsqltag | 192.168.56.36 | SYS  | 880229F50E62AE83EC40D623714EB2E1 |     206 |     206 |    1 | YB4285607B24-000614A1E2113FAC-0-0 | select count(0) from "SYS"."DBA_OBJECTS" |
+------------+---------------+------+----------------------------------+---------+---------+------+-----------------------------------+------------------------------------------+
1 row in set, 1 warning (0.033 sec)

3. 通过gv$plan_cache_Plan_stat查询SQL执行时长不到1秒

MySQL [oceanbase]> select * from gv$plan_cache_Plan_stat where sql_id='880229F50E62AE83EC40D623714EB2E1'\G
*************************** 1. row ***************************
            tenant_id: 1001
               svr_ip: 192.168.56.36
             svr_port: 2882
              plan_id: 835153
               sql_id: 880229F50E62AE83EC40D623714EB2E1
                 type: 1
    is_bind_sensitive: 0
        is_bind_aware: 0
                db_id: 1100611139403782
            statement: select count(?) from "SYS"."DBA_OBJECTS"
            query_sql: select count(0) from "SYS"."DBA_OBJECTS"
       special_params:
          param_infos: {1,0,0,-85,15},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-85,15},{1,0,0,-85,15},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-85,15},{1,0,0,-85,15},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-85,15},{1,0,0,-85,15},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-85,15},{1,0,0,-85,15},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-85,15},{1,0,0,-85,15},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-85,15},{1,0,0,-85,15},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-85,15},{1,0,0,-1,22},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,0},{1,0,0,-1,22},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,0},{1,0,0,-1,22},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,0},{1,0,0,-1,22},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,0},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,0},{1,0,0,-85,15},{1,0,0,-1,22},{1,0,0,-1,0},{1,0,0,-85,0},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,22},{1,0,0,-1,0}
             sys_vars: 45,46,2151677954,2,4,1,0,0,32,3,1,0,1,1,0,10485760,1,1,0,1,BINARY,BINARY,AL32UTF8,AL16UTF16,BYTE,FALSE,1,100,64,200,0,13,NULL,1,1,1,1,0
            plan_hash: 7593735243334499789
      first_load_time: 2024-06-18 14:36:11.910144
       schema_version: 1717579085905632
       merged_version: 225
     last_active_time: 2024-06-18 14:38:01.816915
         avg_exe_usec: 20952 <<<<20 ms
     slowest_exe_time: 2024-06-18 14:36:11.956071
     slowest_exe_usec: 165159
           slow_count: 0
            hit_count: 5206
            plan_size: 1171248
           executions: 5207
           disk_reads: 0
        direct_writes: 0
          buffer_gets: 479082
application_wait_time: 0
concurrency_wait_time: 0
    user_io_wait_time: 0
       rows_processed: 5207
         elapsed_time: 109099595
             cpu_time: 109099595
         large_querys: 0
 delayed_large_querys: 0
    delayed_px_querys: 0
      outline_version: 0
           outline_id: -1
         outline_data: /*+ BEGIN_OUTLINE_DATA LEADING(@"SEL$2" ("SYS.B"@"SEL$2" "A"@"SEL$2" )) USE_HASH(@"SEL$2" ("A"@"SEL$2" )) PQ_DISTRIBUTE(@"SEL$2" ("A"@"SEL$2" ) LOCAL LOCAL) FULL(@"SEL$2" "SYS.B"@"SEL$2") FULL(@"SEL$3" "SYS.ALL_VIRTUAL_TABLE_REAL_AGENT"@"SEL$3") LEADING(@"SEL$4" ("SYS.P"@"SEL$4" "SYS.T"@"SEL$4" )) USE_NL(@"SEL$4" ("SYS.T"@"SEL$4" )) PQ_DISTRIBUTE(@"SEL$4" ("SYS.T"@"SEL$4" ) LOCAL LOCAL) NO_USE_NL_MATERIALIZATION(@"SEL$4" ("SYS.T"@"SEL$4" )) FULL(@"SEL$4" "SYS.P"@"SEL$4") FULL(@"SEL$4" "SYS.T"@"SEL$4") LEADING(@"SEL$5" ("SYS.T"@"SEL$5" "SYS.P"@"SEL$5" )) USE_NL(@"SEL$5" ("SYS.P"@"SEL$5" )) PQ_DISTRIBUTE(@"SEL$5" ("SYS.P"@"SEL$5" ) LOCAL LOCAL) NO_USE_NL_MATERIALIZATION(@"SEL$5" ("SYS.P"@"SEL$5" )) FULL(@"SEL$5" "SYS.T"@"SEL$5") FULL(@"SEL$5" "SYS.P"@"SEL$5") LEADING(@"SEL$6" (("SYS.T"@"SEL$6" "SYS.P"@"SEL$6" )"SYS.SUBP"@"SEL$6" )) USE_NL(@"SEL$6" ("SYS.SUBP"@"SEL$6" )) PQ_DISTRIBUTE(@"SEL$6" ("SYS.SUBP"@"SEL$6" ) LOCAL LOCAL) NO_USE_NL_MATERIALIZATION(@"SEL$6" ("SYS.SUBP"@"SEL$6" )) USE_NL(@"SEL$6" ("SYS.P"@"SEL$6" )) PQ_DISTRIBUTE(@"SEL$6" ("SYS.P"@"SEL$6" ) LOCAL LOCAL) NO_USE_NL_MATERIALIZATION(@"SEL$6" ("SYS.P"@"SEL$6" )) FULL(@"SEL$6" "SYS.T"@"SEL$6") FULL(@"SEL$6" "SYS.P"@"SEL$6") FULL(@"SEL$6" "SYS.SUBP"@"SEL$6") LEADING(@"SEL$7" (("SYS.T"@"SEL$7" "SYS.P"@"SEL$7" )"SYS.DEF_SP"@"SEL$7" )) USE_NL(@"SEL$7" ("SYS.DEF_SP"@"SEL$7" )) PQ_DISTRIBUTE(@"SEL$7" ("SYS.DEF_SP"@"SEL$7" ) LOCAL LOCAL) NO_USE_NL_MATERIALIZATION(@"SEL$7" ("SYS.DEF_SP"@"SEL$7" )) USE_NL(@"SEL$7" ("SYS.P"@"SEL$7" )) PQ_DISTRIBUTE(@"SEL$7" ("SYS.P"@"SEL$7" ) LOCAL LOCAL) NO_USE_NL_MATERIALIZATION(@"SEL$7" ("SYS.P"@"SEL$7" )) FULL(@"SEL$7" "SYS.T"@"SEL$7") FULL(@"SEL$7" "SYS.P"@"SEL$7") FULL(@"SEL$7" "SYS.DEF_SP"@"SEL$7") LEADING(@"SEL$8" ((("SYS.T_MAIN"@"SEL$8" "SYS.T"@"SEL$8" )"SYS.P"@"SEL$8" )"SYS.SUBP"@"SEL$8" )) USE_NL(@"SEL$8" ("SYS.SUBP"@"SEL$8" )) PQ_DISTRIBUTE(@"SEL$8" ("SYS.SUBP"@"SEL$8" ) LOCAL LOCAL) NO_USE_NL_MATERIALIZATION(@"SEL$8" ("SYS.SUBP"@"SEL$8" )) USE_NL(@"SEL$8" ("SYS.P"@"SEL$8" )) PQ_DISTRIBUTE(@"SEL$8" ("SYS.P"@"SEL$8" ) LOCAL LOCAL) NO_USE_NL_MATERIALIZATION(@"SEL$8" ("SYS.P"@"SEL$8" )) USE_MERGE(@"SEL$8" ("SYS.T"@"SEL$8" )) PQ_DISTRIBUTE(@"SEL$8" ("SYS.T"@"SEL$8" ) LOCAL LOCAL) FULL(@"SEL$8" "SYS.T_MAIN"@"SEL$8") FULL(@"SEL$8" "SYS.T"@"SEL$8") FULL(@"SEL$8" "SYS.P"@"SEL$8") FULL(@"SEL$8" "SYS.SUBP"@"SEL$8") LEADING(@"SEL$9" ((("SYS.T_MAIN"@"SEL$9" "SYS.T"@"SEL$9" )"SYS.P"@"SEL$9" )"SYS.DEF_SP"@"SEL$9" )) USE_NL(@"SEL$9" ("SYS.DEF_SP"@"SEL$9" )) PQ_DISTRIBUTE(@"SEL$9" ("SYS.DEF_SP"@"SEL$9" ) LOCAL LOCAL) NO_USE_NL_MATERIALIZATION(@"SEL$9" ("SYS.DEF_SP"@"SEL$9" )) USE_NL(@"SEL$9" ("SYS.P"@"SEL$9" )) PQ_DISTRIBUTE(@"SEL$9" ("SYS.P"@"SEL$9" ) LOCAL LOCAL) NO_USE_NL_MATERIALIZATION(@"SEL$9" ("SYS.P"@"SEL$9" )) USE_MERGE(@"SEL$9" ("SYS.T"@"SEL$9" )) PQ_DISTRIBUTE(@"SEL$9" ("SYS.T"@"SEL$9" ) LOCAL LOCAL) FULL(@"SEL$9" "SYS.T_MAIN"@"SEL$9") FULL(@"SEL$9" "SYS.T"@"SEL$9") FULL(@"SEL$9" "SYS.P"@"SEL$9") FULL(@"SEL$9" "SYS.DEF_SP"@"SEL$9") FULL(@"SEL$10" "SYS.P"@"SEL$10") FULL(@"SEL$14" "SYS.R"@"SEL$14") FULL(@"SEL$16" "SYS.T"@"SEL$16") FULL(@"SEL$18" "SYS.ALL_VIRTUAL_SYNONYM_REAL_AGENT"@"SEL$18") FULL(@"SEL$19" "SYS.ALL_VIRTUAL_SEQUENCE_OBJECT_REAL_AGENT"@"SEL$19") FULL(@"SEL$20" "SYS.ALL_VIRTUAL_TYPE_REAL_AGENT"@"SEL$20") FULL(@"SEL$21" "SYS.ALL_VIRTUAL_OBJECT_TYPE_AGENT"@"SEL$21") FULL(@"SEL$22" "SYS.TS"@"SEL$22") FULL(@"SEL$23" "SYS.ALL_VIRTUAL_PACKAGE_SYS_AGENT"@"SEL$23") FULL(@"SEL$24" "SYS.ALL_VIRTUAL_ROUTINE_SYS_AGENT"@"SEL$24") FULL(@"SEL$25" "SYS.ALL_VIRTUAL_TENANT_TRIGGER_SYS_AGENT"@"SEL$25") LEADING(@"SEL$26" (("SYS.CST"@"SEL$26" "SYS.TBL"@"SEL$26" )"SYS.DB"@"SEL$26" )) USE_HASH(@"SEL$26" ("SYS.DB"@"SEL$26" )) PQ_DISTRIBUTE(@"SEL$26" ("SYS.DB"@"SEL$26" ) LOCAL LOCAL) USE_HASH(@"SEL$26" ("SYS.TBL"@"SEL$26" )) PQ_DISTRIBUTE(@"SEL$26" ("SYS.TBL"@"SEL$26" ) LOCAL LOCAL) FULL(@"SEL$26" "SYS.CST"@"SEL$26") FULL(@"SEL$26" "SYS.TBL"@"SEL$26") FULL(@"SEL$26" "SYS.DB"@"SEL$26") FULL(@"SEL$27" "SYS.ALL_VIRTUAL_CONTEXT_REAL_AGENT"@"SEL$27") END_OUTLINE_DATA*/
         acs_sel_info:
           table_scan: 1
            evolution: 0
       evo_executions: 0
         evo_cpu_time: 0
        timeout_count: 0
           ps_stmt_id: -1
               sessid: 0
          temp_tables:
           is_use_jit: 0
          object_type: SQL_PLAN
           hints_info:
     hints_all_worked: 1
         pl_schema_id: 0
is_batched_multi_stmt: 0
1 row in set (0.045 sec)

参考文档

无