[20200422]最佳化的困惑9.txt
[20200422]最佳化的困惑9.txt
1.環境：
--//生產系統一條語句最佳化：
SYS@aaa.bbb.ccc.ddd:1521/xxxx> @ 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@aaa.bbb.ccc.ddd:1521/xxxx> @ bind_cap 0pv15fhky1mbp ''
C200
---------------------------------------------------------------------------------------------------------------------------
select * from yf_zyfymx a ,gy_ksdm b ,yk_typk c ,yk_cddz d , zy_fyfs e ,gy_ygdm f , zy_bqyz g ,yk_ypsx h,yf_fyjl,zy_brry i
where a.yfsb in (3,6,168,202)
and a.lybq = b.ksdm(+)
and a.ypxh=c.ypxh(+)
and a.ypcd = d.ypcd(+)
and a.fyfs = e.fyfs(+)
and yf_fyjl.fygh = f.ygdm(+)
and a.yzxh = g.jlxh(+)
and c.ypsx = h.ypsx(+)
and a.jlid = yf_fyjl.jlid
and a.zyh = i.zyh
and a.jfrq >=:V00001
and a.jfrq <=:V00002 and a.yfsb =:V00003
--//注：我遮蔽了select的輸出，不然太長。因為前面有條件a.yfsb in (3,6,168,202)，引數:V00003僅僅有4個值，其它查詢沒有意義。
SQL_ID CHILD_NUMBER WAS NAME POSITION MAX_LENGTH LAST_CAPTURED DATATYPE_STRING VALUE_STRING
------------- ------------ --- ------- -------- ---------- ------------------- --------------- -------------------
0pv15fhky1mbp 1 YES :V00001 1 7 2020-04-15 11:03:16 DATE 2020/04/15 10:40:00
YES :V00002 2 7 2020-04-15 11:03:16 DATE 2020/04/15 11:10:00
YES :V00003 3 32 2020-04-15 11:03:16 VARCHAR2(32) 3
--//:V00003型別不一致，當然不存在隱式轉換。
SELECT a.yfsb, COUNT (*)
FROM yf_zyfymx a
WHERE a.yfsb IN (3
,6
,168
,202)
AND a.jfrq >= :V00001
AND a.jfrq <= :V00002
GROUP BY a.yfsb
--//:V00001='2020/4/20' :V00002='2020/4/21'
yfsb COUNT (*)
---- ----------
168 246
3 16006
-------------
16252
--//很明顯先判斷一下是否有記錄再執行不是更好，無語!!這樣的開發。
SYS@aaa.bbb.ccc.ddd:1521/xxxx> @ sqlh 0pv15fhky1mbp 47815
SNAP_ID BEGIN_INTERVAL_TIME END_INTERVAL_TIME ELAPSED_TIME_DELTA CPU_TIME_DELTA EXECUTIONS_DELTA EXECUTIONS_TOTAL ROWS_PROCESSED_DELTA
---------- ------------------------ ------------------------ ------------------ -------------- ---------------- ---------------- --------------------
47815 2020-04-11 22:00:33.205 2020-04-11 23:00:11.171 77305614 76502443 10148 3471387 0
47816 2020-04-11 23:00:11.171 2020-04-12 00:00:33.554 78762529 77146263 9772 3481159 77265
&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&&
47817 2020-04-12 00:00:33.554 2020-04-12 01:00:55.316 79698729 78911938 10244 3491403 0
47818 2020-04-12 01:00:55.316 2020-04-12 02:00:02.557 77782026 76700327 10040 3501443 0
47819 2020-04-12 02:00:02.557 2020-04-12 03:00:11.449 78392037 77706131 10284 3511727 0
47820 2020-04-12 03:00:11.449 2020-04-12 04:00:04.897 77951636 77013260 10256 3521983 0
47821 2020-04-12 04:00:04.897 2020-04-12 05:00:26.140 79284005 78441221 10315 3532298 0
47822 2020-04-12 05:00:26.140 2020-04-12 06:00:33.121 75621658 74918675 10316 3542615 0
47823 2020-04-12 06:00:33.121 2020-04-12 07:00:14.794 76024490 75267525 10204 3552819 0
47824 2020-04-12 07:00:14.794 2020-04-12 08:00:40.550 78478204 77405210 10288 3563107 0
47825 2020-04-12 08:00:40.550 2020-04-12 09:00:03.609 71477866 70448285 7368 3570475 311456
47826 2020-04-12 09:00:03.609 2020-04-12 10:00:29.058 75565743 74416741 7316 3577791 247379
47827 2020-04-12 10:00:29.058 2020-04-12 11:00:05.131 54699291 54021800 3723 3581514 896001
47828 2020-04-12 11:00:05.131 2020-04-12 12:00:13.032 56923578 56115482 3770 3585284 971092
47829 2020-04-12 12:00:13.032 2020-04-12 13:00:19.053 66883283 65913008 7243 3592527 484604
47830 2020-04-12 13:00:19.053 2020-04-12 14:00:02.974 77323469 76399481 10152 3602679 0
47831 2020-04-12 14:00:02.974 2020-04-12 15:00:25.524 62687385 62025504 6788 3609467 573251
47832 2020-04-12 15:00:25.524 2020-04-12 16:00:39.410 54376940 53754789 4309 3613776 872211
47833 2020-04-12 16:00:39.410 2020-04-12 17:00:11.224 74709067 73850647 8035 3621811 186361
47834 2020-04-12 17:00:11.224 2020-04-12 18:00:34.592 79454220 78601120 8408 3630219 156722
47835 2020-04-12 18:00:34.592 2020-04-12 19:00:57.794 79709597 78668081 9856 3640075 24733
47836 2020-04-12 19:00:57.794 2020-04-12 20:00:05.229 77679974 76605261 10036 3650111 0
47837 2020-04-12 20:00:05.229 2020-04-12 21:00:12.091 78478535 77334332 10212 3660323 0
47838 2020-04-12 21:00:12.091 2020-04-12 22:00:06.550 77915975 77098351 10180 3670503 0
47839 2020-04-12 22:00:06.550 2020-04-12 23:00:24.720 78337885 77504187 10260 3680763 0
47840 2020-04-12 23:00:24.720 2020-04-13 00:00:32.607 76569619 75435638 9712 3690475 88086
47841 2020-04-13 00:00:32.607 2020-04-13 01:00:16.075 77560589 76732269 10156 3700631 0
47842 2020-04-13 01:00:16.075 2020-04-13 02:00:39.514 78160623 77193285 10288 3710919 0
47843 2020-04-13 02:00:39.514 2020-04-13 03:00:01.429 76569806 75558571 10164 3721083 0
47844 2020-04-13 03:00:01.429 2020-04-13 04:00:25.450 77262567 76407464 10352 3731435 0
47845 2020-04-13 04:00:25.450 2020-04-13 05:00:05.978 75981865 75228525 10244 3741679 0
47846 2020-04-13 05:00:05.978 2020-04-13 06:00:11.718 76143971 75326497 10320 3751999 0
47847 2020-04-13 06:00:11.718 2020-04-13 07:00:17.928 76246463 75361499 10308 3762307 0
47848 2020-04-13 07:00:17.928 2020-04-13 08:00:25.242 78490760 77512139 10248 3772555 0
47855 2020-04-13 14:00:01.435 2020-04-13 15:00:07.140 54149061 53527948 5161 3799025 623722
47859 2020-04-13 18:00:25.749 2020-04-13 19:00:18.455 76528305 75133560 8432 3823108 70867
47860 2020-04-13 19:00:18.455 2020-04-13 20:00:40.796 80899369 79554844 10256 3833364 0
47861 2020-04-13 20:00:40.796 2020-04-13 21:00:05.055 78852603 77844112 10092 3843456 0
47862 2020-04-13 21:00:05.055 2020-04-13 22:00:28.237 78983338 78134077 10288 3853744 0
47863 2020-04-13 22:00:28.237 2020-04-13 23:00:51.579 79394076 78499021 10240 3863984 0
47864 2020-04-13 23:00:51.579 2020-04-14 00:00:05.458 78122714 76913323 9508 3873492 93354
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
47865 2020-04-14 00:00:05.458 2020-04-14 01:00:11.595 79517395 78623065 10176 3883668 0
47866 2020-04-14 01:00:11.595 2020-04-14 02:00:02.545 79332367 78198129 10148 3893816 0
47867 2020-04-14 02:00:02.545 2020-04-14 03:00:25.675 79285749 78342053 10292 3904108 0
47868 2020-04-14 03:00:25.675 2020-04-14 04:00:33.929 78827499 77876098 10260 3914368 0
47869 2020-04-14 04:00:33.929 2020-04-14 05:00:12.936 77876738 77011275 10192 3924560 0
47870 2020-04-14 05:00:12.936 2020-04-14 06:00:35.252 76343115 75591573 10364 3934924 0
47871 2020-04-14 06:00:35.252 2020-04-14 07:00:53.471 76432578 75506602 10340 3945264 0
47872 2020-04-14 07:00:53.471 2020-04-14 08:00:22.150 77639049 76855340 10015 3955279 372
49 rows selected.
--//你可以發現這個又是一個經典的刷屏語句。可以發現非業務時間的ROWS_PROCESSED_DELTA=0,而執行次數可以達到10XXX，達到1秒執行3次，而在業務時間由於有
--//資料輸出這樣執行次數有所減少。看到這樣的語句真心無語，這麼頻繁的執行有用嗎？減少到5秒甚至10秒1次，對業務有影響嗎？
--//我順便執行select * from GV$OPEN_CURSOR where sql_id='0pv15fhky1mbp',幾乎很難抓取到輸出。有點奇怪，實際上登入時間時間"很長"。
--//如果在執行前加入判斷：比如對a.yfsb 等於202，6的情況。
select count(*) from yf_zyfymx a where and a.jfrq >=:V00001 and a.jfrq <=:V00002 and a.yfsb =:V00003 and rownum<=1;
--//count(*) > 0 再執行該語句不是能大大較少不必要的執行嗎，而且可以在特定的時段先判斷是否有記錄,在選擇執行.
--//遇到這樣開發團隊真心無語。
--//有點吃驚的是23點時段突然出現輸出，因為查詢條件已經限制了a.yfsb in (3,6,168,202)僅僅可以是這4個值。而且對方帶入的引數是字元型別的，
--//當然不會發生隱式轉換。這個是本文主要探查原因。實際上我查詢23:00-0點時間段是沒有資料生成的。為什麼23點-0點有輸出呢？
3.首先確定帶入繫結變數值：
SYS@aaa.bbb.ccc.ddd:1521/xxxx> @ hide bind_cap
NAME DESCRIPTION DEFAULT_VALUE SESSION_VALUE SYSTEM_VALUE ISSES ISSYS_MOD
------------------------------- ----------------------------------------------------------- ------------- ------------- ------------ ----- ---------
_cursor_bind_capture_area_size maximum size of the cursor bind capture area TRUE 400 400 FALSE IMMEDIATE
_cursor_bind_capture_interval interval (in seconds) between two bind capture for a cursor TRUE 900 900 FALSE IMMEDIATE
cursor_bind_capture_destination Allowed destination for captured bind variables TRUE memory+disk memory+disk TRUE IMMEDIATE
--//_cursor_bind_capture_interval = 900,也就是15分鐘。
$ (echo set head off ;seq 10 | xargs -IQ echo -e "@bind_cap 0pv15fhky1mbp '' ;\n host sleep 900") | sqlplus -s -l / as sysdba
SQL_ID CHILD_NUMBER WAS NAME POSITION MAX_LENGTH LAST_CAPTURED DATATYPE_STRING VALUE_STRING
------------- ------------ --- ------- -------- ---------- ------------------- --------------- -------------------
0pv15fhky1mbp 0 YES :V00001 1 7 2020-04-14 08:38:43 DATE 2020/04/14 08:20:00
YES :V00002 2 7 2020-04-14 08:38:43 DATE 2020/04/14 08:50:00
YES :V00003 3 32 2020-04-14 08:38:43 VARCHAR2(32) 3
0pv15fhky1mbp 0 YES :V00001 1 7 2020-04-14 08:53:43 DATE 2020/04/14 08:30:00
YES :V00002 2 7 2020-04-14 08:53:43 DATE 2020/04/14 09:00:00
YES :V00003 3 32 2020-04-14 08:53:43 VARCHAR2(32) 3
0pv15fhky1mbp 0 YES :V00001 1 7 2020-04-14 09:08:43 DATE 2020/04/14 08:50:00
YES :V00002 2 7 2020-04-14 09:08:43 DATE 2020/04/14 09:20:00
YES :V00003 3 32 2020-04-14 09:08:43 VARCHAR2(32) 3
0pv15fhky1mbp 0 YES :V00001 1 7 2020-04-14 09:23:43 DATE 2020/04/14 09:00:00
YES :V00002 2 7 2020-04-14 09:23:43 DATE 2020/04/14 09:30:00
YES :V00003 3 32 2020-04-14 09:23:43 VARCHAR2(32) 202
0pv15fhky1mbp 0 YES :V00001 1 7 2020-04-14 09:38:43 DATE 2020/04/14 09:20:00
YES :V00002 2 7 2020-04-14 09:38:43 DATE 2020/04/14 09:50:00
YES :V00003 3 32 2020-04-14 09:38:43 VARCHAR2(32) 3
0pv15fhky1mbp 0 YES :V00001 1 7 2020-04-14 09:53:44 DATE 2020/04/14 09:30:00
YES :V00002 2 7 2020-04-14 09:53:44 DATE 2020/04/14 10:00:00
YES :V00003 3 32 2020-04-14 09:53:44 VARCHAR2(32) 3
--//注:欄位頭資訊是我加上的.
--//你可以看出實際上900秒取樣。而且查詢時間間隔都是30分鐘。我估計10分鐘10分鐘往前推。
--//比如到了2020/04/14 09:00:00，可能查詢時間範圍就變成了2020/04/14 08:40:00 -- 2020/04/14 09:10:00.
4.跟蹤sql語句：
$ cat sqltt.txt
ALTER SYSTEM SET EVENTS 'sql_trace [sql: sql_id=&&1] bind=true, wait=true';
host sleep &&2
ALTER SYSTEM SET EVENTS 'sql_trace off';
$ at 22:59
at> sqlplus sys/xxxx@RAC1/xxxx as sysdba @sqltt.txt 0pv15fhky1mbp 4000
at> <EOT>
job 9 at 2020-04-21 22:59
$ at 22:59
at> sqlplus sys/xxxx@RAC2/xxxx as sysdba @sqltt.txt 0pv15fhky1mbp 4000
at> <EOT>
job 10 at 2020-04-21 22:59
$ ls -ltr *.trc | egrep "2020-04-21 2[23]:" | awk '{print $8}' | xargs -IQ grep -l 0pv15fhky1mbp Q | xargs -IQ ls -l Q | column -t
-rw-r----- 1 oracle asmadmin 12314360 Apr 21 23:01 xxxx1_ora_100285.trc
-rw-r----- 1 oracle asmadmin 2007848 Apr 21 23:01 xxxx1_ora_110493.trc
-rw-r----- 1 oracle asmadmin 55606528 Apr 21 23:11 xxxx1_ora_110896.trc
-rw-r----- 1 oracle asmadmin 1089426 Apr 21 23:11 xxxx1_ora_121108.trc
-rw-r----- 1 oracle asmadmin 45385673 Apr 21 23:21 xxxx1_ora_121298.trc
-rw-r----- 1 oracle asmadmin 233683 Apr 21 23:22 xxxx1_ora_1412.trc
-rw-r----- 1 oracle asmadmin 51884128 Apr 21 23:32 xxxx1_ora_1557.trc
-rw-r----- 1 oracle asmadmin 151934 Apr 21 23:32 xxxx1_ora_12609.trc
-rw-r----- 1 oracle asmadmin 55306341 Apr 21 23:42 xxxx1_ora_12057.trc
-rw-r----- 1 oracle asmadmin 55168324 Apr 21 23:52 xxxx1_ora_22546.trc
$ ls -ltr *.trc | egrep "2020-04-22 0[09]:" | awk '{print $8}' | xargs -IQ grep -l 0pv15fhky1mbp Q | xargs -IQ ls -l Q | column -t
-rw-r----- 1 oracle asmadmin 30947031 Apr 22 00:02 xxxx1_ora_100426.trc
-rw-r----- 1 oracle asmadmin 32015029 Apr 22 00:03 xxxx1_ora_101674.trc
-rw-r----- 1 oracle asmadmin 11539852 Apr 22 00:05 xxxx1_ora_111835.trc
--//注意ls我定義別名，不過過濾失效。
$ alias ls
alias ls='ls --color=auto --time-style=+"%Y-%m-%d %H:%M:%S"'
--//從轉儲的時間可以看出可以看出大概10分鐘出現2個。不知道為什麼23:52僅僅出現1次。
$ ls -ltr *.trc | egrep "2020-04-21 2[23]:" | awk '{print $8}' | xargs -IQ grep -l 0pv15fhky1mbp Q > /tmp/ee1.txt
$ ls -ltr *.trc | egrep "2020-04-22" | awk '{print $8}' | xargs -IQ grep -l 0pv15fhky1mbp Q >> /tmp/ee1.txt
--//儲存要分析的檔案到/tmp/ee1.txt
$ cat /tmp/ee1.txt | xargs -IQ bash -c "echo Q;grep 0pv15fhky1mbp Q| awk '{print \$4}'| uniq -c "
xxxx1_ora_100285.trc
373 #140591307300936
xxxx1_ora_110493.trc
1 #140598307647200
3 #140598304752672
56 #140598304958360
xxxx1_ora_110896.trc
4 #140494626705520
1015 #140494629561936
665 #140494629449952
xxxx1_ora_121108.trc
1 #140728840941280
3 #140728838009888
28 #140728838215576
xxxx1_ora_121298.trc
4 #139667546106672
1011 #139667543239512
358 #139667545993440
xxxx1_ora_1412.trc
1 #139828203548384
2 #139828200666144
4 #139828200871832
xxxx1_ora_1557.trc
4 #139877515651888
896 #139877512797016
672 #139877515538656
xxxx1_ora_12609.trc
4 #140073655200560
xxxx1_ora_12057.trc
1 #139989832756960
3 #139989829825568
92 #139989830031256
911 #139989832754768
669 #139989832642784
xxxx1_ora_22546.trc
164 #140508294618304
839 #140508297487952
669 #140508297375968
xxxx1_ora_100426.trc
613 #140102612521760
323 #140102614724832
xxxx1_ora_101674.trc
2 #139754577412208
517 #139754580272720
449 #139754580160736
xxxx1_ora_111835.trc
1 #140062327762656
3 #140062324818976
48 #140062325024664
295 #140062327760464
$ cat /tmp/ee1.txt | xargs -IQ egrep 'value="4/2[12]/2020 ' Q | sort | uniq -c
16 value="4/21/2020 0:0:0"
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
1317 value="4/21/2020 22:40:0"
1684 value="4/21/2020 22:50:0"
1180 value="4/21/2020 23:0:0"
2997 value="4/21/2020 23:10:0"
3360 value="4/21/2020 23:20:0"
2844 value="4/21/2020 23:30:0"
3167 value="4/21/2020 23:40:0"
1676 value="4/21/2020 23:50:0"
16 value="4/21/2020 23:59:0"
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
1664 value="4/22/2020 0:0:0"
1487 value="4/22/2020 0:10:0"
--//"出現16次value="4/21/2020 0:0:0",value="4/21/2020 23:59:0".這驗證了為什麼23點－24點之間為什麼會有輸出。在這個時間段重新做了顯示全天的記錄。
--//有點奇怪的是為什麼是23:59:0,而不是23:59:59,這樣可能出現"漏"顯示的問題嗎？開發犯的一個小錯誤。
$ cat /tmp/ee1.txt | xargs -IQ grep -l "4/21/2020 23:59:0" Q | xargs -IQ ls -l Q | column -t
-rw-r----- 1 oracle asmadmin 45385673 Apr 21 23:21 xxxx1_ora_121298.trc
-rw-r----- 1 oracle asmadmin 233683 Apr 21 23:22 xxxx1_ora_1412.trc
-rw-r----- 1 oracle asmadmin 51884128 Apr 21 23:32 xxxx1_ora_1557.trc
--//這就解析為什麼前面的從轉儲的時間可以看出可以看出大概10分鐘出現2個以及為什麼23:52僅僅出現1次。
--//還有點奇怪的是開始執行時間在23:22.
$ echo "@sqlh 0pv15fhky1mbp 48008" | sqlplus -s -l sys/xxxx@aaa.bbb.ccc.ddd:1521/xxxx as sysdba | grep "[0-9] 23:" | grep -v "[0-9] 22:"
SNAP_ID BEGIN_INTERVAL_TIME END_INTERVAL_TIME ELAPSED_TIME_DELTA CPU_TIME_DELTA EXECUTIONS_DELTA EXECUTIONS_TOTAL ROWS_PROCESSED_DELTA BUFFER_GETS_DELTA
---------- ------------------------ ------------------------ ------------------ -------------- ---------------- ---------------- -------------------- -----------------
48008 2020-04-19 23:00:03.764 2020-04-20 00:00:10.952 62219860 61717604 9736 914331 95400 1487682
48032 2020-04-20 23:00:06.684 2020-04-21 00:00:30.205 74459773 73336848 9684 1116347 81260 1300126
48056 2020-04-21 23:00:24.524 2020-04-22 00:00:01.172 96387435 94893606 9512 1317543 67344 1075667
--//修改繫結變數,註解and a.yfsb =:V00003.
:V00001 := '2020/04/21 00:00:00';
:V00002 := '2020/04/22 00:00:00';
--//返回16836。67344/16836 = 4 ,4個值， 4*4=16.正好驗證sqlh指令碼的輸出。
--//另外我也測了其它時間段：
:V00001 := '2020/04/17 00:00:00';
:V00002 := '2020/04/18 00:00:00';
--//返回17480
--//87400/17480 = 5
:V00001 := '2020/04/16 00:00:00';
:V00002 := '2020/04/17 00:00:00';
--//返回16925,84625/16925 = 5
:V00001 := '2020/04/15 00:00:00';
:V00002 := '2020/04/16 00:00:00';
--//返回16791,83955/16791 = 5.
:V00001 := '2020/04/14 00:00:00';
:V00002 := '2020/04/15 00:00:00';
--//返回16341, 98046/16341 = 6.
:V00001 := '2020/04/13 00:00:00';
:V00002 := '2020/04/14 00:00:00';
-//返回15559,93354/15559 = 6
--//OK，已經可以確定在這個時間段掃描4，5，6次(乘以4次)，整個日期範圍內的情況。基本可以確定為什麼23－24點之間有輸出的原因。
5.看看每個跟蹤檔案的執行時間範圍：
$ cat /tmp/ee1.txt | xargs -IQ bash -c "echo Q;grep 0pv15fhky1mbp Q| awk '{print \$10}' | sed -n '1p;\$p'|cut -f2 -d'=' |xargs -IQ xdate Q"
xxxx1_ora_100285.trc
2020-04-21 22:59:03.894046000
2020-04-21 23:01:17.199957000
xxxx1_ora_110493.trc
2020-04-21 23:01:18.549278000
2020-04-21 23:01:38.494729000
--//以上2個可能從中間開始跟蹤，無法判斷。
xxxx1_ora_110896.trc
2020-04-21 23:01:39.846533000
2020-04-21 23:11:38.378720000
--//10分鐘。
xxxx1_ora_121108.trc
2020-04-21 23:11:39.728799000
2020-04-21 23:11:49.975829000
--//10分鐘。
xxxx1_ora_121298.trc
2020-04-21 23:11:51.324993000
2020-04-21 23:21:33.854756000
--//10分鐘。
xxxx1_ora_1412.trc
2020-04-21 23:22:07.700456000
2020-04-21 23:22:14.392132000
--//7分鐘
xxxx1_ora_1557.trc
2020-04-21 23:22:15.776580000
2020-04-21 23:32:15.813717000
--//10分鐘。
xxxx1_ora_12609.trc
2020-04-21 23:32:51.766126000
2020-04-21 23:32:51.880844000
xxxx1_ora_12057.trc
2020-04-21 23:32:17.175933000
2020-04-21 23:42:17.501154000
--//10分鐘。
xxxx1_ora_22546.trc
2020-04-21 23:42:18.855909000
2020-04-21 23:52:18.644104000
--//10分鐘。
xxxx1_ora_100426.trc
2020-04-21 23:52:19.996287000
2020-04-22 00:02:18.424764000
--//10分鐘。
xxxx1_ora_101674.trc
2020-04-21 23:53:42.268303000
2020-04-22 00:03:40.605847000
--//10分鐘。
xxxx1_ora_111835.trc
2020-04-22 00:03:41.955328000
2020-04-22 00:05:44.846208000
--//關閉跟蹤。
--//估計10分鐘一個迴圈。tmd垃圾的刷屏軟體。看看掃描:V00003 順序。
$ grep 0pv15fhky1mbp xxxx1_ora_100285.trc | awk '{print $4}' | uniq | xargs -IQ egrep -A15 "BINDS Q" xxxx1_ora_100285.trc | egrep "Bind#|value="| paste - - | sort | uniq -c
373 Bind#0 value="4/21/2020 22:40:0"
373 Bind#1 value="4/21/2020 23:10:0"
93 Bind#2 value="168"
94 Bind#2 value="202"
93 Bind#2 value="3"
93 Bind#2 value="6"
--//執行373次，而且可以猜測BIND#2的值是迴圈執行的。93*4+1 = 373.
$ grep 0pv15fhky1mbp xxxx1_ora_100285.trc | awk '{print $4}' | uniq | xargs -IQ egrep -A15 "BINDS Q" xxxx1_ora_100285.trc | egrep -A5 "Bind#2" | grep "value=" | paste - - - - | uniq -c
93 value="202" value="3" value="6" value="168"
1 value="202"
--//看看下一個是否從value="3"開始。
$ grep 0pv15fhky1mbp xxxx1_ora_110493.trc | awk '{print $4}' | uniq | xargs -IQ egrep -A15 "BINDS Q" xxxx1_ora_110493.trc | egrep -A5 "Bind#2" | grep "value=" | paste - - - - | uniq -c
15 value="3" value="6" value="168" value="202"
$ grep 0pv15fhky1mbp xxxx1_ora_1557.trc | awk '{print $4}' | uniq | xargs -IQ egrep -A15 "BINDS Q" xxxx1_ora_1557.trc | egrep -A5 "Bind#2" | grep "value=" | paste - - - - | uniq -c
393 value="3" value="6" value="168" value="202"
--//基本可以確定是一個迴圈刷屏軟體。
$ grep 0pv15fhky1mbp xxxx1_ora_110493.trc | awk '{print $10}' | cut -f2 -d'=' | xargs -IQ xdate Q > /tmp/ee2.txt
$ cat /tmp/ee2.txt | xargs -I{} date -d "{}" "+%Y-%m-%d:%T.%N %s.%N" | awk 'NR==1 {a=$1;b=$2} NR>1 {print $1,"-",a,$2-b;a=$1;b=$2}'
2020-04-21:23:01:18.572442000 - 2020-04-21:23:01:18.549278000 0.023164
2020-04-21:23:01:18.593294000 - 2020-04-21:23:01:18.572442000 0.0208519
2020-04-21:23:01:18.657183000 - 2020-04-21:23:01:18.593294000 0.063889
2020-04-21:23:01:19.965149000 - 2020-04-21:23:01:18.657183000 1.30797
2020-04-21:23:01:19.987112000 - 2020-04-21:23:01:19.965149000 0.0219631
2020-04-21:23:01:20.008268000 - 2020-04-21:23:01:19.987112000 0.0211561
2020-04-21:23:01:20.076245000 - 2020-04-21:23:01:20.008268000 0.067977
2020-04-21:23:01:21.388697000 - 2020-04-21:23:01:20.076245000 1.31245
2020-04-21:23:01:21.410812000 - 2020-04-21:23:01:21.388697000 0.022115
2020-04-21:23:01:21.432424000 - 2020-04-21:23:01:21.410812000 0.0216122
2020-04-21:23:01:21.495844000 - 2020-04-21:23:01:21.432424000 0.0634198
2020-04-21:23:01:22.797844000 - 2020-04-21:23:01:21.495844000 1.302
2020-04-21:23:01:22.819725000 - 2020-04-21:23:01:22.797844000 0.0218811
2020-04-21:23:01:22.841356000 - 2020-04-21:23:01:22.819725000 0.021631
2020-04-21:23:01:22.905724000 - 2020-04-21:23:01:22.841356000 0.064368
2020-04-21:23:01:24.209283000 - 2020-04-21:23:01:22.905724000 1.30356
2020-04-21:23:01:24.230426000 - 2020-04-21:23:01:24.209283000 0.021143
2020-04-21:23:01:24.256038000 - 2020-04-21:23:01:24.230426000 0.0256119
2020-04-21:23:01:24.326223000 - 2020-04-21:23:01:24.256038000 0.0701849
2020-04-21:23:01:25.647111000 - 2020-04-21:23:01:24.326223000 1.32089
2020-04-21:23:01:25.672147000 - 2020-04-21:23:01:25.647111000 0.0250361
2020-04-21:23:01:25.694435000 - 2020-04-21:23:01:25.672147000 0.0222878
2020-04-21:23:01:25.759965000 - 2020-04-21:23:01:25.694435000 0.0655301
2020-04-21:23:01:27.063004000 - 2020-04-21:23:01:25.759965000 1.30304
2020-04-21:23:01:27.090415000 - 2020-04-21:23:01:27.063004000 0.027411
2020-04-21:23:01:27.111800000 - 2020-04-21:23:01:27.090415000 0.021385
2020-04-21:23:01:27.175630000 - 2020-04-21:23:01:27.111800000 0.0638301
2020-04-21:23:01:28.479110000 - 2020-04-21:23:01:27.175630000 1.30348
2020-04-21:23:01:28.500069000 - 2020-04-21:23:01:28.479110000 0.0209589
2020-04-21:23:01:28.521447000 - 2020-04-21:23:01:28.500069000 0.021378
2020-04-21:23:01:28.585815000 - 2020-04-21:23:01:28.521447000 0.064368
2020-04-21:23:01:29.895066000 - 2020-04-21:23:01:28.585815000 1.30925
2020-04-21:23:01:29.917030000 - 2020-04-21:23:01:29.895066000 0.0219641
2020-04-21:23:01:29.939078000 - 2020-04-21:23:01:29.917030000 0.022048
2020-04-21:23:01:30.005716000 - 2020-04-21:23:01:29.939078000 0.066638
2020-04-21:23:01:31.303372000 - 2020-04-21:23:01:30.005716000 1.29766
2020-04-21:23:01:31.324338000 - 2020-04-21:23:01:31.303372000 0.0209661
2020-04-21:23:01:31.345285000 - 2020-04-21:23:01:31.324338000 0.020947
2020-04-21:23:01:31.415500000 - 2020-04-21:23:01:31.345285000 0.070215
2020-04-21:23:01:32.717882000 - 2020-04-21:23:01:31.415500000 1.30238
2020-04-21:23:01:32.739167000 - 2020-04-21:23:01:32.717882000 0.0212851
2020-04-21:23:01:32.759835000 - 2020-04-21:23:01:32.739167000 0.020668
2020-04-21:23:01:32.825428000 - 2020-04-21:23:01:32.759835000 0.065593
2020-04-21:23:01:34.129409000 - 2020-04-21:23:01:32.825428000 1.30398
2020-04-21:23:01:34.150984000 - 2020-04-21:23:01:34.129409000 0.021575
2020-04-21:23:01:34.172687000 - 2020-04-21:23:01:34.150984000 0.021703
2020-04-21:23:01:34.238400000 - 2020-04-21:23:01:34.172687000 0.0657129
2020-04-21:23:01:35.542766000 - 2020-04-21:23:01:34.238400000 1.30437
2020-04-21:23:01:35.564471000 - 2020-04-21:23:01:35.542766000 0.0217049
2020-04-21:23:01:35.585334000 - 2020-04-21:23:01:35.564471000 0.0208631
2020-04-21:23:01:35.651166000 - 2020-04-21:23:01:35.585334000 0.0658319
2020-04-21:23:01:36.951535000 - 2020-04-21:23:01:35.651166000 1.30037
2020-04-21:23:01:36.972524000 - 2020-04-21:23:01:36.951535000 0.0209889
2020-04-21:23:01:36.995122000 - 2020-04-21:23:01:36.972524000 0.022598
2020-04-21:23:01:37.062274000 - 2020-04-21:23:01:36.995122000 0.067152
2020-04-21:23:01:38.378726000 - 2020-04-21:23:01:37.062274000 1.31645
2020-04-21:23:01:38.402667000 - 2020-04-21:23:01:38.378726000 0.023941
2020-04-21:23:01:38.425964000 - 2020-04-21:23:01:38.402667000 0.0232971
2020-04-21:23:01:38.494729000 - 2020-04-21:23:01:38.425964000 0.0687649
--//可以看出4個值迴圈，然後sleep大約1秒(估計),然後繼續迴圈。
--//一般1.4秒執行4次。3600/1.4*4 = 10285.7次。這樣與前面的推測基本一致，基本確定1個小時內平均每秒3次的情況。
$ grep 0pv15fhky1mbp xxxx1_ora_110896.trc | awk '{print $10}' | cut -f2 -d'=' | xargs -IQ xdate Q > /tmp/ee3.txt
$ cat /tmp/ee3.txt | xargs -I{} date -d "{}" "+%Y-%m-%d:%T.%N %s.%N" | awk 'NR==1 {a=$1;b=$2} NR>1 {print $1,"-",a,$2-b;a=$1;b=$2}' | head -12
2020-04-21:23:01:39.871090000 - 2020-04-21:23:01:39.846533000 0.0245569
2020-04-21:23:01:39.906213000 - 2020-04-21:23:01:39.871090000 0.0351231
2020-04-21:23:01:39.978123000 - 2020-04-21:23:01:39.906213000 0.0719099
2020-04-21:23:01:41.957241000 - 2020-04-21:23:01:39.978123000 1.97912
2020-04-21:23:01:41.978752000 - 2020-04-21:23:01:41.957241000 0.0215108
2020-04-21:23:01:42.000375000 - 2020-04-21:23:01:41.978752000 0.0216231
2020-04-21:23:01:42.067666000 - 2020-04-21:23:01:42.000375000 0.067291
2020-04-21:23:01:43.362773000 - 2020-04-21:23:01:42.067666000 1.29511
2020-04-21:23:01:43.383414000 - 2020-04-21:23:01:43.362773000 0.0206411
2020-04-21:23:01:43.404418000 - 2020-04-21:23:01:43.383414000 0.021004
2020-04-21:23:01:43.468162000 - 2020-04-21:23:01:43.404418000 0.0637441
2020-04-21:23:01:44.770544000 - 2020-04-21:23:01:43.468162000 1.30238
xargs: date: terminated by signal 13
--//基本可以認定我的判斷。
--//即使業務高峰也可以修改為5秒1個迴圈，根本對業務完全不會有任何影響。10秒都可以。有必要這樣做嗎？
--//像這樣的語句你越最佳化消耗資源越大，執行"越"慢效果越好。
--//附上指令碼：
$ cat sqlh.sql
column BEGIN_INTERVAL_TIME format a24
column END_INTERVAL_TIME format a24
SELECT s.SNAP_ID
,x.BEGIN_INTERVAL_TIME
,x.END_INTERVAL_TIME
,ELAPSED_TIME_DELTA
,CPU_TIME_DELTA
,EXECUTIONS_DELTA
,EXECUTIONS_TOTAL
,ROWS_PROCESSED_DELTA
,BUFFER_GETS_DELTA
FROM DBA_HIST_SQLSTAT s, DBA_HIST_SNAPSHOT x
WHERE s.sql_id = '&&1'
AND s.snap_id = x.snap_id
AND s.instance_number = x.instance_number
AND s.snap_id >= nvl('&&2',0)
ORDER BY 1;
$ cat $(which xdate)
#! /bin/bash
# /bin/date -d "1970-01-01 00:00:00 UTC $( echo "scale=6; $1/1000000" |bc -l) seconds" +"%Y-%m-%d %T.%N"
/bin/date -d "@$( echo "scale=6; $1/1000000" |bc -l)" +"%Y-%m-%d %T.%N"
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/267265/viewspace-2687572/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- [20230511]最佳化的困惑17.txt
- [20230512]最佳化的困惑19.txt
- strtotime 的困惑
- [20211011]變態的windows批處理9.txtWindows
- 困惑度的計算
- 學習java的困惑Java
- [20200422]瞭解相關程式的環境變數.txt變數
- 令人困惑的 TensorFlow！(II)
- 個人部落格的困惑
- [20210203]max優化的困惑.txt優化
- [20180611]函式與標量子查詢9.txt函式
- [20220507]優化的困惑13.txt優化
- [20220428]優化的困惑12.txt優化
- [20200408]優化的困惑6.txt優化
- [20200808]優化的困惑10.txt優化
- [20200401]優化的困惑5.txt優化
- 【原創】多專案控制的困惑
- 優必選的商業化困惑
- [20200320]SQL語句優化的困惑.txtSQL優化
- 關於非同步爬蟲排序的困惑非同步爬蟲排序
- 如何消除ERP選型困惑
- [20201224]sql優化困惑.txtSQL優化
- 設計模式系列 · 無從下手的困惑 (一)設計模式
- 測試面試困惑求解答面試
- [20240313]使用tpt ashtop.sql指令碼的困惑.txtSQL指令碼
- [20200324]SQL語句優化的困惑2.txtSQL優化
- C++運算子過載的一些困惑C++
- [20200422]跟蹤特定sql語句以及v$open_cursor檢視(補充).txtSQL
- 10分鐘搞定讓你困惑的 Jenkins 環境變數Jenkins變數
- android觸控事件分發機制，曾困惑你我的地方Android事件
- 技術轉管理，你遇到了哪些困惑？
- 【譯】關於Webpack中一些讓人困惑的地方的解答Web
- 馮老師的困惑 —— 測試和正式環境掐架篇（二）
- 4月3號下午一條通告帶來的技術困惑
- [原創]成立售後服務部門的一些困惑
- 機器學習中那些必要又困惑的數學知識機器學習
- 負對數似然（NLL）和困惑度（PPL）
- 六西格瑪企業：從困惑到成功的11個步驟！