Dion Cho – Oracle Performance Storyteller

We are natural born scientists

Another way to use trace file

with 6 comments

I believe that many of you sometimes have strong need for customized trace analysis.

For instance, see following wait records of 10046 trace file.

...
WAIT #11: nam='buffer busy waits' ela= 4 file#=17 block#=2313 class#=8 obj#=81140 tim=520863116874
WAIT #11: nam='buffer busy waits' ela= 5456 file#=17 block#=2624 class#=1 obj#=81140 tim=520864249735
WAIT #11: nam='buffer busy waits' ela= 6 file#=17 block#=2569 class#=8 obj#=81140 tim=520864249933
...



What I want is to sort the buffer busy waits events by the class# like this:

CLASS#            CNT ELAPSED
---------- ---------- -------
8                1456    3.01
1                 420    1.54
4                   5     .00
35                  2     .00
77                  1     .00



But traditional tkprof has no such things. So what can I do? Hire developer? Do some excelling?

Nope. My approach is totally 100% SQL based, which is quite natural and easy for me. :) Most of all, it’s totally free. :)

Let’s see how I do it.

1. Create directory and array

-- create directory and varchar2 array
col value new_value user_dump_directory;

select value from v$parameter where name = 'user_dump_dest';

create or replace directory user_dump_dir as '&user_dump_directory';

create or replace type varchar2_array as table of varchar2(4000);
/



2. Create pipelined table function with utl_file package. If you’re not familiar with pipelined table function, visit here.

-- create get_trace_file1 function
create or replace function get_trace_file1(s_id number default userenv('sid'))
return varchar2_array
pipelined
as
  v_handle  utl_file.file_type;
  v_filename  varchar2(2000);
  v_line      varchar2(4000);
begin
  -- get exact file_name
  select i.value||'_ora_'||p.spid||'.trc' into v_filename
  from v$process p, v$session s, 
    (select value from v$parameter where name = 'instance_name') i
  where p.addr = s.paddr 
        and s.sid = s_id
  ;
  
  v_handle := utl_file.fopen('USER_DUMP_DIR', v_filename, 'R', 32767);
  
  loop
    begin
      utl_file.get_line(v_handle, v_line);
    exception when no_data_found then
      exit;
    end;
    
    pipe row(v_line);
  end loop;
  
  return;
end;
/

-- create get_trace_file2 function
create or replace function get_trace_file2(file_name in varchar2)
return varchar2_array
pipelined
as
  v_handle  utl_file.file_type;
  v_line      varchar2(20000);
begin
  
  v_handle := utl_file.fopen('USER_DUMP_DIR', file_name, 'R', 32767);
  
  loop
    begin
      utl_file.get_line(v_handle, v_line);
    exception when no_data_found then
      exit;
    end;
    
    pipe row(v_line);
  end loop;
  
  return;
end;
/



3. Good. Let’s play with it

alter session set events '10046 trace name context forever, level 8';

select count(*) from t1;

alter session set events '10046 trace name context off';

select * from table(get_trace_file1);

Dump file c:\oracle\admin\ukja10\udump\ukja10_ora_2820.trc
Thu Mar 19 15:10:10 2009
ORACLE V10.2.0.1.0 - Production vsnsta=0
vsnsql=14 vsnxtr=3
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production
With the Partitioning, OLAP and Data Mining options
Windows XP Version V5.1 Service Pack 2
CPU                 : 2 - type 586
Process Affinity    : 0x00000000
Memory (Avail/Total): Ph:1481M/3070M, Ph+PgF:3140M/4960M, VA:1359M/2047M
Instance name: ukja10

Redo thread mounted by this instance: 1

Oracle process number: 16

Windows thread id: 2820, image: ORACLE.EXE (SHAD)


*** ACTION NAME:() 2009-03-19 15:10:10.109
*** MODULE NAME:(SQL*Plus) 2009-03-19 15:10:10.109
*** SERVICE NAME:(UKJA10) 2009-03-19 15:10:10.109
*** SESSION ID:(157.1205) 2009-03-19 15:10:10.109
=====================
PARSING IN CURSOR #1 len=68 dep=0 uid=61 oct=42 lid=61 tim=172367882897 hv=740818757 ad='27e12b14'
alter session set events '10046 trace name context forever, level 8'
END OF STMT
...



4. Very cool. Now I sort the buffer busy waits event by class# like this.(Actually, not that elegant query)

col class# format a10
col elapsed format 99.99

with t as (
  select /*+ materialize */
    column_value as line, 
    instr(column_value, 'ela=') ei, 
    instr(column_value, 'file#=') fi,
    instr(column_value, 'block#=') bi,
    instr(column_value, 'class#=') ci,
    instr(column_value, 'obj#=') oi,
    instr(column_value, 'tim=') ti
  from table(get_trace_file2('trc_1.trc'))
  --from table(get_trace_file2('trc_2.trc'))
  where 
    instr(column_value, 'WAIT #2: nam=''buffer busy waits''') > 0
    --instr(column_value, 'WAIT #11: nam=''buffer busy waits''') > 0
)
select
  class# 
  , count(1) as cnt
  , sum(elapsed)/1000000 as elapsed
from
  (
    select
      substr(line, ei+4, fi-ei-4) as elapsed,
      substr(line, fi+6, bi-fi-6) as file#,
      substr(line, bi+7, ci-bi-7) as block#,
      substr(line, ci+7, oi-ci-7) as class#,
      substr(line, oi+5, ti-oi-5) as obj#,
      substr(line, ti+4) as tim
    from
      t 
  ) x
group by 
  class#
order by 
  2 desc, 3 desc
;



What I’m actually doing is:

  1. trc_1.trc file contains the 10046 trace result with 40K extent size in ASSM.
  2. trc_2.trc file contains the 10046 trace result with 10M extent size in ASSM.
  3. 10 concurrent sessions insert into the table with 10046 trace enabled.
  4. I’d like to analyze how extent size affects the pattern of buffer contention.

Here is the result.

-- when extent size is 40K
CLASS#            CNT ELAPSED
---------- ---------- -------
8                 285    1.40
1                 215    4.64
4                  42     .01
9                   2     .00
19                  1     .00
33                  1     .00

-- when extent size is 10M
CLASS#            CNT ELAPSED
---------- ---------- -------
8                1456    3.01
1                 420    1.54
4                   5     .00
35                  2     .00
77                  1     .00



See the diffference. With big extent size, we have major buffer contention on 1st level bitmap block(8). With (too) smaller extent size, the major contention is on data block(1).

Hm… What does this mean? Well, it’s not the topic. :)

My point here is that Oracle has more funtionality than you imagine. Simple tricks with pipelined table function and utl_file package made it possible for me to analyze the whole new pattern of wait events.

PS) Instead of pipelined table function, the external table is also feasible. But I believe that the pipeline table function version is far more elegant.

About these ads

Written by Dion Cho

March 19, 2009 at 6:49 am

6 Responses

Subscribe to comments with RSS.

  1. Good stuff.

    dombrooks

    March 19, 2009 at 9:12 am

  2. That’s really nice.

    You could also use External Tables like this:

    SQL> drop table trace_table ;

    Table dropped.

    SQL>
    SQL> create table
    2 trace_table ( txt varchar2(1000) )
    3 organization external (
    4 type oracle_loader
    5 default directory TRACE_DIR
    6 access parameters (
    7 records delimited by newline
    8 )
    9 location(‘mydb_ora_3248_bbw2.trc’)
    10 );

    Table created.

    SQL>
    SQL> Column Cur_Id Format a6
    SQL> Column Event Format a30
    SQL> Column Class Format a5
    SQL>
    SQL> Select Cursor_number Cur_Id,
    2 Event,
    3 Class,
    4 Round(Sum(Elapsed/1000000), 2) Elapsed_Time,
    5 Count(Event) Cnt
    6 From (Select Substr(REGEXP_SUBSTR(txt, ‘WAIT #[^:]*’), 7) Cursor_number,
    7 Substr(REGEXP_SUBSTR(txt, ”’[^'']*’), 2) Event,
    8 Nvl(Substr(REGEXP_SUBSTR(txt, ‘class#=[^ ]*’), 8), ‘N/A’) Class,
    9 Substr(REGEXP_SUBSTR(txt, ‘ela= [^ ]*’), 6) Elapsed
    10 from trace_table
    11 where REGEXP_SUBSTR(txt, ‘WAIT #[^:]*’) is NOT null)
    12 Group by
    13 Cursor_number,
    14 Event,
    15 Class
    16 Order by Cursor_number;

    CUR_ID EVENT CLASS ELAPSED_TIME CNT
    —— —————————— —– ———— ———-
    3 SQL*Net message from client N/A 13.16 1
    3 SQL*Net message to client N/A 0 1
    6 SQL*Net message from client N/A 17.04 2
    6 SQL*Net message to client N/A 0 2
    6 db file scattered read N/A 443.29 6223
    6 db file sequential read N/A 15.24 210
    6 latch: cache buffers chains N/A .04 22
    6 latch: cache buffers lru chain N/A 0 2
    6 read by other session 1 438.68 11148

    9 rows selected.

    SQL>

    Asif Momen

    March 19, 2009 at 10:06 pm

  3. Asif.

    Yes, external table is another solution, but pipelined table function version is more flexible and easy to manage.

    Anyway, I really like your regular expression solution! :)

    Dion Cho

    March 19, 2009 at 10:49 pm

  4. It is nice post, and very useful for DBAs.

    cheers

    Mehmood

    April 11, 2009 at 4:26 pm

  5. I changed it a bit to get the benefits of 11g.
    get_tracefile1 does not work when you set tracefilename but if you use v$diag_info it gives you to use it with tracefilename identifier.

    — get exact file_name
    select replace(value,(select value||’\’ from v$diag_info where name=’Diag Trace’),”) into v_filename
    from v$diag_info where name=’Default Trace File';

    coskan

    July 14, 2009 at 9:52 pm

  6. @Coskan.

    It’s a nice try. Besides that, many enhancements are possible, like merging multiple tracefiles without trcsess or cat invokation.

    Dion Cho

    July 15, 2009 at 3:17 am


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 60 other followers

%d bloggers like this: