socialite
socialite copied to clipboard
Published
20 hours ago •
mongodb-labs
mongodb-labs
MongoInterruptedException's msg and its stacktrace handling fix in BenchmarkCommand's worker threads
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
