728x90

14.10.xC4 버전부터 공식적으로 클라이언트에서도 쿼리 플랜을 확인할 수 있는 함수가 제공되는군요. 인포믹스는 과거부터 DB서버에서 set explain 문장을 실행한 후 SQL 문장을 실행하면 생성되는 파일에서 쿼리 플랜을 참조할 수 밖에 없었는데요. 그렇다보니 클라이언트에서는 쿼리 플랜을 볼 방법이 없었습니다.

 

그래서 11.50버전부터 쿼리 플랜을 시각화하는 explain_sql이라는 루틴이 제공되었는데 IBM Data Studio에서 제한적으로만 쓸 수 있어서 그렇게 많이 사용되지는 않았습니다. 사실 Data Studio는 Db2에 더 최적화 된 느낌이라 인포믹스 DB에 사용하기에는 좀 불편하지요.

 

그래서 Fernando Nunes씨가 SQL 프로시저를 사용해서 쿼리 플랜을 보는 방법을 제시하기도 했습니다. 사실 이번에 제공되는 루틴과 대동소이합니다. 여러번 루틴을 실행해야하는 번거로움이 있긴 하지만요.

informix-technology.blogspot.com/2012/12/execution-plans-on-client-planos-de.html

 

어쨌든 많이 늦었지만, 이제라도 쿼리 플랜을 IBM에서 제작된 루틴으로 조회할 수 있다는 점에서 매우 환영할만한 기능입니다. IBM Knowledge Center에서 제공되는 문서의 내용을 따라서 getExplain 함수를 만들어 보았습니다.

> CREATE FUNCTION getExplain(LVARCHAR) RETURNS LVARCHAR(30000) EXTERNAL NAME 'com.informix.judrs.Explain.getExplain(java.lang.String)' LANGUAGE JAVA;
Routine created.
> GRANT EXECUTE ON FUNCTION getExplain(LVARCHAR) TO PUBLIC;
Permission granted.

결과는 LVARCHAR 형식으로 출력되는데, 최대 32KB이니 어지간하면 잘리지 않을 것 같습니다. CLOB 형식으로 해도 괜찮지 않을까 싶습니다.

> execute function getExplain("SELECT * FROM systables a, syscolumns b where a.tabid = b.tabid");
(expression)
              QUERY: (OPTIMIZATION TIMESTAMP: 06-25-2020 22:42:56)
              ------
              SELECT * FROM systables a, syscolumns b where a.tabid = b.tabid
              Estimated Cost: 108
              Estimated # of Rows Returned: 779
                1) informix.a: SEQUENTIAL SCAN
                2) informix.b: INDEX PATH
                  (1) Index Name: informix.column
                      Index Keys: tabid colno
                      Lower Index Filter: informix.a.tabid = informix.b.tabid
              NESTED LOOP JOIN
              ----------
              Procedure: informix.getexplain
              Query statistics:
              -----------------
                Table map :
                ----------------------------
                Internal name     Table name
                ----------------------------
                t1                a
                t2                b
                type     table  rows_prod  est_rows  rows_scan  time       est_cost
                -------------------------------------------------------------------
                scan     t1     1          113       7          00:00.00   14
                type     table  rows_prod  est_rows  rows_scan  time       est_cost
                -------------------------------------------------------------------
                scan     t2     4          786       4          00:00.00   1
                type     rows_prod  est_rows  time       est_cost
                -------------------------------------------------
                nljoin   4          780       00:00.00   109
1 row(s) retrieved.

조금 더 욕심을 부리자면 SQL 문장을 실행하지 않는 AVOID_EXECUTE와 같은 기능을 제공하는 인자도 지정할 수 있다면 좋겠네요.

 

아래는 getExplain을 실행했을때 online.log에 표시되는 내용입니다.

2020-06-25 22:41:41.70  Booting Language <java> from module <$INFORMIXDIR/extend/krakatoa/lmjava.so>
2020-06-25 22:41:41.70  Loading Module <$INFORMIXDIR/extend/krakatoa/lmjava.so>
2020-06-25 22:41:41.82  cannot extract stack unwind information for /work1/informix/ids1410fc4w1/gls/dll/64-libicudata.so.60
2020-06-25 22:41:41.83  stack dumps out of /work1/informix/ids1410fc4w1/gls/dll/64-libicudata.so.60 may be incomplete
2020-06-25 22:41:41.83  The C Language Module </work1/informix/ids1410fc4w1/extend/krakatoa/lmjava.so> loaded
2020-06-25 22:41:41.83  Loading Module <com.informix.judrs.Explain>
2020-06-25 22:41:41.86  INFO (autoregvp 1) (Execution of [ autoregvp ] dymamically creating VPCLASS jvp)
2020-06-25 22:41:41.957  Dynamically added 1 jvp VP
2020-06-25 22:41:42.859  Got the mutex
2020-06-25 22:41:42.859  LD_LIBRARY_PATH=/work1/informix/ids1410fc4w1/extend/krakatoa/jre/bin/j9vm
2020-06-25 22:41:42.860  VM args[0]= -Xss512k
2020-06-25 22:41:42.860  VM args[1]= -Djava.security.policy=/work1/informix/ids1410fc4w1/tmp/JVM_security
2020-06-25 22:41:42.860  VM args[2]= -Xms16m
2020-06-25 22:41:42.860  VM args[3]= -Xmx16m
2020-06-25 22:41:42.860  VM args[4]= exit
2020-06-25 22:41:42.860  VM args[5]= abort
2020-06-25 22:41:42.860  VM args[6]= -Djava.class.path=/work1/informix/ids1410fc4w1/extend/krakatoa/krakatoa.jar:/work1/informix/ids1410fc4w1/extend/krakatoa
2020-06-25 22:41:43.24  Successfully created Java VM.
2020-06-25 22:41:43.820  Explain file for session 240 : /tmp/informix-explain1554368260018369330.tmp
2020-06-25 22:42:45.158  Explain file for session 240 : /tmp/informix-explain753362435265703881.tmp
2020-06-25 22:42:56.869  Explain file for session 241 : /tmp/informix-explain3777225348977126759.tmp

내용을 살펴보면 java 클래스를 사용한 사용자 함수를 호출한 형태임을 알 수 있습니다. 그리고 set explain 명령을 수행했을 때 처럼 'Explain file for session ...' 이라는 내용이 표시되는데요. 함수가 실행된 직후에는 해당 파일은 삭제되는 것 같습니다.

 

체감될만한 좋은 기능들이 계속 추가되고 있어서, 앞으로의 변화도 기대되는군요.

728x90
728x90

online.log 파일을 보다가 바뀐부분을 또 찾았네요.

online.log 내용에서 라인마다 날짜를 표시하는 방식이 몇가지 추가되었습니다.

기존에는 MSG_DATE 파라미터 설정값을 0과 1로만 설정할 수 있었는데요. 14.10.xC4 버전부터는 0,1,2,3 의 값을 설정할 수 있습니다. 아래는 onstat에서 보여주는 MSG_DATE 파라미터의 설명입니다.

$ onstat -g cfg full MSG_DATE
IBM Informix Dynamic Server Version 14.10.FC4W1DE -- On-Line -- Up 23:01:10 -- 2631308 Kbytes
Configuration Parameter Info
id   name                      type    maxlen   units   rsvd  tunable
150  MSG_DATE                  INT4    12                     *
     min/max : 0,3
     default : 0
     onconfig: 3
     current : 3
     Description:
     Use the MSG_DATE configuration parameter to specify the format of the
     timestamp preceding messages in the log. The choices are as follows:
     Value     Format
     0         HH:MM:SS
     1         MM/DD/YYYY HH:MM:SS (Locale-dependent ordering of MM and DD)
     2         Milliseconds since epoch + MM/DD/YYYY HH:MM:SS (Locale-dependent
               ordering of MM and DD)
     3         YYYY-MM-DD HH:MM:SS.FFF

14.10.FC3과 14.10.FC4W1 버전에서 출력되는 내용을 비교해보았습니다.

-- 14.10.xC3 (MSG_DATE=1)
06/24/20 21:45:40  Checkpoint Completed:  duration was 0 seconds.
06/24/20 21:45:40  Wed Jun 24 - loguniq 1101, logpos 0x8234, timestamp: 0x13fca499 Interval: 358
06/24/20 21:45:40  Maximum server connections 5
06/24/20 21:45:40  Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 1229, Llog used 10125
-- 14.10.xC4 (MSG_DATE=2, SERVER_LOCALE=ko_kr.ksc)
1593004908957 20/06/24 22:21:48 Checkpoint Completed:  duration was 0 seconds.
1593004908957 20/06/24 22:21:48 Wed Jun 24 - loguniq 20, logpos 0x861018, timestamp: 0x2875df Interval: 345
1593004908957 20/06/24 22:21:48 Maximum server connections 3
1593004908957 20/06/24 22:21:48 Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 39, Llog used 5
-- 14.10.xC4 (MSG_DATE=3)
2020-06-24 21:46:42.356  Checkpoint Completed:  duration was 0 seconds.
2020-06-24 21:46:42.356  Wed Jun 24 - loguniq 20, logpos 0x5e64d4, timestamp: 0x27ae32 Interval: 333
2020-06-24 21:46:42.356  Maximum server connections 11
2020-06-24 21:46:42.356  Checkpoint Statistics - Avg. Txn Block Time 0.000, # Txns blocked 0, Plog used 63, Llog used 55

 아무래도 연월일 순서로 나오는게 보기가 편하겠죠? 근데 밀리세컨드까진 필요없을 것도 같고..

728x90
728x90

6월 23일자로 인포믹스 14.10 버전의 새로운 Fix Pack 14.10.xC4W1이 공개되었습니다.

아직 문서에 새로운 기능 소개는 나오지 않아서 onstat 유틸리티에 새로운 옵션이 생겼나 찾아보니 하나가 눈에 띄네요.

 

onstat -g top이라는 옵션이 새로 생겼습니다. 리눅스의 top과 유사한 기능을 제공하는 옵션인데요. 기본값으로 5초간의 성능수치를 비교하여 시스템 자원을 많이 사용하는 세션이나 스레드를 확인할 수 있습니다. 시간 간격이나 표시할 라인 수, 반복 횟수를 지정할 수 있습니다.

아래는 onstat 명령을 실행했을 때의 top 옵션 설명입니다.

        top [ <entity> <stat> [ <max lines> [ <intvl> [ <reps> ]]]]
            Print top consumers of various resources over specified interval
            Valid <entity> <stat> combinations:
                thread    cpu   (CPU usage)
                thread    drd   (disk reads)
                thread    bfr   (buffer reads)
                thread    bfw   (buffer writes)
                thread    plg   (physical log usage)
                thread    llg   (logical log usage)
                session   cpu   (CPU usage)
                session   drd   (disk reads)
                session   bfr   (buffer reads)
                session   bfw   (buffer writes)
                session   plg   (physical log usage)
                session   llg   (logical log usage)
                chunk     ios   (page reads/writes)
                chunk     art   (average read times)
                chunk     awt   (average write times)
                space     ios   (page reads/writes)
                space     art   (average read times)
                space     awt   (average write times)
                mempool   gro   (memory growth)
                sessmem   gro   (memory growth)
                partition drd   (disk reads)
                table     drd   (disk reads)

위에 나열된 항목을 전부 또는 지정해서 볼 수 있습니다.

watch 명령을 이용해서 인포믹스를 모니터링 하는 것도 괜찮아 보입니다.

아래는 제가 약간의 트랜잭션을 발생시키고 나서 top 옵션으로 본 화면입니다.

[informix@db2 skjeong]$ onstat -g top 10 3
IBM Informix Dynamic Server Version 14.10.FC4W1DE -- On-Line -- Up 18:46:36 -- 2631308 Kbytes
Top Resource Usage (Max lines 10, Time interval 3 seconds):
Top Threads (CPU usage)
 tid    name              sid        CPU_time   #scheds  status
 343    sqlexec           208          0.0014         6  sleeping secs: 1
 344    sqlexec           209          0.0009         6  sleeping secs: 1
 345    sqlexec           210          0.0009         6  sleeping secs: 1
 19     periodic          14           0.0001         5  sleeping secs: 1
Top pools (memory growth)
 name                           increase(b)      total_size(b)
 rsam                           8                3081712
(No partition disk reads to display)
(No DBspace activity to display)
(No physlog activity to display)
Top threads (logical log usage)
 tid      rstcb              llog_bytes   name
 344      0x459af1a8         552          sqlexec
 343      0x459afa88         552          sqlexec
 345      0x459b0c48         552          sqlexec

기존에 스크립트로 모니터링 하시는 분들도 계시겠지만, onstat 명령으로 본다면 좀 더 시스템에 부담은 덜 줄 것 같군요. 실시간 모니터링에 많은 도움이 될 것 같습니다.

 

다른 유용한 기능이 더 생겼는지 찾아봐야겠네요.

728x90

+ Recent posts