본문 바로가기
개발/Spring

[MongoDB] MongoInterruptedException 해결하기

by 방구쟁이 2024. 6. 2.
728x90

기존 배치 방식을 API에서 파일로 데이터를 받아 처리하도록 변경하면서 개발할 당시 다음과 같은 에러를 직면했다.

Interrupted acquiring a permit to retrieve an item from the pool ; nested exception is com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool

Error Log 전문 보기 (아래)

더보기

[pool-8-thread-2] [ERROR] [BatchDao:157] : Interrupted acquiring a permit to retrieve an item from the pool ; nested exception is com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool  
org.springframework.data.mongodb.UncategorizedMongoDbException: Interrupted acquiring a permit to retrieve an item from the pool ; nested exception is com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool 
at org.springframework.data.mongodb.core.MongoExceptionTranslator.translateExceptionIfPossible(MongoExceptionTranslator.java:133)
at org.springframework.data.mongodb.core.MongoTemplate.potentiallyConvertRuntimeException(MongoTemplate.java:2882)
at org.springframework.data.mongodb.core.MongoTemplate.execute(MongoTemplate.java:564)
at org.springframework.data.mongodb.core.DefaultBulkOperations.execute(DefaultBulkOperations.java:290)
at cohttp://m.mobwith.mobtune.dao.BatchDao.upsertMobTuneCampaignAuidList(BatchDao.java:154)
at cohttp://m.mobwith.mobtune.dao.BatchDao$FastClassBySpringCGLIB$c1d8269f.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:771)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
at cohttp://m.mobwith.mobtune.dao.BatchDao$EnhancerBySpringCGLIB$26e5b42b.upsertMobTuneCampaignAuidList(<generated>)
at cohttp://m.mobwith.mobtune.task.CampaignAuidTask.run(CampaignAuidTask.java:41)
at scouter.agent.wrapper.async.WrTask.run(WrTask.java:35)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool 
at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:203)
at cohttp://m.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:140)
at cohttp://m.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:123)
at cohttp://m.mongodb.internal.session.ServerSessionPool.get(ServerSessionPool.java:80)
at com.mongodb.internal.session.BaseClientSessionImpl.<init>(BaseClientSessionImpl.java:44)
at cohttp://m.mongodb.client.internal.ClientSessionImpl.<init>(ClientSessionImpl.java:56)
at cohttp://m.mongodb.client.internal.MongoClientDelegate.createClientSession(MongoClientDelegate.java:110)
at cohttp://m.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.getClientSession(MongoClientDelegate.java:266)
at cohttp://m.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:190)
at cohttp://m.mongodb.client.internal.MongoCollectionImpl.executeBulkWrite(MongoCollectionImpl.java:442)
at cohttp://m.mongodb.client.internal.MongoCollectionImpl.bulkWrite(MongoCollectionImpl.java:422)
at org.springframework.data.mongodb.core.DefaultBulkOperations.bulkWriteTo(DefaultBulkOperations.java:311)
at org.springframework.data.mongodb.core.MongoTemplate.execute(MongoTemplate.java:562)
... 17 common frames omitted
Caused by: java.lang.InterruptedException: null
at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1343)
at java.base/java.util.concurrent.Semaphore.acquire(Semaphore.java:318)
at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:199)
... 29 common frames omitted
[pool-8-thread-1] [INFO] [connection:71] : Closed connection [connectionId{localValue:71, serverValue:128943}] to IP:PORT because there was a socket exception raised by this connection. 
[pool-8-thread-1] [ERROR] [BatchDao:157] : Interrupted acquiring a permit to retrieve an item from the pool ; nested exception is com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool  
org.springframework.data.mongodb.UncategorizedMongoDbException: Interrupted acquiring a permit to retrieve an item from the pool ; nested exception is com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool 
at org.springframework.data.mongodb.core.MongoExceptionTranslator.translateExceptionIfPossible(MongoExceptionTranslator.java:133)
at org.springframework.data.mongodb.core.MongoTemplate.potentiallyConvertRuntimeException(MongoTemplate.java:2882)
at org.springframework.data.mongodb.core.MongoTemplate.execute(MongoTemplate.java:564)
at org.springframework.data.mongodb.core.DefaultBulkOperations.execute(DefaultBulkOperations.java:290)
at cohttp://m.mobwith.mobtune.dao.BatchDao.upsertMobTuneCampaignAuidList(BatchDao.java:154)
at cohttp://m.mobwith.mobtune.dao.BatchDao$FastClassBySpringCGLIB$c1d8269f.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:771)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
at cohttp://m.mobwith.mobtune.dao.BatchDao$EnhancerBySpringCGLIB$26e5b42b.upsertMobTuneCampaignAuidList(<generated>)
at cohttp://m.mobwith.mobtune.task.CampaignAuidTask.run(CampaignAuidTask.java:41)
at scouter.agent.wrapper.async.WrTask.run(WrTask.java:35)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool 
at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:203)
at cohttp://m.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:140)
at cohttp://m.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:123)
at com.mongodb.internal.connection.PowerOfTwoBufferPool.getByteBuffer(PowerOfTwoBufferPool.java:82)
at com.mongodb.internal.connection.PowerOfTwoBufferPool.getBuffer(PowerOfTwoBufferPool.java:77)
at cohttp://m.mongodb.internal.connection.SocketStream.read(SocketStream.java:105)
at cohttp://m.mongodb.internal.connection.SocketStream.read(SocketStream.java:131)
at com.mongodb.internal.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:656)
at com.mongodb.internal.connection.InternalStreamConnection.receiveMessageWithAdditionalTimeout(InternalStreamConnection.java:513)
at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:356)
at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:280)
at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:100)
at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:490)
at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:71)
at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:255)
at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:202)
at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:118)
at com.mongodb.internal.operation.MixedBulkWriteOperation.executeCommand(MixedBulkWriteOperation.java:431)
at com.mongodb.internal.operation.MixedBulkWriteOperation.executeBulkWriteBatch(MixedBulkWriteOperation.java:251)
at cohttp://m.mongodb.internal.operation.MixedBulkWriteOperation.access$700(MixedBulkWriteOperation.java:76)
at com.mongodb.internal.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:194)
at com.mongodb.internal.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:185)
at com.mongodb.internal.operation.OperationHelper.withReleasableConnection(OperationHelper.java:620)
at com.mongodb.internal.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:185)
at com.mongodb.internal.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:76)
at cohttp://m.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:195)
at cohttp://m.mongodb.client.internal.MongoCollectionImpl.executeBulkWrite(MongoCollectionImpl.java:442)
at cohttp://m.mongodb.client.internal.MongoCollectionImpl.bulkWrite(MongoCollectionImpl.java:422)
at org.springframework.data.mongodb.core.DefaultBulkOperations.bulkWriteTo(DefaultBulkOperations.java:311)
at org.springframework.data.mongodb.core.MongoTemplate.execute(MongoTemplate.java:562)
... 17 common frames omitted
Caused by: java.lang.InterruptedException: null
at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1343)
at java.base/java.util.concurrent.Semaphore.acquire(Semaphore.java:318)
at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:199)
... 46 common frames omitted

 

왜 Pool에서 커넥션 객체 획득이 중단되었을까?

먼저 배치 정보를 대략적으로 확인해보자.

  • 적재하기 위한 배치 파일 크기 : 약 4,000,000라인(400만건)
  • 파일을 읽어 BulkOperations(Mongo)로 보내는 단위 : 1,000라인
  • 보내는 과정의 ThreadSleep : 100ms

 정리하자면, 대략 100ms당 1000건씩 MongoDB에 bulk upsert query로 4000번을 수행해야 한다. 이 과정을 수행하는 중 더 이상 커넥션 객체를 획득하지 못해 에러가 발생되었다.

 그럼 왜 객체를 획득하지 못했을까? MongoDB의 설정값을 확인했을때 해당 프로젝트에 따로 MongoClientSettings을 설정하지 않아 Connection 관련 값은 다음과 같았다.

  • maxSize : 100 (default) > 최대 연결 수
  • minSize : 0  (default) > 최소 연결 수
  • maxWaitTime : 120sec (default 2분) >  연결을 얻기 위한 최대 대기 시간

 

 배치 정보와 MongoDB 설정으로 분석한 결과를 그려보았다.

MongoInterruptedException 발생 과정

 1000건을 읽어 Mongodb collection에 bulk upsert query가 수행되는 시간이 100ms(ThreadSleep)보다 길어지는 경우(4000번 처리 과정 중) MongoDB의 connectionPoll이 점점 쌓이게 된다.
 쌓인 connection이 100개(maxSize)가 넘어가게 되면 다음 connection을 기다리게 되는데 waitTime이 지날 경우 해당 Queue는 MongoDB connection을 획득하지 못하고 MongoInterruptedException이 발생하게 된다. (Interrupted acquiring a permit to retrieve an item from the pool 발생)

 다음을 해결하기 위한 방안을 적어보았다.

  • max connectionPoll 갯수를 늘려준다.
  • waitTime을 늘려준다. (커넥션 대기를 길게 가져가는 것은 좋지 못한 방법으로 판단됨)
  • time sleep을 늘려 connectionPoll에 쌓이지 않게 한다.

 

Max Connection & waitTime 설정 방법

- 변경 전 (default 값 사용)

@Primary
@Bean
public MongoDatabaseFactory mongoDbFactory(final MongoProperties mongo) throws Exception {
    MongoClusterListener clusterListener = new MongoClusterListener();
    MongoServerMonitorListener serverMonitorListener = new MongoServerMonitorListener();
    MongoServerListener serverListener = new MongoServerListener();

    MongoCredential credential = MongoCredential
        .createCredential(mongo.getUsername(), 
            mongo.getAuthenticationDatabase(), 
            mongo.getPassword());
    MongoClient mongoClient = MongoClients.create(MongoClientSettings.builder()
        .applyToClusterSettings(builder -> 
            builder.hosts(Collections.singletonList(new ServerAddress(mongo.getHost(), mongo.getPort())))
                .mode(ClusterConnectionMode.MULTIPLE)
                .requiredReplicaSetName(mongo.getReplicaSetName())
                .requiredClusterType(ClusterType.REPLICA_SET)
                .addClusterListener(clusterListener)
            )
        .applyToServerSettings(builder ->
            builder.addServerMonitorListener(serverMonitorListener)
                .addServerListener(serverListener)
            )
        .readPreference(ReadPreference.primary())
        .credential(credential)
        .build());
    return new SimpleMongoClientDatabaseFactory(mongoClient, mongo.getDatabase());
}

- 변경 후

@Primary
@Bean
public MongoDatabaseFactory mongoDbFactory(final MongoProperties mongo) throws Exception {
    MongoClusterListener clusterListener = new MongoClusterListener();
    MongoServerMonitorListener serverMonitorListener = new MongoServerMonitorListener();
    MongoServerListener serverListener = new MongoServerListener();

    MongoCredential credential = MongoCredential
        .createCredential(mongo.getUsername(), 
            mongo.getAuthenticationDatabase(), 
            mongo.getPassword());
    MongoClient mongoClient = MongoClients.create(MongoClientSettings.builder()
        .applyToClusterSettings(builder -> 
            builder.hosts(Collections.singletonList(new ServerAddress(mongo.getHost(), mongo.getPort())))
                .mode(ClusterConnectionMode.MULTIPLE)
                .requiredReplicaSetName(mongo.getReplicaSetName())
                .requiredClusterType(ClusterType.REPLICA_SET)
                .addClusterListener(clusterListener)
            )
        .applyToConnectionPoolSettings(builder -> builder
                .maxSize(200) // 최대 연결 수를 200으로 증가
                .minSize(10)  // 최소 연결 수를 10으로 설정
                .maxWaitTime(60, TimeUnit.SECONDS) // 최대 대기 시간을 60초로 설정
            ) 
        .applyToServerSettings(builder ->
            builder.addServerMonitorListener(serverMonitorListener)
                .addServerListener(serverListener)
            )
        .readPreference(ReadPreference.primary())
        .credential(credential)
        .build());
    return new SimpleMongoClientDatabaseFactory(mongoClient, mongo.getDatabase());
}

 

 저는 3가지 방안 중 ConnectionPoll에 Max만큼 쌓이지 않는 것이 가장 이상적이라고 판단하여 time sleep을 400ms로 변경하도록 선택하였다. 또한, time sleep 값은 configServer를 통해 properties로 관리하고 있어 서버 재배포 없이 변경이 용이하였다.
 실제로 위 포스팅 주제인 MongoInterruptedException이 발생하는 배치는 upsert query로 key를 찾아 추가하는 배치였는데 key 값이 1억7천개 이상이었기 때문에 bulk query임에도 불구하고 100ms(0.1초) 이내에 끝나지 않아 변경하여 해당 이슈를 해결할 수 있었다.


 감사합니다!

 

728x90
저작자표시 비영리 변경금지

'개발 > Spring' 카테고리의 다른 글

[WebClientRequestException] Pending acquire queue has reached its maximum size of 40 해결한 경험  (1) 2024.09.16
RecoverableDataAccessException 해결한 경험  (1) 2024.04.28
[Spring Security] SecurityContextHolder와 Authentication 알아보기  (0) 2023.04.19
Spring boot에 Swagger 적용하기  (0) 2023.03.31
Spring security + JWT 구현 방식  (0) 2023.03.29

관련글

댓글

티스토리툴바