Now and then we are passed a problem that other people have been working on for a while, but despite lots of changes, it hasn’t been resolved. In some cases this makes it impossible to obtain a clear description of the symptoms and history, and may even have introduced other issues. I much prefer a ‘diagnostic approach’ rather the ‘try the usual suspects first method’. One might ‘get lucky’ by simply changing a common tuning parameter, but I prefer to consider the risks, costs and testing effort the customer will incur, and so attempt to understand the problem and provide the best solution.
The case I’m going to briefly cover in this post was one of these problems with more rumour than substance to the problem history. Significant changes had been made to the Oracle database, including changing the optimiser back and forward between cost and rule and cursor sharing between exact and force. I’m not even sure if the problem I investigated was the original one or a side-effect of the various attempts at a solution.
Obvious Symptoms
The highest component of response time was the enqueue wait event.
There were about ten blocked sessions with the same SQL statement:
UPDATE dummytable SET nextId = nextId + 1 WHERE schemaId = 123;
My first thought was that the locking was due to the application incrementing a number field instead of using a sequence. Then I noticed that each blocker relinquished the lock after a minute or so, and one of the other ten sessions became the blocker for another minute, and so on. Assuming the application design hadn’t just changed, it was probably this 60 second delay while holding a lock that was at the heart of the problem.
The Not-so-Obvious
Finding what was happening during that 60 second delay was trickier than usual. How so? I’ll start by sharing a portion of the trace file. Pay attention to the timing parts in blue.
PARSE #1:c=0,e=980,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=3,tim=31325192050363 EXEC #1:c=0,e=158,p=0,cr=4,cu=1,mis=0,r=0,dep=0,og=3,tim=31325192050680 WAIT #1: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0 FETCH #1:c=10000,e=64,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=3,tim=31325192050859 WAIT #1: nam='SQL*Net message from client' ela= 381 p1=1413697536 p2=1 p3=0 WAIT #33: nam='db file sequential read' ela= 103 p1=15 p2=1542515 p3=1 WAIT #33: nam='db file sequential read' ela= 317 p1=15 p2=1542520 p3=1 WAIT #33: nam='direct path write (lob)' ela= 178 p1=10 p2=2008755 p3=1 WAIT #0: nam='SQL*Net message to client' ela= 7 p1=1413697536 p2=1 p3=0 WAIT #0: nam='SQL*Net message from client' ela= 596 p1=1413697536 p2=1 p3=0 STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FOR UPDATE (cr=4 r=0 w=0 time=44 us)' STAT #1 id=2 cnt=2 pid=1 pos=1 obj=42798 op='TABLE ACCESS BY INDEX ROWID table_a (cr=8 r=0 w=0 time=97 us)' STAT #1 id=3 cnt=2 pid=2 pos=1 obj=42799 op='INDEX UNIQUE SCAN table_a_index (cr=6 r=0 w=0 time=57 us)' ===================== PARSING IN CURSOR #1 len=66 dep=0 uid=23 oct=6 lid=23 tim=31325202616132 hv=4020366925 ad='ff8b078' UPDATE table_a SET C2 = EMPTY_CLOB() WHERE C1 = '000000003637834' END OF STMT PARSE #1:c=0,e=2286,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=3,tim=31325202616118 EXEC #1:c=0,e=670,p=0,cr=7,cu=6,mis=0,r=1,dep=0,og=3,tim=31325202616968 WAIT #1: nam='SQL*Net message to client' ela= 2 p1=1413697536 p2=1 p3=0 WAIT #1: nam='SQL*Net message from client' ela= 313 p1=1413697536 p2=1 p3=0 STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE (cr=7 r=0 w=0 time=475 us)' STAT #1 id=2 cnt=1 pid=1 pos=1 obj=42799 op='INDEX UNIQUE SCAN table_a_index (cr=3 r=0 w=0 time=114 us)' ===================== PARSING IN CURSOR #1 len=63 dep=0 uid=23 oct=3 lid=23 tim=31325202618985 hv=1434031237 ad='156ec818' SELECT C2 FROM table_a WHERE C1 = '000000003637834' FOR UPDATE END OF STMT PARSE #1:c=0,e=1203,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=3,tim=31325202618977 EXEC #1:c=0,e=217,p=0,cr=4,cu=1,mis=0,r=0,dep=0,og=3,tim=31325202619378 WAIT #1: nam='SQL*Net message to client' ela= 1 p1=1413697536 p2=1 p3=0 FETCH #1:c=0,e=90,p=0,cr=4,cu=0,mis=0,r=1,dep=0,og=3,tim=31325202619616 WAIT #1: nam='SQL*Net message from client' ela= 505 p1=1413697536 p2=1 p3=0 WAIT #34: nam='db file sequential read' ela= 146 p1=15 p2=1473089 p3=1 *** 2008-11-05 17:14:00.054 WAIT #34: nam='db file sequential read' ela= 950 p1=15 p2=1473090 p3=1 *** 2008-11-05 17:14:14.217 WAIT #34: nam='db file sequential read' ela= 138 p1=15 p2=1473091 p3=1 WAIT #34: nam='SQL*Net more data from client' ela= 110 p1=1413697536 p2=1 p3=0 WAIT #34: nam='direct path write (lob)' ela= 183 p1=10 p2=1595041 p3=1 WAIT #0: nam='SQL*Net message to client' ela= 8 p1=1413697536 p2=1 p3=0 WAIT #0: nam='SQL*Net message from client' ela= 579 p1=1413697536 p2=1 p3=0 STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='FOR UPDATE (cr=4 r=0 w=0 time=56 us)' STAT #1 id=2 cnt=2 pid=1 pos=1 obj=42798 op='TABLE ACCESS BY INDEX ROWID table_a (cr=8 r=0 w=0 time=135 us)' STAT #1 id=3 cnt=2 pid=2 pos=1 obj=42799 op='INDEX UNIQUE SCAN table_a_index (cr=6 r=0 w=0 time=81 us)' ===================== PARSING IN CURSOR #1 len=66 dep=0 uid=23 oct=6 lid=23 tim=31325238065528 hv=3338015855 ad='165cdab0'
We can see that the blocking session is eating up time:
31325202616132 – 31325192050859 = 10565273, or 10 seconds.
31325238065528 – 31325202619616 = 35445912, or 35 seconds.
Whatever is causing the delay, it hasn’t been assigned a wait event name. One clue the trace does have for us is that there are reads to a couple of segments during the mysterious delay and just before writes to a LOB. Using DBA_EXTENTS we can see that these segments are LOB indexes for TABLE_A.
Watching the blocking sessions revealed that they clock up a lot of CPU and consistent gets. The LOB indexes for TABLE_A have high logical read counts. The buffer cache is also full of copies of the LOB index blocks. The picture is becoming clearer – something must be wrong with the LOB indexes.
Theory, Confirmation, Resolution
My best guess at this point was that this performance issue was caused by a big delete of data in TABLE_A. The LOB chunks were marked as deleted (not free), so each time there was a new insert Oracle had to find re-usable space, change the deleted chunks to free and update the LOB index, (as well as manage the various bitmap blocks and undo blocks). According to the Metalink Note:365156.1 this process can take a long time because it “has to traverse the empty LOB INDEX leaf blocks created by all the previous transactions”. This would explain the high number of logical reads recorded against the LOB indexes during each insert/update.
This Oracle database had a long statspack history, so I was able to write some ad-hoc queries to generate a graph of enqueue waits over time to see when the first big locking problems really started, and I was also able to find some large delete statements on TABLE_A. The archive log history showed a huge spike at the time of one of these deletes, and so it looked like the theory was right. This data helped to jog a few memories and we learned that 90% of TABLE_A’s data had been deleted around the time the ‘slowness’ started.
I can hardly do the explanation justice here, but if you know how Oracle LOBS and indexes work in general, then this may make sense:
LOB segments don’t use undo like everything else, but instead mark old chunks of LOB data as re-usable and write over it a later time when an insert or update needs some space. These re-usable chunks are tracked by the LOB index – the same LOB index that tracks the current chunks of LOB data. The current data is in the left side of the index and the re-usable/undo/consistent read data is in the right side. When data is deleted, (or updated), the old LOB locator entries are deleted from the index and new re-usable index rows are entered into the right side of the index. The emptied leaf blocks on the left side of the index are reclaimed and used for leaf blocks during inserts, while the “re-usable” index entries are removed from the tail of the right half of the index with each insert. After a big delete (or many small ones in a row) the freelist is full of blocks from the left side of the index… so as data is inserted again over time, a gap opens up with empty leaf blocks between the left and right sides (used and re-usable) of the index. The empty blocks are on the freelist but not removed from the index structure until they are taken from the freelist.
So… when an insert happens it checks for re-usable space. The index is range scanned for the first free chunk. (Re-usable space is indexed chronologically). Unfortunately, this process takes a lot of CPU time to complete when there are large numbers of empty leaf blocks in the index and multiple LOBs in the same table; over a minute in the example in this blog. Sometimes the delay can be smaller – just a few seconds, and so even harder to identify.
A dump of the index showed the problem clearly, (although it helped to a dump of a few of the index blocks at key points to be sure where the current data index entries stopped and where re-usable chunk list started).
A rebuild of the LOBs for TABLE_A resolved this problem. I set the LOBs to cache before rebuilding them to speed the process up.
Moral of the Story
My recommendation to prevent this from happening again was the usual ‘rebuild/repack database segments after mass deletions, but even better is to purge in small amounts regularly’. This case was an extreme example of why that is important.
A performance tuning lesson emphasised here is to use a multiple diagnostic tools, deductive reasoning and research to identify the real problem so that the best solution can be found and a strategy for preventing its re-occurrence can be designed. Also, tuning LOB related activity can be tricky for those relying on the standard tuning tools and statistics. In a future post, I’ll give another example of how LOB activity cause performance problems that aren’t obvious.
hpdba
James Kim
