달력

52025  이전 다음

  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10
  • 11
  • 12
  • 13
  • 14
  • 15
  • 16
  • 17
  • 18
  • 19
  • 20
  • 21
  • 22
  • 23
  • 24
  • 25
  • 26
  • 27
  • 28
  • 29
  • 30
  • 31

'[펌] 기술자료'에 해당되는 글 2건

  1. 2010.04.29 [펌]Array Processing 활용 115
  2. 2008.11.10 [펌] Log4J 로깅 비용 계산......

04. Array Processing 활요

  • Array Processing 기능을 활용하면 한 번의 SQL 수행으로 다량의 로우를 동시에 insert/update/delete 할 수 있다.
  • 네트워크를 통한 데이터베이스 Call을 감소시켜주고, 궁극적으로 SQL 수행시간과 CPU 사용량을 획기적으로 줄여준다.

사례1 ? Java 프로그렘에서 Array Processing)

public class JavaArrayProcessing{ 
  public static void insertData( Connection con 
                               , PreparedStatement st 
                               , String param1 
                               , String param2 
                               , String param3 
                               , long param4) throws Exception{ 
    st.setString(1, param1); 
    st.setString(2, param2); 
    st.setString(3, param3); 
    st.setLong(4, param4); 
    *st.addBatch();* 
  } 
 
  public static void execute(Connection con, String input_month)  
  throws Exception { 
    long rows = 0; 
    String SQLStmt1 = "SELECT 고객번호, 납입월" 
                    + "     , 지로, 자동이체, 신용카드, 핸드폰, 인터넷 " 
                    + "FROM   월요금납부실적 " 
                    + "WHERE  납입월 = ?"; 
                    
    String SQLStmt2 = "INSERT /*+ test3 */ INTO 납입방법별_월요금집계  "  
            + "(고객번호, 납입월, 납입방법코드, 납입금액) " 
            + "VALUES(?, ?, ?, ?)"; 
 
    con.setAutoCommit(false); 
 
    PreparedStatement stmt1 = con.prepareStatement(SQLStmt1); 
    PreparedStatement stmt2 = con.prepareStatement(SQLStmt2); 
    *stmt1.setFetchSize(1000);* 
    stmt1.setString(1, input_month); 
    ResultSet rs = stmt1.executeQuery(); 
    while(rs.next()){ 
      String 고객번호 = rs.getString(1); 
      String 납입월 = rs.getString(2); 
      long 지로 = rs.getLong(3); 
      long 자동이체 = rs.getLong(4); 
      long 신용카드 = rs.getLong(5); 
      long 핸드폰 = rs.getLong(6); 
      long 인터넷 = rs.getLong(7); 
      if(지로 > 0)     insertData (con, stmt2, 고객번호, 납입월, "A", 지로); 
      if(자동이체 > 0) insertData (con, stmt2, 고객번호, 납입월, "B", 자동이체); 
      if(신용카드 > 0) insertData (con, stmt2, 고객번호, 납입월, "C", 신용카드); 
      if(핸드폰 > 0)   insertData (con, stmt2, 고객번호, 납입월, "D", 핸드폰); 
      if(인터넷 > 0)   insertData (con, stmt2, 고객번호, 납입월, "E", 인터넷); 
      *if(++rows%1000 == 0) stmt2.executeBatch();* 
    } 
 
    rs.close(); 
    stmt1.close(); 
 
    *stmt2.executeBatch();* 
    stmt2.close(); 
 
    con.commit(); 
    con.setAutoCommit(true); 
  } 
 
  public static void main(String[] args) throws Exception{ 
    long btm = System.currentTimeMillis(); 
    Connection con = getConnection(); 
    execute(con, "200903"); 
    System.out.println("elapsed time : " + (System.currentTimeMillis() - btm)); 
    releaseConnection(con); 
} 
 
- 트레이스 결과 
 
SELECT 고객번호, 납입월, 지로, 자동이체, 신용카드, 핸드폰, 인터넷 
FROM 월요금납부실적 WHERE 납입월 = :1 
 
 
call     count       cpu    elapsed       disk      query    current        rows 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
Parse        1      0.00       0.00          0          0          0           0 
Execute      1      0.01       0.01          0         71          0           0 
Fetch       31      0.00       0.04          0        169          0       30000 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
total       33       0.01      0.04          0         240          0       30000 
 
Misses in library cache during parse: 1 
Misses in library cache during execute: 1 
Optimizer mode: ALL_ROWS 
Parsing user id: 54 
 
Rows     Row Source Operation 
-------  --------------------------------------------------- 
  30000  TABLE ACCESS FULL 월요금납부실적 (cr=169 pr=0 pw=0 time=90083 us) 
 
 
INSERT INTO 납입방법별_월요금집계  
(고객번호, 납입월, 납입방법코드, 납입금액) 
VALUES (:1 , :2 , :3 , :4 ) 
 
 
call     count       cpu    elapsed       disk      query    current        rows 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
Parse        1      0.00       0.00          0          0          0           0 
Execute     30      0.18       0.27          2        923       5094      150000 
Fetch        0      0.00       0.00          0          0          0           0 
------- ------  -------- ---------- ---------- ---------- ----------  ---------- 
total        31      0.18       0.27          2        923       5094      150000 
 
Misses in library cache during parse: 1 
Misses in library cache during execute: 1 
Optimizer mode: ALL_ROWS 
Parsing user id: 54
  • 150,000(30,000*5)건을 insert 하는데 단 1.21초 만에 수행
  • insert 문에 대한 Execute Call이 30회만 발생
  • insert 된 로우 수가 150,000건이므로 매번 5,000건씩 Array Processing한 것.
    (커서에서 Fetch되는 각 로우마다 5번씩 insert를 수행하는데, 1,000 로우마다 한번식 executeBatch를 수행하기 때문)
  • select 결과를 Fetch 할 때도 1,000개 단위로 Array Fetch 하도록 조정. (JAVA에서 기본값은 10)
  • 30,000건을 읽는데 Fetch Call이 31회만 발생.

  • 네트워크를 경유해 발생하는 데이터베이스 Call이 얼마맡큼 심각한 성능부하를 일으키는 지 ?수 있다.
  • One-SQL로 통합하지 않더라도 Array Processing 만으로 그에 버금가는 성능개선 효과를 얻을 수 있다.
  • Array Processing의 효과를 극대화하려면 연속된 일련의 처리과정이 모두 Array 단위로 진행 되어야 한다.

사례2 ? PL/SQL Bulk insert

DECLARE 
  l_fetch_size NUMBER DEFAULT 1000;  -- 1,000건씩 Array 처리 
 
  CURSOR c IS  
    SELECT empno, ename, job, sal, deptno, hiredate  
    FROM   emp; 
 
  TYPE array_empno      IS TABLE OF emp.empno%type; 
  TYPE array_ename      IS TABLE OF emp.ename%type; 
  TYPE array_job        IS TABLE OF emp.job%type; 
  TYPE array_sal        IS TABLE OF emp.sal%type; 
  TYPE array_deptno     IS TABLE OF emp.deptno%type; 
  TYPE array_hiredate   IS TABLE OF emp.hiredate%type; 
 
  l_empno     array_empno     := array_empno   (); 
  l_ename     array_ename     := array_ename   (); 
  l_job       array_job       := array_job     (); 
  l_sal       array_sal       := array_sal     (); 
  l_deptno    array_deptno    := array_deptno  (); 
  l_hiredate  array_hiredate  := array_hiredate(); 
 
  PROCEDURE insert_t( p_empno     IN array_empno    
                    , p_ename     IN array_ename    
                    , p_job       IN array_job      
                    , p_sal       IN array_sal      
                    , p_deptno    IN array_deptno   
                    , p_hiredate  IN array_hiredate ) IS 
 
  BEGIN 
    *FORALL i IN p_empno.first..p_empno.last* 
      *INSERT INTO emp2* 
      VALUES ( p_empno   (i) 
             , p_ename   (i) 
             , p_job     (i) 
             , p_sal     (i) 
             , p_deptno  (i) 
             , p_hiredate(i) ); 
 
  EXCEPTION 
    WHEN others THEN 
      DBMS_OUTPUT.PUT_LINE(SQLERRM); 
      RAISE; 
  END insert_t; 
 
BEGIN 
 
  OPEN c; 
 
  LOOP 
 
    *FETCH c BULK COLLECT* 
    *INTO l_empno, l_ename, l_job, l_sal, l_deptno, l_hiredate* 
    *LIMIT l_fetch_size;* 
 
    insert_t( l_empno, l_ename, l_job, l_sal, l_deptno, l_hiredate ); 
 
    EXIT WHEN c%NOTFOUND; 
  END LOOP; 
 
  CLOSE c; 
 
  COMMIT; 
 
EXCEPTION 
  WHEN OTHERS THEN 
    ROLLBACK; 
END; 
/
  • SQL 트레이스 결과를 보면, 10,000건을 처리하는데 select문의 Fetch Call과 insert문의 Execute Call이 각각 10번씩만 발생한 것을 알 수 있다.
    (select의 Fetch Call이 11번이 발생한 것은 데이터가 더 있는지 확인하기 위한 것임)
  • EXP, IMP 명령을 통해 데이터를 Export, Import 할 때도 내부적으로 Array Proccessing이 활용
    (buffer 옵션으로 지정가능, byte 단위로 지정 = rows_in_array * maximum_row_size)
  • Array Processing을 지원하는 인터페이스가 프로그램 언어별로 각기 다르므로 API를 통해 확인하고 이를 활용할 것.

문서에 대하여

  • 최초작성자 : [김종원]
  • 최초작성일 : 2010년 01월 09일
  • 이 문서는 오라클클럽 코어 오라클 데이터베이스 스터디 모임에서 작성하였습니다.
  • 이 문서의 내용은 (주)비투엔컬설팅에서 출간한 '오라클 성능 고도화 원리와 해법I'를 참고하였습니다.

# 이 문서는 
오라클클럽에서 작성하였습니다. 
# 이 문서를 다른 블로그나 홈페이지에 게재하실 경우에는 출처를 꼭 밝혀 주시면 고맙겠습니다.~^^ 
# 출처 : 
http://wiki.oracleclub.com/pages/viewpage.action?pageId=3901805&
Posted by InuxKr
|

기존의 System.out.println() 으로 로깅 할 때 발생하는 문제의 대안으로 Log4J를 요즘 많이 사용한다.

Log4J를 사용하면 OutputStream시 발생하는 자원독점 문제 해결, logging 레벨 설정을 코드와 분리, 로깅 output target 설정 변경 등 다양한 잇점을 얻을 수 있다.

그러나 Log4J가 실행될 때 발행하는 비용을 계산해 보면 Log4J를 사용할 때 주의가 필요하다.
무작정 사용하는 것은 WAS 전체에 심각한 문제를 발생 시킬 수 있다.

모 사이트에서 JVM의 GC가 자주 발생하는 문제가 발생하여 시스템 전체에 심각한 문제가 발생한 사례가 있었다. 물론 Log4J가 문제의 핵심은 아니었지만 어느 정도 영향은 미쳤다고 생각된다.

지금 다룰 내용은 "Log4J The Complete Manual" 23 페이지에 나온 내용을 참조하였다.
이 내용을 메뉴얼을 읽을 때는 심각하게 받아 들이지 않았지만 실제 사례를 접하니 간과할 수만은 없는 문제인 듯 싶다.

문제 코드 분석
문제가 발생한 사이트는 Struts를 기반으로 하는 프레임웍 구조를 갖고 있었다.
Session 정보를 추출하기 위하여 다음과 같은 코드가 공통 코드 레벨에서 수행되고 있었다.

while ( i.hasNext()  ) {                                                                                  
Map.Entry e = (Map.Entry) i.next();                                                               
logger.debug("TABLE KEY : " + e.getKey() );                                                  
logger.debug("SESSION ID : " + ((HttpSession) e.getValue()).getId());                
}
                                                                                                                 


특정 상황에서 이 코드는 246번의 반복을 수행하였고, 두 개의 debug()이 실행하면서 각각 8메가의 임시 객체를 생성하였다. 해당 while문이 수행되면서 16메가의 임시 객체를 생성하였다.

물론 문제의 while문이 구동할 때 Log4J는 DEBUG 모드로 운영중인 상태였다.

이 코드로 발생하는 문제는 Log4J를 DEBUG 모드로 운영 중이기 때문에 발생한 것이고 WARNING이나 ERROR 모드로 운영하면 문제가 발생하지 않는다고 생각할 수도 있다. 그러나 Log4J가 실행되는 비용을 계산해 보면 이러한 문제는 Log4J의 운영 모드를 변경해도 동일하게 발생한다는 것을 알수 있다.(물론 일정 부분 감소는 할 것이다.)

1. Log4J 로깅 메소드 비용 계산
예제 코드
logger.debug("Entry number: "+i+" is "+String.valueOf(entry[i]));

예제 코드와 같은 코드가 있다고 할 때 다음과 같은 순서로 실행된다.


  1. logging 문자열 생성
    1. String 문자열 1개 생성: "Entry number: "
    2. String 문자열 1개 생성 총 2개: "Entry number: " + i
    3. String 문자열 1개 신규 생성, + 결합 1개 생성, 총 4개: 신규 생성: " is ", 결합 문자열: "Entry number: " + +i+" is "
    4. String 문자열 1개 신규 생성, + 결합 1개 생성, 총 6개: 신규생성: String.valueOf(entry[i]), 결합문자열: "Entry number: "+i+" is "+String.valueOf(entry[i])

  2. logger의 logging 레벨 체크
    1. 현재 등록된 로거의 로깅 레벨을 체크
    2. 현재 logger의 로깅 레벨이 DEBUG이면 다음단계 진행
    3. 현재 logger의 로깅 레벨이 INFO 이상이면 정지

  3. logger의 appender에 등록된 output에 출력
    1. layout 적용
    2. 출력



위와 같은 순서로 실행된다.

2. Log4j 운영 모드에 따른 비용 계산


  • Debug 모드일 때

    1. 1번 로깅 문자열 생성 = 6개의 스트링 객체 생성, 1개만 사용, 5개의 스트링 객체는 GC 대상
    2. 2번 logger의 레벨 체크 실행
    3. 3번 로깅 실행 - layout 적용 후 output에 로깅 적용

  • non-Debug 모드일 때

    1. 1번 로깅 문자열 생성 = 6개의 스트링 객체 생성, 1개만 사용, 5개의 스트링 객체는 GC 대상
    2. 2번 logger의 레벨 체크 실행
    3. 3번 실행 없이 종료



로 그의 모드에 따라서 Log4J에서 생략되는 부분은 3번에 국한된다. 즉 로깅 문자열 생성이나 로그 레벨 체크의 비용은 발생한다. 여기서 로그레벨 체크는 전체 로깅 비용의 1%이하이고 극히 적은 비용을 발생하기 때문에 2번은 큰 문제가 되지 않을 수 있다. 그러나 1번의 발생 비용은 경우에 따라서 매우 심각해 질 수도 있다.

1번의 로깅 문자열은 스트링을 "+"하는 방식이기 때문에
수백번의 loop안에서 발생하거나 로깅 로직이 빈번하게 발생하는 조건에서는 temporary object를 양산하는 로직이 될 가능성이 크다.

위의 Log4j 운영 모드에 따른 실행 순서에서 알수 있듯이 이것은 로깅 모드를 변경한다고 해서 발생하지 않는 부분은 아니다.

3. 문제 해결 코드

if(logger.isDebugEnabled() {                                                                                      
logger.debug("Entry number: "+i+" is "+String.valueOf(entry[i]));                              
}
                                                                                                                             
 

위 와 같은 코드의 사용이 바람직 하다. 이러한 코드는 Log4J의 예제에서 나오는 isDebugEnabled() 메소드를 이용하는 방법이다. 실제 프로젝트에서 보변 isDebugEnabled 메소드의 사용을 간과 하는 경우가 많다.

이 코드를 사용하면 로깅 문자열을 생성하기 전에 로깅 레벨을 체크하는 isDebugEnabled 메소드를 실행하여 로깅을 실행할 것인가를 미리 체크하게 된다. 기본적인 코드이지만 이러한 코드를 사용하는 것은 매우 중요하다.


4. 문제 해결 코드의 side-effect

이 코드는 DEBUG 모드일대 부가적인 문제를 발생 시킨다.
if(logger.isDebugEnabled() {                                                                                      
logger.debug("Entry number: "+i+" is "+String.valueOf(entry[i]));                              
}
                                                                                                                           


이 코드는 DEBUG 모드일 때 LOGGER의 실행 레벨 체크를 두번한다는 단점을 갖는다.

isDubugEnabled 메소드에서 한번 체크하고 debug 메소드에서 다시 체크한다. debug 모드에서 로깅 레벨 체크후 degub 상태이면 로깅을 한다.

이 러한 실행 과정은 단일 로깅일 때는 문제가 되지 않지만(로깅 전체에서 체크의 실행 비용은 1% 이하이다.) debug 메소드가 loop 문 안에 있거나, 하나의 메소드에서 debug 메소드가 여러번 호출될 때는 문제가 될수 있다. 1%이하라도 반복적으로 실행된다면 문제가 될 것이다.


public void foo(Object[] a) {
for(int i = 0; i < a.length; i++) {
if(logger.isDebugEnabled()){
   logger.debug("Original value of entry number: "+i+" is "+a[i]);
}
a[i] = someTransformation(a[i]);
if(logger.isDebugEnabled()){
   logger.debug("After transformation the value is "+a[i]);
}
}


위 와 같은 메소드가 있을 경우에는 반복문속에서 두번의 debug 메소드가 실행된다.
Debug 모드 운영 중이라고 가정할 때
반복문 속에서
1. 로그레벨 체크
2. 로그레벨 체크 후 로깅
3. 로그레벨 체크
4. 로그레벨 체크 후 로깅

의 순서로 실행된다. 반복문 자체도 문제지만 반복적인 로깅 체크 역시 문제이다. 이러한 코드는 다음과 같이 변경하는 것이 바람직하다.


public void foo(Object[] a) {
boolean isLogging = logger.isDebugEnabled();
for(int i = 0; i < a.length; i++) {
if(isLogging ){
   logger.debug("Original value of entry number: "+i+" is "+a[i]);
}
a[i] = someTransformation(a[i]);
if(isLogging ){
   logger.debug("After transformation the value is "+a[i]);
}
}

} 



작은 결론 debug 메소드 사용시 주의 사항

지금은 debug 메소드에 대해서 알아 보았다. debug 메소드를 사용할 경우 다음과 같은 두가지 사항에 주의해야 할 것이다.

1. isDebugEnabled 메소드를 사용하여 사전에 로그레벨 체크: 불필요한 로깅 문자열 생성 비용 절감
2. 반복문에서는 isDebugEnabled 메소드를 반복문 외부에서 실행하여 결과 저장 및 반복문 안에서 재사용: 불필요한 로깅 레벨 중복 체크의 비용 절감

또다른 숙제...
Log4J 를 사용함으로써 예전에 로깅 문제의 만은 부분은 해결되고 있지만 Log4J에 대한 올바른 사용에 주의를 기울일 필요가 있다. 지금은 debug 메소드만을 다루었지만 debug 외의 info(), warning(), error(), fatal() 메소드 역시 동일한 문제를 내포하고 있다.

이러한 고민에 앞서 로깅 관련 코드를 작성할 때 로깅 문자열 생성에 대한 각별한 주의가 필요한 것 같다.

무심코 작성한 코드 한줄이 폭탄이 될수도 있다.....^^
2008/04/14 10:03 2008/04/14 10:03
Posted by InuxKr
|