我要评论
[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;
- 站内搜索
发表评论