[20240409]为什么一条sql语句在实例2执行要慢的分析.txt

[20240409]为什么一条sql语句在实例2执行要慢的分析.txt

–//生产系统遇到一个奇怪现象,一条sql语句在实例2要比实例1慢很多,展开分析看看.

1.环境:

SYS@127.0.0.1:9014/ywdb> @ ver1

PORT_STRING                    VERSION        BANNER

—————————— ————– ——————————————————————————–

x86_64/Linux 2.4.xx            11.2.0.4.0     Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 – 64bit Production

2.问题展开:

SYS@127.0.0.1:9014/ywdb> @ sqlhh af4692qv1f56q 10/24

time unit : millisecond

BEGIN_INTERVAL_TIME    INST_ID SQL_ID        PLAN_HASH_VALUE EXECUTIONS ELA_MS_PER_EXEC CPU_MS_PER_EXEC ROWS_PER_EXEC LIOS_PER_EXEC BLKRD_PER_EXEC IOW_MS_PER_EXEC  AVG_IOW_MS CLW_MS_PER_EXEC APW_MS_PER_EXEC CCW_MS_PER_EXEC

——————- ———- ————- ————— ———- ————— ————— ————- ————- ————– ————— ———– ————— ————— —————

2024-04-09 00:00:19          1 af4692qv1f56q      1518780269          1               4               4           1.0           209              0               0         0.0               0               0               0

2024-04-09 00:00:19          2 af4692qv1f56q      1518780269          1            1968            1698           1.0           265              0               0         0.0               0               0               0

2024-04-09 01:00:24          1 af4692qv1f56q      1518780269          4               4               3           1.0           209              0               0         0.0               0               0               0

2024-04-09 01:00:24          2 af4692qv1f56q      1518780269          1            2097            2010           1.0           265              0               0         0.0               0               0               0

2024-04-09 02:00:06          1 af4692qv1f56q      1518780269          3               5               5           1.0           209              0               0         0.0               0               0               0

2024-04-09 02:00:06          2 af4692qv1f56q      1518780269          1            2095            1722           1.0           265              0               0         0.0               0               0               0

2024-04-09 03:00:18          1 af4692qv1f56q      1518780269          3               4               4           1.0           209              0               0         0.0               0               0               0

2024-04-09 03:00:18          2 af4692qv1f56q      1518780269          1            2022            1846           1.0           265              0               0         0.0               0               0               0

2024-04-09 04:00:05          1 af4692qv1f56q      1518780269          2               5               5           1.0           209              0               0         0.0               0               0               0

2024-04-09 04:00:05          2 af4692qv1f56q      1518780269          2            1007             998           1.0           237              0               0         0.0               0               0               0

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

2024-04-09 05:00:31          2 af4692qv1f56q      1518780269          5               4               3           1.0           209              0               0         0.0               0               0               0

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

2024-04-09 05:00:31          1 af4692qv1f56q      1518780269          1               4               3           1.0           209              0               0         0.0               0               0               0

2024-04-09 06:00:33          2 af4692qv1f56q      1518780269          3               4               3           1.0           209              0               0         0.0               0               0               0

2024-04-09 06:00:34          1 af4692qv1f56q      1518780269          2               3               3           1.0           209              0               0         0.0               0               0               0

2024-04-09 07:00:53          1 af4692qv1f56q      1518780269          2               4               4           1.0           209              0               0         0.0               0               0               0

2024-04-09 07:00:53          2 af4692qv1f56q      1518780269          3               4               3           1.0           209              0               0         0.0               0               0               0

2024-04-09 08:00:07          2 af4692qv1f56q      1518780269          3               5               4           1.0           209              0               0         0.0               0               0               0

2024-04-09 08:00:07          1 af4692qv1f56q      1518780269          2               4               4           1.0           209              0               0         0.0               0               0               0

18 rows selected.

–//可以发现一个特点,执行没有变化PLAN_HASH_VALUE=1518780269,实例2执行要有一点慢,也有执行快的时候,如果你仔细看就可以发现

–//这条sql语句执行次数很少.无论是实例1还是实例2.按照道理这类sql语句应该不会记录在dba_hist_sqlstat里面,可以推断,因为实例

–//2共享内存紧张,该语句经常被踢出共享池,导致执行出现硬分析导致的情况,而且每次硬分析时间还”很长”.

SYS@127.0.0.1:9014/ywdb> @ ashtop inst_id,module sql_id=’af4692qv1f56q’  &day  ”

    Total                                                                                                     Distinct Distinct    Distinct

  Seconds     AAS %This      INST_ID MODULE                         FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1

——— ——- ——- ———- —————————— ——————- ——————- ———- ——– ———–

      150      .0  100% |          2 httpd.exe                      2024-04-08 09:15:24 2024-04-09 04:25:32          1      150         150

–//仅仅实例2出现性能问题.

–//先看看是什么语句:

SYS@127.0.0.1:9014/ywdb> @ sqlid_fms af4692qv1f56q

C200

———————————————————————————————————————————

                SELECT D.constraint_type as CONSTRAINT_TYPE, C.COLUMN_NAME, C.position, D.r_constraint_name,

                E.table_name as table_ref, f.column_name as column_ref,

                C.table_name

        FROM ALL_CONS_COLUMNS C

        inner join ALL_constraints D on D.OWNER = C.OWNER and D.constraint_name = C.constraint_name

        left join ALL_constraints E on E.OWNER = D.r_OWNER and E.constraint_name = D.r_constraint_name

        left join ALL_cons_columns F on F.OWNER = E.OWNER and F.constraint_name = E.constraint_name and F.position = c.position

        WHERE C.OWNER = ‘PORTAL_HIS’

           and C.table_name = ‘DATA_EXCHANGE_FP’

           and D.constraint_type <> ‘P’

        order by d.constraint_name, c.position

–//多数情况这语句是递归调用执行的,这类语句里面的视图定义非常复杂,如果查看执行计划非常复杂.第1次分析时间长,不可避免的.

time unit : microsecond

SQL_ID        CHILD_NUMBER    INST_ID FIRST_LOAD_TIME                        BUFFER_GETS EXECUTIONS ELAPSED_TIME AVG_ELA_TIME PLAN_HASH_VALUE LIOS_PER_EXEC FORCE_MATCHING_SIGNATURE

————- ———— ———- ————————————– ———– ———- ———— ———— ————— ————- ————————

af4692qv1f56q            0          2 2024-03-29/10:25:38                           3400         16      2071474    129467.13      1518780269           213      3702873826194195448

af4692qv1f56q            0          1 2024-03-29/10:04:51                         131289        628      4634160      7379.24      1518780269           209      3702873826194195448

–//可以发现实例2记录的执行次数少(16次),可以推断该语句一直呆在实例1共享池中,而实例2经常被刷出共享池,导致实例2的执行出现硬分析.

–//如果仔细看sql语句的执行计划就知道,这条sql语句的执行计划非常复杂,可以参考链接:

–//https://blog.itpub.net/267265/viewspace-3008682/ => 20240311]sql_id=c8s65f1cuhcb1的优化.txt ,与这个例子有一些类似.

–//如何验证我的推断呢?

SYS@127.0.0.1:9014/ywdb> @ ashtop inst_id,event sql_id=’af4692qv1f56q’  &day  ”

    Total                                                                                                                 Distinct Distinct    Distinct

  Seconds     AAS %This      INST_ID EVENT                                      FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1

——— ——- ——- ———- —————————————— ——————- ——————- ———- ——– ———–

      148      .0  100% |          2                                            2024-04-08 09:25:30 2024-04-09 04:25:32          1      148         148

–//event记录为空,基本消耗CPU上,如果知道消耗集中在分析上呢?

–//最新的ashtop脚本加入了time_model_name,可以了解一些细节.

SYS@127.0.0.1:9014/ywdb> @ ashtop inst_id,time_model_name,time_model sql_id=’af4692qv1f56q’  &day  ”

    Total                                                                                                                                    Distinct Distinct    Distinct

  Seconds     AAS %This      INST_ID TIME_MODEL_NAME                                    TIME_MODEL FIRST_SEEN          LAST_SEEN           Execs Seen  Tstamps Execs Seen1

——— ——- ——- ———- ————————————————– ———- ——————- ——————- ———- ——– ———–

      148      .0  100% |          2 PARSE HARD_PARSE                                          144 2024-04-08 09:25:30 2024-04-09 04:25:32          1      148         148

–//很明显CPU的消耗集中在PARSE HARD_PARSE,注:我猜测PARSE表示软分析,HARD_PARSE是硬分析.

–//TIME_MODEL= 144 = 0x90

$ echo “obase=2;144” | bc -l

10010000

–//第4,7位为1,从0开始计数.

–//看看ashtop.sql脚本的其中一段:

    , CASE WHEN BITAND(time_model, POWER(2, 01)) = POWER(2, 01) THEN ‘DBTIME ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 02)) = POWER(2, 02) THEN ‘BACKGROUND ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 03)) = POWER(2, 03) THEN ‘CONNECTION_MGMT ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 04)) = POWER(2, 04) THEN ‘PARSE ‘  END

           ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

           ||CASE WHEN BITAND(time_model, POWER(2, 05)) = POWER(2, 05) THEN ‘FAILED_PARSE ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 06)) = POWER(2, 06) THEN ‘NOMEM_PARSE ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 07)) = POWER(2, 07) THEN ‘HARD_PARSE ‘  END

           ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

           ||CASE WHEN BITAND(time_model, POWER(2, 08)) = POWER(2, 08) THEN ‘NO_SHARERS_PARSE ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 09)) = POWER(2, 09) THEN ‘BIND_MISMATCH_PARSE ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 10)) = POWER(2, 10) THEN ‘SQL_EXECUTION ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 11)) = POWER(2, 11) THEN ‘PLSQL_EXECUTION ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 12)) = POWER(2, 12) THEN ‘PLSQL_RPC ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 13)) = POWER(2, 13) THEN ‘PLSQL_COMPILATION ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 14)) = POWER(2, 14) THEN ‘JAVA_EXECUTION ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 15)) = POWER(2, 15) THEN ‘BIND ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 16)) = POWER(2, 16) THEN ‘CURSOR_CLOSE ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 17)) = POWER(2, 17) THEN ‘SEQUENCE_LOAD ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 18)) = POWER(2, 18) THEN ‘INMEMORY_QUERY ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 19)) = POWER(2, 19) THEN ‘INMEMORY_POPULATE ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 20)) = POWER(2, 20) THEN ‘INMEMORY_PREPOPULATE ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 21)) = POWER(2, 21) THEN ‘INMEMORY_REPOPULATE ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 22)) = POWER(2, 22) THEN ‘INMEMORY_TREPOPULATE ‘  END

           ||CASE WHEN BITAND(time_model, POWER(2, 23)) = POWER(2, 23) THEN ‘TABLESPACE_ENCRYPTION ‘ END time_model_name

–//注意看下划线,cpu消耗集中在PARSE 以及HARD_PARSE上,这也验证我的判断.

3.继续:

–//按照链接https://blog.itpub.net/267265/viewspace-3008682/ => 20240311]sql_id=c8s65f1cuhcb1的优化.txt

–//应该还有优化空间,尝试看看,不行放弃!!

–//像这类硬分析很慢的sql语句如何解决呢,可以使用sql profile来控制减少分析时间.

–//参考 https://blog.itpub.net/267265/viewspace-2151428/=>[20180302]sql profile能减少分析时间吗?

–//注意如果你使用sql profile,一般情况下记录是一些统计信息,并不是执行计划的outline.

–//必须使用sql profile交换方法.

SYS@127.0.0.1:9014/ywdb> @ spsw af4692qv1f56q 0 af4692qv1f56q 0 ” true

PL/SQL procedure successfully completed.

=================================================================================================================================================

if drop or alter sql profile ,run :

execute dbms_sqltune.drop_sql_profile(name => ‘switch tuning af4692qv1f56q’)

execute dbms_sqltune.alter_sql_profile(name => ‘switch tuning af4692qv1f56q’,attribute_name=>’STATUS’,value=>’DISABLED’)

=================================================================================================================================================

–//先禁用sql profile

SYS@127.0.0.1:9014/ywdb> execute dbms_sqltune.alter_sql_profile(name => ‘switch tuning af4692qv1f56q’,attribute_name=>’STATUS’,value=>’DISABLED’)

PL/SQL procedure successfully completed.

$ cat aa.txt

alter session set current_schema=PORTAL_PPI;

alter session set statistics_level=all;

column COLUMN_REF format a20

        SELECt D.constraint_type as CONSTRAINT_TYPE, C.COLUMN_NAME, C.position, D.r_constraint_name,

                E.table_name as table_ref, f.column_name as column_ref,

                C.table_name

        FROM ALL_CONS_COLUMNS C

        inner join ALL_constraints D on D.OWNER = C.OWNER and D.constraint_name = C.constraint_name

        left join ALL_constraints E on E.OWNER = D.r_OWNER and E.constraint_name = D.r_constraint_name

        left join ALL_cons_columns F on F.OWNER = E.OWNER and F.constraint_name = E.constraint_name and F.position = c.position

        WHERE C.OWNER = ‘PORTAL_HIS’

           and C.table_name = ‘DATA_EXCHANGE_FP’

           and D.constraint_type <> ‘P’

        order by d.constraint_name, c.position;

alter session set current_schema=SYS ;

–//注:适当将SELECT换成小写,做小量修改.

SYS@127.0.0.1:9014/ywdb> @ aa.txt

Session altered.

Session altered.

C COLUMN_NAME            POSITION R_CONSTRAINT_NAME              TABLE_REF                      COLUMN_REF           TABLE_NAME

– ——————– ———- —————————— —————————— ——————– ———-

C NO                                                                                                                 DATA_EXCHANGE_FP

Elapsed: 00:00:02.30

Session altered.

–//可以发现第1次执行需要硬分析总是在2秒上下.

SYS@127.0.0.1:9014/ywdb> execute dbms_sqltune.alter_sql_profile(name => ‘switch tuning af4692qv1f56q’,attribute_name=>’STATUS’,value=>’ENABLED’)

PL/SQL procedure successfully completed.

–//适当修改aa.txt里面的sql语句,就是顺便找一个字符换成小写.我的测试依次将SELECT换成小写,这样sql profile依旧生效.

SYS@127.0.0.1:9014/ywdb> @ aa.txt

Session altered.

Session altered.

C COLUMN_NAME            POSITION R_CONSTRAINT_NAME              TABLE_REF                      COLUMN_REF           TABLE_NAME

– ——————– ———- —————————— —————————— ——————– ———-

C NO                                                                                                                 DATA_EXCHANGE_FP

Elapsed: 00:00:01.24

Session altered.

–//再次小量修改aa.txt

SYS@127.0.0.1:9014/ywdb> @ aa.txt

Session altered.

Session altered.

C COLUMN_NAME            POSITION R_CONSTRAINT_NAME              TABLE_REF                      COLUMN_REF           TABLE_NAME

– ——————– ———- —————————— —————————— ——————– ———-

C NO                                                                                                                 DATA_EXCHANGE_FP

Elapsed: 00:00:00.92

Session altered.

–//可以发现这样第一次执行的硬分析远比原来没有使用sql profile的时间小.

–//不做修改:

SYS@127.0.0.1:9014/ywdb> @ aa.txt

Session altered.

Session altered.

C COLUMN_NAME            POSITION R_CONSTRAINT_NAME              TABLE_REF                      COLUMN_REF           TABLE_NAME

– ——————– ———- —————————— —————————— ——————– ———-

C NO                                                                                                                 DATA_EXCHANGE_FP

Elapsed: 00:00:00.02

Session altered.

–//因为语句已经在共享池,做的是软分析,执行很快.

–//顺便说一下,该问题也许跟我最近设置一些会话设置cursor_sharing=exact有关,谓词存在to_char函数,并且大量语句使用文字变量.

–//等一段时间观察看看.

SYS@127.0.0.1:9014/ywdb> @ sqlhh af4692qv1f56q 4/24

time unit : millisecond

BEGIN_INTERVAL_TIME    INST_ID SQL_ID        PLAN_HASH_VALUE EXECUTIONS ELA_MS_PER_EXEC CPU_MS_PER_EXEC ROWS_PER_EXEC LIOS_PER_EXEC BLKRD_PER_EXEC IOW_MS_PER_EXEC  AVG_IOW_MS CLW_MS_PER_EXEC APW_MS_PER_EXEC CCW_MS_PER_EXEC

——————- ———- ————- ————— ———- ————— ————— ————- ————- ————– ————— ———– ————— ————— —————

2024-04-09 12:00:15          2 af4692qv1f56q      1518780269          1             790             765           1.0           265              0               0         0.0               0               0               0

2024-04-09 12:00:15          1 af4692qv1f56q      1518780269          1               5               5           1.0           209              0               0         0.0               0               0               0

2024-04-09 13:00:23          1 af4692qv1f56q      1518780269          1               4               4           1.0           209              0               0         0.0               0               0               0

2024-04-09 13:00:23          2 af4692qv1f56q      1518780269          1             773             641           1.0           265              0               0         0.0               0               0               0

2024-04-09 14:00:00          1 af4692qv1f56q      1518780269          2               4               5           1.0           209              0               0         0.0               0               0               0

2024-04-09 14:00:00          2 af4692qv1f56q      1518780269          1             884             875           1.0           307              0               0         0.0               0               0               0

6 rows selected.

–//下午观察,现在平均8XX毫秒,问题还是在实例2.

SYS@127.0.0.1:9014/ywdb> @ dashtop to_char(sample_time,’yyyymmdd’),time_model  sql_id=’af4692qv1f56q’ &100day

    Total

  Seconds     AAS %This   TO_CHAR  TIME_MODEL FIRST_SEEN          LAST_SEEN

——— ——- ——- ——– ———- ——————- ——————-

      180      .0   31%   20240408        144 2024-04-08 00:40:34 2024-04-08 23:18:10

      110      .0   19%   20240407        144 2024-04-07 13:33:56 2024-04-07 23:09:44

       90      .0   16%   20240329        144 2024-03-29 09:44:09 2024-03-29 23:48:32

       70      .0   12%   20240313        144 2024-03-13 10:04:45 2024-03-13 21:12:21

       30      .0    5%   20240401        144 2024-04-01 15:31:07 2024-04-01 16:44:27

       30      .0    5%   20240409        144 2024-04-09 00:09:17 2024-04-09 13:24:14

       20      .0    3%   20240311        144 2024-03-11 20:12:36 2024-03-11 21:53:53

       20      .0    3%   20240330        144 2024-03-30 00:48:52 2024-03-30 00:58:55

       10      .0    2%   20240331        144 2024-03-31 21:49:00 2024-03-31 21:49:00

       10      .0    2%   20240401       1024 2024-04-01 20:51:10 2024-04-01 20:51:10

       10      .0    2%   20240409       1024 2024-04-09 09:37:57 2024-04-09 09:37:57

11 rows selected.

4.附上sqlid_fms.sql脚本:

$ cat sqlid_fms.sql

— Copyright 2023 lfree. All rights reserved.

— Licensed under the Apache License, Version 2.0. See LICENSE.txt for terms and conditions.

——————————————————————————–



— File name:   sqlid_fms.sql

— Purpose:     query sql_id to find  force_matching_signature from gv$sql



— Author:      lfree



— Usage:

—     @ sqlid_fms.sql <sql_id>



——————————————————————————–

SELECT REPLACE (sql_fulltext, CHR (13), ”) c200

  FROM gv$sqlarea

 WHERE sql_id = ‘&&1’ AND ROWNUM = 1;

prompt

prompt time unit : microsecond

prompt

SELECT sql_id

     , child_number

     , inst_id

     , first_load_time

     , buffer_gets

     , executions

     , elapsed_time

     , ROUND (elapsed_time / nullif(executions, 0), 2) avg_ela_time

         , plan_hash_value, ROUND (buffer_gets / nullif(executions, 0), 2) lios_per_exec

         , force_matching_signature

  FROM gv$sql

 WHERE sql_id = ‘&&1’

 ORDER BY 4 DESC;

© 版权声明
THE END
支持一下吧
点赞5 分享
评论 抢沙发
头像
请文明发言!
提交
头像

昵称

取消
昵称表情代码快捷回复

    暂无评论内容