[웹로직] MDB가 JMS 대기열에서 동시에 메시지를 처리하지 않는 현상

이번 글에서는 S 사이트의 이슈 사례를 적어보려고 한다.

​

- WLS 12.2.1.3.0

- PSU_18년도 패치 셋 적용

- IBM AIX 7.2

- JDK 1.8

- EJB 3.0

​

1. 현상

: 현재 S사 에서 발생하고 있는 인터페이스 지연 현상의 경우 A 라는 인터페이스가 장시간 처리 지연이 되면서 B라는 인터페이스가 처리되지 않고 Queue에서 대기중인 현상

 

 

2. 해당 현상과 비슷한 사례(오라클 공식 문서)

: MDB (Message Driven Bean)가 JMS 대기열에서 동시에 메시지를 처리하지 않음 (문서 ID 2634884.1)

적용 대상 : Oracle WebLogic Server-버전 10.3.6 이상 이 문서의 정보는 모든 플랫폼에 적용됩니다. ​ 조짐 max-beans-in-free-pool 요소가 2로 설정된 MDB (Message Driven Bean)는 JMS 대기열에서 동시에 메시지를 처리 ​​할 수 ​​없습니다. 사용 사례 1. JMS 대기열 만들기 2. max-beans-in-free-pool을 2로 사용하여 JMS 대기열에서 메시지를 사용하는 MDB를 배포합니다. 3. 큐 M1 (대형 메시지)에 2 개의 메시지를 넣은 다음 M2 (소형 메시지)를 입력합니다. 4. M1이 완료 될 때까지 M2가 처리되지 않는 것이 관찰되었습니다. ​ 변화 대기열에서 메시지를 사용하는 max-beans-in-free-pool 값이 2 인 MDB (Message Driven Bean)를 배포합니다. ​ 원인 이 "세션 당 최대 메시지 수"를 MDB가 사용하는 연결 팩토리에서 1로 설정해야합니다. MDB는 기본 연결 팩토리를 사용하고있었습니다. 해결책 MDB에서 사용할 새 연결 팩토리를 만들고 "세션 당 최대 메시지 수"를 1로 설정하거나 MDB가 메시지를 소비하는 큐를 사용하는 연결 팩토리를 활용합니다. "세션 당 최대 메시지"는 다음과 같이 수정할 수 있습니다. 1. 관리 콘솔에 로그인 2. JMS 모듈 ==> ==> ==> 클라이언트로 이동합니다. 3. "세션 당 최대 메시지 수"를 1로 업데이트합니다. 4. 변경 사항 저장 및 활성화 weblogic-ejb-jar.xml에 다음을 추가하십시오. 연결 팩토리의 jndi 아래에서 문서 참조를 찾으십시오. 1. 연결 팩토리 클라이언트 매개 변수 구성 연결 팩토리 구성 >> 구성> 클라이언트 세션 당 메시지 최대 수에서 비동기 세션에 대해 존재할 수 있고 아직 메시지 리스너로 전달되지 않은 메시지의 최대 수를 지정합니다. 동기식 소비자에 대한 프리 페치 모드 필드가 활성화 된 경우이 값은 한 서버 액세스에서 메시지를 프리 페치하는 메시지 소비자가있는 동기 세션에도 영향을줍니다. 2. 'connection-factory-jndi-name'및 'max-beans-in-free-pool'에 대한 정보는 weblogic-ejb-jar.xml 배포 설명자 참조

> 오라클 공식 문서를 보면 현재 S사에서 발생하고 있는 현상과 동일한 문서가 있습니다. 사이즈가 큰 메시지를 처리할 때 오래 걸리는 경우 다른 메시지가 처리 되지 않고 기다린다는 내용이고,

해당 이슈에서 솔루션은 MessageMaximum 이라는 JMS Connection Factory 값을 1로 수정하라는 가이드 입니다.

 

> MessageMaximum : 비동기 세션에 존재할 수 있는 그러나 메시지 리스너에 전달되지 않은 최대 메시지 수

해당 옵션의 default value는 10이며, 비동기 세션에 총 10개의 메시지가 존재한다는 의미입니다. 그 중 하나의 메시지가 오래 걸릴 경우, 비동기 세션 안에 존재하는 다른 메시지가 메시지 리스너에 전달되지 않고 그 전 메시지가 처리될 때까지 기다릴 수 있습니다.

https://docs.oracle.com/middleware/12213/wls/WLACH/taskhelp/jms_modules/connection_factories/ConfigureClientParams.html

specify the maximum number of messages that can exist for an asynchronous session and that have not yet been passed to the message listener. When the Prefetch Mode for Synchronous Consumers field is enabled, this value also affects synchronous sessions with a message consumer that will prefetch messages in one server access.

​

​

3. 내부 테스트 내용(MDB 예제)

: 아래 내용은 해당 현상 재현 및 옵션 적용 테스트를 위해 자체적으로 테스트한 결과 입니다.

​

- 테스트 시나리오

JMS Sender와 Consumer가 있고,

Sender에서 JMS Queue에 10개의 메시지를 넣는 과정에서 7번째 메시지의 경우에는 Sleep()함수를 넣어주어 3분 정도 지연이 발생하게 하였습니다.

그런 다음 JMS Queue 상태를 확인하였습니다.

 

- 예상 동작 : 오래 걸리는 “7번째 메시지” 스레드의 경우에만 큐에 남아있고 나머지 0, 1, 2, 3, 4, 5, 6, 8, 9 메시지는 바로 처리되어야 함.

- 추가 조건 : JTA > sleep함수보다 크게 주었습니다.(sleep 시간이 JTA 시간 보다 클 경우, 재처리 동작하여 receive transaction 상태의 7번째 메시지는 계속 처리되지 않음

 

 

# 3) 테스트 내용

# 3-1) MDB 프로세스 4번 호출

Wed Feb 17 20:50:05 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 0 Wed Feb 17 20:50:05 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 1 Wed Feb 17 20:50:05 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 2 Wed Feb 17 20:50:05 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 3 Wed Feb 17 20:50:05 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 4 Wed Feb 17 20:50:05 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 5 Wed Feb 17 20:50:05 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 6 Wed Feb 17 20:50:05 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 8 Wed Feb 17 20:50:05 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 9 Wed Feb 17 20:50:12 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 0 Wed Feb 17 20:50:12 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 1 Wed Feb 17 20:50:12 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 2 Wed Feb 17 20:50:12 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 3 Wed Feb 17 20:50:12 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 4 Wed Feb 17 20:50:12 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 5 Wed Feb 17 20:50:12 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 6 Wed Feb 17 20:50:12 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 8 Wed Feb 17 20:50:12 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 9 Wed Feb 17 20:50:19 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 0 Wed Feb 17 20:50:19 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 1 Wed Feb 17 20:50:19 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 2 Wed Feb 17 20:50:19 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 4 Wed Feb 17 20:50:19 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 5 Wed Feb 17 20:50:19 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 6 Wed Feb 17 20:50:19 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 8 Wed Feb 17 20:50:19 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 9 Wed Feb 17 20:50:29 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 0 Wed Feb 17 20:50:29 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 1 Wed Feb 17 20:50:29 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 2 Wed Feb 17 20:50:29 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 4 Wed Feb 17 20:50:29 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 5 Wed Feb 17 20:50:29 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 6 Wed Feb 17 20:50:29 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 8

> MDB에서 onMessage()를 통해 처리된 내용을 노헙 로그로 확인

> 10개씩 총 4세트 실행 결과 counter 7번은 sleep() 조건으로 인해 처리되지 않음.

> 빨간 부분을 잘 보면, 7번 뿐만 아니라 counter 3, 9번도 실행되지 않음.

​

​

# 3-2) JMS Queue 모니터링

Ø 자세히 보시면 현재 receive transaction 상태의 메시지들은 전부 메시지 7번입니다.

Ø 나머지 receive 상태의 메시지는 3, 9번이고 해당 메시지들은 receive 상태도 남아있습니다. (처리되지 않음)

​

> 이상하게 다른 메시지들은 처리되었는데 몇몇 메시지는 receive 상태도 처리되지 않음(S사와 현상과 동일해 보임)

​

​

​

# 3-3) 3분 뒤 sleep 풀리고 로그

Wed Feb 17 20:50:05 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 7 Wed Feb 17 20:53:05 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 3 Wed Feb 17 20:53:05 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 9 Wed Feb 17 20:50:12 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 7 Wed Feb 17 20:53:12 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 3 Wed Feb 17 20:50:19 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 7 Wed Feb 17 20:50:29 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 7

> Receive 상태였던 3, 9 counter 메시지가 3분 뒤 7번 메시지가 처리됨과 동시에 처리됨을 확인할 수 있음.

​

​

​

# 3-4) JMS Queue 모니터링에서도 빠짐

​

# 3-5) MessageMaximum Per Session 값 수정 (10 >> 1)

​

# 3-6) 다시 MDB 호출

Mon Feb 22 00:26:59 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 0 Mon Feb 22 00:26:59 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 1 Mon Feb 22 00:26:59 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 2 Mon Feb 22 00:26:59 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 3 Mon Feb 22 00:26:59 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 4 Mon Feb 22 00:26:59 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 5 Mon Feb 22 00:26:59 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 6 Mon Feb 22 00:26:59 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 8 Mon Feb 22 00:26:59 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 9 Mon Feb 22 00:27:07 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 0 Mon Feb 22 00:27:08 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 1 Mon Feb 22 00:27:08 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 2 Mon Feb 22 00:27:08 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 3 Mon Feb 22 00:27:08 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 4 Mon Feb 22 00:27:08 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 5 Mon Feb 22 00:27:08 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 6 Mon Feb 22 00:27:08 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 8 Mon Feb 22 00:27:08 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 9 Mon Feb 22 00:27:16 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 0 Mon Feb 22 00:27:16 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 1 Mon Feb 22 00:27:16 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 2 Mon Feb 22 00:27:16 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 3 Mon Feb 22 00:27:16 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 4 Mon Feb 22 00:27:16 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 5 Mon Feb 22 00:27:16 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 6 Mon Feb 22 00:27:16 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 8 Mon Feb 22 00:27:16 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 9 Mon Feb 22 00:27:23 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 0 Mon Feb 22 00:27:23 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 1 Mon Feb 22 00:27:23 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 2 Mon Feb 22 00:27:24 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 3 Mon Feb 22 00:27:24 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 4 Mon Feb 22 00:27:24 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 5 Mon Feb 22 00:27:24 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 6 Mon Feb 22 00:27:24 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 8 Mon Feb 22 00:27:24 KST 2021nnt(mdb) MyMDB Received nTest Message Body with counter = 9

> 오래 걸리는 7번 메시지를 제외하고는 전부 다 처리가 되고 있습니다. 나머지 메시지가 receive 상태로 남아 있지 않음

MessageMaximum 옵션 수정을 통해 현상이 사라짐.

위의 5개 receive transaction 메시지는 sleep 타임 이후에 전부 처리 됨.

​

​

4. SR 내용

앞서 전달드린 note 이외에 MDB 사용시 async consumer인 message pipeline 을 1로 설정하라는 내용이 다음 document에 있습니다. ​ - https://docs.oracle.com/middleware/12213/wls/JMSPG/manage_apps.htm#JMSPG258 ​ Required Message Pipeline Setting for the Messaging Bridge and MDBs ​ For asynchronous consumers or JMS applications using the WebLogic Messaging Bridge or MDBs, the size of the message pipeline must be set to 1. The pipeline size is set using the Messages Maximum attribute on the JMS connection factory used by the receiving application. Any value higher than 1 means there may be additional in-flight messages that will appear ahead of a redelivered message. MDB applications must define an application-specific JMS connection factory and set the Messages Maximum attribute value to 1 on that connection factory, and then reference the connection factory in the EJB descriptor for their MDB application. ​ 튜닝문서에 보면 Messages Maximum를 크게 해주면 특정환경에서는 성능개선을 해주지만 처리지연이 발생하는 경우는 이미처리중(inflignt)인 메세지 지연으로 인해 처리되지 않을 수 있습니다. ​ https://docs.oracle.com/middleware/12213/wls/PERFM/jmstuning.htm#PERFM304 - 13 Tuning WebLogic JMS JMS Performance & Tuning Check List For asynchronous consumers and MDBs, tune MessagesMaximum on the connection factory. Increasing MessagesMaximum can improve performance, decreasing MessagesMaximum to its minimum value can lower performance, but helps ensure that messages do not end up waiting for a consumer that's already processing a message. See Tuning MessageMaximum. ​ Tuning MessageMaximum WebLogic JMS pipelines messages that are delivered to asynchronous consumers (otherwise known as message listeners) or prefetch-enabled synchronous consumers. This action aids performance because messages are aggregated when they are internally pushed from the server to the client. The messages backlog (the size of the pipeline) between the JMS server and the client is tunable by configuring the MessagesMaximum setting on the connection factory. See Asynchronous Message Pipeline in Developing JMS Applications for Oracle WebLogic Server. ​ In some circumstances, tuning the MessagesMaximum parameter may improve performance dramatically, such as when the JMS application defers acknowledges or commits. In this case, Oracle suggests setting the MessagesMaximum value to: ​ application 성격에 따라 튜닝이 필요한 부분으로 side effect라고 할 부분은 없습니다. 현재 매월 초에만 발생하는 오래 걸리는 application에 의한 지연으로 인해 발생하는 현상으로 application을 수정이 필요하며 위 문서에 언급된대로 MessagesMaximum 을 1로 지정하시면 되곘습니다. ​ MDB free pool은 max 값은 default 값이 충분하기 때문에 init pool 갯수정도만 좀 늘리는것을 고려해볼 수 있겠으나 현재까지 성능에 큰이슈가 없으셨다면 크게 문제가 되지 않을것으로 판단됩니다.

​