태터데스크 관리자

도움말
닫기
적용하기   첫페이지 만들기

태터데스크 메시지

저장하였습니다.

'Regular Expression'에 해당되는 글 2건

  1. 2009.06.23 나에게 딱! 필요한 만큼의 Regular Expression
  2. 2009.03.20 trace 파일을 사용하는 또 한가지 방법 (2)

나에게 딱! 필요한 만큼의 Regular Expression

오라클 2009.06.23 13:04
Oracle 10g부터 Regular Expression이 제공되지만 나는 팬이라고 할 수는 없다. 무엇보다 용도가 그리 많지 않고, 이해하기 어렵고, 속도도 느리다. 버그가 꽤 많고.

하지만, 특정 작업을 할 때는 Regular Expression이 너무나 유용할 때가 많다. 이런 작업을 할 때 사용하는 Regular Expression들은 결코 복잡한 것이 아니고 매우 심플한 것들이다. 복잡한 것이라면 아예 시도도 안했겠지! 나는 딱 이 정도의 기능만 알고 있으면 된다.

몇 가지 예를 통해 내가 Regular Expression을 사용하는 예를 들어 본다.

1. 첫번째 예제는 10046 Trace 파일 원본을 내 입맛대로 분석하는 것이다.

drop table t1 purge;

create table t1(c1 int);

ed temp.sql
/*
begin
    for idx in 1 .. 300000 loop
        insert into t1(c1) values(idx);
    end loop;
end;
/
*/

ho start sqlplus ukja/ukja@ukja102 @temp
ho start sqlplus ukja/ukja@ukja102 @temp
ho start sqlplus ukja/ukja@ukja102 @temp
ho start sqlplus ukja/ukja@ukja102 @temp
ho start sqlplus ukja/ukja@ukja102 @temp

exec dbms_lock.sleep(1);
@trace_on 10046 8
@temp
@trace_off

INSERT INTO T1(C1)
VALUES
(:B1 )


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute 300000      7.98      29.66          0       2012     309299      300000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   300001      7.98      29.66          0       2012     309299      300000

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 61     (recursive depth: 1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  buffer busy waits                            2810        1.02         13.09
  latch: library cache pin                       31        0.03          0.12
  latch: cache buffers chains                    11        0.04          0.08
  latch: library cache                           14        0.05          0.12
  log file switch completion                      7        0.99          2.24
  log file switch (checkpoint incomplete)         4        0.75          1.31
  enq: HW - contention                           18        0.03          0.07
  enq: TX - contention                            9        0.00          0.00
  enq: FB - contention                            8        0.01          0.01
  latch: redo allocation                          2        0.04          0.07
  log buffer space                                2        0.26          0.26


buffer busy waits 대기가 문제가 있어 보인다. 추가적인 분석을 위해 원본 Trace 파일을 열어 보았더니 이런 모양이다.

WAIT #6: nam='buffer busy waits' ela= 26148 file#=10 block#=27298 class#=1 obj#=89644 tim=94342641391
EXEC #6:c=0,e=64798,p=0,cr=4,cu=4,mis=0,r=1,dep=1,og=1,tim=94342680018
EXEC #6:c=0,e=55,p=0,cr=6,cu=4,mis=0,r=1,dep=1,og=1,tim=94342680397
EXEC #6:c=0,e=29,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=94342683501
WAIT #6: nam='buffer busy waits' ela= 18336 file#=10 block#=27310 class#=1 obj#=89644 tim=94342704683
EXEC #6:c=0,e=18644,p=0,cr=8,cu=4,mis=0,r=1,dep=1,og=1,tim=94342704954
EXEC #6:c=0,e=29,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=94342707772
EXEC #6:c=0,e=23,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=94342708005
WAIT #6: nam='buffer busy waits' ela= 26111 file#=10 block#=27314 class#=1 obj#=89644 tim=94342738234

내가 하려고 하는 것은 buffer busy waits 대기 현상이 Class별, File별로 어떻게 분포되었는지 분석하는 것이다. Regular Expression! 딱 아래 정도의 Regular Expression이면 충분하다.

UKJA@ukja102> define __VALUE = 'WAIT #6: nam=''buffer busy waits'' ela= 18336 file#=10 block#=27310
class#=1 obj#=89644 tim=94342704683'
UKJA@ukja102> prompt &__VALUE
WAIT #6: nam='buffer busy waits' ela= 18336 file#=10 block#=27310 class#=1 obj#=89644 tim=9434270468
3
UKJA@ukja102>
UKJA@ukja102> select
  2     substr(regexp_substr(q''&__VALUE'', 'ela= [[:digit:]]+'), 6) as ela,
  3     substr(regexp_substr(q''&__VALUE'', 'file#=[[:digit:]]+'), 7) as f#,
  4     substr(regexp_substr(q''&__VALUE'', 'block#=[[:digit:]]+'), 8) as b#,
  5     substr(regexp_substr(q''&__VALUE'', 'class#=[[:digit:]]+'), 8) as c#
  6  --from table(get_trace_file2('temp.trc'))
  7  from dual
  8  where
  9     regexp_like(q''&__VALUE'', 'buffer busy waits')
 10  ;

ELA   F# B#    C
----- -- ----- -
18336 10 27310 1


다음과 같이 Trace 파일 전체에서 내가 원하는 패턴만 추출한다.

select
        substr(regexp_substr(column_value, 'ela= [[:digit:]]+'), 6) as ela,
        substr(regexp_substr(column_value, 'file#=[[:digit:]]+'), 7) as f#,
        substr(regexp_substr(column_value, 'block#=[[:digit:]]+'), 8) as b#,
        substr(regexp_substr(column_value, 'class#=[[:digit:]]+'), 8) as c#
    from table(get_trace_file2('temp.trc'))
    where
        regexp_like(column_value, 'buffer busy waits')


Regular Expression을 이용해 Class 별, File 별 buffer busy waits 대기를 분석한 결과는 다음과 같다.

UKJA@ukja102> select
  2     c#, count(*), sum(ela)
  3  from t_temp1
  4  group by c#
  5  ;

        C#   COUNT(*)   SUM(ELA)
---------- ---------- ----------
         1       2808   13098056
         8          2         10

Elapsed: 00:00:00.04
UKJA@ukja102>
UKJA@ukja102> select
  2     f#, c#, count(*), sum(ela)
  3  from t_temp1
  4  group by f#, c#
  5  ;

        F#         C#   COUNT(*)   SUM(ELA)
---------- ---------- ---------- ----------
        11          1       1323    5553501
        11          8          2         10
        12          1       1002    4062191
        10          1        483    3482364

Elapsed: 00:00:00.03


흐음... ASSM을 사용하면서 동시 Insert에 의한 Class#=1 에 대한 경합이 줄어들었다고는 하지만, 여전히 상당한 정도의 경합이 발생하는 것을 알 수 있다. 정말 대단히 유용한 분석 결과가 아닌가!

2. 두 번째 예제는 Internal Cursor(Pseudo Cursor)에 대해 어떤 Object와 관련이 있는지 추적하는 것이다.

간혹 V$SQL에는 등장하지 않는 Internal Cursor가 사용되는 경우가 있다. 아래 문서에 잘 설명되어 있다.

http://kerryosborne.oracle-guy.com/2009/04/hidden-sql-why-cant-i-find-my-sql-text/

여기서 table_4_9_15d7b_0_0_ 와 같은 Pseudo Object 이름을 볼 수 있는데 여기서 네번째 문자열(15d7b)이 Base Object의 ID 값이다. Regular Expression을 이용하면 다음과 같이 손쉽게 Object ID로 변환할 수 있다.

UKJA@ukja116> select to_dec(regexp_substr('table_4_9_15d7b_0_0_', '[^_]+', 1, 4))
  2             as object_id
  3  from dual
  4  ;

 OBJECT_ID
----------
     89467


3. Heap Dump 분석
PGA나 SGA Dump를 수행하면 다음과 같이 개별 Chunk들에 대한 크기 및 종류 등의 상세한 정보를 얻을 수 있다.

EXTENT 10 addr=083BC23C
  Chunk  83bc244 sz=     3696    perm      "perm           "  alo=3696
  Chunk  83bd0b4 sz=     2316    perm      "perm           "  alo=2316
  Chunk  83bd9c0 sz=      212    freeable  "PLS cca hp desc"
  Chunk  83bda94 sz=     2068    freeable  "kjztprq struct "
EXTENT 11 addr=08522048
  Chunk  8522050 sz=    18448    perm      "perm           "  alo=18448
EXTENT 12 addr=083BA1B8
  Chunk  83ba1c0 sz=     4272    perm      "perm           "  alo=4272
  Chunk  83bb270 sz=     3928    recreate  "KSFQ heap      "  latch=00000000
     ds  83bc1d4 sz=     3928 ct=        1
  Chunk  83bc1c8 sz=       92    freeable  "KSFQ heap descr"


이 정보들을 Regular Expression을 통해 분석하려면 다음과 같이 간단한 수준이면 충분하다.

UKJA@ukja116> define __VALUE = '  Chunk 4f1436cc sz=   248116    freeable  "session heap   "  ds=085
A760'
UKJA@ukja116> prompt &__VALUE
Chunk 4f1436cc sz=   248116    freeable  "session heap   "  ds=085A760
UKJA@ukja116>
UKJA@ukja116> select
  2     substr(regexp_substr('&__VALUE', 'sz=[ ]*[[:digit:]]+'),4) as chunk_size,
  3     regexp_substr('&__VALUE', '(freeable|free|perm|recreate)') as chunk_type,
  4     regexp_substr('&__VALUE', '"[[:print:]]+"') as obj_type,
  5     substr(regexp_substr('&__VALUE', 'ds=[[:xdigit:]]+'),4) as subheap
  6  from dual
  7  where
  8     regexp_like('&__VALUE', 'Chunk')
  9  ;

CHUNK_SIZ CHUN OBJ_TYPE          SUBHEAP
--------- ---- ----------------- -------
   248116 free "session heap   " 085A760


따라서 다음과 같이 전체 Heap Dump 파일에서 내가 원하는 패턴만 추출할 수 있다.

select
    substr(regexp_substr(column_value, 'sz=[ ]*[[:digit:]]+'),4) as chunk_size,
    regexp_substr(column_value, '(freeable|free|perm|recreate)') as chunk_type,
    regexp_substr(column_value, '"[[:print:]]+"') as obj_type,
    substr(regexp_substr(column_value, 'ds=[[:xdigit:]]+'),4) as subheap
from table(get_trace_file2('heap_dump_1.trc'))
where
    regexp_like(column_value, 'Chunk')
;

아래에 실제로 분석해 본 결과가 있다.

UKJA@ukja102> select
  2     chunk_type,
  3     decode(chunk_type, 'free',
  4                     count(*)/2, count(*)) as count#,
  5     decode(chunk_type, 'free',
  6                     sum(chunk_size/2), sum(chunk_size)) as size#
  7  from t_temp2
  8  group by chunk_type
  9  ;

CHUNK_TYPE               COUNT#      SIZE#
-------------------- ---------- ----------
perm                         32     181928
recreate                      8      87180
freeable                   3584  498650144
free                       3552   99660580

Elapsed: 00:00:00.12
UKJA@ukja102>
UKJA@ukja102> select
  2     obj_type,
  3     decode(obj_type, '"               "',
  4                     count(*)/2, count(*)) as count#,
  5     decode(obj_type, '"               "',
  6                     sum(chunk_size/2), sum(chunk_size)) as size#
  7  from t_temp2
  8  group by obj_type
  9  ;

OBJ_TYPE                 COUNT#      SIZE#
-------------------- ---------- ----------
"KFIO PGA struct"             1         72
"KSFQ heap      "             1       3928
"KJZT context   "             1         60
"kpuinit env han"             1       1584
"perm           "            32     181928
"               "          3552   99660580
"kzsna:login nam"             1         24
"kews sqlstat st"             1       1292
"PLS cca hp desc"             1        212
"callheap       "             2       2144
"kopolal dvoid  "             5       2524
"session heap   "          3547  498632732
"PLS non-lib hp "             3      18560
"koh-kghu call h"             2       1328
"KFK PGA        "             1        260
"KSFQ heap descr"             1         92
"Fixed Uga      "             1      20572
"ldm context    "            13      12712
"external name  "             1         24
"kjztprq struct "             1       2068
"Alloc environm "             1       4144
"kgh stack      "             1      17012
"qmtmInit       "             4      13980
"joxp heap      "             2       2000

24 rows selected.

Elapsed: 00:00:00.17
UKJA@ukja102>
UKJA@ukja102>
UKJA@ukja102> select
  2     subheap, count(*), sum(chunk_size)
  3  from t_temp2
  4  where subheap is not null
  5  group by subheap
  6  ;

SUBHEAP                COUNT(*) SUM(CHUNK_SIZE)
-------------------- ---------- ---------------
083BD9CC                      2           10320
08563470                      3           12436
085A7600                   3546       498567256

Elapsed: 00:00:00.09


정말 엄청나게 유용한 정보를 간단하게 추출할 수 있지 않은가! Regular Expression이 없이도 충분히 같은 일을 할 수 있지만, 훨씬 유연한 접근 방식이다. 하지만 Regular Expression을 과도하게 사용하면 성능이 만족스럽지 않은 경우가 많으므로 꼭 필요한 경우에만 사용해야 한다는 것이 개인적 경험이다.


Trackback 0 : Comment 0

Write a comment


trace 파일을 사용하는 또 한가지 방법

오라클 2009.03.20 14:02
자신만의 방식으로 trace 분석을 해야만 하는 경우가 종종 있다.

예를 들어, 아래와 같이 10046 trace 파일의 대기 레코드들이 있다고 하자.

...
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
...


다음과 같이 buffer busy waits 를 class# 항목으로 정렬해서 보고 싶다. :

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


일반적인 tkprof로는 방법이 없다. 그럼 어떻게 해야할까, 개발자를 새로 고용? 뭔가 멋진 방법이 있을까?

No. 나라면 100% SQL로 구현할 것이다. SQL이라면, 쉽고 유연하며 무엇보다 공짜다.

자, 그럼 내가 제안하는 방법을 한번 보자.


1. 디렉토리와 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. utl_file 패키지와 함께 pipelined table function를 생성한다. 만약 pipelined table function에 대해 잘 모른다면 여기를 참조한다.

-- 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. 자... 그럼 간단한 데모를 보자.

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. 이제 buffer busy waits 이벤트를 class#로 정렬해서 분석할 수 있다.

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
;


내가 실제로 수행하고자 한 것은 다음과 같다.

1. trc_1.trc 파일은 ASSM 으로 된 40K extent size의 10046 trace result를 갖고있다.
2. trc_2.trc 파일은 ASSM 으로 된 10M extent size 의 10046 trace result를 갖고있다.
3. 10개의 동시 세션이 10046 trace가 enable된 상태에서 테이블에 insert를 수행한다.
4. extent size가 buffer 경합 패턴에 어떻게 영향을 주는지 분석하고자 한다.

결과는 아래와 같다.

-- 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


차이점을 보면 extent size 가 큰 경우에는 1st level 비트맵 블럭(8)에서 주로 버퍼 경합이 발생했고, extent size 가 작은 경우, data block(1)에서 경합이 주로 발생했다.

이 결과가 무엇을 의미 하는가? 여기서 이야기하고자 하는 주제는 아니므로 생략...

여기서 내가 말하고자 하는것은, 오라클은 우리가 상상하는 것 이상의 기능을 갖고 있다는 것이다. pipelined table function 과 utl_file 패키지라는 간단한 트릭을 사용해서 wait 이벤트의 새로운 패턴을 분석할 수 있었다.

PS1) pipelined table function 대신 external table도 이용할수 있으나 아무래도 pipelined table function 이 훨씬 멋진 방법인것 같다.

PS2) 10g부터는 다음과 같이 Regular Expression을 이용해서 훨씬 간단하게 분석할 수 있다.

select
  cursor_number cur_id,
  event,
  class,
  round(sum(elapsed/1000000), 2) elapsed_time,
  count(event) cnt
from (
  select
    substr(regexp_substr(txt, ‘wait #[^:]*’), 7) cursor_number,
    substr(regexp_substr(txt, ”’[^'']*’), 2) event,
    nvl(substr(regexp_substr(txt, ‘class#=[^ ]*’), 8), ‘n/a’) class,
    substr(regexp_substr(txt, ‘ela= [^ ]*’), 6) elapsed
  from table(get_trace_file1)
  where regexp_substr(txt, ‘wait #[^:]*’) is not null
)
group by
  cursor_number,
  event,
  class
  order by cursor_number
;

Trackback 1 : Comments 2
  1. 바다모습 2009.03.21 10:05 신고 Modify/Delete Reply

    오~ 오랫동안 가지고 있던 고민을 한번에 풀어 주는 것 같은데요~
    감사합니다.~!^^

  2. moncler online 2013.01.04 16:38 Modify/Delete Reply

    관리자의 승인을 기다리고 있는 댓글입니다

Write a comment

티스토리 툴바