[OAK-1890] Concurrent System Login: slowdown for high concurrency levels

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 1.0.2, 1.1.0
• Component/s: jcr
• Assignee: Michael Dürig
• Reporter: Angela Schreiber
• Created: 13/Jun/14 17:15
• Updated: 01/Oct/14 17:11
• Resolved: 09/Jul/14 14:01

Description

output of running the system login/logout test with profiling enabled:

$ java -Dprofile=true -Xmx2048M org.apache.jackrabbit.oak.run.Main benchmark LoginSystemTest Oak-Tar --concurrency 1,2,4,8,10,15,20,50

Apache Jackrabbit Oak 1.1-SNAPSHOT

1. LoginSystemTest C min 10% 50% 90% max N
   Oak-Tar 1 12 13 19 24 42 266
   Oak-Tar 2 12 15 20 24 32 496
   Oak-Tar 4 20 23 30 37 60 660
   Oak-Tar 8 41 67 75 85 95 532
   Oak-Tar 10 77 90 96 113 5166 122
   Oak-Tar 15 109 127 5559 5673 5701 27
   Oak-Tar 20 5868 5874 5928 5943 5944 20
   Oak-Tar 50 22116 22133 22151 22157 22162 50
   Profiler: top 5 stack trace(s) of 70414 ms:
   1865/21120 (8%):
   at org.apache.jackrabbit.stats.RepositoryStatisticsImpl.getOrCreateRecorder(RepositoryStatisticsImpl.java:99)
   at org.apache.jackrabbit.stats.RepositoryStatisticsImpl.getCounter(RepositoryStatisticsImpl.java:80)
   at org.apache.jackrabbit.oak.stats.StatisticManager.getCounter(StatisticManager.java:81)
   at org.apache.jackrabbit.oak.jcr.session.SessionContext.getCounter(SessionContext.java:182)
   at org.apache.jackrabbit.oak.jcr.session.SessionImpl.<init>(SessionImpl.java:89)
   at org.apache.jackrabbit.oak.jcr.session.SessionContext.createSession(SessionContext.java:161)
   at org.apache.jackrabbit.oak.jcr.session.SessionContext.getSession(SessionContext.java:141)
   at org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl.login(RepositoryImpl.java:260)
   at org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl.login(RepositoryImpl.java:195)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest$1.run(LoginSystemTest.java:54)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest$1.run(LoginSystemTest.java:51)
   at java.security.AccessController.doPrivileged(Native Method)
   at javax.security.auth.Subject.doAsPrivileged(Subject.java:515)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest.runTest(LoginSystemTest.java:51)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.execute(AbstractTest.java:279)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest.execute(LoginSystemTest.java:33)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.execute(AbstractTest.java:288)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.access$000(AbstractTest.java:42)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest$Executor.run(AbstractTest.java:215)
   1704/21120 (8%):
   at java.lang.Throwable.fillInStackTrace(Native Method)
   at java.lang.Throwable.<init>(Throwable.java:196)
   at java.lang.Exception.<init>(Exception.java:41)
   at org.apache.jackrabbit.oak.jcr.session.SessionStats.<init>(SessionStats.java:40)
   at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.<init>(SessionDelegate.java:154)
   at org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl$1.<init>(RepositoryImpl.java:271)
   at org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl.createSessionDelegate(RepositoryImpl.java:269)
   at org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl.login(RepositoryImpl.java:255)
   at org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl.login(RepositoryImpl.java:195)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest$1.run(LoginSystemTest.java:54)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest$1.run(LoginSystemTest.java:51)
   at java.security.AccessController.doPrivileged(Native Method)
   at javax.security.auth.Subject.doAsPrivileged(Subject.java:515)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest.runTest(LoginSystemTest.java:51)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.execute(AbstractTest.java:279)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest.execute(LoginSystemTest.java:33)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.execute(AbstractTest.java:288)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.access$000(AbstractTest.java:42)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest$Executor.run(AbstractTest.java:215)
   1167/21120 (5%):
   at java.lang.Throwable.fillInStackTrace(Native Method)
   at java.lang.Throwable.<init>(Throwable.java:181)
   at java.lang.Exception.<init>(Exception.java:29)
   at java.lang.RuntimeException.<init>(RuntimeException.java:32)
   at java.lang.IllegalStateException.<init>(IllegalStateException.java:27)
   at java.util.concurrent.CancellationException.<init>(CancellationException.java:24)
   at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:220)
   at java.util.concurrent.FutureTask.get(FutureTask.java:83)
   at com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:63)
   at com.google.common.util.concurrent.Uninterruptibles.getUninterruptibly(Uninterruptibles.java:135)
   at com.google.common.util.concurrent.Futures$4.run(Futures.java:1158)
   at com.google.common.util.concurrent.MoreExecutors$SameThreadExecutorService.execute(MoreExecutors.java:297)
   at com.google.common.util.concurrent.ExecutionList.executeListener(ExecutionList.java:156)
   at com.google.common.util.concurrent.ExecutionList.add(ExecutionList.java:101)
   at com.google.common.util.concurrent.ListenableFutureTask.addListener(ListenableFutureTask.java:83)
   at com.google.common.util.concurrent.ForwardingListenableFuture.addListener(ForwardingListenableFuture.java:47)
   at com.google.common.util.concurrent.Futures.addCallback(Futures.java:1172)
   at com.google.common.util.concurrent.Futures.addCallback(Futures.java:1108)
   at org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl$1.logout(RepositoryImpl.java:282)
   at org.apache.jackrabbit.oak.jcr.session.SessionImpl$10.perform(SessionImpl.java:464)
   at org.apache.jackrabbit.oak.jcr.session.SessionImpl$10.perform(SessionImpl.java:460)
   at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.perform(SessionDelegate.java:236)
   at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.safePerform(SessionDelegate.java:282)
   at org.apache.jackrabbit.oak.jcr.session.SessionImpl.safePerform(SessionImpl.java:132)
   at org.apache.jackrabbit.oak.jcr.session.SessionImpl.logout(SessionImpl.java:460)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest.runTest(LoginSystemTest.java:51)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.execute(AbstractTest.java:279)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest.execute(LoginSystemTest.java:33)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.execute(AbstractTest.java:288)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.access$000(AbstractTest.java:42)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest$Executor.run(AbstractTest.java:215)
   1161/21120 (5%):
   at org.apache.jackrabbit.stats.RepositoryStatisticsImpl.getOrCreateRecorder(RepositoryStatisticsImpl.java:99)
   at org.apache.jackrabbit.stats.RepositoryStatisticsImpl.getCounter(RepositoryStatisticsImpl.java:80)
   at org.apache.jackrabbit.oak.stats.StatisticManager.getCounter(StatisticManager.java:81)
   at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.<init>(SessionDelegate.java:158)
   at org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl$1.<init>(RepositoryImpl.java:271)
   at org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl.createSessionDelegate(RepositoryImpl.java:269)
   at org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl.login(RepositoryImpl.java:255)
   at org.apache.jackrabbit.oak.jcr.repository.RepositoryImpl.login(RepositoryImpl.java:195)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest$1.run(LoginSystemTest.java:54)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest$1.run(LoginSystemTest.java:51)
   at java.security.AccessController.doPrivileged(Native Method)
   at javax.security.auth.Subject.doAsPrivileged(Subject.java:515)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest.runTest(LoginSystemTest.java:51)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.execute(AbstractTest.java:279)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest.execute(LoginSystemTest.java:33)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.execute(AbstractTest.java:288)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.access$000(AbstractTest.java:42)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest$Executor.run(AbstractTest.java:215)
   1156/21120 (5%):
   at java.lang.Throwable.fillInStackTrace(Native Method)
   at java.lang.Throwable.<init>(Throwable.java:196)
   at java.lang.Exception.<init>(Exception.java:41)
   at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate$WarningLock.lock(SessionDelegate.java:695)
   at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate$WarningLock.lock(SessionDelegate.java:700)
   at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.perform(SessionDelegate.java:213)
   at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.safePerform(SessionDelegate.java:282)
   at org.apache.jackrabbit.oak.jcr.session.SessionImpl.safePerform(SessionImpl.java:132)
   at org.apache.jackrabbit.oak.jcr.session.SessionImpl.logout(SessionImpl.java:460)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest.runTest(LoginSystemTest.java:51)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.execute(AbstractTest.java:279)
   at org.apache.jackrabbit.oak.benchmark.LoginSystemTest.execute(LoginSystemTest.java:33)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.execute(AbstractTest.java:288)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest.access$000(AbstractTest.java:42)
   at org.apache.jackrabbit.oak.benchmark.AbstractTest$Executor.run(AbstractTest.java:215)
   summary:
   27%: org.apache.jackrabbit.stats
   19%: org.apache.jackrabbit.oak.jcr.session
   15%: org.apache.jackrabbit.oak.jcr.delegate
   12%: com.google.common.util.concurrent
   12%: org.apache.jackrabbit.oak.benchmark