Doug's Oracle Blog

(* Inspired by Cary Millsap, although the story isn't as elegant as one of his ...)

It's 3 weeks, 4 weeks, 2 months since I disembarked from my second boat cruise in a week but it already seems longer. Perhaps it's because my client had thoughtfully waited until I got back into the office for the next Production release of the application I've been working on. That went well, but the subsequent infrastructure performance issues were the latest part of a 5 week long haze, and then it was time to handover to my replacement and make a start on a new role. It's been an extremely busy few months :-((

Sunday
My almost traditional pre-conference illness (maybe it's because these things are in Autumn and Spring or maybe it's pre-conference stress - who knows?) and the last frantic bits of work for the release on the horizon meant that I had very little time to work on my two new presentations so when I set off for Helsinki on Sunday, it was with laptop powered up and ready to go. Fortunately I had managed at least half of one of the presentations before I got ill. What I didn't have yet was a hotel room in Oslo for the Wednesday night because when I got around to checking on Friday, there was literally nothing. I was utterly baffled (really, how often is there *nothing* except for a hostel?) but decided I could sort that out later ....

The time difference stole another two hours from me (these things seem more signifcant when your back's against the wall) but it was a pleasant, uneventful trip and a quiet night in the hotel prepared me for setting sail on Silja Serenade the next morning.

Monday
Having never spent any time in Helsinki, I decided I might as well walk to the boat and Helsinki looks like a beautiful city that I'll be going back to at some point. Once on board and unpacked in my beautiful sea-view room, I realised that there was a stowaway on board! He has a habit of getting lost ...



Tom Kyte and Bryn Llewellyn had the good grace to give keynote presentations using slides that I'd seen several times by now which gave me most of the first day to work on ...  (you get the picture). Never have I been so happy to presenting on the second day of a two-day conference But I was very keen to see Melanie Caffrey's 'Keeping It Simple in Database Application Development'. She'd been giving this presentation at Oak Table Sunday last year at the same time as my 8-bit presentation, so I'd missed out then.

Although I know Melanie through her being a regular at the annual UKOUG conference, I'm not sure that I've ever seen her present much before, but she was as engaging and smart as I expected as she went through some of the lessons learned in her role as a Senior Development Manager at Oracle, working on linux.oracle.com. I wish I could remember more of them now, but sometimes I'm so busy listening to the messenger that I can miss some of the message! LOL

I'd warned Melanie how weird it is to be presenting just as the boat sets sail because I remember it from my first time and, sure enough, stuff started clanging, the boat started humming and swaying ever so slightly - it's an experience everyone should have at least once She also learned just how polite and quiet Finnish people are when in a sober audience of more than a few people. Never try a rhetorical question to the audience - you're likely to just get stoney silence back! However, they truly come into their own when you add beer or have a more private conversation - somewhat like most Scots I know!

After that, Heli Helskyaho (@HeliFromFinland) gave the OUGF 25th Anniversary Speech, flipping effortlessly between Finnish and English which is about as impressive as it gets to my ears. Although I have to say, it seems that this 25th Anniversay thing is a bit debatable. Is it 25 or 26 or .... I think someone forgot to start counting!

One of the most enjoyable aspects of a boat conference is the food, and we had one of the first of many great meals, all with plenty of wine thrown in and I was lucky enough to have Melanie, Debra Lilley and Alex Nuijten for company so it was a great way to wrap the day up, particularly as I had almost finished my slides

Tuesday

Tuesday was a day of worrying about and deliverying two presentations and feeling not a little unwell. It wasn't so much seasickness as the continuation of the long-running cold that I'd shared with lots of other people, so I was a little tense when I started presenting "10053 Trace Files - Mostly Harmless", particularly as Tom Kyte and Melanie were in the audience, knowing Tom's encyclopedic knowledge of Oracle! But it seemed to go reasonably well for the first time giving this presentation, but with some areas that I can improve, particularly some more useful examples.

Then there was time to actually eat some lunch (which is an achievement for me on presentation day) before I moved on to "Fast ETL Processes using Native Oracle Features". But im the lead-up, I felt really sick and I was concerned I might perform the impressive but disgusting trick of being physically sick mid-presentation! I mentioned the possibility on Twitter, so Alex made sure he turned up with his phone at the ready so he could tweet the evidence! Fortunately I got through it ok. Again, it probably needs a little more polish but the small room was absolutely packed and it went well enough. What I needed most was to lie down and rest, which meant that I missed Alex's Analytic Functions presentation again (something I have a long personal history of doing ...)

It was worth it though, as I was in a much better state when I made it back to the conference area just in time for Heli's wrap-up session. As well as having a prize-giving raffle from the numbers on peoples conference badges during which some really inconsiderate delegates walked off with all of the Cuddly Toys ;-), Heli tossed balls around the room to elicit feedback from whichever attendee caught the balls and she asked what was their best thing about the conference. At first I thought it might be embarassing and took a while to get going (Scots and Finns have a lot in common!) but it actually worked really well because I don't think anyone would have volunteered otherwise Maybe the real reason I liked the idea was when one of the delegates said that his favourite thing was my presentations, which was brilliant to hear. I always speak at a lot of conferences with great speaker line-ups, so I've never actually been told that in the past! Others who I won't mention are used to it on a regular basis *cough* Jonathan, Tom, Cary ... *cough*

Which put me in a great mood for the final dinner which was delicious, as all the catering was. Did I mention? But if you could have seen Bryn, Tom and Melanie *piling* the starters on to their plates, you would know I wasn't exaggerating. In fact, there were so many interesting and tasty options (particularly for those with wider tastes than me) that a lot of people just about managed a bunch of starters and then a few puddings. Between the company and the food, I didn't think it could get much better, but then I was voted Speaker of the Day. Again, that's something that never happened to me and I probably shouldn't care, but I'm afraid I did, particularly when I considered the other speakers on the agenda. Of course, I cheated a bit by doing two presentations on one day but, hey, I'll take what I can get Heli presented me with a Moomin mug and some whisky


In the interests of actually submitting a blog post, I'll leave it there for now. Justin Bieber? He can wait!

Rather than just describing the contents of the trace file, I thought it might be a good idea to tie the various sections into how they might help you solve Real World^TM problems. Which might not be immediately obvious when the first example I use is the trace file for :- 

SELECT * FROM DUAL;

But here it is. The first thing to note is that it's a 66KB file of over 2000 lines, even for something so trivial, which is just a taste of just how massive these files can be. It will also be environment and version-specific, as you'll see. Such is the nature of low-level trace files.

Going through the initial sections at a very high level, we have ....

Lines 1-20 - The standard type of trace file pre-amble that you might have seen in other trace files including

- The trace file name
- Instance and version information
- Host and O/S information
- Session Instrumentation of the type set by calls to DBMS_APPLICATION_INFO

Then we get to the first 10053-specific information (lines 22-27) which registers the various Query Blocks in this query. Understandably there is only one entry here in the QUERY BLOCK SIGNATURE section, were Oracle automatically names the query block to SEL$1

Line 28 is a note from SQL Plan Management highlighting that this statement does not already exist in the SQL Management Base.

Lines 29-32 contain a note that 11g Auto-DOP is disabled and at this point hopefully you'll start to see that if you already have a reasonable understanding of the CBO and related features, the trace file is actually pretty descriptive and verbose. From memory, I'm not sure it was always as easy to read.

For more information on Predicate Move-Around (as mentioned in lines 33-35), this 1994 VLDB paper is worth a look. Of course, when your statement is SELECT * FROM DUAL, there aren't exactly a lot of predicates to move around!

Next we go into a long section describing OPTIMIZER INFORMATION gathered from a variety of sources.

Line 40 shows the SQL statement and dont underestimate how important this is as further confirmation that you're looking at the right tracefile.

Lines 42-94 are a very handy Legend that lists the abbreviations that are used in the trace file. Some of these might have been guessable but, with so many terms used, it's great that you don't have to guess any more.

Lines 95-419 are a section that I often find very handy in solving issues with bad plans in two different database environments. The classic case of a developer telling me that it runs fine in Test but not in Production. The developer might send along the two plans and, even with a couple of good SQL Monitoring reports or the output of DBMS_XPLAN, that doesn't really tell me why the two plans are different, just that they are different. Working in an environment with multiple Dev, Test and Prod environments, it's not unusual to find that there is some drift in the instance configurations or someone has different session parameters set. It's a quick job to just open up the two trace files in a visual diff tool and make absolutely sure that the parameters the optimizer references (and you'll see just how many there are these days!) are truly identical.

It's just a small tip, but you'd be surprised by the number of issues that's helped me identify!

Before getting into the contents of a 10053 trace file and looking at any useful stuff, you need to know what the files are for and how and where they are created.

Essentially, setting event 10053 causes the Cost Based Optimizer to write information to a trace file describing the information it is using and the results of it's calculations whilst walking through the decision-making process to determine the best execution plan. It includes the options that it has considered and discarded, those that it has accepted and options which are unavailable for various reasons. Because the decision making process is detailed and extensive, the files tend to be large for all but the most trivial statements and I'd challenge most people to read and understand an entire 10053 trace file! However, you are often looking for the reason for a particular bad decision, which helps to narrow the scope and, personally, I've found recent versions of 10053 trace files much more verbose and readable.

The best and most detailed reference I've seen is Wolfgang Breitling's paper 'A Look under the Hood of the CBO' although it was written many years ago and, as with all low-level undocumented Oracle information, things change frequently and without warning. At the start of the paper he describes how to set event 10053 to generate the related trace file in the instance's user dump destination. However, since Oracle 11g, there is a more flexible way to generate the trace file that Maria Colgan describes in a couple of posts on the Optimizer Development Groups blog here and here. The latter post is particularly interesting because that approach automatically triggers a hard parse of the statement in order to generate the trace file.

Which solves what I suspect is one of the most confusing aspects of generating 10053 trace files when you're first getting used to it. The statement needs to be hard-parsed to ensure that the trace file will be generated. It might help you to remember what it is that is being traced - the CBO making it's decisions as it chooses an optimal execution plan. So, if the plan has already been generated then no trace file! One simple technique to get around this prior to 11g is to add a new comment to the statement to force a hard parse. Remember that if you find that the trace file is not being produced as expected, that might be the reason.

In the next post, I'll start to look at the contents of a 10053 trace file.

Sometimes I'm really not sure whether a blog post is a good idea or not. This is one of those times.

I remember a while ago that Neil Chandler wrote a blog post about why you probably don't need 10046 trace files that I didn't completely agree with and I kept thinking I must comment on it or write a post from a different perspective. Neil's a mate, a London Oracle Beers regular and I understood where he was coming from in that post. He makes some excellent points, so I recommend you read it. But I don't think it's so hard to get a trace enabled these days as people think. You don't necessarily need to change a line of code with the availability of the DBMS_MONITOR package and (although I accept this is unusual) the client I've worked for most recently makes trace file access very easy for developers. We also have ASH, AWR and SQL Monitoring though and I tend to agree with Neil that the times when 10046 trace files are truly required to solve problems are limited. Now I read this back, it sounds like I agree with him, but I know that I use 10046 trace files more regularly than the post suggests. I would say 10046 trace files are incredibly useful sometimes. In fact, when they are useful they are the only correct tool for the job.

But the real reason for referencing Neil's post is this statement.

"I have never used a 10053 trace on a Production system. I have simply never needed to know the decisions taken by the optimizer in that much detail."

I've had this discussion with most well-known experts in the Oracle community at some point or other and there's general agreement that there's no need to bother with those pesky and ridiculously geeky 10053 trace files most of the time. Most SQL performance problems simply aren't that complicated. I've probably agreed whenever the argument has come up but the fact is that I increasingly find myself using them and it worries me a little that 'most of the time you don't need them - concentrate on the basics' is heard as - 'don't ever bother looking at them - they won't help' and I've been tempted to redress the balance for a while.

But something stopped me. 10053 trace files are exceptionally long and contain a lot of information that I wouldn't begin to pretend I understand and so if you can't cover a subject properly and it is quite a technical subject then, not only are you in danger of doing people a disservice but you are also opening yourself up to all sorts of challenges, corrections and debates. But, hey, that's what a community and what blogging is all about - people learning from each other. I'm also not a big fan of any technical writing which is about how clever the writer is above it actually being useful! The more I know, the more I find myself avoiding the wilfully geeky stuff.

I still wasn't sure but at least one person at my current client has been badgering me about this for ages so I've decided, what the hell, I'm going to write a few blog posts about the things I find useful about 10053 trace files and hopefully give some very high level hints about how you might use them too.

If it's not technical enough for some people then tough and if I go astray, there are plenty of people out there who probably know the subject much better who can keep me straight (Just off the top of my head, I can think of Maria Colgan, Jonathan Lewis, Wolfgang Breitling, Christian Antognini .... well, it could be a long list).

Enough of the intro, but let me finish by saying what I think is the most important reason to use 10053 trace files. There are many posts about inaccurate row source cardinalities leading to bad plans (This is one of my favourites). But I believe that it's actually only the experts who can compare E-ROWS and A-ROWS and make educated guesses about why the cardinalities are wrong. (To give you an example, many is the time that Jonathan Lewis has said to me - 'Oh, that looks like a classic Optimizer 5% guess' - or words to that effect, anyway.) But most of us can't just 'see' those things when we look at a plan. At best, a 10053 trace file offers the possibility of knowing why the CBO picked the wrong plan.

I've blogged about deadlocks in Oracle at least once before. I said then that although the following message in deadlock trace files is usually true, it isn't always.

The following deadlock is not an Oracle error. Deadlocks of  
this type can be expected if certain SQL statements are      
issued. The following information may aid in determining the 
cause of the deadlock.

So when I came across another example recently, it seemed worth a quick blog post. Not least for the benefit of other souls who hit the same issue (and probably hit Google moments later).

But while it's easy to say - "Hey! Look! I found an exception! Aren't I clever?" - it occurred to me that actually Oracle's capabilities in this area might be underrated by raising the occasional anomaly. Because the truth is

1) In most cases, deadlock errors are down to the way you've written your application or some documented restriction in Oracle. The type of restrictions that you're more likely to hit if you're handling high degrees of concurrency with lots of DDL, parallel query, partition management and the like. Such activities often have unusually restrictive locking requirements and most locking issues can be turned into deadlock issues quite easily if you have a few sessions running concurrently.

2) It's still the case that Oracle will handle the deadlock situation, at least to the extent of rolling back one of the statements causing the issue. (Although, whilst writing this post, I noticed that Jonathan Lewis raised the question of what exactly people mean when they suggest that Oracle resolves deadlock issues.

3) Deadlock trace files are typically very useful and not the most difficult to read. Yes, they tend to use Oracle kernel terminology (not surprising) but I'd wager that most people could have a rough idea of the root cause with some initial analysis and could have a very detailed idea, given more time. Even if you can't decipher the things yourself, it gives Oracle Support detailed information to help root cause analysis.

So, to the particular issue we hit. Towards the end of a data loading process that loads around a billion rows in a short period of time (30/60 minutes that also includes a bunch of surrounding activities), we would hit the occasional deadlock error. Fortunately, the site I'm working at just now has a very enlightened policy towards developer access to the alert log and trace files, so I can do my own initial investigation. On digging out the relevant deadlock trace file, it looked like this (some details changed)

Trace file /app/ora/local/admin/PRD/diag/rdbms/PRD_prod_server/PRD/trace/PRD_dia0_1627682.trc 

Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production 
With the Partitioning, Automatic Storage Management, OLAP, Data Mining 
and Real Application Testing options 
ORACLE_HOME = /app/ora/local/product/11.2.0.3/db_1 
System name:    Linux 
Node name:      prod_server.ldn.orcldoug.com 
Release:        2.6.32-220.13.1.el6.x86_64 
Version:        #1 SMP Thu Mar 29 11:46:40 EDT 2012 
Machine:        x86_64 
Instance name: PRD 
Redo thread mounted by this instance: 1 
Oracle process number: 8 
Unix process pid: 1627682, image: oracle@prod_server.ldn.orcldoug.com (DIA0)
*** 2013-01-16 09:09:10.925 
*** SESSION ID:(201.1) 2013-01-16 09:09:10.925 
*** CLIENT ID:() 2013-01-16 09:09:10.925 
*** SERVICE NAME:(SYS$BACKGROUND) 2013-01-16 09:09:10.925 
*** MODULE NAME:() 2013-01-16 09:09:10.925 
*** ACTION NAME:() 2013-01-16 09:09:10.925 
  
------------------------------------------------------------------------------- 
  
DEADLOCK DETECTED (id=0xd0102292) 
  
Chain Signature: 'library cache lock'<='row cache lock' (cycle) 
Chain Signature Hash: 0x52a8007d 
  
The following deadlock is not an Oracle error. Deadlocks of  
this type can be expected if certain SQL statements are      
issued. The following information may aid in determining the 
cause of the deadlock.                                       
  
Resolving deadlock by signaling ORA-00060 to 'instance: 1, os id: 3443329, session id: 161' 
  dump location: /app/ora/local/admin/PRD/diag/rdbms/PRD_prod_server/PRD/trace/PRD_ora_3443329.trc 
  
Performing diagnostic dump on 'instance: 1, os id: 3443222, session id: 779' 
  dump location: /app/ora/local/admin/PRD/diag/rdbms/PRD_prod_server/PRD/trace/PRD_ora_3443222.trc 
  
------------------------------------------------------------------------------- 
    Oracle session identified by: 
    { 
                instance: 1 (PRD_prod_server.PRD) 
                   os id: 3443222 
              process id: 127, oracle@prod_server.ldn.orcldoug.com 
              session id: 779 
        session serial #: 605 
    } 
    is waiting for 'row cache lock' with wait info: 
    { 
                      p1: 'cache id'=0x8 
                      p2: 'mode'=0x0 
                      p3: 'request'=0x5 
            time in wait: 1 min 58 sec 
           timeout after: never 
                 wait id: 1655 
                blocking: 1 session 
             current sql: Begin run_manager_pkg.finalize_all_values_prc(:v0); End; 
            wait history: 
              * time between current wait and wait #1: 0.002176 sec 
              1.       event: 'enq: PS - contention' 
                 time waited: 0.000082 sec 
                     wait id: 1654            p1: 'name|mode'=0x50530006 
                                              p2: 'instance'=0x1 
                                              p3: 'slave ID'=0x2f 
              * time between wait #1 and #2: 0.000013 sec 
              2.       event: 'PX Deq: Slave Session Stats' 
                 time waited: 0.000001 sec 
                     wait id: 1653            p1: 'sleeptime/senderid'=0x0 
                                              p2: 'passes'=0x0 
              * time between wait #2 and #3: 0.000001 sec 
              3.       event: 'PX Deq: Slave Session Stats' 
                 time waited: 0.000002 sec 
                     wait id: 1652            p1: 'sleeptime/senderid'=0x0 
                                              p2: 'passes'=0x0 
    } 
    and is blocked by 
=> Oracle session identified by: 
    { 
                instance: 1 (PRD_prod_server.PRD) 
                   os id: 3443329 
              process id: 134, oracle@prod_server.ldn.orcldoug.com 
              session id: 161 
        session serial #: 247 
    } 
    which is waiting for 'library cache lock' with wait info: 
    { 
                      p1: 'handle address'=0x101f8eac98 
                      p2: 'lock address'=0xfdef83738 
                      p3: '100*mode+namespace'=0x10f2000010003 
            time in wait: 1.739719 sec 
           timeout after: never 
                 wait id: 508 
                blocking: 1 session 
             current sql: ALTER INDEX "DOUG"."VALUE_PK" REBUILD PARTITION "SYS_P4089"

            wait history: 
              * time between current wait and wait #1: 0.000973 sec 
              1.       event: 'enq: CR - block range reuse ckpt' 
                 time waited: 0.003220 sec 
                     wait id: 507             p1: 'name|mode'=0x43520006 
                                              p2: '2'=0x10086 
                                              p3: '0'=0x1 
              * time between wait #1 and #2: 0.000008 sec 
              2.       event: 'reliable message' 
                 time waited: 0.000107 sec 
                     wait id: 506             p1: 'channel context'=0x101c5afa98 
                                              p2: 'channel handle'=0x101c0f2260 
                                              p3: 'broadcast message'=0x101b5cfd58 
              * time between wait #2 and #3: 0.003791 sec 
              3.       event: 'db file sequential read' 
                 time waited: 0.000321 sec 
                     wait id: 505             p1: 'file#'=0x5e 
                                              p2: 'block#'=0x118784 
                                              p3: 'blocks'=0x1 
    } 
    and is blocked by the session at the start of the chain. 

I would hope that a few things would be immediately obvious, particularly if it's 'your' application that generated this issue

1) The two sessions are running the following parts of the application.

Session 1: Begin run_manager_pkg.finalize_all_values_prc(:v0); End;
Session 2: ALTER INDEX "DOUG"."VALUE_PK" REBUILD PARTITION "SYS_P4089"

Which happened to fit in with what we were seeing. We have two concurrent runs which perform similar actions using different input files that load into different partitions.

2) The first session is using Parallel Query (note the enq: PS - contention and different PX Deq wait events)

3) The deadlock is a little unusual because it's not between two transactions trying to lock database objects or rows being locked by the other session but between in-memory structures. One session is waiting on 'row cache lock' and the other is waiting on 'library cache lock', as opposed to waiting for specific row or table-level locks. This is also visible from the chain signature at the start of the trace file.

Chain Signature: 'library cache lock'<='row cache lock' (cycle)

Armed with 2) and 3) in particular, my next step was to go to My Oracle Support, as usual. I find that Google isn't too great with issues like this because some of them are quite specific and might not be affecting too many others. Sure enough, a search turned up :-

Bug 14356507  Deadlock between partition maintenance and parallel query operations

Which is confirmed as affecting versions 11.2.0.2 and 11.2.0.3. The fix is in Bundle Patch 12 for Exadata, in Oracle 12.1 and is also available as one-off patch that we're in the process of applying to different environments.

The issue is that "When a parallel query is hard parsed, first QC hard parses the query and then all the slaves.  When a partition maintenance operation (DDL) comes in between the hard parses of QC and Slaves.", then you can hit the deadlock. There's more detail in the bug notes, but it's worth noting this phrase "This is basically a timing issue, in high concurrency environments.", which means it only affects us very intermittently and is a nightmare to prove we've eliminated without a lot of testing.

What I find a little disconcerting is that there seem to be quite a few of these library cache deadlock issues kicking around in recent versions that I haven't been used to seeing in prior versions. Given some of the library cache madness I've seen in my few years with 11g, I do wonder what on earth they've done to it!