最近频繁遭遇latch相关等待，ASH信息只给出了系统级别的统计，为了能够从session级别定位latch的信息，使用TANEL的脚本进行测试，以便日后能够从session级别获得信息，快速定位问题。
测试一
Session 1 SID:137
运行语句：
declare v_string varchar2(100) := 'alter system flush shared_pool'; msql varchar2(200); begin loop execute immediate v_string; for i in 1 .. 70000 loop msql:='select object_id from lichao.t where object_id='||i; execute immediate msql; end loop; end loop; end; /
Session 2 SID:74
运行语句：
declare v_string varchar2(100) := 'alter table t parallel 1'; msql varchar2(200); begin loop execute immediate v_string; for i in 1 .. 70000 loop msql:='select object_id from t where object_id='||i; execute immediate msql; end loop; end loop; end;
/
使用latchprof获取当前系统中latch hold信息：
SQL> @latchprof name % % 100000 NAME Held Gets Held % Held ms Avg hold ms ----------------------------------- ---------- ---------- ------- ----------- ----------- shared pool 749 749 .75 219.083 .293 row cache objects 161 161 .16 47.093 .293 kks stats 97 97 .10 28.373 .293 shared pool simulator 68 68 .07 19.890 .293 enqueues 40 40 .04 11.700 .293 hash table column usage latch 23 23 .02 6.728 .293 enqueue hash chains 18 18 .02 5.265 .293 cache buffers chains 12 12 .01 3.510 .293 active service list 2 2 .00 .585 .293 resmgr:schema config 1 1 .00 .293 .293 SQL memory manager workarea list la 1 1 .00 .293 .293
获取shared pool相关latch的信息：
SID NAME Held Gets Held % Held ms Avg hold ms
---------- ----------------------------------- ---------- ---------- ------- ----------- -----------
137 shared pool 1123 1123 1.12 341.504 .304
137 shared pool simulator 68 68 .07 20.679 .304
197 shared pool 17 17 .02 5.170 .304
74 shared pool 3 3 .00 .912 .304
190 shared pool 3 3 .00 .912 .304
134 shared pool 2 2 .00 .608 .304
197 shared pool simulator 1 1 .00 .304 .304
190 shared pool simulator 1 1 .00 .304 .304
8 rows selected.
使用snapper获得当前session的统计信息，可以有个大致判断，比如我的测试用例中hard parse肯定很高。
----------------------------------------------------------------------------------------------------------------- SID, USERNAME , TYPE, STATISTIC , HDELTA, HDELTA/SEC, %TIME, GRAPH ----------------------------------------------------------------------------------------------------------------- 137, SYS , STAT, opened cursors cumulative , 4.01k, 667.67, 137, SYS , STAT, recursive calls , 16.9k, 2.82k, 137, SYS , STAT, recursive cpu usage , 471, 78.5, 137, SYS , STAT, pinned cursors current , -1, -.17, 137, SYS , STAT, session logical reads , 284, 47.33, 137, SYS , STAT, CPU used by this session , 521, 86.83, 137, SYS , STAT, concurrency wait time , 2, .33, 137, SYS , STAT, non-idle wait time , 2, .33, 137, SYS , STAT, non-idle wait count , 12, 2, 137, SYS , STAT, session pga memory , 65.54k, 10.92k, 137, SYS , STAT, enqueue requests , 3.93k, 655.67, 137, SYS , STAT, enqueue releases , 3.93k, 655.67, 137, SYS , STAT, consistent gets , 284, 47.33, 137, SYS , STAT, consistent gets from cache , 284, 47.33, 137, SYS , STAT, consistent gets from cache (fastpath) , 147, 24.5, 137, SYS , STAT, consistent gets - examination , 137, 22.83, 137, SYS , STAT, calls to get snapshot scn: kcmgss , 4.01k, 667.67, 137, SYS , STAT, no work - consistent read gets , 147, 24.5, 137, SYS , STAT, table fetch by rowid , 38, 6.33, 137, SYS , STAT, cluster key scans , 49, 8.17, 137, SYS , STAT, cluster key scan block gets , 71, 11.83, 137, SYS , STAT, index fetch by key , 49, 8.17, 137, SYS , STAT, index scans kdiixs1 , 38, 6.33, 137, SYS , STAT, sql area evicted , 3.69k, 614.5, 137, SYS , STAT, session cursor cache hits , 83, 13.83, 137, SYS , STAT, buffer is not pinned count , 234, 39, 137, SYS , STAT, workarea executions - optimal , 13, 2.17, 137, SYS , STAT, parse time cpu , 359, 59.83, 137, SYS , STAT, parse time elapsed , 379, 63.17, 137, SYS , STAT, parse count (total) , 3.94k, 656.33, 137, SYS , STAT, parse count (hard) , 3.94k, 656.83, 137, SYS , STAT, execute count , 4.02k, 669.67, 137, SYS , STAT, sorts (memory) , 48, 8, 137, SYS , STAT, sorts (rows) , 793, 132.17, 137, SYS , TIME, hard parse elapsed time , 2.45s, 408.34ms, 40.8%, |@@@@@ | 137, SYS , TIME, repeated bind elapsed time , 3.47ms, 578.5us, .1%, | | 137, SYS , TIME, parse time elapsed , 4.12s, 685.94ms, 68.6%, |@@@@@@@ | 137, SYS , TIME, PL/SQL execution elapsed time , 463.67ms, 77.28ms, 7.7%, |@ | 137, SYS , TIME, DB CPU , 5.85s, 974.73ms, 97.5%, |@@@@@@@@@@| 137, SYS , TIME, sql execute elapsed time , 6.04s, 1.01s, 100.6%, |@@@@@@@@@@| 137, SYS , TIME, DB time , 6.04s, 1.01s, 100.6%, |@@@@@@@@@@| 137, SYS , WAIT, latch: shared pool , 14.06ms, 2.34ms, .2%, | | End of Stats snap 1, end=2012-04-14 21:56:53, seconds=6
以上采样时间只有7s中的样子，以上信息可以作为分析的参考。
发现sid，sql_id等信息：
SID NAME SQLID Held Gets Held % Held ms Avg hold ms
---------- ----------------------------------- ------------- ---------- ---------- ------- ----------- -----------
137 shared pool bqh67d48k8ufy 433 433 .43 125.743 .290
137 shared pool 107 107 .11 31.073 .290
197 shared pool 21 21 .02 6.098 .290
74 shared pool c20zmr5d5u1h3 5 5 .01 1.452 .290
137 shared pool 64p598m3da1m0 5 5 .01 1.452 .290
137 shared pool simulator 5 5 .01 1.452 .290
137 shared pool simulator bqh67d48k8ufy 3 3 .00 .871 .290
74 shared pool 2 2 .00 .581 .290
抓出相关的sql信息：
SQL> select*from table(dbms_xplan.display_cursor('&sql_id','','ALL'));
Enter value for sql_id: bqh67d48k8ufy
PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------------
SQL_ID bqh67d48k8ufy, child number 0
declare v_string varchar2(100) := 'alter system flush shared_pool';
msql varchar2(200); begin loop execute immediate v_string; for i in 1
.. 70000 loop msql:='select object_id from lichao.t where
object_id='||i; execute immediate msql; end loop; end loop; end;
NOTE: cannot fetch plan for SQL_ID: bqh67d48k8ufy, CHILD_NUMBER: 0
Please verify value of SQL_ID and CHILD_NUMBER;
It could also be that the plan is no longer in cursor cache (check v$sql_plan)
以上sql正是SID 137中执行的。
测试二
Session 1 SID:73
执行语句：
declare msql varchar2(200); begin for i in 1 .. 75000 loop msql:='alter table t parallel 1'; execute immediate msql; end loop; end; /
Session 2 SID:12
执行语句：
declare msql varchar2(200); begin for i in 1 .. 75000 loop msql:='select object_id from t where object_id='||i; execute immediate msql; end loop; end;
抓取相关latch hold信息：
NAME Held Gets Held % Held ms Avg hold ms ----------------------------------- ---------- ---------- ------- ----------- ----------- cache buffers chains 35 35 .04 2.013 .058 row cache objects 25 25 .03 1.438 .058 kks stats 14 14 .01 .805 .058 redo copy 7 7 .01 .403 .058 shared pool simulator 6 6 .01 .345 .058 enqueue hash chains 4 4 .00 .230 .058 call allocation 3 3 .00 .173 .058 SQL memory manager latch 3 3 .00 .173 .058 enqueues 3 3 .00 .173 .058 SQL memory manager workarea list la 1 1 .00 .058 .058 redo allocation 1 1 .00 .058 .058 12 rows selected.
session快照信息：
--------------------------------------------------------------------------------------------------------------- ID, USERNAME , TYPE, STATISTIC , HDELTA, HDELTA/SEC, %TIME, GRAPH --------------------------------------------------------------------------------------------------------------- 73, LICHAO , STAT, opened cursors cumulative , 4.35k, 725.33, 73, LICHAO , STAT, opened cursors current , -3, -.5, 73, LICHAO , STAT, recursive calls , 15.88k, 2.65k, 73, LICHAO , STAT, recursive cpu usage , 241, 40.17, 73, LICHAO , STAT, pinned cursors current , -3, -.5, 73, LICHAO , STAT, session logical reads , 15.45k, 2.57k, 73, LICHAO , STAT, CPU used by this session , 243, 40.5, 73, LICHAO , STAT, concurrency wait time , 62, 10.33, 73, LICHAO , STAT, user I/O wait time , 22, 3.67, 73, LICHAO , STAT, non-idle wait time , 85, 14.17, 73, LICHAO , STAT, non-idle wait count , 356, 59.33, 73, LICHAO , STAT, session uga memory max , 2.09M, 348.28k, 73, LICHAO , STAT, messages sent , 163, 27.17, 73, LICHAO , STAT, session pga memory max , 1.25M, 207.53k, 73, LICHAO , STAT, enqueue requests , 737, 122.83, 73, LICHAO , STAT, enqueue releases , 737, 122.83, 73, LICHAO , STAT, physical read total IO requests , 17, 2.83, 73, LICHAO , STAT, physical read total bytes , 155.65k, 25.94k, 73, LICHAO , STAT, cell physical IO interconnect bytes , 155.65k, 25.94k, 73, LICHAO , STAT, db block gets , 539, 89.83, 73, LICHAO , STAT, db block gets from cache , 539, 89.83, 73, LICHAO , STAT, consistent gets , 14.91k, 2.48k, 73, LICHAO , STAT, consistent gets from cache , 14.91k, 2.48k, 73, LICHAO , STAT, consistent gets from cache (fastpath) , 12.27k, 2.05k, 73, LICHAO , STAT, consistent gets - examination , 2.3k, 382.5, 73, LICHAO , STAT, physical reads , 19, 3.17, 73, LICHAO , STAT, physical reads cache , 19, 3.17, 73, LICHAO , STAT, physical read IO requests , 17, 2.83, 73, LICHAO , STAT, physical read bytes , 155.65k, 25.94k, 73, LICHAO , STAT, db block changes , 835, 139.17, 73, LICHAO , STAT, change write time , 4, .67, 73, LICHAO , STAT, free buffer requested , 133, 22.17, 73, LICHAO , STAT, dirty buffers inspected , 11, 1.83, 73, LICHAO , STAT, hot buffers moved to head of LRU , 158, 26.33, 73, LICHAO , STAT, free buffer inspected , 67, 11.17, 73, LICHAO , STAT, commit cleanouts , 208, 34.67, 73, LICHAO , STAT, commit cleanouts successfully completed , 208, 34.67, 73, LICHAO , STAT, switch current to new buffer , 104, 17.33, 73, LICHAO , STAT, physical reads cache prefetch , 5, .83, 73, LICHAO , STAT, shared hash latch upgrades - no wait , 328, 54.67, 73, LICHAO , STAT, calls to kcmgcs , 12, 2, 73, LICHAO , STAT, calls to kcmgas , 426, 71, 73, LICHAO , STAT, calls to get snapshot scn: kcmgss , 4.01k, 668, 73, LICHAO , STAT, redo entries , 520, 86.67, 73, LICHAO , STAT, redo size , 236.62k, 39.44k, 73, LICHAO , STAT, redo ordering marks , 10, 1.67, 73, LICHAO , STAT, redo subscn max counts , 10, 1.67, 73, LICHAO , STAT, file io wait time , 95.11k, 15.85k, 73, LICHAO , STAT, Batched IO vector read count , 1, .17, 73, LICHAO , STAT, Batched IO vector block count , 4, .67, 73, LICHAO , STAT, Batched IO single block count , 1, .17, 73, LICHAO , STAT, Batched IO block miss count , 7, 1.17, 73, LICHAO , STAT, Batched IO double miss count , 2, .33, 73, LICHAO , STAT, Batched IO same unit count , 2, .33, 73, LICHAO , STAT, undo change vector size , 70.3k, 11.72k, 73, LICHAO , STAT, no work - consistent read gets , 12.27k, 2.05k, 73, LICHAO , STAT, deferred (CURRENT) block cleanout applic , 208, 34.67, 73, LICHAO , STAT, table scans (short tables) , 4, .67, 73, LICHAO , STAT, table scan rows gotten , 1.51k, 251, 73, LICHAO , STAT, table scan blocks gotten , 216, 36, 73, LICHAO , STAT, table fetch by rowid , 525, 87.5, 73, LICHAO , STAT, cluster key scans , 1.89k, 314.33, 73, LICHAO , STAT, cluster key scan block gets , 5k, 833.17, 73, LICHAO , STAT, rows fetched via callback , 205, 34.17, 73, LICHAO , STAT, index fetch by key , 968, 161.33, 73, LICHAO , STAT, index scans kdiixs1 , 3.59k, 597.67, 73, LICHAO , STAT, HSC Heap Segment Block Changes , 208, 34.67, 73, LICHAO , STAT, sql area purged , 103, 17.17, 73, LICHAO , STAT, sql area evicted , 13, 2.17, 73, LICHAO , STAT, CCursor + sql area evicted , 1, .17, 73, LICHAO , STAT, session cursor cache hits , 3.75k, 624.5, 73, LICHAO , STAT, session cursor cache count , 2, .33, 73, LICHAO , STAT, cursor authentications , 3, .5, 73, LICHAO , STAT, buffer is pinned count , 384, 64, 73, LICHAO , STAT, buffer is not pinned count , 9.75k, 1.63k, 73, LICHAO , STAT, workarea executions - optimal , 40, 6.67, 73, LICHAO , STAT, parse time cpu , 33, 5.5, 73, LICHAO , STAT, parse time elapsed , 136, 22.67, 73, LICHAO , STAT, parse count (total) , 2.86k, 475.83, 73, LICHAO , STAT, parse count (hard) , 211, 35.17, 73, LICHAO , STAT, execute count , 4.42k, 736.83, 73, LICHAO , STAT, sorts (memory) , 64, 10.67, 73, LICHAO , STAT, sorts (rows) , 257, 42.83, 73, LICHAO , TIME, hard parse elapsed time , 675.08ms, 112.51ms, 11.3%, |@@ | 73, LICHAO , TIME, repeated bind elapsed time , 18.01ms, 3ms, .3%, | | 73, LICHAO , TIME, parse time elapsed , 957.39ms, 159.57ms, 16.0%, |@@ | 73, LICHAO , TIME, PL/SQL execution elapsed time , 645.44ms, 107.57ms, 10.8%, |@@ | 73, LICHAO , TIME, DB CPU , 2.72s, 452.7ms, 45.3%, |@@@@@ | 73, LICHAO , TIME, sql execute elapsed time , 6.21s, 1.03s, 103.4%, |@@@@@@@@@@| 73, LICHAO , TIME, hard parse (sharing criteria) elapsed ti , 4.72ms, 786.83us, .1%, | | 73, LICHAO , TIME, DB time , 6.21s, 1.03s, 103.4%, |@@@@@@@@@@| 73, LICHAO , WAIT, db file sequential read , 94ms, 15.67ms, 1.6%, |@ | 73, LICHAO , WAIT, db file scattered read , 1.11ms, 184.83us, .0%, | | 73, LICHAO , WAIT, db file parallel read , 126.78ms, 21.13ms, 2.1%, |@ | 73, LICHAO , WAIT, latch: shared pool , 25.33ms, 4.22ms, .4%, | | 73, LICHAO , WAIT, library cache lock , 153.11ms, 25.52ms, 2.6%, |@ | 73, LICHAO , WAIT, library cache load lock , 446.16ms, 74.36ms, 7.4%, |@ | 73, LICHAO , WAIT, library cache: mutex X , 75us, 12.5us, .0%, | | -- End of Stats snap 1, end=2012-04-14 22:58:00, seconds=6
抓取cache buffers chains相关sql：
NAME SQLID Held Gets Held % Held ms Avg hold ms ----------------------------------- ------------- ---------- ---------- ------- ----------- ----------- cache buffers chains c20zmr5d5u1h3 26 26 .03 .746 .029 cache buffers chains 1mkmz2c6nr80d 25 25 .03 .718 .029 cache buffers chains 771fxqca8q3qb 3 3 .00 .086 .029 cache buffers chains 8cc6ny309xt6b 2 2 .00 .057 .029 cache buffers chains gyusama37nbcw 1 1 .00 .029 .029 cache buffers chains 92s9jym52r04q 1 1 .00 .029 .029 cache buffers chains aypbk27fmmntf 1 1 .00 .029 .029 cache buffers chains dqm554mzcqq2f 1 1 .00 .029 .029 cache buffers chains 64qbk8b6ndvmf 1 1 .00 .029 .029 cache buffers chains 2839y91kq7ukw 1 1 .00 .029 .029 cache buffers chains 02gjwu2ap25jm 1 1 .00 .029 .029 cache buffers chains 1 1 .00 .029 .029 cache buffers chains 784q868rp5tmv 1 1 .00 .029 .029
查看sql：
SQL> select*from table(dbms_xplan.display_cursor('c20zmr5d5u1h3'));
PLAN_TABLE_OUTPUT
---------------------------------------------------------------------------------------
SQL_ID c20zmr5d5u1h3, child number 0
alter table t parallel 1
NOTE: cannot fetch plan for SQL_ID: c20zmr5d5u1h3, CHILD_NUMBER: 0
Please verify value of SQL_ID and CHILD_NUMBER;
It could also be that the plan is no longer in cursor cache (check v$sql_plan)
8 rows selected.