[20200408]優化的困惑6.txt
[20200408]優化的困惑6.txt
1.環境：
> @ 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
--//生產系統awr報表(1個小時取樣9:00-10:00),一般上午的業務高峰在9－11點。
SQL ordered by Elapsed Time
Elapsed Time (s)Executions Elapsed Time per Exec (s) %Total %CPU %IO SQL Id SQL Module SQL Text
1,660.15 6,522,522 0.00 10.16 99.45 0.00 190q1sz3ywrd7 xxxxxx.eee begin :con := "TASSETACL"."QUE..."
....
256.02 20,773 0.01 1.57 98.58 0.18 ck3nrshb15tb4 httpd.exe begin tlogon.logon; end;
> @ashtop username sql_id='190q1sz3ywrd7' trunc(sysdate) sysdate
Total
Seconds AAS %This USERNAME FIRST_SEEN LAST_SEEN
--------- ------- ------- -------------------- ------------------- -------------------
57 .0 100% | ppppp_hhh 2020-04-08 00:09:01 2020-04-08 10:49:37
--//你可以發現記錄的差異很大,ashtop抓取一天的(截至11點)僅僅57次。而實際上awr一個小時的取樣上記錄的消耗就是1,660.15秒。
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
FROM DBA_HIST_SQLSTAT s, DBA_HIST_SNAPSHOT x
WHERE s.sql_id = '190q1sz3ywrd7'
AND s.snap_id = x.snap_id
AND s.instance_number = x.instance_number
AND s.snap_id > 47717
ORDER BY 1;
SNAP_ID BEGIN_INTERVAL_TIME END_INTERVAL_TIME ELAPSED_TIME_DELTA CPU_TIME_DELTA EXECUTIONS_DELTA EXECUTIONS_TOTAL ROWS_PROCESSED_DELTA
---------- ------------------------ ------------------------ ------------------ -------------- ---------------- ---------------- --------------------
47717 2020-04-07 20:00:27.425 2020-04-07 21:00:40.767 425178360 429067659 2028755 376359816 2028656
47718 2020-04-07 21:00:40.767 2020-04-07 22:00:11.917 393515919 397370610 1871627 378231458 1871552
47719 2020-04-07 22:00:11.917 2020-04-07 23:00:35.213 423088126 427605907 2053886 380285348 2053797
47720 2020-04-07 23:00:35.213 2020-04-08 00:00:58.924 429128635 431995342 1995530 382280880 1995440
47721 2020-04-08 00:00:58.924 2020-04-08 01:00:05.598 337517500 341298355 1609105 383889985 1609050
47722 2020-04-08 01:00:05.598 2020-04-08 02:00:13.056 282346751 285727015 1336993 385226998 1336967
47723 2020-04-08 02:00:13.056 2020-04-08 03:00:09.325 308328198 311747635 1532358 386759424 1532308
47724 2020-04-08 03:00:09.325 2020-04-08 04:00:25.469 305779343 309529920 1543277 388302709 1543234
47725 2020-04-08 04:00:25.469 2020-04-08 05:00:31.997 259257887 263003051 1278748 389581461 1278727
47726 2020-04-08 05:00:31.997 2020-04-08 06:00:17.175 225393781 228169213 1107595 390689123 1107583
47727 2020-04-08 06:00:17.175 2020-04-08 07:00:40.763 239479033 242475052 1228663 391917786 1228653
47728 2020-04-08 07:00:40.763 2020-04-08 08:00:03.617 405715775 409634835 1901449 393819235 1901364
47729 2020-04-08 08:00:03.617 2020-04-08 09:00:27.330 1402061211 1390975250 5463459 399282696 5462542
47730 2020-04-08 09:00:27.330 2020-04-08 10:00:03.866 1660151958 1650944455 6522522 405805428 6521177
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~=>awr報表看到的情況。
47731 2020-04-08 10:00:03.866 2020-04-08 11:00:10.612 1684893892 1668526722 6614401 412419904 6613025
65 rows selected.
--//與awr報表結果能夠對上。
> set verify off
> @ tpt/sqlid 190q1sz3ywrd7 ''
Show SQL text, child cursors and execution stats for SQLID 190q1sz3ywrd7 child nvl('','%')
HASH_VALUE PLAN_HASH_VALUE CH# SQL_TEXT
---------- --------------- ---- ----------------------------------------------------
3354287527 0 0 begin :con := "TASSETACL"."QUERYACL"(:sn, :on); end;
CH# PARENT_HANDLE OBJECT_HANDLE PLAN_HASH PARSES H_PARSES EXECUTIONS FETCHES ROWS_PROCESSED ROWS_PER_FETCH CPU_SEC CPU_SEC_EXEC ELA_SEC ELA_SEC_EXEC LIOS LIOS_EXEC PIOS SORTS USERS_EXECUTING
---- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- -------------- -------------- ---------- ------------ ---------- ------------ ---------- ---------- ---------- ---------- ---------------
0 0000000257135C60 00000012F7FB7550 0 401749624 21 412651534 0 408108832 7000034.21 .016963548 7039372.73 .017058879 48083 .000116522 787 0 1
2 0000000257135C60 00000012F9A978B0 0 232 16 232 0 232 .086992 .000374966 .087203 .000375875 25 .107758621 2 0 0
> set numw 13
> @ d_buffer 190q1sz3ywrd7 60
EXECUTIONS1 BUFFER_GETS1 ELAPSED_TIME1 ROWS_PROCESSED1
------------- ------------- ------------- ---------------
412766619 48108 7039402462143 408223884
... sleep 60 , waiting ....
EXECUTIONS2 BUFFER_GETS2 ELAPSED_TIME2 ROWS_PROCESSED2
------------- ------------- ------------- ---------------
412864987 48108 7039427092606 408322243
總buffer_gets 每次buffer_gets 執行次數 總執行時間 每次執行時間 總處理記錄數 平均處理記錄數
------------- --------------- ------------- ------------- ------------- ------------- --------------
0 0 98368 24630463 250.391011304 98359 .999908506831
--//1分鐘執行98368，相當於98368/60 = 1639次/秒。總執行時間24630463/1000000 = 24.63秒。如果1個小時需要時間 24.63*60 = 1477.8秒。
--//實際上就是語句執行很快很頻繁，ash抓取的很少，使用ashtop查詢感覺就很少，而實際上該語句執行頻繁，導致累計的執行時間很長。
--//awr通過共享池記錄資訊得到的執行時間就很長，我僅僅想說的是如果一味依賴ashtop優化很有可能漏掉一些語句，必須結合awr報表分析。
--//再看看其它sqlid的情況:
SQL ordered by Executions
%CPU - CPU Time as a percentage of Elapsed Time
%IO - User I/O Time as a percentage of Elapsed Time
Total Executions: 23,199,582
Captured SQL account for 34.2% of Total
Executions Rows Processed Rows per Exec Elapsed Time (s)%CPU %IO SQL Id SQL Module SQL Text
6,522,522 6,521,177 1.00 1,660.15 99.4 0 190q1sz3ywrd7 xxxxxx.eee begin :con := "TASSETACL".QUE...
2,228,287 2,228,115 1.00 107.98 99.5 0 g7ytdh9mxt1s0 xxxxxx.eee select count ( :"SYS_B_0" ) fr...
1,586,496 1,586,318 1.00 54.90 100.3 0 f8733rs2f3bng xxxxxx.eee SELECT sysdate FROM Dual
--//看看sql_id=f8733rs2f3bng的情況.每秒1586496 /3600 = 440次,真心不知道2層應用這麼頻繁的取時間幹嗎？
> @ashtop username sql_id='f8733rs2f3bng' trunc(sysdate) trunc(sysdate)+1
Total
Seconds AAS %This USERNAME FIRST_SEEN LAST_SEEN
--------- ------- ------- -------------------- ------------------- -------------------
202 .0 100% | ppppp_hhh 2020-04-09 00:07:21 2020-04-09 09:02:13
> @ sqlh f8733rs2f3bng 47725
SNAP_ID BEGIN_INTERVAL_TIME END_INTERVAL_TIME ELAPSED_TIME_DELTA CPU_TIME_DELTA EXECUTIONS_DELTA EXECUTIONS_TOTAL ROWS_PROCESSED_DELTA
---------- ------------------------ ------------------------ ------------------ -------------- ---------------- ---------------- --------------------
47725 2020-04-08 04:00:25.469 2020-04-08 05:00:31.997 7141572 7203923 215786 3354343829 215775
47726 2020-04-08 05:00:31.997 2020-04-08 06:00:17.175 4574151 4673262 136395 3354480224 136393
47727 2020-04-08 06:00:17.175 2020-04-08 07:00:40.763 3798263 3817422 112460 3354592684 112458
47728 2020-04-08 07:00:40.763 2020-04-08 08:00:03.617 13867983 13889906 411939 3355004626 411922
47729 2020-04-08 08:00:03.617 2020-04-08 09:00:27.330 43644031 43617459 1244318 3356248945 1244221
47730 2020-04-08 09:00:27.330 2020-04-08 10:00:03.866 54897269 55068562 1586496 3357835458 1586318
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~=>awr報表看到的情況。
47731 2020-04-08 10:00:03.866 2020-04-08 11:00:10.612 60389158 60230921 1749372 3359584835 1749174
47732 2020-04-08 11:00:10.612 2020-04-08 12:00:18.524 59827861 59805942 1758971 3361343815 1758782
47733 2020-04-08 12:00:18.524 2020-04-08 13:00:02.355 23749911 24026347 695032 3362038859 694984
47734 2020-04-08 13:00:02.355 2020-04-08 14:00:26.007 15035649 15211668 432078 3362470943 432061
47735 2020-04-08 14:00:26.007 2020-04-08 15:00:40.175 22348860 22415693 633409 3363104353 633383
47736 2020-04-08 15:00:40.175 2020-04-08 16:00:14.460 49562753 49574393 1444387 3364548740 1444230
47737 2020-04-08 16:00:14.460 2020-04-08 17:00:38.031 54970827 55141616 1606165 3366154922 1606023
47738 2020-04-08 17:00:38.031 2020-04-08 18:00:01.399 49183175 48795619 1466208 3367621148 1466066
47739 2020-04-08 18:00:01.399 2020-04-08 19:00:07.235 27137146 27088885 821674 3368442823 821623
47740 2020-04-08 19:00:07.235 2020-04-08 20:00:14.101 14831048 14991744 447466 3368890291 447452
47741 2020-04-08 20:00:14.101 2020-04-08 21:00:11.637 12160351 12101217 370494 3369260790 370481
47742 2020-04-08 21:00:11.637 2020-04-08 22:00:27.950 12319875 12638031 379221 3369640012 379206
47743 2020-04-08 22:00:27.950 2020-04-08 23:00:34.225 11564187 11710203 334095 3369974111 334082
47744 2020-04-08 23:00:34.225 2020-04-09 00:00:22.968 12027081 12308169 358049 3370332161 358038
47745 2020-04-09 00:00:22.968 2020-04-09 01:00:45.856 7381876 7455839 209685 3370541849 209683
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
47746 2020-04-09 01:00:45.856 2020-04-09 02:00:08.315 5077171 5127228 143303 3370685152 143300
47747 2020-04-09 02:00:08.315 2020-04-09 03:00:31.720 6364851 6399034 198665 3370883819 198658
47748 2020-04-09 03:00:31.720 2020-04-09 04:00:06.878 5217293 5217218 160556 3371044375 160553
47749 2020-04-09 04:00:06.878 2020-04-09 05:00:14.312 4524945 4684314 137784 3371182161 137785
47750 2020-04-09 05:00:14.312 2020-04-09 06:00:20.776 3627379 3765428 109897 3371292058 109897
47751 2020-04-09 06:00:20.776 2020-04-09 07:00:02.527 3555284 3517481 108242 3371400300 108241
47752 2020-04-09 07:00:02.527 2020-04-09 08:00:26.637 13776302 13749953 406720 3371807020 406694
47753 2020-04-09 08:00:26.637 2020-04-09 09:00:40.259 44080344 44001288 1243052 3373050074 1242961
29 rows selected.
--//7381876+5077171+6364851+5217293+4524945+3627379+3555284+13776302+44080344 = 93605445
--//93605445/1000000 = 93.605445
--//通過ashtop看到大約202秒。而實際上僅僅94秒。正好與前面看到的情況相反。因為ashtop的取樣是業務最不忙的情況。
--//看看上面8－12點的ELAPSED_TIME_DEL他的情況就明白
--//總之做優化時ashtop與awr報表兩者相結合，才能更好的解決優化問題。
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/267265/viewspace-2685107/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- [20210203]max優化的困惑.txt優化
- [20220507]優化的困惑13.txt優化
- [20220428]優化的困惑12.txt優化
- [20200808]優化的困惑10.txt優化
- [20200401]優化的困惑5.txt優化
- 優必選的商業化困惑
- [20201224]sql優化困惑.txtSQL優化
- [20200320]SQL語句優化的困惑.txtSQL優化
- [20200324]SQL語句優化的困惑2.txtSQL優化
- [20230511]最佳化的困惑17.txt
- [20230512]最佳化的困惑19.txt
- [20200422]最佳化的困惑9.txt
- strtotime 的困惑
- [20210915]探究mutex的值 6.txtMutex
- 困惑度的計算
- 學習java的困惑Java
- 令人困惑的 TensorFlow！(II)
- 個人部落格的困惑
- [20190219]變態的windows批處理6.txtWindows
- [20210218]shared latch spin count 6.txt
- 【原創】多專案控制的困惑
- MySQL優化（1）——–常用的優化步驟MySql優化
- hive的優化Hive優化
- [20210831]bbed讀取資料塊6.txt
- 關於非同步爬蟲排序的困惑非同步爬蟲排序
- 前端效能優化（JS/CSS優化，SEO優化）前端優化JSCSS
- 數值最優化—優化問題的解(二)優化
- Android效能優化——效能優化的難題總結Android優化
- 如何消除ERP選型困惑
- [20180925]等待事件SQLNet more data from client 6.txt事件SQLclient
- Flutter的效能優化Flutter優化
- 優化你的 PhpStorm優化PHPORM
- Hive --------- hive 的優化Hive優化
- nginx的location優化Nginx優化
- java Synchronized的優化Javasynchronized優化
- Oracle優化的方法Oracle優化
- 設計模式系列 · 無從下手的困惑 (一)設計模式
- 資料庫優化 - SQL優化資料庫優化SQL