Recently I was asked to help with a case involving library cache locks, and even though it was really simple, I think it’s good for illustrating a few points in performance analysis.
As it often happens, it all started with customers complaining about “the database being slow”. I asked for more specific details, and I found that it wasn’t the entire database, but rather a reporting subsystem. Since I didn’t have specific session sid or sql_id at hand, I started with analyzing a 30-min AWR report, and since there wasn’t much time to look at everything, I just focused on top timed events:
Event Waits Time (s) Avg Wait(ms) %Total Wait Class CPU time 16,188 46.2 db file sequential read 18,230,956 11,787 1 33.6 User I/O db file parallel write 278,480 4,509 16 12.9 System I/O library cache lock 1,131 3,297 2,915 9.4 Concurrency log file sync 120,356 1,686 14 4.8 Commit
The one that stands out is obviously the “library cache lock”: it’s a concurrency-class event so it should always raise suspicion. Wait time for this event is 3,297 s for a 1,800 s interval, i.e. it corresponds to 1.8 sessions waiting on it on the average, which sounded about right (the subsystem would have about a dozen sessions running out of which 2-5 would typically be active at the same time, so this event would have had a massive effect on its performance).
The next step would to look in the V$ACTIVE_SESSION_HISTORY to confirm that waits on “library cache lock” were indeed associated with the subsystem in question — and yes, indeed it turned out to be the case. Now I had to identify the source of this contention, which was a bit tricky, because blocking_session_id field of V$ACTIVE_SESSION_HISTORY was blank. There are ways to find the object holding the lock using X$ tables, but I didn’t have SYS access so instead I decided to check one common scenario for library cache locking: stats gathering. And indeed, there was stats gathering job in progress, and it was stuck waiting on a library cache lock held by a runaway session (KILLED status, but still not cleaned up by PMON for whatever reason), while holding a library cache lock itself, thus making yet more sessions wait. Killing the stats gathering job resolved the issue.
I’d like to focus on several points here.
1. Identifying the problem. There is a general rule, that states that you obtain the maximum return on your tuning effort by addressing events with largest % DB time ((see great article by Milsap explaining it’s application to database performance tuning here). But it’s important to understand that this law doesn’t apply to database performance incidents of a local scale (i.e. when a significant part of processes on the database is experiencing a significant performance degradation, but the database as a whole is still running more or less ok). So we have to focus not on biggest events, but on any events that are out of ordinary. However, we have to only look at events whose contribution to the overall wait time is comparable to the size of the problem. That’s why it’s convenient to express performance impact of events in average sessions.
2. In a situation like this, people are often tempted to use the traditional top-down approach, i.e. they turn to top resource consuming SQL and pronounce it a root cause. Many innocent long-running queries were killed for that. Well, that’s wrong: top resource consumers only matter when the affected SQL is experiencing deficit of this specific resource. E.g. it needs CPU time, but the all CPUs are taken by another heavy overparallelized query — yes, then it’s justified. But more often than not, this approach won’t work. Instead, you have to go where the symptoms take you, and that’s where ASH steps in.
Diagrammatically, I would picture this as a AWR -> ASH approach: use AWR to identify the suspect(s), use ASH to confirm your suspicions.
3. In this case (as in many other cases) ASH is unable to provide the necessary information about the culprit directly. When this happens, sometimes you can use wait event parameters (P2 column of ASH) to decipher the sid of the session holding the resource, like with cursor: pin S waits in 10g. Sometimes you can use X$ tables to obtain this information. But you can always use good judgement to make a reasonable guess and confirm it more quickly, than any accurate analysis could, and that’s very important when resolving ongoing production issues. In this particular case, once I suspected gather stats job, it took me just a few seconds to confirm that it was indeed responsible.
2 thoughts on “Library cache locks: a case study”
“Wait time for this event is 2,915 s for a 1,800 s interval, i.e. it corresponds to 1.6 sessions waiting on it on the average,”
I don’t understand from where you get this 2915 s? Can you please explain how do you conclude 1.6 sessions wait on an average?
I think I typed in wrong numbers in the post. The wait time for this event is 3,297 s (2,915 is the average wait time in milliseconds). If you divide this number by 1800 you get 1.8 sessions waiting on this event on the average.
Fortunately, the numbers are quite close so all the conclusions are still true.
Thanks for spotting the error, I’ll update the post.