Why did that report run slow? ASH says log file sequential read

“Dump Online Redo for Buffers in Pin History”

I’ve just been investigating why a certain report ran slow last night.
Read more of this post

Regexp hungry for CPU? Real time sql monitoring shows just how

Not exactly a snappy blog post title…

First up, an execution plan showing the old problem of how the costs of a scalar subquery are not properly accounted for, even in the latest 11gR2 releases.
Read more of this post

Poll: SQL Plan Management

I’m interested in what SQL Plan Management features people are actively using.
Read more of this post

ORA-00600 [kkqtSetOp.1] – Join Factorization

Just a quick note about an ORA-00600 that recently occurred following an upgrade to 11.2.0.3.

I’ve not been able to distill an isolated test case from the specific production code generating this error so I’ll skip the application-specific example.

The error message reported was:
Read more of this post

Timeslot SQL

A reminder about sql logic required to deal with express datetimes to the nearest x mins – for example, this particular question come up on an internal forum last week where the poster wanted to aggregate data per quarter hour.

There are two approaches depending on the exact requirement.

The first option is to generate the timeslots using a data generator and then join to the source data.

SQL>  alter session set nls_date_format = 'DD-MON-YYYY Hh24:MI';

Session altered.

SQL> with times as
  2  (select trunc(sysdate) + ((rownum-1)*15/60/24) slot
  3   from   dual
  4   connect by rownum <= 10)  --<-- just to keep the output short
  5  select * from times;

SLOT
-----------------
30-APR-2012 00:00
30-APR-2012 00:15
30-APR-2012 00:30
30-APR-2012 00:45
30-APR-2012 01:00
30-APR-2012 01:15
30-APR-2012 01:30
30-APR-2012 01:45
30-APR-2012 02:00
30-APR-2012 02:15

10 rows selected.

The second options is to round/floor/ceil the relevant existing date/timestamp in the table to the nearest x minutes.

For this solution, there is a generic approach as follows, demonstrated using sysdate:

SQL> select sysdate,
  2         trunc(sysdate)
  3       + floor(to_char(sysdate,'sssss') / 900) / 96 floor_slot,
  4         trunc(sysdate)
  5       + round(to_char(sysdate,'sssss') / 900) / 96 round_slot,
  6         trunc(sysdate)
  7       + ceil(to_char(sysdate,'sssss') / 900) / 96 ceil_slot
  8  from   dual;

SYSDATE           FLOOR_SLOT        ROUND_SLOT        CEIL_SLOT
----------------- ----------------- ----------------- -----------------
30-APR-2012 09:58 30-APR-2012 09:45 30-APR-2012 10:00 30-APR-2012 10:00

SQL> 

Where the basic forumla is:

 trunc(sysdate)
+ floor(to_char(sysdate,'sssss') / x ) / y 
  1. The date – example uses sysdate but this would probably be a column – truncated to start of day.
  2. The usage of FLOOR / ROUND / CEIL depends on the requirement.
  3. to_char(sysdate,’sssss’) is the number of seconds since midnight
  4. x is the number of seconds in the timeslot length we’re interested in – for the example, 15 minutes * 60 seconds per minute = 900
  5. Because date arithmetic is done in days, y is the number of timeslots in a day – for this example 4 timeslots per hour * 24 hours per day = 96

So, if we want five minute timeslots, x is 5*60=300; y is 12*24=288:

SQL> select sysdate,
  2         trunc(sysdate)
  3       + floor(to_char(sysdate,'sssss') / 300) / 288 floor_stamp,
  4         trunc(sysdate)
  5       + round(to_char(sysdate,'sssss') / 300) / 288 round_stamp,
  6         trunc(sysdate)
  7       + ceil(to_char(sysdate,'sssss') / 300) / 288 ceil_stamp
  8  from   dual;

SYSDATE           FLOOR_STAMP       ROUND_STAMP       CEIL_STAMP
----------------- ----------------- ----------------- -----------------
30-APR-2012 10:13 30-APR-2012 10:10 30-APR-2012 10:15 30-APR-2012 10:15

SQL> 

Or, for half hour timeslots, x is 60*30=1800; y is 2*24=48:

SQL> select sysdate,
  2         trunc(sysdate)
  3       + floor(to_char(sysdate,'sssss') / 1800) / 48 floor_stamp,
  4         trunc(sysdate)
  5       + round(to_char(sysdate,'sssss') / 1800) / 48 round_stamp,
  6         trunc(sysdate)
  7       + ceil(to_char(sysdate,'sssss') / 1800) / 48 ceil_stamp
  8  from   dual;

SYSDATE           FLOOR_STAMP       ROUND_STAMP       CEIL_STAMP
----------------- ----------------- ----------------- -----------------
30-APR-2012 10:19 30-APR-2012 10:00 30-APR-2012 10:30 30-APR-2012 10:30

SQL> 

Deadlock trace file enhancements

Just browsing some deadlock trace files on 11gR2.

I normally look at sections:

  • Deadlock Graph
  • Information for the OTHER waiting session
  • Information for THIS session

and very rarely go beyond section PROCESS_STATE.

But, casually browsing, I came across these sections relating to the killed session:

  • Session Wait History
  • Sampled Session History of session

Nice additions. When did that happen?

Upgrade 11.2.0.3 Days 1 and 2

AKA being knee deep in …

Go-live at the weekend from 9i Solaris to 11.2.0.3 Linux.

There were a couple of minor issues on arrival Monday morning but first critical situation started @ 8:29 am Monday morning and is still ongoing Tuesday evening.

More details later but key points are:
1. Degradation of various durations, longest so far about two hours.
2. Three deliberate bounces, one crash.
3. Unrelated to above, ongoing ORA-00600s at a rate of a couple per hour, ongoing ORA-07445s at a peak rate of about 4 per minute.

Technical considerations from above:
1. Library Cache : Mutex X Contention and change to DBMS_ALERT.REGISTER
If you make significant use of DBMS_ALERT then beware a signature change in 11.2 to DBMS_ALERT.REGISTER which relates to cleanup of orphaned pipes, the default value of which is TRUE.

This new cleanup behaviour, introduced due to some other bug that I don’t have detail of right now, is apparently quite an expensive operation and in practice for us, this has resulted in critical hanging scenarios on “library cache: mutex x” effectively bringing the db to its knees.

The key recursive SQL that seems to be at the heart of this mutex issue is:

SELECT DISTINCT SUBSTR(KGLNAOBJ,11) SID FROM X$KGLOB WHERE KGLHDNSP = 7 AND KGLNAOBJ LIKE 'ORA$ALERT$%' AND BITAND(KGLHDFLG,128)!=0 UNION SELECT DISTINCT SID FROM DBMS_ALERT_INFO

Changing calls to DBMS_ALERT.REGISTER to make an explicit FALSE value for cleanup is currently the advised approach but raises the question of how you should deal with the cleanup that you’d think must be required if it was introduced as default behaviour.

At the moment, I am unconvinced by the declaration that this is expected behaviour of DBMS_ALERT.REGISTER. An expensive operation is not one that causes a massive chain of “library cache:mutex x” waits for 2 hours until the database is effectively down and has to be bounced. That smacks of bug to me.

Observations from the issue – firstly that 11.2.0.3 seems to be reporting mutex waits better than previous versions but whilst all blocking indicators (in ASH, V$SESSION and V$MUTEX_SLEEP_HISTORY) were clear about who they thought was the suspect – i.e. they all identified the same session – that session itself was waiting on the same mutex with a blocking_session of UNKNOWN. And killing that session at the head of the chain just resulted in someone higher up the chain taking their place and everyone else pointing the finger at the new #1.

2. ORA-00600 and ORA-07445s
We have multiple ORA-00600 and ORA-07445 errors, most of which seem to be related to the same area – application contexts and the introduction of the caching of instantiation objects (iobs) for application contexts in order to reduce library cache mutex contention. As mentioned this has caused one crash from PMON which inevitably crashed the instance and a steady stream of application errors. Not all the below are related to the same issue – those that are will “probably” be fixed by the same patch – but this is the current list of ongoing:

ORA-600: [kgldafr-bad-ext]
ORA-600: [kglbrk-bad-lock]
ORA-07445: [kglbrk()+45]
ORA-07445: [kglLockHandle()+23]
ORA-07445: [kksampp()+97]
ORA-07445: [qertbStart()+119]
ORA-07445: [keswxCurPushPlanMonitoring()+510]
ORA-07445: [ktspsrchsc_free()+321]

Just a brief summary for visibility, more details another time…

As I was coming in on Monday morning, I thought that maybe I was being too pessimistic with my expectations and that it might turn out to be a quiet day. Tuns out I wasn’t pessimistic enough. And we spent months testing this…

Fun, fun…

Follow

Get every new post delivered to your Inbox.

Join 69 other followers