[20211217]滑稽可笑的程序代码2.txt

[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.总结:
--//总结实在不知道什么写,以及当时的心情,我真心不明白开发做这样的查询为什么,如何保证查询数据一致性.
--//我们团队的代码如何管理的,这样的代码怎么能提交到生产系统使用.
--//语句除了写法存在问题外,应该放存储过程之类的,采用批量处理方式,并且在服务端执行减少网络往返.