Skip to content
This repository was archived by the owner on Nov 10, 2025. It is now read-only.

MongoInterruptedException's msg and its stacktrace handling fix in BenchmarkCommand's worker threads#16

Open
v1k1nghawk wants to merge 1 commit into
mongodb-labs:masterfrom
v1k1nghawk:MongoInterruptedException_handling_fix
Open

MongoInterruptedException's msg and its stacktrace handling fix in BenchmarkCommand's worker threads#16
v1k1nghawk wants to merge 1 commit into
mongodb-labs:masterfrom
v1k1nghawk:MongoInterruptedException_handling_fix

Conversation

@v1k1nghawk

@v1k1nghawk v1k1nghawk commented Nov 30, 2022 •
edited
Loading

Copy link
Copy Markdown

Each successful benchmark's run currently ends with this output from each BenchmarkCommand's worker Runnable caused by their interruption:

...
at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:123)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:242)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:233)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:136)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:701)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:695)
        at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:457)
        at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:401)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:695)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:83)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:179)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:161)
        at com.mongodb.DBCursor.initializeCursor(DBCursor.java:896)
        at com.mongodb.DBCursor.hasNext(DBCursor.java:148)
        at com.mongodb.socialite.users.DefaultUserService.getUsersFromCursor(DefaultUserService.java:597)
        at com.mongodb.socialite.users.DefaultUserService.getFollowing(DefaultUserService.java:176)
        at com.mongodb.socialite.feed.FanoutOnRead.getFeedFor(FanoutOnRead.java:46)
        at com.mongodb.socialite.resources.UserResource.getTimeline(UserResource.java:153)
        at com.mongodb.socialite.benchmark.traffic.TrafficModel.next(TrafficModel.java:151)
        at com.mongodb.socialite.cli.BenchmarkCommand$1.run(BenchmarkCommand.java:217)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
        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: java.lang.InterruptedException
        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)
        ... 40 more
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 com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:140)
        at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:123)
        at com.mongodb.internal.connection.PowerOfTwoBufferPool.getBuffer(PowerOfTwoBufferPool.java:78)
        at com.mongodb.internal.connection.SocketStream.read(SocketStream.java:85)
        at com.mongodb.internal.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:562)
        at com.mongodb.internal.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:425)
        at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:289)
        at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:255)
        at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:99)
        at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:444)
        at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:72)
        at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:200)
        at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:269)
        at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:131)
        at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:123)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:242)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:233)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:136)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:701)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:695)
        at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:457)
        at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:401)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:695)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:83)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:179)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:161)
        at com.mongodb.DBCursor.initializeCursor(DBCursor.java:896)
        at com.mongodb.DBCursor.hasNext(DBCursor.java:148)
        at com.mongodb.socialite.users.DefaultUserService.getUsersFromCursor(DefaultUserService.java:597)
        at com.mongodb.socialite.users.DefaultUserService.getFollowing(DefaultUserService.java:176)
        at com.mongodb.socialite.feed.FanoutOnRead.getFeedFor(FanoutOnRead.java:46)
        at com.mongodb.socialite.resources.UserResource.getTimeline(UserResource.java:153)
        at com.mongodb.socialite.benchmark.traffic.TrafficModel.next(TrafficModel.java:151)
        at com.mongodb.socialite.cli.BenchmarkCommand$1.run(BenchmarkCommand.java:217)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
        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: java.lang.InterruptedException
        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)
        ... 40 more
com.mongodb.MongoInterruptedException: Interrupted acquiring a permit to retrieve an item from the pool
INFO  [2022-11-25 16:57:48,570] org.mongodb.driver.connection: Closed connection [connectionId{localValue:33}] to 172.31.29.190:27017 because there was a socket exception raised by this connection.
        at com.mongodb.internal.connection.ConcurrentPool.acquirePermit(ConcurrentPool.java:203)
        at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:140)
        at com.mongodb.internal.connection.ConcurrentPool.get(ConcurrentPool.java:123)
        at com.mongodb.internal.connection.PowerOfTwoBufferPool.getBuffer(PowerOfTwoBufferPool.java:78)
        at com.mongodb.internal.connection.SocketStream.read(SocketStream.java:85)
        at com.mongodb.internal.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:562)
        at com.mongodb.internal.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:425)
        at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:289)
        at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:255)
        at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:99)
        at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:444)
        at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:72)
        at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:200)
        at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:269)
        at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:131)
        at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:123)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:242)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:233)
        at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:136)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:701)
        at com.mongodb.operation.FindOperation$1.call(FindOperation.java:695)
        at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:457)
        at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:401)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:695)
        at com.mongodb.operation.FindOperation.execute(FindOperation.java:83)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:179)
        at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:161)
        at com.mongodb.DBCursor.initializeCursor(DBCursor.java:896)
        at com.mongodb.DBCursor.hasNext(DBCursor.java:148)
        at com.mongodb.socialite.content.DefaultContentService.getFromCursor(DefaultContentService.java:126)
        at com.mongodb.socialite.content.DefaultContentService.getContentFor(DefaultContentService.java:93)
        at com.mongodb.socialite.feed.FanoutOnRead.getFeedFor(FanoutOnRead.java:47)
        at com.mongodb.socialite.resources.UserResource.getTimeline(UserResource.java:153)
        at com.mongodb.socialite.benchmark.traffic.TrafficModel.next(TrafficModel.java:155)
        at com.mongodb.socialite.cli.BenchmarkCommand$1.run(BenchmarkCommand.java:217)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
        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: java.lang.InterruptedException
        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)
        ... 40 more
...
INFO  [2022-11-25 16:57:50,172] com.mongodb.socialite.ServiceManager: Stopping configured services
INFO  [2022-11-25 16:57:50,182] com.mongodb.socialite.ServiceManager: All services shut down successfully

As far as this interruption is part of the designed stopping mechanics, my proposal is to suppress the output of MongoInterruptedException and especially its stacktrace in BenchmarkCommand's worker threads.
After this fix, the successful output looks like this:

...
scroll_timeline
             count = 2415
         mean rate = 40.25 calls/second
     1-minute rate = 41.36 calls/second
     5-minute rate = 43.14 calls/second
    15-minute rate = 43.57 calls/second
               min = 0.78 milliseconds
               max = 37.49 milliseconds
              mean = 1.59 milliseconds
            stddev = 1.59 milliseconds
            median = 1.26 milliseconds
              75% <= 1.62 milliseconds
              95% <= 2.76 milliseconds
              98% <= 3.54 milliseconds
              99% <= 9.03 milliseconds
            99.9% <= 36.81 milliseconds
send_content
             count = 258
         mean rate = 4.30 calls/second
     1-minute rate = 4.19 calls/second
     5-minute rate = 4.05 calls/second
    15-minute rate = 4.02 calls/second
               min = 1.53 milliseconds
               max = 85.90 milliseconds
              mean = 3.52 milliseconds
            stddev = 6.14 milliseconds
            median = 2.68 milliseconds
              75% <= 3.20 milliseconds
              95% <= 4.99 milliseconds
              98% <= 6.49 milliseconds
              99% <= 36.67 milliseconds
            99.9% <= 85.90 milliseconds
unfollow
             count = 47
         mean rate = 0.78 calls/second
     1-minute rate = 0.66 calls/second
     5-minute rate = 0.47 calls/second
    15-minute rate = 0.42 calls/second
               min = 1.17 milliseconds
               max = 4.21 milliseconds
              mean = 2.11 milliseconds
            stddev = 0.54 milliseconds
            median = 1.97 milliseconds
              75% <= 2.26 milliseconds
              95% <= 3.57 milliseconds
              98% <= 4.21 milliseconds
              99% <= 4.21 milliseconds
            99.9% <= 4.21 milliseconds


INFO  [2022-11-29 14:53:13,219] com.mongodb.socialite.cli.BenchmarkCommand: Test done. Shutting down...
INFO  [2022-11-29 14:53:13,223] com.mongodb.socialite.ServiceManager: Stopping configured services
INFO  [2022-11-29 14:53:13,228] com.mongodb.socialite.ServiceManager: All services shut down successfully

@v1k1nghawk
disabled output with MongoInterruptedException's msg and its stacktra…
73338ed 
…ce during worker thread's stop in BenchmarkCommand
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Reviewers

No reviews

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

1 participant

@v1k1nghawk