Pythian Group

Or, Why I Like Broccoli and Wait Events

There’s been a fair bit of discussion with respect to whose vegetables are the freshest in Ottawa. From one DBA to another, I’m here to tell you that St. Laurent Fruit and Vegetable (beside the Mideast Meat Market) is probably the place to go for the best prices on… well… fruits and vegetables. They also carry lots of bags, and they’re strategically placed so you’ll never need old men to help you get more :-)

What’s more interesting about grocery shopping is that it lets you daydream and go over all the good work you’ve done over the last week (assuming you go weekly and a certain amount good work done). Last week was particularly tough. One of our more stable clients had some serious “mystery” production problems. To paraphrase, their app that was running “OK” starting running “sucky”. I knew that nothing had changed from our end and so being the intrepid super-sleuths that we are, we determined that the problems were related to I/O. How? Here’s how (forgive me, but I haven’t really gone into massive amounts of detail on this one, it’s more of a general framework).

Step 1

Run a handy query originally written by Steve Adams. I use this as my very first step to troubleshooting anything that resembles an Oracle performance issue, and work from there.

-----------------------------------------------------------
--
-- Script:      waiters.sql
-- Purpose:     to count the waiters for each event type
-- For:         8.0 and higher
--
-- Copyright:   (c) 2000 Ixora Pty Ltd
-- Author:      Steve Adams
--
-----------------------------------------------------------
select /*+ ordered */
  substr(n.name, 1, 29)  event,
  t0,
  t1,
  t2,
  t3,
  t4,
  t5,
  t6,
  t7,
  t8,
  t9
from
  sys.v_$event_name  n,
  (select event e0, count(*)  t0 from sys.v_$session_wait group by event),
  (select event e1, count(*)  t1 from sys.v_$session_wait group by event),
  (select event e2, count(*)  t2 from sys.v_$session_wait group by event),
  (select event e3, count(*)  t3 from sys.v_$session_wait group by event),
  (select event e4, count(*)  t4 from sys.v_$session_wait group by event),
  (select event e5, count(*)  t5 from sys.v_$session_wait group by event),
  (select event e6, count(*)  t6 from sys.v_$session_wait group by event),
  (select event e7, count(*)  t7 from sys.v_$session_wait group by event),
  (select event e8, count(*)  t8 from sys.v_$session_wait group by event),
  (select event e9, count(*)  t9 from sys.v_$session_wait group by event)
where
  n.name != 'Null event' and
  n.name != 'null event' and
  n.name != 'rdbms ipc message' and
  n.name != 'pipe get' and
  n.name != 'virtual circuit status' and
  n.name not like '%timer%' and
  n.name not like '%slave wait' and
  n.name not like 'SQL*Net message from %' and
  n.name not like 'io done' and
  n.name != 'queue messages' and
  e0 (+) = n.name and
  e1 (+) = n.name and
  e2 (+) = n.name and
  e3 (+) = n.name and
  e4 (+) = n.name and
  e5 (+) = n.name and
  e6 (+) = n.name and
  e7 (+) = n.name and
  e8 (+) = n.name and
  e9 (+) = n.name and
  nvl(t0, 0) + nvl(t1, 0) + nvl(t2, 0) + nvl(t3, 0) + nvl(t4, 0) +
  nvl(t5, 0) + nvl(t6, 0) + nvl(t7, 0) + nvl(t8, 0) + nvl(t9, 0) > 0
order by
  nvl(t0, 0) + nvl(t1, 0) + nvl(t2, 0) + nvl(t3, 0) + nvl(t4, 0) +
  nvl(t5, 0) + nvl(t6, 0) + nvl(t7, 0) + nvl(t8, 0) + nvl(t9, 0)
/

It’s really a nifty “group by” from v$session_wait. So, if you really want, you can go straight there. This query showed me the following:

SQL*Net more data from client 1 1 1 1 1 1 1 1 1 1
latch free   2 2 2 2 2 2 2 2 2 2
db file sequential read  2 2 2 2 2 2 2 2 2 2
db file scattered read  3 3 3 3 3 3 3 3 3 3
enqueue    8 8 8 8 8 8 8 8 8 8
buffer busy waits  15 15 15 15 15 15 15 15 15 15

Ok, so now I know we definitely had a problem with enqueues and buffer_busy_waits. In addition, when I ran this a few times, I also encountered significant latch free waits. So what’s the deal? Poking around the web, you’ll come up with a few standard answers for each of these. To summarize, here’s a great paper on resolving latch free waits.

Looking in v$session_wait told me the latch I was waiting on was the kghalo latch for the shared_pool. This was expected. Our client was known for not binding any SQL, and so we were parsing everything. This wasn’t unusual.

The P2 column in v$session_wait tells you the latch# it’s waiting for, which can be looked up in v$latchname. In addition, for some system stats, you can run this:

select * from v$latch_misses order by 5 desc;

Step 2

What was unusual, however, were the absolute number of enqueues and buffer_busy_waits. Linking the sid from v$session_wait to v$session and then to v$sqlarea, a trend emerged. All the buffer_busy_waits were against the same object (in memory). In addition, the enqueues were also on the same object. How did I know this? Well, the waiting queries were one indication, however, I also looked at v$session_wait to get the information I needed.

When you look at buffer_busy waits, the P1 column gives you the file_name and the P2 column gives you the block#. P3 gives you the reason you’re waiting. Run the following to get the object you’re waiting on.

select * from dba_extents where file_id = [[your_file] and [your_block] between block_id and block_id + blocks;

Typically, you’re hitting hot blocks. You can try to use some of the techniques discussed here.

Step 3

Troubleshooting enqueue uses a similar strategy. For enqueues, the P2 column gives you the object_id of the object, and from there you figure out what’s going on.

select * from dba_objects where object_id = [your_P2_object];

In 10G, the interface is a little more useful, giving you the actual type of enqueue and the reason. In 8173, we’re not so fortunate. Either way, we managed to isolate a number of bad running queries this way, and it was obvious that we were hitting an I/O bottleneck based on one table in the database. My recommendation to the client was to check the disks. After they assured us that everything was okay, I went ahead and looked for query plan flips, etc.

At the end of 3 days of query tuning, one of the clients’ sys admins finally discovered that a battery had failed on the disk controller, causing all write cacheing to no longer be available. I’m sure there must have been a way to see this, but I just don’t know how.

To summarize folks, always check your batteries. But if you don’t, and your DBA starts lifting the hood and poking around, they’re sure to find tons of other stuff that can be fixed and that came to light only when the hardware didn’t behave nicely. Kinda like a nice stress test, eh?

What my team and I discovered was that the object in question needed some serious love, since the client does plan on growing their operation. Because of all the queries we fixed, their app is that much faster. So in the long run, this was good for us. Just like broccoli.

I’m off to dinner.

I’ve received the call more times than I can count. You know, the one that arrives ten minutes before you pack up for the trip home to see the kids, play ball, and generally not be at the office. The caller is normally your boss/administrator/guy in charge of all things not working. And when the caller reaches you, you’re the guy in charge of making it work again.

In my experience, the solution to most problems (the ones the caller refers to as “it’s running slow”) are not rooted in hardware, because hardware problems generally cause things to not run at all. It always baffles me when developers and architects prescribe hardware upgrades to make things run faster, because about 80% of the performance-related problems and subsequent solutions I’ve dealt with were resolved by tuning the application. In the hands of an experienced tuner, the cost of getting more out of the whole system does not compare with the cost of a hardware upgrade. It’s just apples and oranges… and my apples are much cheaper than their oranges.

This first installment will deal with the biggest contributor to bad application design — the dreaded bad query. I’ve actually had busy systems crash because a developer unleashed a query that performed a full tablescan too many.

This approach can be used both for troubleshooting in a crisis, or preferably, pro-actively to help you identify potential bottlenecks before they cause problems. It might not be the most efficient, and I can’t guarantee that the query is bug-free, but it works. If you find any problems, please let me know. I always appreciate efforts to make my work better.

You need to know what’s running on the system, and how “expensive” it is. That’s the only way to know what you should attack, and in my experience it’s the hardest part of this making-things-run-faster thing.

On Oracle systems we can identify the SQL that’s been running by querying the v$sqlarea/v$sqltext views. You can also do this with statspack using a level 6 or higher snap. These methods work superbly under ideal conditions. However, real-life is rarely ideal. We flush the shared_pool every now and then; some of the systems have a cold backup taken; some of them crash; and last, some of them obfuscate the SQL by not using bind_variables, making it difficult to isolate queries.

Running the following always works as a good starting point:
select executions, buffer_gets, sql_text from v$sqlarea;

74522 166474 INSERT INTO UNIQUE_OBJECT VALUES ( :b1,:b2,:b3,:b4,:b5,:b6,:b7  )
35263 71972 INSERT INTO UNIQUE_USER_ACCOUNT VALUES ( :b1,:b2,:b3  )
953 4105 INSERT INTO UQ_USER_SNAPSHOT VALUES ( SEQ_UQ_USER_SNAPSHOT.NEXTVAL,:b1,:b2,SYSDATE  )
953 16415 INSERT INTO UQ_USER_SNAPSHOT_ENTRY VALUES ( :b1,:b2,:b3  )
1 4 SELECT  MODIFIED_BY "modified_by", MODIFY_DT "modify_dt" FROM UQ_ANSWER where (ID=12899182)
1 4 SELECT  MODIFIED_BY "modified_by", MODIFY_DT "modify_dt" FROM UQ_ANSWER where (ID=12899184)
1 4 SELECT  MODIFIED_BY "modified_by", MODIFY_DT "modify_dt" FROM UQ_ANSWER where (ID=12899192)
1 4 SELECT  MODIFIED_BY "modified_by", MODIFY_DT "modify_dt" FROM UQ_ANSWER where (ID=12899194)

You’ll notice that some of the queries — the ones highlighted in bold — have literal values. These literal values get in the way of figuring out how expensive a query really is. For instance, I could try doing a group by summing the buffer_gets, but those pesky literals just get in the way. They prevent the underlying query from getting grouped properly because Oracle thinks they’re all different! Also, these buffer_gets and executions are relevant only since the time this shared_pool was last flushed or bounced, or if the query hadn’t been aged out. Are we really getting the information we need to make a good judgement?

I found this function from Tom Kyte’s webspace, and I haven’t touched it in any way. It takes unbound SQL and strips away the bind variables. Thank you Tom, it was a life saver.

create or replace function remove_constants( p_query in varchar2 ) return varchar2 as l_query long;
l_char varchar2(1);
l_in_quotes boolean default FALSE;
begin for i in 1 .. length( p_query ) loop l_char := substr(p_query,i,1);
if ( l_char = '''' and l_in_quotes ) then l_in_quotes := FALSE;
elsif ( l_char = '''' and NOT l_in_quotes ) then l_in_quotes := TRUE;
l_query := l_query || '''#';
end if;
if ( NOT l_in_quotes ) then l_query := l_query || l_char;
end if;
end loop;
l_query := translate( l_query, '0123456789', '@@@@@@@@@@' );
for i in 0 .. 8 loop l_query := replace( l_query, lpad('@',10-i,'@'), '@' );
l_query := replace( l_query, lpad(' ',10-i,' '), ' ' );
end loop;
return upper(l_query);
end;
/

The next section is where we get creative. Because we’re flushing the shared_pool, and crashing, and taking cold backups, we need to periodically keep track of the sqlarea. I do this by scheduling the following procedure that takes the shared_pool and simply stuffs it into a holding table. You can schedule it at whatever interval you want. Here’s the syntax for the underlying tables.

drop table bob_sqlarea;
create table bob_sqlarea tablespace INDX as select hash_value
     , sql_text
     , executions, buffer_gets
     , parsing_user_id from v$sqlarea;
alter table avail.bob_sqlarea add sql_text_wo_constants varchar2(4000);
alter table avail.bob_sqlarea add timestamp date;
create or replace procedure pop_bob_sqlarea as begin insert into bob_sqlarea select sysdate timestamp
     , hash_value, sql_text
     , executions , buffer_gets
     , parsing_user_id from v$sqlarea;
commit; end;
/  

exec sys.dbms_job.submit(:x,'pop_bob_sqlarea;',sysdate+1/24,'sysdate + 1/24');

Now that we’re catching the entire shared_pool, we stand a chance of getting meaningful cumulative stats for the DB. Here I have scheduled my job to run every hour.

When you’re ready to look at the data after a few minutes/hours/days/years of gathering it, you simply do this:

update bob_sqlarea set sql_text_wo_constants = remove_constants(sql_text); commit;

Now, run this query and look at the report. It’s ugly because it takes into account both the SQL getting flushed in/out and also the time of the DB bounce. You do lose some data on a bounce, but if you’re taking stats every x minutes, it’s better than what statspack gives you.

select sum(total_execs), sum(total_bg), case when sum(total_execs) > 0 then round(sum(total_bg)/sum(total_execs),0) else sum(total_bg) end ratio, sql_text
from (
select
username,
substr(sql_text_wo_constants,0,900) sql_text,
hash_value,
executions,
buffer_gets,
count(*) over (partition by hash_value) num_hashes,
executions - lag(executions,1,0) over (partition by hash_value order by timestamp) diff,
case
when count(*) over (partition by hash_value) = 1 then executions
when executions - lag(executions,1,0) over (partition by hash_value order by timestamp asc) = 0 then 0
when executions - lag(executions,1,0) over (partition by hash_value order by timestamp asc) > 0 then executions - lag(executions,1,0) over (partition by hash_value order by timestamp asc)
when count(*) over (partition by hash_value) = 2 then executions
when executions - lag(executions,1,0) over (partition by hash_value order by timestamp asc) < 0 then executions
else executions - lag(executions,1,0) over (partition by hash_value order by timestamp)
end total_execs,
case
when count(*) over (partition by hash_value) = 1 then buffer_gets
when buffer_gets - lag(buffer_gets,1,0) over (partition by hash_value order by timestamp asc) = 0 then 0
when buffer_gets - lag(buffer_gets,1,0) over (partition by hash_value order by timestamp asc) > 0 then buffer_gets - lag(buffer_gets,1,0) over (partition by hash_value order by timestamp asc)
when count(*) over (partition by hash_value) = 2 then buffer_gets
when buffer_gets - lag(buffer_gets,1,0) over (partition by hash_value order by timestamp asc) < 0 then buffer_gets
else buffer_gets - lag(buffer_gets,1,0) over (partition by hash_value order by timestamp)
end total_bg
from bob_sqlarea, dba_users
where bob_sqlarea.parsing_user_id = dba_users.user_id)
group by sql_text
order by case when sum(total_execs) > 0 then round(sum(total_bg)/sum(total_execs),0) else sum(total_bg) end desc;

With this query, you can see a truer picture of what SQL your database is actually running, despite the bounces, crashes, and general badness that the app is throwing at it. It should save you some time in identifiying heavy resource-hogging queries, because you have the queries grouped together despite having unbound literals, and the numbers will make sense even if the DB has been bounced.

This is what you’ll see (indented for readability):

3 12 4 SELECT MUMP_CREATE_DT "CREATEDT", MUMP_MODIFY_DT "MODIFYDT"
    , MUMP_BREAKFAST "MUMP_BREAKFAST", MUMP_DAY_NUMBER "MUMP_DAY_NUMBER"
    , MUMP_DINNER "MUMP_DINNER", MUMP_ID "MUMP_ID"
    , MUMP_LUNCH "MUMP_LUNCH" , MUMP_SNACK_@ "MUMP_SNACK_@"
    , MUMP_SNACK_@ "MUMP_SNACK_@" , MUMP_SNACK_@ "MUMP_SNACK_@"
    , MUMP_STATUS "MUMP_STATUS" , MUMP_USER_ID "MUMP_USER_ID"
    FROM MP_USER_MEAL_PLAN WHERE ((MUMP_ID=@))
11 44 4 SELECT MODIFY_DT "MODIFY_DT" FROM UT_DATAPOINT WHERE (ID=@)
139 558 4 SELECT MODIFIED_BY "MODIFIED_BY"
, MODIFY_DT "MODIFY_DT" FROM UQ_ANSWER WHERE (ID=@)
1916 6792 4 SELECT ID FROM UQ_USER_SNAPSHOT WHERE USER_ID = :B@ AND QUESTIONNAIRE_ID = :B@
1449 5850 4 SELECT ID FROM UQ_RESPONSE_PROFILE WHERE USER_ID = @ 

In case you’re wondering who the “bob” is for “bob_sqlarea”, feel free to shoot me an email :-)

In the second part of this series, I’ll be highlighting techniques that use the Oracle Wait interface to identify performance issues.