Long wait times for cursor: pin S and latch: library cache

On our OLTP db we sometimes experienced short bursts (5-15 seconds) of CPU starvation and waits for cursor: pin S or latch: library cache. Especially during busy times. CPU utilization is normally 65% so we were confident that the waits also cause the CPU starvation and not vice versa. In the past few months we have logged multiple SRs with Oracle for the issue but only made progress with 1 where bug Bug 6904068 - High CPU usage when there are "cursor: pin S" waits [ID 6904068.8] was identified. The problem with the other SRs was a case of wrong scope definition. Even though I would upload all the relevant information (ASH, AWR and OS Watcher stats) Oracle Support would look at the top wait in AWR (“db file sequenctial read”) and suggest that we solve that by doing some query tuning and hopefully the mutex/latch problem will also disappear. Even when I convinced them that the problem is not “db file sequential read” they would ask me to take 3x system state dumps when the problem appears. That was an impossible task as the first sytem state dump would kick in when the problem is already occurring, so we could never give support the info they claimed they needed to diagnose the problem.

We were in the fortunate position to ask Tanel Poder to have a look. He also posted some info about the problem and how he systematically solved it. And with the same info I always give to Oracle support, he could correctly identify the problem in a couple of minutes! Most amazing is that the solution is available in the Oracle Documentation. 10g Release 2 (10.2) for UNIX-Based Operating Systems. B15658-02. Appendix B Administering Oracle Database on HP-UX.

What the documentation says:
On HP-UX, most processes use a time-sharing scheduling policy. Time sharing can have detrimental effects on Oracle performance by descheduling an Oracle process during critical operations, for example, when it is holding a latch. HP-UX has a modified scheduling policy, referred to as SCHED_NOAGE, that specifically addresses this issue. Unlike the normal time-sharing policy, a process scheduled using SCHED_NOAGE does not increase or decrease in priority, nor is it preempted.
This feature is suited to online transaction processing environments because online transaction processing environments can cause competition for critical resources.

So the OS scheduler may deschedule a Oracle process while it is holding a mutex/latch because the OS is not aware of what is going on inside Oracle. Now other processes which happen to use that cursor will fail to get the mutex and start spinning. If the mutex holder process has a lower priority than all the other processes who yielded CPU, then it may not get onto CPU soon enough, so it still holds that mutex and the other processes spin and use CPU trying to get that mutex.

How Tanel proved it:
Below are queries from v$event_histogram for the top 2 problem waits. Notice the number of histogram buckets where the wait time is > 512ms:

EVENT_NAME WAIT_TIME_MILLI WAIT_COUNT WAIT%
------------------------------ --------------- -------------- ------
latch: library cache 1 815,980 52.76
latch: library cache 2 187,232 12.11
latch: library cache 4 168,402 10.89
latch: library cache 8 138,053 8.93
latch: library cache 16 102,906 6.65
latch: library cache 32 69,149 4.47
latch: library cache 64 43,797 2.83
latch: library cache 128 11,916 0.77
latch: library cache 256 3,867 0.25
latch: library cache 512 1,005 0.06
latch: library cache 1,024 1,108 0.07
latch: library cache 2,048 1,516 0.10
latch: library cache 4,096 1,293 0.08
latch: library cache 8,192 351 0.02

EVENT_NAME WAIT_TIME_MILLI WAIT_COUNT WAIT%
------------------------------ --------------- -------------- ------
cursor: pin S 1 59,309,179 86.63
cursor: pin S 2 5,988,534 8.75
cursor: pin S 4 2,313,442 3.38
cursor: pin S 8 675,114 0.99
cursor: pin S 16 113,084 0.17
cursor: pin S 32 23,804 0.03
cursor: pin S 64 15,434 0.02
cursor: pin S 128 9,643 0.01
cursor: pin S 256 4,247 0.01
cursor: pin S 512 2,912 0.00
cursor: pin S 1,024 2,871 0.00
cursor: pin S 2,048 2,626 0.00
cursor: pin S 4,096 1,980 0.00
cursor: pin S 8,192 967 0.00
cursor: pin S 16,384 278 0.00
cursor: pin S 32,768 32 0.00

ps –efl > ps.txt
cat ps.txtgrep ".:..:.."awk '{ printf "%6d %50s\n", $7, $15 }'>ps1.txt
cat ps.txtgrep -v ".:..:.."awk '{ printf "%6d %50s\n", $7, $16 }'>ps2.txt
cat ps1.txt ps2.txtgrep ora.*abcprdsort -nuniq -csort -nbrhead -20

NUM
PROCS PRIO PROCESS_NAME
----- ------ -------------------
1936 154 oracleabcprd
25 148 oracleabcprd
4 241 oracleabcprd
1 240 oracleabcprd
1 235 oracleabcprd
1 229 oracleabcprd
1 223 oracleabcprd
1 207 oracleabcprd
1 195 oracleabcprd
1 187 oracleabcprd
1 181 oracleabcprd
1 179 oracleabcprd
1 154 ora_smon_abcprd
1 154 ora_rvwr_abcprd
1 154 ora_rsm0_abcprd
1 154 ora_reco_abcprd
1 154 ora_rbal_abcprd
1 154 ora_qmnc_abcprd
1 154 ora_q004_abcprd
1 154 ora_q003_abcprd
Note the different priorities of the oracle client processes. After we enabled SCHED_NOAGE for Oracle Database as described in the documentation. The output looked like this:

EVENT_NAME WAIT_TIME_MILLI WAIT_COUNT WAIT%
------------------------------ --------------- -------------- ------
latch: library cache 1 53,212 57.39
latch: library cache 2 10,517 11.34
latch: library cache 4 11,069 11.94
latch: library cache 8 5,308 5.72
latch: library cache 16 3,715 4.01
latch: library cache 32 3,506 3.78
latch: library cache 64 5,254 5.67
latch: library cache 128 131 0.14
latch: library cache 256 5 0.01
latch: library cache 512 7 0.01
latch: library cache 1,024 3 0.00

EVENT_NAME WAIT_TIME_MILLI WAIT_COUNT WAIT%
------------------------------ --------------- -------------- ------
cursor: pin S 1 2,267 15.46
cursor: pin S 2 0 0.00
cursor: pin S 4 0 0.00
cursor: pin S 8 0 0.00
cursor: pin S 16 0 0.00
cursor: pin S 32 0 0.00
cursor: pin S 64 0 0.00
cursor: pin S 128 12,380 84.45
cursor: pin S 256 12 0.08

NUM
PROCS PRIO PROCESS_NAME
----- ------ -------------------
1992 178 oracleabcprd
1 178 ora_smon_abcprd
1 178 ora_rvwr_abcprd
1 178 ora_rsm0_abcprd
1 178 ora_reco_abcprd
1 178 ora_rbal_abcprd
1 178 ora_qmnc_abcprd
1 178 ora_q001_abcprd
1 178 ora_q000_abcprd
1 178 ora_psp0_abcprd
1 178 ora_pmon_abcprd
1 178 ora_p009_abcprd
1 178 ora_p008_abcprd
1 178 ora_p007_abcprd
1 178 ora_p006_abcprd
1 178 ora_p005_abcprd
1 178 ora_p004_abcprd
1 178 ora_p003_abcprd
1 178 ora_p002_abcprd
Note that the number of wait buckets are less. The wait times are sort as it should be. And the process priority report shows that all oracle client processes are on the same priority.

Thanks Tanel!

Fast Index Creation

I recently had to create a new index on a fairly large date ranged partitioned table. I tried a few permutations on test, but found the following steps to be the fastest;

01:01:03 SQL> alter session set workarea_size_policy=manual

Session altered.

01:13:44 SQL> alter session set hash_area_size=1073741824

Session altered.

01:13:44 SQL> alter session set sort_area_size=1073741824

Session altered.

01:13:44 SQL> select force_logging from v$database

FOR
---
YES

01:13:44 SQL> alter database no force logging

Database altered.

01:13:46 SQL>create index imei_prod.usage_profile_idx1 on imei_prod.usage_profile(msisdn)
01:13:46 2 nologging
01:13:46 3 compress
01:13:46 4 parallel 16
01:13:46 5 local
01:13:46 6 (
01:13:46 7 partition USAGE_199401 tablespace indx nologging compress,
01:13:46 8 partition USAGE_200106 tablespace indx nologging compress,
01:13:46 9 partition USAGE_200202 tablespace indx nologging compress,
01:13:46 10 partition USAGE_200207 tablespace indx nologging compress,
...
01:13:46 56 partition USAGE_200809 tablespace indx nologging compress,
01:13:46 57 partition USAGE_200810 tablespace indx nologging compress,
01:13:46 58 partition USAGE_200811 tablespace indx nologging compress
01:13:46 59 )
01:13:46 60 /

Index created

Elapsed: 01:58:57.99


03:12:44 SQL> SELECT st.sid, se.username, TO_CHAR(se.logon_time,'dd-mon-yy hh24:mi')
03:12:44 2 logtime, se.program, (value/1048576) VALUE
03:12:44 3 FROM gv$sesstat st, gv$statname sn, gv$session se
03:12:44 4 WHERE username = 'MEYERM'
03:12:44 5 and sn.name = 'redo size'
03:12:44 6 AND sn.statistic# = st.statistic#
03:12:44 7 AND st.sid = se.sid
03:12:44 8 /


Redo
Generated
SID USERNAME Logon Time PROGRAM in MB
--------------------------------------------------------------
146 MEYERM 26-nov-08 01:13 sqlplus@pxxxx1 (TNS V1-V3) 116.583

03:12:46 SQL> alter database force logging

Database altered.

03:12:46 SQL> alter index imei_prod.usage_profile_idx1 logging;

Index altered.

SQL*Loader direct

We had to setup SQL Server Replication to an Oracle database. The 2 tables in questions are huge. The small table has 63mill rows and the big one has 1.5bill rows. The big table has 50 date ranged partitions.

I used SQL Loader direct path without any indexes in place from csv files to do the initial load.

The first thing to do was to prepare the database for Direct Loading by executing the script $ORACLE_HOME/rdbms/admin/catldr.sql.

I also had to set my session’s DATE format to be the same as the format in the CSV file.

$ export NLS_DATE_FORMAT='YYYY-MM-DD HH24:MI:SS'

To get the fastest possible load performance on the 50 partitions I followed these rules:
There were no indexes on the table
The table was set to NOLOGGING
The database was put in NOARCHIVELOG mode

And the following SQL Loader options were used:
DIRECT=TRUE to invoke Direct Loading. This will effectively bypass most of the RDBMS processing
UNRECOVERABLE to turn off database logging
PARELLEL=TRUE and APPEND in order to run multiple load jobs concurrently for the different partitions.

My Korn Shell Script looked like this:

#!/bin/ksh

export ORAENV_ASK=NO;
export ORACLE_SID=xxprd;
. oraenv;

export NLS_DATE_FORMAT='YYYY-MM-DD HH24:MI:SS".000"'

sqlldr xx/xx control=c1.ctl DIRECT=TRUE PARALLEL=TRUE log=c1.log &
sqlldr xx/xx control=c2.ctl DIRECT=TRUE PARALLEL=TRUE log=c2.log &
sqlldr xx/xx control=c3.ctl DIRECT=TRUE PARALLEL=TRUE log=c3.log &

… etc up to 10 jobs

And I created 10 control files they all looked identical except for the infile:

UNRECOVERABLE LOAD DATA
 infile '/dump/exports/XXprd/x200512.csv'
 append into table usage_profile
 fields terminated by "," TRAILING NULLCOLS
 (MONTH_ID, MSISDN, IMSI, IMEI, START_DT, END_DT, EVENT_CNT, STREAM, SUCCESS_CALLS, UNSUCCESS, DURATION, VOLUME_UPLINK, VOLUME_DOWNLINK, VOLUME, SUBSCRIBER_TYPE, SP_CODE)

The job completed in 12 minutes and 5 jobs later all 1.5 billion records were loaded!

Using various tools to solve a problem

I was recently called in to take over a performance problem. I quickly determined that only a portion of the database was affected, but it was the most visible part, affecting the business ability to offer a certain feature to millions of our customers. Some queries that should take less than 5 seconds suddenly took minutes to complete.

Of course the App Vendor claimed that nothing changed around that particular query in years, so it had to be a database problem.

Looking at OEM’s Average Active Sessions graph on the Performance tab, I could clearly see a huge red stripe (red means the wait is Application related). Drilling down I found waits for an event called “enq: UL – contention” to be the problem. A metalink search retuned no hits and a google search retuned hundreds of forum websites with DBA’s asking “What is enq: UL – contention?”, most of them did not have any replies. The only reference to this event in the manual was found in Oracle® Database Reference 10g Release 2 (10.2) (B14237-01) Appendix E: Oracle Enqueue Names . It simply stated “UL, User-defined Locks”. To me that meant that the app could be using DBMS_LOCK, but the Vendor said they don’t and app support told me that these queries do not write to the database.

I queried V$SESSION for sessions waiting for EVENT=”enq: UL – contention” to find the SID of the BLOCKING_SESSION, but the BLOCKING_SESSION kept on changing. One blocking session would have confirmed an App issue and the short term solution would have been to kill that process.

Then I logged a priority 1 SR and was asked to provide system state dumps. Eventually BUG 4367986 was identified as a possibility. The patch was applied, but it made no difference!

OK, I clearly had to try something else, so I decided to trace 1 session and go through the TKPROF output. I found that the app related SQL statements all executed in less than 5 second, but one statement stood out at 60 seconds elapsed time. That SQL statement was;

begin ctxsys.drvdml.com_sync_index(:idxname, :idxmem, :partname); end;

Schema ctxsys means Oracle Text is in use and the Vendor then confirmed that Oracle Text indexes where build on an app related audit table almost 2 months ago. The TKPROF also showed INSERTs into the app audit table, so we were finally on the right track.

This information was uploaded in the SR and I had to check the SYNC intervals via a select from dr$index and confirmed that the 2 audit indexes had SYNC ON COMMIT. We changed the COMMIT interval to MANUAL , just to proof if this problem is related to the SYNC ON COMMIT. Once we changed the commit interval to MANUAL, the wait event disappeared.

exec CTX_DDL.REPLACE_INDEX_METADATA('XX','REPLACE METADATA SYNC (MANUAL)');

The SR engineer then supplied the following script to change the SYNC to every 5 minutes.

exec CTX_DDL.REPLACE_INDEX_METADATA('XX','REPLACE METADATA SYNC (every "SYSDATE+5/1440")');

So the “moral of the story” is that as a DBA you have more than one tool to solve a problem and you should use as many of them as possible until the root cause of the problem is clear.