[20211217]滑稽可笑的程序代码2.txt
--//实在不知道如何取标题..感觉很无奈无语...
--//昨天上午快下班的时候我使用ashtop看等待事件，无意中发现生产系统的一条sql语句执行时间有点长，但是快下班没有仔细看，下
--//午又因为别的时间下班了才仔细看该sql语句,我实在无法表达我昨天当时的心情，开发怎么能这样写程序代码。
--//下面仔细展开分析，分析有点繁琐，主要记录我自己整个的分析过程：
1.环境：
xxxx1> @ 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.问题分析:
--//注语句很长，我仅仅显示where条件部分,原始代码很乱,而且我很佩服写代码的人很长的代码就一行没带换行的。我做了一些格式化
--//处理，里面还有7处标量子查询。
--//sql_id=367u7411u9krd.
SELECT *
FROM (SELECT ROWNUM AS NO
,A.ZYH WATENUMBER
,B.MZHM BRID
...
, (SELECT DMMC
FROM GY_XTPZ
WHERE DMLB = :"SYS_B_13"
AND PZBH = A.YZZT
AND DMSB <> :"SYS_B_14")
THESTATE
...
, :"SYS_B_21" RESERVE3
FROM EMR_YZB A, ZY_BRRY B
WHERE A.ZYH = B.ZYH
AND B.CYPB IN ( :"SYS_B_22", :"SYS_B_23")
AND ROWNUM < :"SYS_B_24")
WHERE NO >= :"SYS_B_25"
--//一看基本就知道是一个经典的翻页程序，EMR_YZB是医嘱表，看看绑定变量的值：
xxxx1> @ bind_cap 367u7411u9krd ''
SQL_ID CHILD_NUMBER WAS NAME POSITION MAX_LENGTH LAST_CAPTURED DATATYPE_STRING VALUE_STRING
------------- ------------ --- ---------- -------- ---------- ------------------- --------------- ------------
367u7411u9krd 0 YES :SYS_B_09 10 22 2021-12-17 02:00:35 NUMBER 301
YES :SYS_B_10 11 22 2021-12-17 02:00:35 NUMBER 0
YES :SYS_B_13 14 22 2021-12-17 02:00:35 NUMBER 302
YES :SYS_B_14 15 22 2021-12-17 02:00:35 NUMBER 0
YES :SYS_B_22 23 22 2021-12-17 02:00:35 NUMBER 0
YES :SYS_B_23 24 22 2021-12-17 02:00:35 NUMBER 1
YES :SYS_B_24 25 22 2021-12-17 02:00:35 NUMBER 794000
YES :SYS_B_25 26 22 2021-12-17 02:00:35 NUMBER 793000
8 rows selected.
--//查询B.CYPB in (0,1) 的相关数据，CYPB出院判别 0在院病人 1出院证明 2预结出院 8正常出院 9终结出院 99注销出院，也就是在
--//院病人的信息,有时候也需要了解一些业务信息。
--//我当时想那个用户有这么大的耐心在临晨时刻在电脑前翻页查询到794页，每次显示1000条。再仔细想想也许界面上有一个可以输入
--//查询页码的地方，再仔细看不对，查询里面没有order by，这样程序无法控制每次显示的一致性的，除非没人往表中输入数据，即使
--//没人做DML操作，每次显示也有可能出现不一致的,开发为什么这样写代码,在做什么,不理解?
--//参考链接：http://blog.itpub.net/267265/viewspace-2763181/=>[20210316]为什么刷新缓存后输出记录顺序发生变化.txt
--//看看awr记录这条语句的执行历史，我使用Tanel Poder的tpt scripts包，可以在https://tanelpoder.com/downloads/找到下载。
xxxx1> @awr/awr_sqlstats_per_exec.sql 367u7411u9krd % &100day
BEGIN_INTERVAL_TIME 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
------------------- ------------- --------------- ---------- --------------- --------------- ------------- ------------- -------------- --------------- ----------- --------------- --------------- ---------------
2021-11-08 00:00:26 367u7411u9krd 2094450556 305 446 444 1000.0 77152 0 1 1.9 0 0 0
2021-11-08 01:00:01 367u7411u9krd 2094450556 300 1516 1429 999.3 290537 146 86 0.6 0 0 0
2021-11-09 00:00:33 367u7411u9krd 2094450556 314 466 463 1000.0 79429 0 0 1.2 0 0 0
2021-11-09 01:00:35 367u7411u9krd 2094450556 274 1531 1442 999.3 290616 155 88 0.6 0 0 0
...
2021-12-14 00:00:14 367u7411u9krd 2094450556 301 419 418 1000.0 73341 0 0 1.6 0 0 0
2021-12-14 01:00:18 367u7411u9krd 2094450556 498 1702 1628 1000.0 338715 81 67 0.8 7 0 0
2021-12-14 02:00:21 367u7411u9krd 2094450556 143 2481 2476 994.1 510349 0 0 0.5 0 0 0
2021-12-15 00:00:42 367u7411u9krd 2094450556 302 430 428 1000.0 73566 0 0 1.5 0 0 0
2021-12-15 01:00:03 367u7411u9krd 2094450556 501 1726 1659 1000.0 338172 82 60 0.7 8 0 0
2021-12-15 02:00:08 367u7411u9krd 2094450556 133 2572 2566 994.5 508577 0 0 0.0 0 0 0
2021-12-16 00:00:12 367u7411u9krd 2094450556 317 460 458 1000.0 76692 0 1 3.7 0 0 0
2021-12-16 01:00:15 367u7411u9krd 2094450556 495 1864 1726 1000.0 346445 87 130 1.5 8 0 0
2021-12-16 02:00:18 367u7411u9krd 2094450556 106 2547 2541 993.2 507294 0 0 0.0 0 0 0
2021-12-17 00:00:39 367u7411u9krd 2094450556 305 431 429 1000.0 73006 0 0 1.4 0 0 0
2021-12-17 01:00:44 367u7411u9krd 2094450556 491 1720 1650 998.0 333590 85 63 0.7 7 0 0
2021-12-17 02:00:48 367u7411u9krd 2094450556 91 2496 2489 1010.3 496449 0 0 0.0 0 0 1
12 rows selected.
--//注: awr_sqlstats_per_exec.sql 名字有点长,我做了一个链接命名为sqlh.sql.
--//一看基本明白开发做什么，大约在每天的凌晨0点开始做这个操作(这里估计错误,应该在0:30上下)，每次取1000条，做操作，然后循
--//环反复。你可以看出一个特点，看ELA_MS_PER_EXEC列(单位是毫秒)，431->1720->2496(看日期2021-12-17)，对比CPU_MS_PER_EXEC列
--//基本可以判定主要消耗在CPU上,后面每次执行时间越来越大。每次的逻辑读也出现这样的规律，ROWS_PER_EXEC基本都是1000.
--//让我感觉奇怪的地方是为什么凌晨1-2点的执行次数(491)反而多过0-1的执行次数(305)，2点执行次数少是因为已经结束了.
--//我开始以为是和0点启动分析表之类的后台作业有关，我们维护团队讲分析时间修改到0点.
--//使用ashtop观察才发现，出现一个很奇怪的情况1点出现等待事件cell single block physical read。连续看了几天的情况都是如此
--//,前面的BLKRD_PER_EXEC列也说明类似的情况.
--//另外仔细看AVG_IOW_MS 列,0点的总是大于1点,也许真是后台的分析表造成这样的情况.
--//不过0点的执行次数少原因可以定位,该语句的FIRST_SEEN出现0:3X上下(看下面下划线内容),开始执行相对较快,这样我估计开发编程
--//是0:30分开始执行.这样就能解析得通0-1点的执行次数相对1点少的原因.还有出现cell single block physical read的时间段,我估
--//计当时数据缓存不足,EMR_YZB很大,在相似的时间段出现短暂的cell single block physical read也能找到合理的解析.
xxxx1> @dashtop trunc(sample_time,'hh24'),event sql_id='367u7411u9krd' trunc(sysdate-2) sysdate
Total
Seconds AAS %This TRUNC(SAMPLE_TIME,' EVENT FIRST_SEEN LAST_SEEN
--------- ------- ------- ------------------- ------------------------------------------ ------------------- -------------------
840 .0 23% 2021-12-16 01:00:00 2021-12-16 01:00:12 2021-12-16 01:59:33
830 .0 22% 2021-12-15 01:00:00 2021-12-15 01:00:17 2021-12-15 01:59:46
750 .0 20% 2021-12-17 01:00:00 2021-12-17 01:00:21 2021-12-17 01:59:51
310 .0 8% 2021-12-15 02:00:00 2021-12-15 02:00:07 2021-12-15 02:17:38
250 .0 7% 2021-12-16 02:00:00 2021-12-16 02:00:03 2021-12-16 02:14:02
250 .0 7% 2021-12-17 02:00:00 2021-12-17 02:00:22 2021-12-17 02:12:40
160 .0 4% 2021-12-16 00:00:00 2021-12-16 00:36:16 2021-12-16 00:58:41
130 .0 4% 2021-12-17 00:00:00 2021-12-17 00:33:23 2021-12-17 00:59:00
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
100 .0 3% 2021-12-15 00:00:00 2021-12-15 00:32:08 2021-12-15 00:59:46
30 .0 1% 2021-12-15 01:00:00 cell single block physical read 2021-12-15 01:04:20 2021-12-15 01:08:53
30 .0 1% 2021-12-17 01:00:00 cell single block physical read 2021-12-17 01:09:48 2021-12-17 01:11:39
10 .0 0% 2021-12-16 01:00:00 cell single block physical read 2021-12-16 01:09:39 2021-12-16 01:09:39
10 .0 0% 2021-12-16 01:00:00 gc cr grant 2-way 2021-12-16 01:07:48 2021-12-16 01:07:48
13 rows selected.
--//找到这台主机的machine,看看这段时间到底执行了什么？为了减少查询范围,加入条件session_id=14344.
xxxx1> @dashtop sql_id "MACHINE='ZDFW\DELL56' and to_char(sample_time,'hh24') in ('00','01','02') and session_id=14344" date'2021-12-17' "timestamp'2021-12-17 02:30:00'"
Total
Seconds AAS %This SQL_ID FIRST_SEEN LAST_SEEN
--------- ------- ------- ------------- ------------------- -------------------
1160 .1 98% 367u7411u9krd 2021-12-17 00:33:23 2021-12-17 02:12:40
20 .0 2% g8usxst7f41xb 2021-12-17 00:02:11 2021-12-17 00:03:22
2 rows selected.
--//能抓到的就这么2条。g8usxst7f41xb 的执行时间在367u7411u9krd之前，注意看FIRST_SEEN，LAST_SEEN。
--//是否可以从时间链条上推断该链接开始执行g8usxst7f41xb,然后367u7411u9krd.因为session_id不变.还是看看serial_num#是否一样.
xxxx1> @dashtop sql_id,SESSION_SERIAL# "MACHINE='ZDFW\DELL56' and to_char(sample_time,'hh24') in ('00','01','02') and session_id=14344" date'2021-12-17' "timestamp'2021-12-17 02:30:00'"
Total
Seconds AAS %This SQL_ID SESSION_SERIAL# FIRST_SEEN LAST_SEEN
--------- ------- ------- ------------- --------------- ------------------- -------------------
1160 .1 98% 367u7411u9krd 58605 2021-12-17 00:33:23 2021-12-17 02:12:40
20 .0 2% g8usxst7f41xb 58605 2021-12-17 00:02:11 2021-12-17 00:03:22
--//SESSION_SERIAL#不变，基本可以确定同一个会话执行的。中间有30分钟做什么，或者没有抓到。
xxxx1> @awr/sqlh g8usxst7f41xb % &100day
BEGIN_INTERVAL_TIME 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
------------------- ------------- --------------- ---------- --------------- --------------- ------------- ------------- -------------- --------------- ----------- --------------- --------------- ---------------
2021-11-21 00:00:06 g8usxst7f41xb 8177585 44 891 885 962.3 14224 2 1 0.7 0 0 0
2021-11-23 00:00:16 g8usxst7f41xb 8177585 44 883 878 963.0 14225 4 1 0.6 0 0 0
2021-11-24 00:00:49 g8usxst7f41xb 8177585 44 846 841 963.4 14224 4 2 1.0 0 0 0
2021-11-25 00:00:34 g8usxst7f41xb 8177585 44 869 865 961.4 14227 4 1 0.5 0 0 0
2021-11-26 00:00:10 g8usxst7f41xb 8177585 44 872 867 962.2 14225 4 1 0.5 0 0 0
2021-11-27 00:00:02 g8usxst7f41xb 8177585 44 822 818 962.5 14224 2 1 0.6 0 0 0
2021-11-29 00:00:43 g8usxst7f41xb 8177585 44 842 837 962.7 14231 3 2 1.1 0 0 0
2021-11-30 00:00:10 g8usxst7f41xb 3162016426 44 837 833 964.1 14235 2 1 0.6 0 0 0
2021-12-10 00:00:48 g8usxst7f41xb 3162016426 44 855 851 964.4 14231 3 1 0.6 0 0 0
9 rows selected.
--//再次佩服这位开发程序猿，比语句比前面的语句有一点点进步，写成了两行,还是一个分页查询程序，从执行时间上看与我要解决的
--//问题无关。注:实际上还是一行,因为我sqlplus设置的是set linesize 4000,真不知道这位开发那个学校毕业的.
--//sql_id=g8usxst7f41xb,在dba_hist_sqlstat视图中没有这段时间的记录,不过从前面BEGIN_INTERVAL_TIME还是可以看出在0点执行,
--//还可以发现一个规律每次执行44次,ROWS_PER_EXEC接近1000,程序又在翻页,这到底在做什么操作,无语..........
--//44*890 = 39160 ,大约39秒.前面dashtop查询2021-12-17-2021-12-17 02:30:00仅仅记录2次(20秒).
--//不展开分析这条语句了。
xxxx1> @awr/awr_sqlstats_per_exec.sql 367u7411u9krd % &1day
BEGIN_INTERVAL_TIME 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
------------------- ------------- --------------- ---------- --------------- --------------- ------------- ------------- -------------- --------------- ----------- --------------- --------------- ---------------
2021-12-17 00:00:39 367u7411u9krd 2094450556 305 431 429 1000.0 73006 0 0 1.4 0 0 0
2021-12-17 01:00:44 367u7411u9krd 2094450556 491 1720 1650 998.0 333590 85 63 0.7 7 0 0
2021-12-17 02:00:48 367u7411u9krd 2094450556 91 2496 2489 1010.3 496449 0 0 0.0 0 0 1
3 rows selected.
--//305*431 = 131455 =131秒
--//491*1720 = 844520 =845秒
--//91*2496 = 227136 =227秒
--//其他时间在做怎么,如果取1000条记录处理.每次处理一条,循环执行次数很多,我应该能看到内循环执行的sql语句.显然不是这样.
--//如果批量处理,这样每次执行能看到1次执行,如果处理很快,ash无法抓取倒是正常的.
--//难道还有另外的可能取出1000条,交给另外的机器处理数据吗?
--//我测试关闭statistics_level=typical,大约3秒传输完成(注意不是很精确).
--//3000*305 = 915000
--//915000+131455 = 1046455 ,1046 秒. (30分钟=1800秒).
--//看来只能使用10046跟踪看看.另外写blog以及脚本跟踪看看到底在做什么.
3.总结:
--//总结实在不知道什么写,以及当时的心情,我真心不明白开发做这样的查询为什么,如何保证查询数据一致性.
--//我们团队的代码如何管理的,这样的代码怎么能提交到生产系统使用.
--//语句除了写法存在问题外,应该放存储过程之类的,采用批量处理方式,并且在服务端执行减少网络往返.