티스토리 뷰

728x90
반응형

 포스팅은 JEUS - WebtoB의 각종 TimeOut 옵션에 대한 테스트를 다뤄보겠습니다.


 

1. read-timeout
설정 : WEBMain.xml 
 <web-container> <context-group> <webserver-connection> <webtob-listener> <read-timeout>
  - millisecond value
  - Default Value : 0

의미 : WebtoB Web Server sends "ping" continuously to Web Container for set interval on "svrchktime" variable of WebtoB configuration file. Web Container sets time interval in this element for checking on "ping" in which WebtoB has sent. If WebtoB ping is not inspected in the set time interval, it will reset by considering network link as broken.



2. postdata-read-timeout

설정 : WEBMain.xml
 <jeus-system><web-container> <context-group> <webserver-connection> <webtob-listener> <postdata-read-timeout>
- millisecond value
- Default Value : 30000

의미 : postdata read timeout 설정은 웹서버나 Web 클라이언트으로부터 보내진  post-data를 읽어 들일 때 기다릴 수 있는 최대 시간 값이다.

 

- HttpPostClient.java : Http요청(헤더를 포함해)을 직접 보내는 java client, 헤더에 삽입할 전체 데이터의 길이와 실제 전송할 데이터의 길이를 설정할 수 있다. 테스트를 위해서는, 헤더에 설정할 데이터의 길이를 실제 전송하는 데이터의 길이보다 길게 설정해야 한다.
 => 이 경우, WebtoB에서는 헤더에 설정된 길이 만큼의 데이터가 모두 전송되기 까지 기다리기 때문에, 기다리는 시간 동안 JEUS의 postdata-read-timeout에 걸리게 된다
- 테스트 결과,JEUS에서는 postdata-read-timeout에 의해서 WebtoB와의 연결을 끊기 위해서, 연속 2회 이상의 시도 이후에 연결을 끊는다.

 

[테스트] 

- Client
<HttpPostClient.java> : 헤더에 설정한 데이터 길이 20480
           실제 전송할 데이터 12288
- WebtoB : <http.m>
  *SERVER
  MyGroup         SVGNAME = jsvg, MinProc = 2, MaxProc = 5, HttpInBufSize = 8192

- JEUS : WEBMain.xml
   <webtob-listener>
                     ...
                <postdata-read-timeout>5000</postdata-read-timeout>
  </webtob-listener>

 

[결과]

[WebtoB_Err_Log] 없음.
그러나
1) WebtoB의 Timeout값을 postdata-read-timeout보다 짧게 할 경우, Timeout 에러로그가 남는다.
  postdata-read-timeout : 5초
  Timeout : 1초
  <java파일 실행결과>
  java.lang.Exception: unexcepted header data format
          at HttpPostClient.main(HttpPostClient.java:90)
  Elapsed Time: 1750 ms(1 sec)
[08/Jul/2015:17:03:10 +0900] [error] [client 65.65.65.65] TIMEOUT is expired while svc is running

2) postdata-read-timeout값을 Timeout보다 충분히 짧게하지 않을 경우(postdata-read-timeout의 2배보다 여유있게 커야 함), Timeout에러로그가 남는다. 
  postdata-read-timeout : 5초
  Timeout : 10초
  <java파일 실행결과>
  java.lang.Exception: unexcepted header data format
          at HttpPostClient.main(HttpPostClient.java:90) 
  Elapsed Time: 10734 ms(10 sec) 
[08/Jul/2015:17:03:10 +0900] [error] [client 65.65.65.65] TIMEOUT is expired while svc is running

3) [netstat] JEUS-WebtoB간의 연결
2015. 07. 20. (ÀÏ) 12:10:25 KST
tcp        0      0 0.0.0.0:9900            0.0.0.0:*               LISTEN      
tcp        0      0 127.0.0.1:9900          127.0.0.1:48505         ESTABLISHED 
tcp        0      0 127.0.0.1:9900          127.0.0.1:48609         ESTABLISHED 
++++ 5초가 지난 후 ++++
2015. 07. 20. (ÀÏ) 12:10:33 KST
tcp        0      0 0.0.0.0:9900            0.0.0.0:*               LISTEN      
tcp        0      0 127.0.0.1:9900          127.0.0.1:48505         ESTABLISHED  => 여전히 유지
tcp        0      0 127.0.0.1:9900          127.0.0.1:48609         ESTABLISHED 
++++  10초가 지난후 ++++
2015. 07. 20. (ÀÏ) 12:10:35 KST
tcp        0      0 0.0.0.0:9900            0.0.0.0:*               LISTEN      
tcp        0      0 127.0.0.1:9900          127.0.0.1:48609         ESTABLISHED 
tcp        0      0 127.0.0.1:9900          127.0.0.1:48636         ESTABLISHED  => 새로운 연결 설정

4) [webadmin ti]
Sun Jul 20 12:10:24 KST 2015] trials = 2
-- Thread State [webtob1-hth0(localhost_9900)] --
[webtob1-hth0(localhost:9900)-w0][active , rt=356 ms, uri=/hello/data.jsp]
[webtob1-hth0(localhost:9900)-w1][waiting, wt=117244 ms]
[total : 2    active : 1    idle : 1    blocked : 0    reconnecting : 0]

++++ 10초 후 ++++

Sun Jul 20 12:10:34 KST 2015] trials = 7
-- Thread State [webtob1-hth0(localhost_9900)] --
[webtob1-hth0(localhost:9900)-w0][waiting, wt=5841 ms]
[webtob1-hth0(localhost:9900)-w1][waiting, wt=127738 ms]
[total : 2    active : 0    idle : 2    blocked : 0    reconnecting : 0] 

 

3. active-timeout

설정 : JEUSMain.xml
<jeus-system><node> <engine-container> <tm-config> <active-timeout>
  - millisecond value
  - Default Value : 600000

의미 : 글로벌 트랜잭션이 시작되면 이 시간 안에 commit이 실행되어야 한다. 그렇지 않으면 트랜잭션 매니저가 rollback 시켜버린다.

[테스트] 

- Client : EJB CMT(Container-Management-Trancsaction)샘플을 이용
BEAN (class ProductManagerEJB implements SessionBean)
 : Long-Query를 수행 (100초 정도의 수행시간)
 select COUNT(*) COUNT from (select * from dba_objects, dba_segments union all select * from dba_objects,dba_segments)
- JEUS : JEUSMain.xml
   <tm-config>
                  <active-timeout>10000</active-timeout>
   <database>
     <stmt-query-timeout>30000</stmt-query-timeout>

[결과] 

[JEUS_Container_Log]
[2015.07.21 16:12:47][4][0_520-3] [container1-23] [TM-3629] try to activate active state timeout for current coordinator associated with transaction (0:192.168.110.50:10941:119:0x4473bdd9:0x0)
[2015.07.21 16:12:47][0][0_520-3] [container1-23] [TM-3632] activate active state timeout for current coordinator associated with transaction (0:192.168.110.50:10941:119:0x4473bdd9:0x0)
[2015.07.21 16:12:47][4][0_520-3] [container1-23] [TM-3715] start to rollback current coordinator associated with transaction (0:192.168.110.50:10941:119:0x4473bdd9:0x0)
java.sql.SQLException: ORA-01013: 현 조작의 취소가 요구되었습니다 
 at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:134)
        at oracle.jdbc.ttc7.TTIoer.processError(TTIoer.java:289)
        at oracle.jdbc.ttc7.Oall7.receive(Oall7.java:582)
             **  중 략 **
        at oracle.jdbc.driver.OracleStatement.doExecuteQuery(OracleStatement.java:2529)
        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:2840)
        at oracle.jdbc.driver.OracleStatement.executeQuery(OracleStatement.java:640)
        at transaction.cmt.ProductManagerEJB.insertProduct(ProductManagerEJB.java:70)

 

[DB에서 DBA권한으로 세션 확인]
SQL> select status, user#,program , username from v$session where username='SCOTT' ;
STATUS        USER# PROGRAM                                          USERNAME
-------- ---------- ------------------------------------------------ 
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT

-------- ---------- ------------------------------------------------ 
INACTIVE         26 JDBC Thin Client                                 SCOTT
ACTIVE           26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT

** 중략 **
-------- ---------- ------------------------------------------------ 
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT


4. stmt-qeury-timeout

설정 : JEUSMain.xml
     <resource><data-source><database><stmt-query-timeout>
  - millisecond value
  - Default Value : 600000

의미 : statement 객체를 통해서 query를 수행할 때 설정하는 옵션이며, 지정된 시간 동안 query가 끝나지 않으면 JDBC Driver에서SQLException을 던진다
Stmt-query-timeout과 동일한 효과를 낼 수 있는 것으로, Statement API에서 setQueryTimeout(int seconds)가 있다

[테스트] 

Client : Long Query 수행
JEUS : JEUSMain.xml
   <database>
        <stmt-query-timeout>10000 </stmt-query-timeout> 
      <tm-config>
                <active-timeout>600000</active-timeout>

[결과] 

[JEUS_Container_Log]
 [2015.07.21 16:31:47][4][0_520-3] [container1-22] [TM-5528] thread Socket[localhost:9900] is not associated with any transaction context
  java.sql.SQLException: ORA-01013: 현 조작에 대한 취소가 요구되었습니다
        at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:134) 
        at oracle.jdbc.ttc7.TTIoer.processError(TTIoer.java:289)
        at oracle.jdbc.ttc7.Oall7.receive(Oall7.java:582)
        at oracle.jdbc.ttc7.TTC7Protocol.doOall7(TTC7Protocol.java:1983)
        at oracle.jdbc.ttc7.TTC7Protocol.fetch(TTC7Protocol.java:1250)
        at oracle.jdbc.driver.OracleStatement.doExecuteQuery(OracleStatement.java:2529)
        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:2840)
        at oracle.jdbc.driver.OracleStatement.executeQuery(OracleStatement.java:640)
        at jeus_jspwork._500_longquery_5fjsp._jspService(_500_longquery_5fjsp.java:78)
  ** 중 략 **

 

[DBPooladmin coninfo]
--------------------------------------------------------
| id                   | state | usecount | state time(sec)
--------------------------------------------------------
SpringDS-3            idle    1          0.0
SpringDS-2            idle    1          0.0
SpringDS-1            active  1          0.0
SpringDS-4            idle    1          0.0

** 10초 경과 **
--------------------------------------------------------
| id                   | state | usecount | state time(sec)
--------------------------------------------------------
SpringDS-3            idle    1          10.0
SpringDS-2            idle    1          10.0
SpringDS-1            idle    2          0.0     SQLException발생과 함께 connection이 반환
SpringDS-4            idle    1          10.0


[DB에서 DBA권한으로 세션 확인]
SQL> select status, user#,program , username from v$session where username='SCOTT' ;
STATUS        USER# PROGRAM                                          USERNAME
-------- ---------- ------------------------------------------------ 
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT

-------- ---------- ------------------------------------------------ 
INACTIVE         26 JDBC Thin Client                                 SCOTT
ACTIVE           26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT

** 중략 **
-------- ---------- ------------------------------------------------ 
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT
INACTIVE         26 JDBC Thin Client                                 SCOTT  

 

5. active-timeout과 stmt-query-timeout의 관계

테스트 (1) active-timeout >> stmt-query-timeout
Client : Long Query 수행 하는 jsp와 CMT EJB
JEUS : JEUSMain.xml
   <database>
        <stmt-query-timeout> 10000 </stmt-query-timeout> 
      <tm-config>
                <active-timeout>600000</active-timeout>

결과 (1)Longquery.jsp : 정상처리 (stmt-query-timeout가 적용됨)

[JEUS_Container_Log]
java.sql.SQLException: ORA-01013: 현 조작의 취소가 요구되었습니다
        at oracle.jdbc.dbaccess.DBError.throwSqlException(DBError.java:134)
     ** 중 략 **
oracle.jdbc.driver.OracleStatement.doExecuteQuery(OracleStatement.java:2529)
        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:2840)
        at oracle.jdbc.driver.OracleStatement.executeQuery(OracleStatement.java:640)
        at jeus_jspwork._500_longquery_5fjsp._jspService(_500_longquery_5fjsp.java:78)
   ** 중 략 **
        at jeus.servlet.engine.WebtobRequestProcessor.run(WebtobRequestProcessor.java:181)
[2008.07.22 12:24:58][4][0_520-3] [container1-21] [JDBC-0016] The handle of the physical connection[JeusPooledConnection[ID=SpringDS-1,actual=oracle.jdbc.pool.OraclePooledConnection@19d5fe6]] is closed.

결과 (2) CMT EJB : 에러 (stmt-query-timeout이 적용됨)

[JEUS_Container_Log]
javax.ejb.EJBException: Error caught : ORA-01013: 현 조작의 취소가 요구되었습니다
        at transaction.cmt.ProductManagerEJB.transactionTest(ProductManagerEJB.java:38)
         ** 중 략 **
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:701)
        at java.lang.Thread.run(Thread.java:534)
[2008.07.22 12:32:56][4][0_520-3] [container1-24] [EJB-4256] exception is occurred on container transaction context
         ** 중 략 **
[2008.07.22 12:32:56][4][0_520-3] [container1-24] [TM-3628] disabled active state timeout timer for current coordinator associated with transaction (0:192.168.110.50:10941:119:0x48cbe1b6:0x0)
   => stmt-query-timeout이 먼저 적용되어 active-timeout이 적용될수 없음

 

테스트 (2) active-timeout << stmt-query-timeout
Client : Long Query 수행 하는 jsp와 CMT EJB
JEUS : JEUSMain.xml
   <database>
        <stmt-query-timeout> 600000 </stmt-query-timeout> 
      <tm-config>
                <active-timeout>10000</active-timeout>

결과 (1)Longquery.jsp : 정상 처리 (stmt-query-timeout 적용됨)

 [JEUS_Container_Log]
[2008.07.22 11:53:38][4][0_520-3] [container1-21] [WEB-7909] [_MyGroup/hello] notify a session creation event( id=4ZZxBZMea6sSVpvANNhq1QAflpo4QN7XGyAxnFrzFIOEokdRuZDEMvO5ppLd1mZ4 )
[2008.07.22 11:53:38][3][0_520-3] [container1-21] [JNDI.Context-0064] lookup SpringDS from localhost:9736 
[2008.07.22 11:53:38][4][0_520-3] [container1-21] [TM-5528] thread Socket[localhost:9900] is not associated with any transaction context
[2008.07.22 11:53:38][4][0_520-3] [container1-21] [TM-5528] thread Socket[localhost:9900] is not associated with any transaction context
[2008.07.22 11:53:47][4][0_520-3] [container1-20] [TM-5532] associate thread Thread[jeus.util.SimpleTimer [container1-20],5,main] with transaction null
[2008.07.22 11:54:12][4][0_520-3] [container1-21] [JDBC-0016] The handle of the physical connection[JeusPooledConnection[ID=SpringDS-4,actual=oracle.jdbc.pool.OraclePooledConnection@177c977]] is closed. => sql 처리 완료

결과 (2)CMT EJB : 에러 (active-timeout이 적용됨)

[JEUS_Container_Log]
[2008.07.22 11:49:36][4][0_520-3] [container1-26] [TM-3763] return global transaction id (0:192.168.110.50:10941:119:0x48a481cd:0x1) of current transaction
[2008.07.22 11:49:36][0][0_520-3] [container1-26] [TM-5106] current transaction (0:192.168.110.50:10941:119:0x48a481cd:0x1) is already timed out
[2008.07.22 11:49:36][1][0_520-3] [container1-26] [TM-5907] transaction is rolled-back
[2008.07.22 11:49:36][1][0_520-3] [container1-26] [EJB-4302] exception occurred while handling transaction context after invocation
jeus.ejb.container.ContainerException: exception occurred while handling transaction context after invocation
        at jeus.ejb.container.SessionContainer.postTxFilter(SessionContainer.java:732)
          ** 중략** 
Caused by: javax.transaction.RollbackException
        at jeus.transaction.TransactionImpl.commit(TransactionImpl.java:118)
        at jeus.ejb.container.SessionContainer.postTxFilter(SessionContainer.java:688)

테스트 (3) active-timeout , stmt-query-timeout 모두 여유있게 설정
Client : Long Query 수행 하는 jsp와 CMT EJB
JEUS : JEUSMain.xml
   <database>
        <stmt-query-timeout> 600000 </stmt-query-timeout> 
      <tm-config>
                <active-timeout>600000</active-timeout>

결과 (1)Longquery.jsp : 정상 처리 (sql 수행 완료와 함께 세션이 INACTIVATE)

[JEUS_Container_Log]
[2008.07.22 13:03:45][2][0_520-3] [container1-22] [JMX-0011] create MBean : JEUS:j2eeType=JDBCDataSource,JMXManager=youchj_container1,JeusManager=youchj,J2EEServer=youchj_container1,JDBCResource=youchj_container1,name=SpringDS
         ** 중 략 **
[2008.07.22 13:04:20][4][0_520-3] [container1-22] [JDBC-0016] The handle of the physical connection[JeusPooledConnection[ID=SpringDS-1,actual=oracle.jdbc.pool.OraclePooledConnection@eb607d]] is closed.
         ** 중 략 **
[2008.07.22 13:04:20][4][0_520-3] [container1-22] [WEB-3850] response to 192.168.110.2:-1. servlet = jeus.servlet.servlets.JspServlet, contentLength = 98

결과 (2)CMT EJB : 정상 (sql 수행 완료와 함께 세션이 INACTIVATE)

[JEUS_Container_Log]
[2008.07.22 13:34:07][4][0_520-3] [container1-24] [EJB-4215] caller transaction is not exist. start new transaction
[2008.07.22 13:34:07][4][0_520-3] [container1-24] [TM-3601] initiating root coordinator of (0:192.168.110.50:10941:119:0x48e4b740:0x0) with active state timeout value 600000 msec
[2008.07.22 13:34:07][4][0_520-3] [container1-24] [TM-3619] synchronization jeus.ejb.container.EJBSynchronization@f87478 is registered to current coordinator associated with transaction (0:192.168.110.50:10941:119:0x48e4b740:0x0)
[2008.07.22 13:34:42][4][0_520-3] [container1-24] [EJB-4287] exception is not occurred in container managed transaction context.
[2008.07.22 13:34:42][4][0_520-3] [container1-24] [EJB-4288] transaction attribute of executed procedure is Required
[2008.07.22 13:34:42][4][0_520-3] [container1-24] [TM-3628] disabled active state timeout timer for current coordinator associated with transaction (0:192.168.110.50:10941:119:0x48e4b740:0x0) => 트랜잭션이 무사 종료됨
[2008.07.22 13:34:42][4][0_520-3] [container1-24] [EJB-4294] commit success

결론
EJB를 사용하는 경우에 유의할 점은 active-timeout과 , stmt-query-timeout 이 모두 설정되어 있다면 둘 중에 작은 timeout값이 적용된다는 점이다

고맙습니다.

728x90
반응형