[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包，可以在找到下載。
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.總結:
--//總結實在不知道什麼寫,以及當時的心情,我真心不明白開發做這樣的查詢為什麼,如何保證查詢資料一致性.
--//我們團隊的程式碼如何管理的,這樣的程式碼怎麼能提交到生產系統使用.
--//語句除了寫法存在問題外,應該放儲存過程之類的,採用批次處理方式,並且在服務端執行減少網路往返.
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/267265/viewspace-2850221/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 整潔的程式碼VS卓越的程式碼
- 最快的程式碼，是不執行的程式碼
- 程式程式碼裡的幽默精神
- 程式碼模板 | 我的程式碼沒有else
- 低程式碼和無程式碼的區別
- 《程式碼大全》程式碼生成
- 企業中的低程式碼與無程式碼
- 低程式碼和無程式碼的注意事項
- 程式碼·--四則運算的主要核心程式碼
- 什麼樣的程式碼才算是好程式碼
- shell替換程式裡的程式碼
- 程式的機器級程式碼表示
- 碼農深耕 - 什麼樣的程式碼才是好程式碼？
- 低程式碼VS無程式碼
- 生成驗證碼程式程式碼
- 我見過的最糟糕的程式程式碼
- 程式碼質量第 4 層 - 健壯的程式碼
- 程式碼質量第 2 層 - 可重用的程式碼
- 程式碼質量第 3 層 - 可讀的程式碼
- 什麼樣的程式碼稱得上是好程式碼？
- 程式碼的印象派：寫點好程式碼吧
- 快速程式碼展示之快速的例子程式碼片段(轉)
- Java普通程式碼塊，構造程式碼塊，靜態程式碼塊區別，執行順序的程式碼例項Java
- 如何閱讀他人的程式程式碼[轉]
- 五顏六色的程式碼：論程式碼的正確位置
- 你的程式碼或許漂亮，但我的程式碼能執行
- .Net Core——用程式碼寫程式碼？
- Flutter 程式碼混淆 混淆Dart程式碼FlutterDart
- 程式碼安全 兩種程式碼漏洞
- JNI：Java程式碼呼叫原生程式碼Java
- 好程式碼、壞程式碼之二
- 低程式碼優於無程式碼？
- 控制程式碼表篇——程式控制程式碼表
- 優雅的程式碼
- 這神奇的程式碼
- 常用的ＨＴＭＬ程式碼
- 拯救你的程式碼
- 寫程式碼的困惑