As the relevant IOUG webpage hasn’t been updated yet, I thought to delay this announcement until the update was done – but I just found an official enough announcement (press release) by accident from Reuters site:

• http://www.reuters.com/article/2011/05/12/idUS279518+12-May-2011+BW20110512

Woo-hoo! :-)

The article itself is here:

• http://tech.e2sn.com/oracle/troubleshooting/latch-contention-troubleshooting

Thanks to IOUG crew, John Kanagaraj and everyone else who has read, used my stuff and given feedback! :-)

• http://www.cernatis.com/index.php/oracle-databases/performancetuning/107-fix-high-qlatch-cache-buffers-chainsq-waits

A common cause for cache buffers chains latch contention is that some blocks are visited and re-visited way too much by a query execution. This usually happens due to nested loops joins or FILTER loops retrieving many rows from their outer (driving) row sources and then visiting the inner row-source again for each row from driving row source. Once you manage to fix your execution plan (perhaps by getting a hash join instead of the loop), then the blocks will not be re-visited so much and the latches will be hammered much less too.

The moral of the story is that if you have latch contention in a modern Oracle database, you don’t need to start tweaking undocumented latching parameters, but reduce the latch usage instead. And Laurent has done a good job with systematically identifying the SQL that needs to be fixed.

Good stuff!

If you don’t know what LatchProfX is, read this:

• http://tech.e2sn.com/oracle/troubleshooting/latch-contention-troubleshooting

I have planned to create such index for years, but never got to it. I probably never will :) So a good way to extract the descriptions of some scripts is this (run the command in the directory where you extracted my scripts to):

Note: the single and double-quotes may get messed up when the browser tries to be smart and replace them with nicer looking characters (which Unix doesn’t recognize then). When copying & pasting this command, make sure that the single & double-quotes are the regular ones Unix shell can accept):

You can download the new versions here:

• LatchProf (reads V$ views)
• LatchProfX (reads X$ tables, but gives better info, run as SYS)

Example output (with SQLID info) is below:

SQL> @latchprof name,sid,sqlid % % 100000

-- LatchProf 1.21 by Tanel Poder ( http://www.tanelpoder.com )

NAME                                       SID SQLID               Held       Gets  Held %     Held ms Avg hold ms
----------------------------------- ---------- ------------- ---------- ---------- ------- ----------- -----------
cache buffers chains                       133 3jbwa65aqmkvm        349        348     .35      14.169        .041
simulator lru latch                        133 3jbwa65aqmkvm         51         51     .05       2.071        .041
row cache objects                          133 3jbwa65aqmkvm          5          5     .01        .203        .041
cache buffers chains                        24                        5          5     .01        .203        .041
cache buffers chains                       149 3jbwa65aqmkvm          3          3     .00        .122        .041
resmgr group change latch                   33 147a57cxq3w5y          2          2     .00        .081        .041
cache buffers chains                         9 5raw2bzx227wp          2          1     .00        .081        .081
In memory undo latch                       149 f3y38zthh270n          2          1     .00        .081        .081
active checkpoint queue latch                5                        2          1     .00        .081        .081
cache buffers chains                       149 75621g9y3xmvd          2          2     .00        .081        .041
cache buffers chains                         9 gvgdv2v90wfa7          2          2     .00        .081        .041
cache buffers chains                        33 75621g9y3xmvd          2          2     .00        .081        .041
checkpoint queue latch                       5                        1          1     .00        .041        .041
ksuosstats global area                       8                        1          1     .00        .041        .041
cache buffers lru chain                    133 3jbwa65aqmkvm          1          1     .00        .041        .041
multiblock read objects                    155 75ju2gn3s8009          1          1     .00        .041        .041
resmgr group change latch                    9 0w2qpuc6u2zsp          1          1     .00        .041        .041
resmgr group change latch                   33 apgb2g9q2zjh1          1          1     .00        .041        .041
resmgr group change latch                  133 apgb2g9q2zjh1          1          1     .00        .041        .041
space background task latch                 17                        1          1     .00        .041        .041
cache buffers chains                       149 5raw2bzx227wp          1          1     .00        .041        .041
cache buffers chains                        33 5raw2bzx227wp          1          1     .00        .041        .041
cache buffers chains                        33 05s4vdwsf5802          1          1     .00        .041        .041
cache buffers chains                        31 0yas01u2p9ch4          1          1     .00        .041        .041
cache buffers chains                         9 41zu158rqf4kf          1          1     .00        .041        .041
In memory undo latch                        33 0bzhqhhj9mpaa          1          1     .00        .041        .041
In memory undo latch                        31 gvgdv2v90wfa7          1          1     .00        .041        .041
In memory undo latch                         9 gvgdv2v90wfa7          1          1     .00        .041        .041
simulator lru latch                        149 3jbwa65aqmkvm          1          1     .00        .041        .041
row cache objects                          133 5yq51dtyc6qf2          1          1     .00        .041        .041
SQL memory manager workarea list la        133 3jbwa65aqmkvm          1          1     .00        .041        .041
enqueues                                   141                        1          1     .00        .041        .041
row cache objects                          132                        1          1     .00        .041        .041

33 rows selected.

LatchProf scripts allow you to easily identify which session and SQLID (or sqlhash in 9i) cause the latch(es) to be held the most.

Let’s check what’s the most “latch-holding” SQL reported by LatchProf:

SQL> @sqlid 3jbwa65aqmkvm

HASH_VALUE  CH# SQL_TEXT
---------- ---- ------------------------------------------------------------------------------------------------------------------------------------------------------
1432996723    0 SELECT O.ORDER_ID, LINE_ITEM_ID, PRODUCT_ID, UNIT_PRICE, QUANTITY, ORDER_MODE, ORDER_STATUS, ORDER_TOTAL, SALES_REP_ID, PROMOTION_ID, C.CUSTOMER_ID,
 CUST_FIRST_NAME, CUST_LAST_NAME, CREDIT_LIMIT, CUST_EMAIL, ORDER_DATE FROM ORDERS O , ORDER_ITEMS OI, CUSTOMERS C WHERE O.ORDER_ID = OI.ORDER_ID AND
 O.CUSTOMER_ID = C.CUSTOMER_ID AND O.ORDER_STATUS <= 4

If you want to read more about the capabilities of LatchProf and LatchProfX, go here:

• http://blog.tanelpoder.com/2008/07/09/advanced-oracle-troubleshooting-guide-part-7-sampling-latch-holder-statistics-using-latchprof/
• http://blog.tanelpoder.com/2008/07/23/advanced-oracle-troubleshooting-guide-part-8-even-more-detailed-latch-troubleshooting-using-latchprofx/

Note that the latest version (v1.21) also fixes a problem with Oracle 11.2 where the script execution plan order was wrong, causing the sampling to not happen in correct order. I added a NO_TRANSFORM_DISTINCT_AGG hint to disable a new transformation happening in 11.2 to make the scripts behave correctly…

SQL> select * from v$sgastat where lower(name) like '%sim%' order by name;

POOL         NAME                            BYTES
------------ -------------------------- ----------
shared pool  kglsim alloc latch area          1700
shared pool  kglsim alloc latches               68
shared pool  kglsim count of pinned he        9248
shared pool  kglsim free heap list             204
shared pool  kglsim free obj list              204
shared pool  kglsim hash table                4104
shared pool  kglsim hash table bkts        2097152
shared pool  kglsim heap                    635536
shared pool  kglsim latch area                1700
shared pool  kglsim latches                     68
shared pool  kglsim main lru count           87040
shared pool  kglsim main lru size           174080
shared pool  kglsim object batch            909440
shared pool  kglsim pin list arr               816
shared pool  kglsim recovery area             2112
shared pool  kglsim sga                      22092
shared pool  kglsim size of pinned mem       18496
shared pool  ksim client list                   84
shared pool  log_simultaneous_copies           480
shared pool  sim cache nbufs                   640
shared pool  sim cache sizes                   640
shared pool  sim kghx free lists                 4
shared pool  sim lru segments                  640
shared pool  sim segment hits                 1280
shared pool  sim segment num bufs              640
shared pool  sim state object                   48
shared pool  sim trace buf                    5140
shared pool  sim trace buf context             120
shared pool  sim_knlasg                       1200
shared pool  simulator hash buckets          16512
shared pool  simulator latch/bucket st        4608

31 rows selected.

See, a bunch of “kgl sim” and then just “sim” allocations.

… or sometimes you can see latch contention on following latches:

SQL> select name from v$latch where name like '%sim%';

NAME
-------------------------------------------------------
ksim membership request latch
simulator lru latch
simulator hash latch
sim partition latch
shared pool simulator
shared pool sim alloc

6 rows selected.

Again, there seems to be some “simulation” work going on in Oracle instance.

So what are these simulators about?

These simulators help Oracle to determine how much time and effort would have been saved if buffer cache or shared pool size was bigger than current. And this info is summarized and externalized in various advisor views such V$SHARED_POOL_ADVICE, V$MTTR_TARGET_ADVICE, V$DB_CACHE_ADVICE and so on. These simulation engines were introduced in Oracle 9i along the mentioned V$ views.

Also this stuff is used by MMAN for making SGA resizing decisions if SGA_TARGET (10g+) or MEMORY_TARGET (11g+) is enabled.

I decided to write an article about simulators as quite a few people have been asking me about it lately. So, I first googled around to see if someone has already written about it already and found one here. It turned out it was written by me, I just didn’t know about it anymore :)

So, I will write an edited version of my original explanation here. Note that I don’t know the exact algorithm of the simulator, just explaining the fundamentals here.

KGL simulator is the shared pool memory allocation tracking and simulation engine.

KGL=Kernel General Library cache manager, as the name says it deals with library objects such cursors, cached stored object definitions (PL/SQL stored procs, table definitions etc).

KGL simulator is used for estimating the benefit of caching if the cache was larger than currently. The general idea is that when flushing out a library cache object, it’s hash value (and few other bits of info) are still kept in the KGL simulator hash table. This stores a history of objects which were in memory in past but got flushed out. That’s the key part: we keep a history of objects flushed out (this is done by selective sampling though, not at every object flush as it would have too much overhead).

When loading a library cache object into library cache (which means that no existing such object is in there already), Oracle goes and checks the KGL simulator hash table to see whether an object with matching hash value is in there. If a matching object is found, that means that the required object had been in cache in past, but flushed out due space pressure. That’s the second important part: we know when we would have been able to (probably) just reuse an object if the shared pool had been bigger.

Using that information of how many library cache object (re)loads could have been been avoided if cache had been bigger (thanks to KGL simulator history) and also thanks to knowing how much time the (current) object reloads took, Oracle can predict how much response time would have been saved instancewide if shared pool was bigger. So, we don’t need to increase shared pool itself to measure the benefit, we simulate a bigger shared pool by just keeping a history of aged out library cache objects hash values in a special array – and that’s why there are various kglsim and simulator allocations seen in V$SGASTAT.

The simulation results are seen from v$shared_pool_advice and are used by other advisors such ADDM.

Apparently Oracle keeps track also about how much memory is pinned in the shared pool (thus can’t be flushed out) over time. This info is probably used also for estimating shared pool resize requirements as pinned memory chunks are not usable for anything else (as long as they are pinned) in the shared pool. These measurements are also done on sampling basis.

I did a little test with my lotshparses.sql script (which just runs a lot of hard parses inside a PL/SQL loop) and ran latchprofx to report which latches and why was my session using. Note the “sim” instead of usual % in the latchprofx syntax. I am interested in only these latches which have “sim” in their name in this experiment:

SQL> @latchprofx sid,name,func,hmode 146 sim 100000

-- LatchProfX 1.12 by Tanel Poder ( http://www.tanelpoder.com )

       SID NAME                                FUNC                                     HMODE              Held       Gets  Held %
---------- ----------------------------------- ---------------------------------------- ------------ ---------- ---------- -------
 146 shared pool simulator               kglsim_unpin_simhp                       exclusive           514         49     .51
 146 shared pool simulator               kglsim_upd_newhp                         exclusive           206        198     .21
 146 shared pool simulator               kglsim_scan_lru: scan                    exclusive            95         93     .10
 146 shared pool simulator               kglsim_chg_simhp_free                    exclusive            32         32     .03
 146 shared pool simulator               kglsim_chg_simhp_noob                    exclusive            32         32     .03
 146 shared pool sim alloc               kglsim_chk_heaplist: alloc               exclusive             4          3     .00
 146 shared pool sim alloc               kglsim_chk_objlist: alloc                exclusive             3          2     .00
 146 shared pool simulator               kglsim_chk_objlist: extend               exclusive             1          1     .00
 146 shared pool simulator               kglsim_scan_lru: rebalance               exclusive             1          1     .00

This simulation engine is pretty cool because its the first time someone has tried to measure the time what could be saved by increasing shared pool size. (Response) Time is the ultimate measure of performance, so this simulator measures the right thing. Do you remember what people used before that? Library cache hit ratio! A lot of people back then (and some still today) have been misleaded by measuring the wrong things like hit ratios.

Anyway, while this is a cool feature – it can cause trouble in big systems. This is because the extra CPU usage for simulation and also the potential concurrency issues like simulator latch contention (like the shared pool simulator latch above, these latches are used even on 11g where most library cache latches have been replaced with KGX mutexes for efficiency and avoiding false contention issues). Also, some people are sensitive about the potential large memory allocations the shared pool simulator can take from shared pool (this is controlled by _kglsim_max_percent parameter which defaults to max 5% of total shared pool size). As these allocations are dynamic, then when your application suddenly starts making lots of hard parses due newly released code, causing memory shortage, then the simulator can make things even worse as it can make relatively big allocations for itself too! And as far as I know the simulator arrays don’t shrink back.

Note that I’m talking about big systems here, in most other cases the simulation shouldn’t cause trouble (on recent db versions anyway).

In some databases I have disabled all of the advisors and simulators with setting statistics_level = basic. All features what you see from V$STATISTICS_LEVEL would be disabled when setting statistics_level to basic:

SQL> select statistics_name,activation_level from v$statistics_level;

STATISTICS_NAME                          ACTIVAT
---------------------------------------- -------
Buffer Cache Advice                      TYPICAL
MTTR Advice                              TYPICAL
Timed Statistics                         TYPICAL
Timed OS Statistics                      ALL
Segment Level Statistics                 TYPICAL
PGA Advice                               TYPICAL
Plan Execution Statistics                ALL
Shared Pool Advice                       TYPICAL
Modification Monitoring                  TYPICAL
Longops Statistics                       TYPICAL
Bind Data Capture                        TYPICAL
Ultrafast Latch Statistics               TYPICAL
Threshold-based Alerts                   TYPICAL
Global Cache Statistics                  TYPICAL
Active Session History                   TYPICAL
Undo Advisor, Alerts and Fast Ramp up    TYPICAL
Streams Pool Advice                      TYPICAL
Time Model Events                        TYPICAL
Plan Execution Sampling                  TYPICAL
Automated Maintenance Tasks              TYPICAL
SQL Monitoring                           TYPICAL
Adaptive Thresholds Enabled              TYPICAL
V$IOSTAT_* statistics                    TYPICAL
.
23 rows selected.

Sometimes you don’t want to disable absolutely everything, but only the troublemakers. The good news is that there’s an (undocumented) parameter for disabling every feature separately. As always, make sure that you know what you’re doing before changing these and get blessing from Oracle support in order to not get yourself in trouble.

So, for example the library cache memory simulation (shared pool advice) can be disabled by setting _library_cache_advice = false .

I covered shared pool and library cache above. Oracle has more cache advisors, the underlying principle in them is the same. They save some small metadata/info about flushed out objects in a simulator array and just check that array when someone is allocating memory for new object. If matching object’s metadata still happens to be in the simulator array, then Oracle knows that we could have avoided the time and effort loading (generating) that object back into memory if the corresponding cache had been bigger. Of course the algorithm must be more sophisticated than just checking for object’s existence, there are probably object’s flush timestamp and size stored in the simulator arrays as well.

While the library cache simulator array stores library cache objects hash values for looking up historical memory allocations metadata, then the buffer cache advisor stores just data block addresses (DBAs) of blocks previously in cache. When Oracle spots that a block was previously in cache while intiating physical IO for re-reading it back again, it will measure the time it took to complete the current physical IO and add this info into the simulator array. Again, that’s how Oracle can measure how much response time would have been saved if the block would still have been in the buffer cache.

The buffer cache advisor needs some special attention, as I have had most issues with that (on large systems again), mostly with buffer cache’s simulator lru latch contention in systems with lots of CPUs and physical IOs going on. The problem here is that even though you can have hundreds of thousands of cache buffers chains latches in a system, the number of simulator lru latches remains relatively low by default, causing contention.

Oracle provides a documented parameter for disabling the buffer cache simulation – you need to set db_cache_advice = off (or ready).

So, hopefully this sheds some light into how the advisors work and what the heck the simulators simulate in Oracle. Even though I provided a list of parameters which allow you to control this stuff – don’t change any of them unless you actually have a problem which they should fix (and you are sure that these parameters would fix your problem).

Update:

Jonathan Lewis has written a good article about buffer cache advisor details on his website – I recommend to read that one too if you’re interested in this stuff:

http://www.jlcomp.demon.co.uk/Cache_advice.html

SQL> @bhla 27E5A780  <-- latch address reported by wait interface (Parameter1 in latch: cache buffers chains wait event)

FLG_LRUFLG                 OBJ OBJECT_TYPE         object                                          TCH DBA     
------------------- ---------- ------------------- ---------------------------------------- ---------- ---------
80000:8                      2 TABLE               SYS.SUBCOLTYPE$                                   0 1 7873  
80000:8                      2 TABLE               SYS.ATTRCOL$                                      0 1 7873  
0:0                      50472 INDEX               SYSMAN.MGMT_JOB_EXEC_IDX04                        1 3 27699 
0:0                      50472 INDEX               SYSMAN.MGMT_JOB_EXEC_IDX04                        1 3 27699 
0:4                      50472 INDEX               SYSMAN.MGMT_JOB_EXEC_IDX04                        1 3 27699 
2202000:8                 3710 TABLE               SYS.WRI$_ADV_REC_ACTIONS                          1 3 972   
0:0                      50472 INDEX               SYSMAN.MGMT_JOB_EXEC_IDX04                        1 3 27699 
0:0                      50472 INDEX               SYSMAN.MGMT_JOB_EXEC_IDX04                        1 3 27699 
2202000:8                94227 TABLE PARTITION     SYS.WRH$_ROWCACHE_SUMMARY                         2 3 36142 
80000:8                  54880 INDEX               PERFSTAT.STATS$UNDOSTAT_PK                       14 4 118331
0:8                         37 INDEX               SYS.I_OBJ2                                       24 1 55591 
2000:8                    3680 TABLE               SYS.WRI$_ADV_TASKS                               26 3 739   
0:8                         75 TABLE               SYS.IDL_UB2$                                     35 1 11745 
0:8                         73 TABLE               SYS.IDL_UB1$                                     38 1 12211

From above we see that this child latch is protecting many blocks in buffer cache. So which one is the troublemaker? This is where the touchcount (TCH column) has been traditionally used, the higher the TCH the hotter the buffer, right?

Actually this may not always be true. For example if there is a somewhat hot block which has been steadily in buffer cache for weeks, it may have very high touch count. Now if there is an extremely hot block used by every morning’s batch job (and causing the trouble) but not used later on in the day, this block will get aged out later in the day. Once a block is aged out, its metadata, including TCH is gone! So when the block is loaded back in next morning (causing trouble again), its touch count starts from zero again.

So, by just looking into touchcount numbers you can’t always reliably detect who’s the current troublemaker. One option here would be to query the touchcounts, then wait for a minute, query the touchcounts again and see who’s touchcount increased the most during the minute. This would give a bit better picture about who is causing trouble now.

But still, it would not be always reliable for another reason – touchcounts are incremented only after 3 seconds have passed since last increment! This factor has been coded in to avoid situation such a short but crazy nested loop join hammering a single buffer hundreds of thousands of times in few seconds and then finishing. The buffer wouldn’t be hot anymore but the touchcount would be hundreds of thousands due a single SQL execution. So, unless 3 seconds (of SGA internal time) has passed since last TCH update, the touchcounts would not be increased during buffer access.

This time is controlled by SGA variable kcbatt_ by the way:

SQL> oradebug dumpvar sga kcbatt_
ub4 kcbatt_ [3C440F4, 3C440F8) = 00000003

This 3-second delay leaves us in the following situation, let say there are 2 blocks protected by a CBC child latch:

One block has been accessed once every 3 seconds for 24 hours in a row. A block accessed once per 3 seconds is definitely not a hot block, but its touchcount would be around 28800 (86400 seconds per 24 hours / 3 = 28800).

And there is another block which is accessed crazily for 2 seconds in a row and this happens every 10 seconds. 2 seconds of consecutive access would increase the touchcount by 1. If such access pattern has been going on every 10 seconds over last 24 hours, then the touch count for that buffer would be 86400 / 10 = 8640.

In the first case we can have a very cold block with TCH = 28800 and in second case a very hot block with TCH = 8640 only and this can mislead DBAs to fixing the wrong problem.

Luckily this problem can be solved with LatchProfX :-)

If you don’t know what LatchProfX is, you may want to read these articles first – LatchProf gives you a better way for latch contention troubleshooting compared to old approaches:

• http://blog.tanelpoder.com/2008/07/09/advanced-oracle-troubleshooting-guide-part-7-sampling-latch-holder-statistics-using-latchprof/
• http://blog.tanelpoder.com/2008/07/23/advanced-oracle-troubleshooting-guide-part-8-even-more-detailed-latch-troubleshooting-using-latchprofx/
• http://blog.tanelpoder.com/2009/03/20/another-latchprofx-use-case/

And now I introduce a new feature in LatchProfX.

In addition to being able to report the SID of the latch holder and the kernel function why this latch was taken by the session, the newest LatchProfX can also report the object what was protected by the latch under investigation. For cache buffers chains the object is data block address of the block being accessed.

Here’s an example, let say I have CBC latch contention problems and from monitoring tools or sql_trace I have identified the hot latch, I use my sw.sql script here, to report what a session is waiting for:

SQL> @sw 138
 SID STATE   EVENT                        SEC_IN_WAIT                 P1
------- ------- ---------------------------- ----------- ------------------
    138 WAITING latch: cache buffers chains            0 address=0x27E5A780

Sw reports that this session is waiting on cache buffer chains child latch with address 0x27E5a780.

Now we can run latchprofx and report sid, name, hold mode and protected object for that child latch only (instead of latch name we specified its address):

SQL> @latchprofx sid,name,hmode,object % 27E5A780 100000

 SID NAME                   HMODE         OBJECT   Held  Gets  Held %  Held ms
---- ---------------------- ------------ ------- ------ ----- ------- --------
 138 cache buffers chains   exclusive     40EB02   3928  3797    3.93   41.637
 151 cache buffers chains   exclusive     40EB02   3711  3660    3.71   39.337
 138 cache buffers chains   shared        40EB02    623   623     .62    6.604
 151 cache buffers chains   shared        40EB02    544   544     .54    5.766

As you see, LatchProfX has reported a data block address in the object column. This is the datablock we are trying to access in buffer cache under protection of the given child latch.

Lets see what this DBA translates to:

SQL> @dba 40EB02

 RFILE#     BLOCK#
---------- ----------
         1      60162

Press enter to find the segment using V$BH (this may take CPU time), CTRL+C to cancel:

STATE      BLOCK_CLASS        OBJECT_TYPE         object                                          TCH  MODE_HELD
---------- ------------------ ------------------- ---------------------------------------- ---------- ----------
xcur       data block         INDEX               SYS.SYS_IOT_TOP_94276                           331          1

Press enter to query what segment resides there using DBA_EXTENTS (this can be IO intensive), CTRL+C to cancel:

OWNER                          SEGMENT_NAME         PARTITION_NAME  TABLESPACE_NAME
------------------------------ -------------------- --------------- -----------------
SYS                            SYS_IOT_TOP_94276                    SYSTEM
So, the troublemaker is an IOT index segment block belonging to table with object_id 94276. I can find the table name from dba_objects by object_id, or by using my script:

SQL> @oid 94276

owner                     object_name                    object_type        CREATED
------------------------- ------------------------------ ------------------ -----------------
SYS                       KILL_CPU                       TABLE              20090825 23:19:49

Also, as we know the segment name and relative file number (RFILE#) and block number (BLOCK#)  from above output we can dump the datablock with an ALTER SYSTEM DUMP DATAFILE command.

As that command requires absolute file id (not relative) we have to do a little conversion first (in cases where there are multiple files with same relative file number in database):

SQL> select file_id from dba_extents where relative_fno = 1 and segment_name = 'SYS_IOT_TOP_94276';

 FILE_ID
----------
 1

Of course in my little test case all relative file numbers match with absolute numbers (but if you have lots of datafiles, have directly migrated from Oracle 7 or use transportable tablespaces, you may hit this issue).

Finally I can run ALTER SYSTEM DUMP DATAFILE 1 BLOCK 60162 to find out more about the contents of that block. Another option would be to construct a rowid from the data_object_id, rfile and block and query the table using that but as that’s complicated for IOTs, I’ll leave this to a future post.

You can download latest version of LatchProfX here:

• http://www.tanelpoder.com/files/scripts/latchprofx.sql

I used Snapper v2.0 beta during my demos there and also an improved version of LatchProfX which can give some additional context information about reasons why latches were taken. As they are beta, not final versions, I have uploaded them into a temporary location:

Update: These scripts are out of beta now so here are their permanent locations:

• http://www.tanelpoder.com/files/scripts/snapper.sql
• http://www.tanelpoder.com/files/scripts/latchprofx.sql

Also, the Sesspack (session level statspack) v0.05 files are in my TPT script set, under tools/sesspack_v0.05 directory in the zip file:

• http://www.tanelpoder.com/files/TPT_public.zip

Toine van Beckhoven attended the seminar as well and wrote a review of it, if you’re still hesitating if you should attend as well, read his review first :)

Especially if the latch contention problem is ongoing, looking into system wide stats (like v$latch.sleep columns) is not the best idea in busy systems. This may sometimes lead you to fixing the wrong problem.

This is because sometimes the latch contention is not caused by some system wide inefficiency but rather by one or few sessions.

The right approach would be to measure the following things:

1. Which latch (and exact child latches) the problem session is waiting for (query v$session_wait, ASH, sql_trace)
2. Why is the problem session trying to get that latch so often (query v$sesstat counters for problem session and check execution plan if only single/few statements executed)
3. Why this latch is busy: who’s holding it (query v$latchholder, LatchProf)
4. Why is that someone holding the latch so much (query v$sesstat counters for that session or run LatchProfX)

Riyaj used this approach and successfully found out the troublemaker causing heavy library cache latch contention. He used my LatchProfX tool for part of the diagnosis (and I’m very happy to see that my advanced oracle troubleshooting tools find real world use in hands of other troubleshooters/tuners too!).

Here’s an excerpt from latchprofx output (from a little test case I put together), showing which session is holding which library cache latch how much, hold mode (shared/exclusive) and also the actual reason (function name) why the latch is held:

SQL> @latchprofx sid,name,laddr,ksllwnam,ksllwlbl,hmode 159 % 100000

-- LatchProfX 1.08 by Tanel Poder ( http://www.tanelpoder.com )

 SID NAME           LADDR            KSLLWNAM  KSLLWLBL  HMODE        Held  Gets  Held %  Held ms Avg hold ms
---- -------------- ---------------- --------- --------- ---------- ------ ----- ------- -------- -----------
 159 library cache  00000003A93513E0 kglic     child     exclusive   10044  9314   10.04  301.320        .032
 159 library cache  00000003A9351340 kglic     child     exclusive    9895  8458    9.90  296.850        .035
 159 library cache  00000003A9351660 kglic     child     exclusive    9761  8440    9.76  292.830        .035
 159 library cache  00000003A9351700 kglic     child     exclusive    9737  8924    9.74  292.110        .033
 159 library cache  00000003A9351480 kglic     child     exclusive    8999  7765    9.00  269.970        .035
 159 library cache  00000003A93515C0 kglic     child     exclusive    8553  7832    8.55  256.590        .033
 159 library cache  00000003A9351520 kglic     child     exclusive    6852  6828    6.85  205.560        .030

7 rows selected.

kglic means Kernel Generic Library cache Iterate Chain (AFAIK), it’s the function which is executed when you access most X$KGL tables. And this is where Riyaj got the evidence that the latch contention comes from inefficient scanning of library cache, caused by a session running queries against V$SQL_PLAN views with a bad plan.

So, check out Riyaj’s articele, my LatchProfX script, my Latch & Mutex contention troubleshooting conference slides and if you want more, then my Advanced Oracle Troubleshooting Seminar. I recently added Dallas, Denver, Salt Lake City and Hong-Kong to the list of cities where you can attend it this year!

Thanks to everyone who attended!

I have uploaded the slides here: http://www.tanelpoder.com/files/Advanced_Oracle_Troubleshooting.pdf

PerfSheet (the Excel based automatic data visualization tool) is uploaded here: http://www.tanelpoder.com/files/PerfSheet.zip

The TPT scripts (scripts like snapper, latchprofx, ostackprof etc I demoed and a lot more) are uploaded here: http://www.tanelpoder.com/files/TPT_public.zip

Few links to my past blog entries about how to use Snapper, LatchProfX and os_explain:

• Advanced Oracle Troubleshooting Guide, part 8: LatchProfX
• Oracle Session Snapper v1.06 released
• Advanced Oracle Troubleshooting Guide, part 6: os_explain

I haven’t blogged about usage of OStackProf yet (as the tool’s very fresh), I will do so in coming week.

Feel free to send any further questions to tanel@tanelpoder.com

Also, if you liked my presentation, you will sure like my 2-day seminar on the same topic. I will go even deeper in there ;-)

Check out this page: http://blog.tanelpoder.com/seminar/. I’ve arranged my seminar in 18 cities already for 2008 and early 2009, if your city is not in the list, let me know and I’ll see what I can do :)

Thanks once more for everyone attending my OOW presentation and also my blog readers for continued support!

Have you noticed that DML on tables residing in SYSTEM tablespace is slower than tables in other tablespaces?

Here’s an example, I’ll create two similar tables, one in USERS tablespace, other in SYSTEM, and inset into the first one (Oracle 10.2.0.3 on Solaris x64):

SQL> create table t1(a int) tablespace USERS;

Table created.

SQL> create table t2(a int) tablespace SYSTEM;

Table created.

SQL> exec for i in 1..100000 loop insert into t1 values(i); end loop;

PL/SQL procedure successfully completed.

Elapsed: 00:00:03.09

Insert into table in USERS tablespace took 3 seconds.

Ok, let’s commit and flush dirty buffers that they wouldn’t get on the way of next insert.

SQL> commit;

Commit complete.

Elapsed: 00:00:00.02

SQL> alter system checkpoint; -- checkpointing to flush dirty buffers from previous inserts

System altered.

Elapsed: 00:00:01.34
SQL>

And now to the insert into the SYSTEM tablespace table:

SQL> exec for i in 1..100000 loop insert into t2 values(i); end loop;

PL/SQL procedure successfully completed.

Elapsed: 00:00:08.98
SQL>

What?! The same insert took 3 times longer, almost 9 seconds?

Fine! Let’s troubleshoot it!

First (as usual) I start from my Snapper for getting a performance snapshot of the session. I ran both inserts again and used Snapper from another session to monitor the insert activity (for brevity I didn’t monitor all stat counters, but used the sinclude filter to leave only various “gets” in from V$SESSTAT).

This is the insert to USERS tablespace table:

SQL> @snapper out,gather=tsw,sinclude=gets 10 1 148

-- Session Snapper v1.07 by Tanel Poder ( http://www.tanelpoder.com )

---------------------------------------------------------------------------------------------------------------------------------------------
HEAD,     SID, SNAPSHOT START   ,  SECONDS, TYPE, STATISTIC                               ,         DELTA,  DELTA/SEC,     HDELTA, HDELTA/SEC
---------------------------------------------------------------------------------------------------------------------------------------------
DATA,     148, 20080901 17:20:53,       10, STAT, db block gets                           ,        103448,      10345,    103.45k,     10.34k
DATA,     148, 20080901 17:20:53,       10, STAT, db block gets from cache                ,        103448,      10345,    103.45k,     10.34k
DATA,     148, 20080901 17:20:53,       10, STAT, consistent gets                         ,           495,         49,        495,       49.5
DATA,     148, 20080901 17:20:53,       10, STAT, consistent gets from cache              ,           495,         49,        495,       49.5
DATA,     148, 20080901 17:20:53,       10, STAT, consistent gets - examination           ,           219,         22,        219,       21.9
DATA,     148, 20080901 17:20:53,       10, STAT, no work - consistent read gets          ,            89,          9,         89,        8.9
DATA,     148, 20080901 17:20:53,       10, STAT, rollbacks only - consistent read gets   ,            18,          2,         18,        1.8
DATA,     148, 20080901 17:20:53,       10, STAT, cluster key scan block gets             ,            65,          6,         65,        6.5
DATA,     148, 20080901 17:20:53,       10, TIME, hard parse elapsed time                 ,          4090,        409,     4.09ms,      409us
DATA,     148, 20080901 17:20:53,       10, TIME, PL/SQL compilation elapsed time         ,          3139,        314,     3.14ms,    313.9us
DATA,     148, 20080901 17:20:53,       10, TIME, parse time elapsed                      ,          5131,        513,     5.13ms,    513.1us
DATA,     148, 20080901 17:20:53,       10, TIME, PL/SQL execution elapsed time           ,        174288,      17429,   174.29ms,    17.43ms
DATA,     148, 20080901 17:20:53,       10, TIME, DB CPU                                  ,       3108026,     310803,      3.11s,    310.8ms
DATA,     148, 20080901 17:20:53,       10, TIME, sql execute elapsed time                ,       3104607,     310461,       3.1s,   310.46ms
DATA,     148, 20080901 17:20:53,       10, TIME, hard parse (sharing criteria) elapsed ti,          4110,        411,     4.11ms,      411us
DATA,     148, 20080901 17:20:53,       10, TIME, DB time                                 ,       3108026,     310803,      3.11s,    310.8ms
DATA,     148, 20080901 17:20:53,       10, WAIT, log file switch completion              ,         71104,       7110,     71.1ms,     7.11ms
DATA,     148, 20080901 17:20:53,       10, WAIT, SQL*Net message to client               ,             3,          0,        3us,       .3us
DATA,     148, 20080901 17:20:53,       10, WAIT, SQL*Net message from client             ,       6684030,     668403,      6.68s,    668.4ms
--  End of snap 1

PL/SQL procedure successfully completed.

You see, the DB CPU equals to DB time (in other words all the time spent servicing my request in database was spent on CPU, thus there were no waits, blocks involved). And the insert still took roughly 3 seconds.

This is the insert to SYSTEM tablespace table:

SQL> @snapper out,gather=tsw,sinclude=gets 10 1 148

-- Session Snapper v1.07 by Tanel Poder ( http://www.tanelpoder.com )

---------------------------------------------------------------------------------------------------------------------------------------------
HEAD,     SID, SNAPSHOT START   ,  SECONDS, TYPE, STATISTIC                               ,         DELTA,  DELTA/SEC,     HDELTA, HDELTA/SEC
---------------------------------------------------------------------------------------------------------------------------------------------
DATA,     148, 20080901 17:21:23,       11, STAT, db block gets                           ,        102616,       9329,    102.62k,      9.33k
DATA,     148, 20080901 17:21:23,       11, STAT, db block gets from cache                ,        102616,       9329,    102.62k,      9.33k
DATA,     148, 20080901 17:21:23,       11, STAT, consistent gets                         ,           384,         35,        384,      34.91
DATA,     148, 20080901 17:21:23,       11, STAT, consistent gets from cache              ,           384,         35,        384,      34.91
DATA,     148, 20080901 17:21:23,       11, STAT, consistent gets - examination           ,           218,         20,        218,      19.82
DATA,     148, 20080901 17:21:23,       11, STAT, no work - consistent read gets          ,            94,          9,         94,       8.55
DATA,     148, 20080901 17:21:23,       11, STAT, rollbacks only - consistent read gets   ,            17,          2,         17,       1.55
DATA,     148, 20080901 17:21:23,       11, STAT, cluster key scan block gets             ,            65,          6,         65,       5.91
DATA,     148, 20080901 17:21:23,       11, TIME, hard parse elapsed time                 ,          2350,        214,     2.35ms,   213.64us
DATA,     148, 20080901 17:21:23,       11, TIME, PL/SQL compilation elapsed time         ,          1751,        159,     1.75ms,   159.18us
DATA,     148, 20080901 17:21:23,       11, TIME, parse time elapsed                      ,          3359,        305,     3.36ms,   305.36us
DATA,     148, 20080901 17:21:23,       11, TIME, PL/SQL execution elapsed time           ,        172153,      15650,   172.15ms,    15.65ms
DATA,     148, 20080901 17:21:23,       11, TIME, DB CPU                                  ,       8751163,     795560,      8.75s,   795.56ms
DATA,     148, 20080901 17:21:23,       11, TIME, sql execute elapsed time                ,       8749139,     795376,      8.75s,   795.38ms
DATA,     148, 20080901 17:21:23,       11, TIME, hard parse (sharing criteria) elapsed ti,          2367,        215,     2.37ms,   215.18us
DATA,     148, 20080901 17:21:23,       11, TIME, DB time                                 ,       8751163,     795560,      8.75s,   795.56ms
DATA,     148, 20080901 17:21:23,       11, WAIT, SQL*Net message to client               ,             3,          0,        3us,      .27us
DATA,     148, 20080901 17:21:23,       11, WAIT, SQL*Net message from client             ,      -1442849,    -131168,     -1.44s,  -131.17ms
--  End of snap 1

PL/SQL procedure successfully completed.

You see the DB Time is still equal to DB CPU, thus all response was spent on CPU. Moreover, the time model stats tell me that all the elapsed time was spent executing SQL statements (which makes sense as I’m running INSERT SQL in a tight loop).

So, for some reason the INSERT SQL statements take almost 3 times longer when inserting to SYSTEM tablespace.

In cases where there is no waiting going on (things like Oracle Wait Interface / WaitProf would not help here), but only difference in CPU time, I normally look into V$SESSTAT counter differences first. But as seen from above, there is no major difference in counters such logical IOs (db block gets, consistent gets) to justify 3x increase in CPU usage (also there was no major difference in other counters which I have excluded for brevity).

So, the obvious next step is to sample the process stack during execution of both statements and see where the difference is. In my previous posts I’ve used pstack for getting a few stack samples out of a process and a pstack loop could be used here as well.

But for demo purposes (and convenience) I will use my DTrace stack sampling script today.

It’s dead easy to sample user process and kernel stacks using DTrace in Solaris 10 (and MacOS X and FreeBSD too). However the DTrace stack aggregator also takes account of the current program counter offset inside functions when distinguishing between stacks (this means that CPU program counter location main() + 0×10 will be different from main() + 0×12). But I don’t want such granularity, I want to see where the execution was at function level, not instruction level.

So I wrote my script to strip off the PC function offsets from DTrace output and order the stacks the way that most frequently sampled stack “branch” is displayed last, in bottom of the output. So, whatever stack and function you see outputted last, is probably the “troublemaker”. I still recommend scrolling up and reviewing few other stacks too.

So, I ran the insert to USERS tablespace table again and ran my dstackprof script on the server process with SPID 859.

This is from the “well behaving” process, so normally you should just compare this stack profile to the “bad behaving” process stack profile and see if you can spot any major differences in these. I will explain few of the functions on the go.

# ./dstackprof.sh 859

DStackProf v1.02 by Tanel Poder ( http://www.tanelpoder.com )
Sampling pid 859 for 5 seconds with stack depth of 100 frames...

147 samples with stack below
__________________
kcbchg1_main
kcbchg1                 <- buffer change function in buffer cache layer
ktuchg                    <- undo layer generate change
ktbchg2                  <- block (header) change
kdtchg                    <- data layer generate change
kdtwrp
kdtInsRow              <- data layer row insert function
insrowFastPath
insdrvFastPath
inscovexe
insExecStmtExecIniEngine
insexe                   <- OPI insert execution entry point
opiexe                   <- OPI execute (executing my recursive INSERT INTO statement)
opipls
opiodr
rpidrus                  <- all the RPI functions belong to recursive program interface (which allows making recursive calls in db)
skgmstack
rpidru                    <- these RPI functions (and few OPI ones above) are what PL/SQL context switches physically are
rpiswu2
rpidrv
psddr0                  <- most of the functions starting with "p" are PL/SQL execution ones
psdnal
pevm_EXECC
pfrinstr_EXECC
pfrrun_no_tool
pfrrun
plsql_run
peicnt                    <- PL/SQL execution engine entry point
kkxexe                  <- cursor to PL/SQL execution interface
opiexe                   <- OPI call execution dispatcher
kpoal8
opiodr
ttcpip
opitsk
opiino
opiodr
opidrv
sou2o
opimai_real
main
0xe54ffc

193 samples with stack below
__________________
libc.so.1`times         <-- during these 193 samples the execution was in opiexe (note that
opiexe                   -- it's a recursive OPI call execution (as there's the RPI layer below in the
opipls                    -- stack and there's another opiexe below. The lower opiexe is for executing
opiodr                   -- my PL/SQL anonymous block and upper is for the recursive INSERT statement
rpidrus
skgmstack
rpidru
rpiswu2
rpidrv
psddr0
psdnal
pevm_EXECC
pfrinstr_EXECC
pfrrun_no_tool
pfrrun
plsql_run
peicnt
kkxexe
opiexe
kpoal8
opiodr
ttcpip
opitsk
opiino
opiodr
opidrv
sou2o
opimai_real
main
0xe54ffc

3147 Total samples captured

Anyway, the two stacks which I have copied here don’t show anything obvious. And also, see that there were total 3147 samples taken when the process was on CPU. But the execution point was in the “top” stack during only 193 samples, which is around 6% of all samples.

As the above stacks come from a well-behaving process, let’s leave their deeper analysis and just compare them to the bad-behaving process. So, I ran the SYSTEM tablespace insert again (you still remember, we were troubleshooting why inserts into system tablespace were slower, right ;)

The top stack in profile was following:

# ./dstackprof.sh 859

DStackProf v1.02 by Tanel Poder ( http://www.tanelpoder.com )
Sampling pid 859 for 5 seconds with stack depth of 100 frames...

[...some output snipped...]


917 samples with stack below
__________________
libc.so.1`qsort
kd4_entries_overlap
kdb4chk
kd4chk
kcbchk
kco_blkchk    <-- what the heck is this? the name suggests that it's block checking of some kind
kcoapl
kcbapl
kcrfw_redo_gen             <-- also note this function, looks like the block change function (kcbchg) has called
kcbchg1_main                   <-- a function to generate redo on its behalf
kcbchg1
ktuchg
ktbchg2
kdtchg
kdtwrp
kdtInsRow
insrowFastPath
insdrvFastPath
inscovexe
insExecStmtExecIniEngine
insexe
opiexe
opipls
opiodr
rpidrus
skgmstack
rpidru
rpiswu2
rpidrv
psddr0
psdnal
pevm_EXECC
pfrinstr_EXECC
pfrrun_no_tool
pfrrun
plsql_run
peicnt
kkxexe
opiexe
kpoal8
opiodr
ttcpip
opitsk
opiino
opiodr
opidrv
sou2o
opimai_real
main
0xe54ffc

6202 Total samples captured

As most of the top stacks from the bad behaving process were spending their time somewhere in kco_blkchk() function, it rang a bell – database block checking!

However it was weird as the db_block_checking parameter was set false in my instance:

SQL> show parameter db_block_checking

NAME                                 TYPE        VALUE
------------------------------------ ----------- -----
db_block_checking                    string      FALSE
SQL>

After a little digging, I found this parameter:

NAME                          VALUE     DESCRIPTION
----------------------------- --------- -------------------------------------------------------------
_db_always_check_system_ts    TRUE      Always perform block check and checksum for System tablespace

This parameter makes Oracle (since version 8.1.6) do block structure checking in SYSTEM tablespace even if db_block_checking itself is set to FALSE. Considering the criticality of data dictionary objects, it’s a good idea.

So, now you might say: so what that there’s a performance issue, you shouldn’t keep your application tables in SYSTEM tablespace anyway!

Well, I have three words for you: AUD$, FGA_LOG$, DEF$_AQCALL :)

If you rely on auditing functionality heavily and especially if you use advanced replication, having the crucial tables (and associated LOB segments) in SYSTEM tablespace can mean quite a hit to your CPUs and system throughput. In which cases you probably would want to explore the option of moving these tables out of system tablespace.

Warning: before moving anything, consult Metalink or Oracle Support as only few strictly defined ways for moving these object are supported. See notes 731908.1 for Audit and 1037317.6 for Advanced Replication.

So, the key point of this article is that I could have started guessing or setting various events or undocumented parameters for probing Oracle here and there, for figuring out what’s going on. But I used a simple systematic approach instead. When Oracle Wait Interface and V$SESSTAT counters didn’t help, looked into process stack next. And this gave me the vital clue (kdo_blkchk) that there’s block checking going on. And if I hadn’t figured out the cause myself, I would have had some solid evidence for support.

Note that you don’t have to use DTrace for this kind of stack profiling (even though it is very convenient). On non-Solaris 10 OS’es I would use whatever safe stack dump mechanism is available (pstack for example) and post-process the results. I probably wouldn’t take thousands of samples though, but probably 100 or even less.

Also, if you want to get a complete overview of the process execution profile, you would need to do much more complex aggregations, as you’d need to aggregate “child” branches of stack samples with their “parents” (currently the samples of a backtrace “a->b->c” are not accounted in “a->b” for example). But for my case (just checking if there’s any major difference between execution profiles) this approach was good enough.

By the way (if you haven’t given up yet :), check the differences in LatchProfX output. The top is from well-behaving process and bottom one is the bad one:

SQL> @latchprofx sid,name,ksllwnam,ksllwlbl 128 % 1000000

-- LatchProfX 1.06 by Tanel Poder ( http://www.tanelpoder.com )

       SID NAME                                KSLLWNAM                                 KSLLWLBL                   Held       Gets  Held %     Held ms Avg hold ms
---------- ----------------------------------- ---------------------------------------- -------------------- ---------- ---------- ------- ----------- -----------
       128 redo copy                           kcrfw_redo_gen: nowait                   latch                     49399      48937    4.94     674.790        .014
       128 cache buffers chains                kcbchg1: kslbegin: bufs not pinned                                  4574       2320     .46      62.481        .027
       128 cache buffers chains                kcbchg1: kslbegin: call CR func                                     2101       1445     .21      28.700        .020
       128 cache buffers chains                kcbgcur_2                                                           1323       1060     .13      18.072        .017
       128 cache buffers chains                kcbnew: new latch again                                              269        243     .03       3.675        .015
       128 simulator lru latch                 kcbs_simulate: simulate set              setid                       170        170     .02       2.322        .014
       128 redo allocation                     kcrfw_redo_gen: redo allocation 1        strand #                     68         13     .01        .929        .071
       128 cache buffers chains                kcbrls_2                                                              29         29     .00        .396        .014
       128 cache buffers chains                kcbgtcr: fast path                                                    25         25     .00        .342        .014
       128 cache buffers chains                kcbgcur: fast path (shr)                                               8          8     .00        .109        .014
       128 cache buffers lru chain             kcbzgws_1                                                              7          7     .00        .096        .014

SQL> @latchprofx sid,name,ksllwnam,ksllwlbl 128 % 1000000

-- LatchProfX 1.06 by Tanel Poder ( http://www.tanelpoder.com )

       SID NAME                                KSLLWNAM                                 KSLLWLBL                   Held       Gets  Held %     Held ms Avg hold ms
---------- ----------------------------------- ---------------------------------------- -------------------- ---------- ---------- ------- ----------- -----------
       128 redo copy                           kcrfw_redo_gen: nowait                   latch                    356465      79839   35.65    6088.422        .076
       128 cache buffers chains                kcbchg1: kslbegin: bufs not pinned                                  4704       2233     .47      80.344        .036
       128 cache buffers chains                kcbchg1: kslbegin: call CR func                                     3542       1997     .35      60.497        .030
       128 cache buffers chains                kcbgcur_2                                                           1929       1448     .19      32.947        .023
       128 redo allocation                     kcrfw_redo_gen: redo allocation 1        strand #                   1018         34     .10      17.387        .511
       128 shared pool simulator               kglsim_unpin_simhp: fast path                                        713        713     .07      12.178        .017
       128 simulator lru latch                 kcbs_simulate: simulate set              setid                       266        266     .03       4.543        .017
       128 cache buffers chains                kcbnew: new latch again                                              182        171     .02       3.109        .018
       128 cache buffers chains                kcbgtcr: fast path (cr pin)                                           29         29     .00        .495        .017
       128 cache buffers chains                kcbgtcr: fast path                                                    15         15     .00        .256        .017

See, how the redo copy latches were held for much longer (both total time and average time of individual hold) when the block checking was enabled. This indicates that in addition to keeping the buffer pinned, also a redo copy latch is held during block checking (if not using an IMU transaction). If you use high-throughput advanced replication, think that CPU usage is too high for work done and can’t get rid of the redo copy latch contention, this may be a reason.