Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Ansible playbook based gatling JVM gets stuck when there is high CPU usage of Keycloak pods #960

Open
kami619 opened this issue Aug 28, 2024 · 2 comments
Open

Ansible playbook based gatling JVM gets stuck when there is high CPU usage of Keycloak pods #960

kami619 opened this issue Aug 28, 2024 · 2 comments
Labels
automation kind/bug Something isn't working status/triage

Comments

@kami619
Copy link
Contributor

kami619 commented Aug 28, 2024

Describe the bug

When we execute the Ansible playbooks and run the kcb.sh script on the EC2 load runners, once the test execution is done, the playbook should consolidate the gatling report in the last phase.

However, when this playbook is run against a Keycloak K8s cluster with a high CPU utilization, the JVM process of the Gatling application seems to be waiting indefinitely and the job only times out after the 60 min timeout configured inside the Ansible playbook.

Version

keycloak-benchmark latest main

Expected behavior

The Gatling should run and complete successfully irrespective of the Application Under Test behavior.

Actual behavior

It gets stuck in the last phase of the Gatling load test and doesn't finish independently.

How to Reproduce?

./aws_ec2.sh create eu-west-1

./benchmark.sh eu-west-1 --scenario=keycloak.scenario.authentication.AuthorizationCode --server-url=<KEYCLOAK_URL> --realm-name=realm-0 --users-per-sec=150 --ramp-up=20 --logout-percentage=100 --measurement=600 --users-per-realm=20000 --sla-error-percentage=0.001

PROJECT=<KEYCLOAK_NAMESPACE> ./kc-chaos.sh <RESULTS_DIR>

Observe if the playbook finishes and collects the report in the last phase before the timeout is triggered for the Async polling.

Anything else?

Thread Dump from the stuck JVM process

[root@ip-172-31-36-162 bin]# jcmd 20703 Thread.print
20703:
2024-08-27 18:38:12
Full thread dump OpenJDK 64-Bit Server VM (21.0.4+7-LTS mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x0000ffff64000c30, length=25, elements={
0x0000ffff9402a970, 0x0000ffff94083ce0, 0x0000ffff94085450, 0x0000ffff94086f70,
0x0000ffff940885a0, 0x0000ffff94089b30, 0x0000ffff9408b5f0, 0x0000ffff9408cca0,
0x0000ffff940a32e0, 0x0000ffff940a7870, 0x0000ffff946ec1b0, 0x0000aaab02ab4d90,
0x0000ffff949da7e0, 0x0000ffff95092c20, 0x0000ffff38024b00, 0x0000ffff3802e4b0,
0x0000ffff5090f850, 0x0000ffff5c0014c0, 0x0000ffff502157e0, 0x0000ffff58010440,
0x0000aaab02abb700, 0x0000ffff38050660, 0x0000ffff380519b0, 0x0000ffff38052b60,
0x0000ffff6400e4d0
}

"main" #1 [20707] prio=5 os_prio=0 cpu=2273.04ms elapsed=2244.68s tid=0x0000ffff9402a970 nid=20707 waiting on condition  [0x0000ffff98dfd000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
	- parking to wait for  <0x00000007565ab660> (a scala.concurrent.impl.CompletionLatch)
	at java.util.concurrent.locks.LockSupport.parkNanos([email protected]/LockSupport.java:269)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire([email protected]/AbstractQueuedSynchronizer.java:756)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos([email protected]/AbstractQueuedSynchronizer.java:1126)
	at scala.concurrent.impl.Promise$DefaultPromise.tryAwait0(Promise.scala:241)
	at scala.concurrent.impl.Promise$DefaultPromise.result(Promise.scala:261)
	at scala.concurrent.Await$.$anonfun$result$1(package.scala:201)
	at scala.concurrent.Await$$$Lambda/0x00000080012e2480.apply(Unknown Source)
	at scala.concurrent.BlockContext$DefaultBlockContext$.blockOn(BlockContext.scala:62)
	at scala.concurrent.Await$.result(package.scala:124)
	at io.gatling.app.Runner.start(Runner.scala:113)
	at io.gatling.app.Runner.run(Runner.scala:61)
	at io.gatling.app.Gatling$.start(Gatling.scala:86)
	at io.gatling.app.Gatling$.fromArgs(Gatling.scala:48)
	at io.gatling.app.Gatling$.main(Gatling.scala:42)
	at io.gatling.app.Gatling.main(Gatling.scala)

"Reference Handler" #4 [20710] daemon prio=10 os_prio=0 cpu=3.78ms elapsed=2244.65s tid=0x0000ffff94083ce0 nid=20710 waiting on condition  [0x0000ffff7b7fe000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.ref.Reference.waitForReferencePendingList([email protected]/Native Method)
	at java.lang.ref.Reference.processPendingReferences([email protected]/Reference.java:246)
	at java.lang.ref.Reference$ReferenceHandler.run([email protected]/Reference.java:208)

"Finalizer" #5 [20711] daemon prio=8 os_prio=0 cpu=0.16ms elapsed=2244.65s tid=0x0000ffff94085450 nid=20711 in Object.wait()  [0x0000ffff7b5ef000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait0([email protected]/Native Method)
	- waiting on <0x0000000755996fd8> (a java.lang.ref.NativeReferenceQueue$Lock)
	at java.lang.Object.wait([email protected]/Object.java:366)
	at java.lang.Object.wait([email protected]/Object.java:339)
	at java.lang.ref.NativeReferenceQueue.await([email protected]/NativeReferenceQueue.java:48)
	at java.lang.ref.ReferenceQueue.remove0([email protected]/ReferenceQueue.java:158)
	at java.lang.ref.NativeReferenceQueue.remove([email protected]/NativeReferenceQueue.java:89)
	- locked <0x0000000755996fd8> (a java.lang.ref.NativeReferenceQueue$Lock)
	at java.lang.ref.Finalizer$FinalizerThread.run([email protected]/Finalizer.java:173)

"Signal Dispatcher" #6 [20712] daemon prio=9 os_prio=0 cpu=0.39ms elapsed=2244.65s tid=0x0000ffff94086f70 nid=20712 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #7 [20713] daemon prio=9 os_prio=0 cpu=4.20ms elapsed=2244.65s tid=0x0000ffff940885a0 nid=20713 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Monitor Deflation Thread" #8 [20714] daemon prio=9 os_prio=0 cpu=228.50ms elapsed=2244.65s tid=0x0000ffff94089b30 nid=20714 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #9 [20715] daemon prio=9 os_prio=0 cpu=25649.20ms elapsed=2244.65s tid=0x0000ffff9408b5f0 nid=20715 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #10 [20716] daemon prio=9 os_prio=0 cpu=3069.22ms elapsed=2244.65s tid=0x0000ffff9408cca0 nid=20716 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"Notification Thread" #11 [20717] daemon prio=9 os_prio=0 cpu=0.06ms elapsed=2244.65s tid=0x0000ffff940a32e0 nid=20717 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #12 [20718] daemon prio=8 os_prio=0 cpu=6.03ms elapsed=2244.65s tid=0x0000ffff940a7870 nid=20718 waiting on condition  [0x0000ffff7a78d000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
	- parking to wait for  <0x0000000755997100> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos([email protected]/LockSupport.java:269)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await([email protected]/AbstractQueuedSynchronizer.java:1847)
	at java.lang.ref.ReferenceQueue.await([email protected]/ReferenceQueue.java:71)
	at java.lang.ref.ReferenceQueue.remove0([email protected]/ReferenceQueue.java:143)
	at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:218)
	at jdk.internal.ref.CleanerImpl.run([email protected]/CleanerImpl.java:140)
	at java.lang.Thread.runWith([email protected]/Thread.java:1596)
	at java.lang.Thread.run([email protected]/Thread.java:1583)
	at jdk.internal.misc.InnocuousThread.run([email protected]/InnocuousThread.java:186)

"GatlingSystem-scheduler-1" #14 [20719] prio=5 os_prio=0 cpu=8118.53ms elapsed=2243.11s tid=0x0000ffff946ec1b0 nid=20719 waiting on condition  [0x0000ffff7a45d000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep0([email protected]/Native Method)
	at java.lang.Thread.sleep([email protected]/Thread.java:509)
	at akka.actor.LightArrayRevolverScheduler.waitNanos(LightArrayRevolverScheduler.scala:90)
	at akka.actor.LightArrayRevolverScheduler$$anon$3.nextTick(LightArrayRevolverScheduler.scala:300)
	at akka.actor.LightArrayRevolverScheduler$$anon$3.run(LightArrayRevolverScheduler.scala:270)
	at java.lang.Thread.runWith([email protected]/Thread.java:1596)
	at java.lang.Thread.run([email protected]/Thread.java:1583)

"GatlingSystem-akka.actor.default-dispatcher-5" #18 [20723] prio=5 os_prio=0 cpu=2163.63ms elapsed=2242.97s tid=0x0000aaab02ab4d90 nid=20723 waiting on condition  [0x0000ffff79c25000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
	- parking to wait for  <0x0000000755db5820> (a akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool)
	at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:371)
	at java.util.concurrent.ForkJoinPool.awaitWork([email protected]/ForkJoinPool.java:1893)
	at java.util.concurrent.ForkJoinPool.runWorker([email protected]/ForkJoinPool.java:1809)
	at java.util.concurrent.ForkJoinWorkerThread.run([email protected]/ForkJoinWorkerThread.java:188)

"Timer-0" #19 [20724] daemon prio=5 os_prio=0 cpu=19.10ms elapsed=2242.75s tid=0x0000ffff949da7e0 nid=20724 in Object.wait()  [0x0000ffff79a17000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait0([email protected]/Native Method)
	- waiting on <0x0000000755e76460> (a java.util.TaskQueue)
	at java.lang.Object.wait([email protected]/Object.java:366)
	at java.util.TimerThread.mainLoop([email protected]/Timer.java:563)
	- locked <0x0000000755e76460> (a java.util.TaskQueue)
	at java.util.TimerThread.run([email protected]/Timer.java:516)

"gatling-1-1" #24 [20728] prio=5 os_prio=0 cpu=30060.17ms elapsed=2241.33s tid=0x0000ffff95092c20 nid=20728 runnable  [0x0000ffff79808000]
   java.lang.Thread.State: RUNNABLE
	at io.netty.channel.epoll.Native.epollWait(Native Method)
	at io.netty.channel.epoll.Native.epollWait(Native.java:220)
	at io.netty.channel.epoll.Native.epollWait(Native.java:213)
	at io.netty.channel.epoll.EpollEventLoop.epollWaitNoTimerChange(EpollEventLoop.java:308)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:365)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.runWith([email protected]/Thread.java:1596)
	at java.lang.Thread.run([email protected]/Thread.java:1583)

"GatlingSystem-akka.actor.default-dispatcher-6" #25 [20729] prio=5 os_prio=0 cpu=1435.64ms elapsed=2240.96s tid=0x0000ffff38024b00 nid=20729 waiting on condition  [0x0000ffff795fb000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
	- parking to wait for  <0x0000000755db5820> (a akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool)
	at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:371)
	at java.util.concurrent.ForkJoinPool.awaitWork([email protected]/ForkJoinPool.java:1893)
	at java.util.concurrent.ForkJoinPool.runWorker([email protected]/ForkJoinPool.java:1809)
	at java.util.concurrent.ForkJoinWorkerThread.run([email protected]/ForkJoinWorkerThread.java:188)

"GatlingSystem-akka.actor.default-dispatcher-7" #26 [20730] prio=5 os_prio=0 cpu=2662.91ms elapsed=2240.95s tid=0x0000ffff3802e4b0 nid=20730 waiting on condition  [0x0000ffff78bfd000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
	- parking to wait for  <0x0000000755db5820> (a akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool)
	at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:371)
	at java.util.concurrent.ForkJoinPool.awaitWork([email protected]/ForkJoinPool.java:1893)
	at java.util.concurrent.ForkJoinPool.runWorker([email protected]/ForkJoinPool.java:1809)
	at java.util.concurrent.ForkJoinWorkerThread.run([email protected]/ForkJoinWorkerThread.java:188)

"GatlingSystem-akka.actor.default-dispatcher-8" #27 [20731] prio=5 os_prio=0 cpu=349.31ms elapsed=2240.95s tid=0x0000ffff5090f850 nid=20731 waiting on condition  [0x0000ffff789ef000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
	- parking to wait for  <0x0000000755db5820> (a akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool)
	at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:371)
	at java.util.concurrent.ForkJoinPool.awaitWork([email protected]/ForkJoinPool.java:1893)
	at java.util.concurrent.ForkJoinPool.runWorker([email protected]/ForkJoinPool.java:1809)
	at java.util.concurrent.ForkJoinWorkerThread.run([email protected]/ForkJoinWorkerThread.java:188)

"GatlingSystem-akka.actor.default-dispatcher-9" #28 [20732] prio=5 os_prio=0 cpu=1892.13ms elapsed=2240.95s tid=0x0000ffff5c0014c0 nid=20732 waiting on condition  [0x0000ffff787e1000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
	- parking to wait for  <0x0000000755db5820> (a akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool)
	at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:371)
	at java.util.concurrent.ForkJoinPool.awaitWork([email protected]/ForkJoinPool.java:1893)
	at java.util.concurrent.ForkJoinPool.runWorker([email protected]/ForkJoinPool.java:1809)
	at java.util.concurrent.ForkJoinWorkerThread.run([email protected]/ForkJoinWorkerThread.java:188)

"GatlingSystem-akka.actor.default-dispatcher-10" #29 [20733] prio=5 os_prio=0 cpu=1660.16ms elapsed=2240.94s tid=0x0000ffff502157e0 nid=20733 waiting on condition  [0x0000ffff785d3000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
	- parking to wait for  <0x0000000755db5820> (a akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool)
	at java.util.concurrent.locks.LockSupport.park([email protected]/LockSupport.java:371)
	at java.util.concurrent.ForkJoinPool.awaitWork([email protected]/ForkJoinPool.java:1893)
	at java.util.concurrent.ForkJoinPool.runWorker([email protected]/ForkJoinPool.java:1809)
	at java.util.concurrent.ForkJoinWorkerThread.run([email protected]/ForkJoinWorkerThread.java:188)

"GatlingSystem-akka.actor.default-dispatcher-11" #30 [20734] prio=5 os_prio=0 cpu=2584.48ms elapsed=2240.93s tid=0x0000ffff58010440 nid=20734 waiting on condition  [0x0000ffff783c5000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park([email protected]/Native Method)
	- parking to wait for  <0x0000000755db5820> (a akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinPool)
	at java.util.concurrent.locks.LockSupport.parkUntil([email protected]/LockSupport.java:449)
	at java.util.concurrent.ForkJoinPool.awaitWork([email protected]/ForkJoinPool.java:1891)
	at java.util.concurrent.ForkJoinPool.runWorker([email protected]/ForkJoinPool.java:1809)
	at java.util.concurrent.ForkJoinWorkerThread.run([email protected]/ForkJoinWorkerThread.java:188)

"GatlingSystem-akka.io.pinned-dispatcher-12" #31 [20735] prio=5 os_prio=0 cpu=21.51ms elapsed=2240.88s tid=0x0000aaab02abb700 nid=20735 runnable  [0x0000ffff3fffd000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.EPoll.wait([email protected]/Native Method)
	at sun.nio.ch.EPollSelectorImpl.doSelect([email protected]/EPollSelectorImpl.java:121)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:130)
	- locked <0x00000007569ea528> (a sun.nio.ch.Util$2)
	- locked <0x00000007569ea4d8> (a sun.nio.ch.EPollSelectorImpl)
	at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:142)
	at akka.io.SelectionHandler$ChannelRegistryImpl$$anon$2.tryRun(SelectionHandler.scala:152)
	at akka.io.SelectionHandler$ChannelRegistryImpl$Task.run(SelectionHandler.scala:292)
	at akka.io.SelectionHandler$ChannelRegistryImpl$$anon$2.run(SelectionHandler.scala:185)
	at akka.util.SerializedSuspendableExecutionContext.run$1(SerializedSuspendableExecutionContext.scala:74)
	at akka.util.SerializedSuspendableExecutionContext.run(SerializedSuspendableExecutionContext.scala:79)
	at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1144)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:642)
	at java.lang.Thread.runWith([email protected]/Thread.java:1596)
	at java.lang.Thread.run([email protected]/Thread.java:1583)

"gatling-1-2" #32 [20736] prio=5 os_prio=0 cpu=29719.96ms elapsed=2240.82s tid=0x0000ffff38050660 nid=20736 runnable  [0x0000ffff3fdef000]
   java.lang.Thread.State: RUNNABLE
	at io.netty.channel.epoll.Native.epollWait(Native Method)
	at io.netty.channel.epoll.Native.epollWait(Native.java:220)
	at io.netty.channel.epoll.Native.epollWait(Native.java:213)
	at io.netty.channel.epoll.EpollEventLoop.epollWaitNoTimerChange(EpollEventLoop.java:308)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:365)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.runWith([email protected]/Thread.java:1596)
	at java.lang.Thread.run([email protected]/Thread.java:1583)

"gatling-1-3" #33 [20737] prio=5 os_prio=0 cpu=29632.89ms elapsed=2240.82s tid=0x0000ffff380519b0 nid=20737 runnable  [0x0000ffff3fbe1000]
   java.lang.Thread.State: RUNNABLE
	at io.netty.channel.epoll.Native.epollWait(Native Method)
	at io.netty.channel.epoll.Native.epollWait(Native.java:220)
	at io.netty.channel.epoll.Native.epollWait(Native.java:213)
	at io.netty.channel.epoll.EpollEventLoop.epollWaitNoTimerChange(EpollEventLoop.java:308)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:365)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.runWith([email protected]/Thread.java:1596)
	at java.lang.Thread.run([email protected]/Thread.java:1583)

"gatling-1-4" #34 [20738] prio=5 os_prio=0 cpu=29598.46ms elapsed=2240.81s tid=0x0000ffff38052b60 nid=20738 runnable  [0x0000ffff3f9d3000]
   java.lang.Thread.State: RUNNABLE
	at io.netty.channel.epoll.Native.epollWait0(Native Method)
	at io.netty.channel.epoll.Native.epollWait(Native.java:193)
	at io.netty.channel.epoll.EpollEventLoop.epollWait(EpollEventLoop.java:304)
	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:368)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:994)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.runWith([email protected]/Thread.java:1596)
	at java.lang.Thread.run([email protected]/Thread.java:1583)

"Attach Listener" #36 [22915] daemon prio=9 os_prio=0 cpu=0.49ms elapsed=0.10s tid=0x0000ffff6400e4d0 nid=22915 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"VM Thread" os_prio=0 cpu=1470.34ms elapsed=2244.66s tid=0x0000ffff94072500 nid=20709 runnable

"VM Periodic Task Thread" os_prio=0 cpu=1395.39ms elapsed=2244.66s tid=0x0000ffff94057c50 nid=20708 waiting on condition

JNI global refs: 23, weak refs: 4
@ahus1
Copy link
Contributor

ahus1 commented Aug 30, 2024

@kami619 - can you please provide the output of the Gatling run on the console? Maybe by running the Gatling test locally and not on an EC2 instance when triggering the failures? IMHO this could give additional insights on what errors were triggered, and it would probably be the first things asked for when opening an issue upstream.

@kami619
Copy link
Contributor Author

kami619 commented Aug 30, 2024 •
edited
Loading

@ahus1 It goes beyond the specified 600s in the run duration and gets stuck here.


================================================================================
2024-08-30 14:39:54 GMT                                    1765s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=102452 KO=2091  )
> Browser to Log In Endpoint                               (OK=28413  KO=2087  )
> Browser posts correct credentials                        (OK=24681  KO=2     )
> Exchange Code                                            (OK=24679  KO=2     )
> Browser logout                                           (OK=24679  KO=0     )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException                                     2072 (99.09%)
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================

full log:

INFO: Running benchmark in single-run mode.
INFO: Running benchmark with users-per-sec=50.0, result output will be available in: /opt/keycloak-benchmark-0.14-SNAPSHOT/bin/../results/
14:10:27.650 [INFO ] a.e.s.Slf4jLogger - Slf4jLogger started
==========================================================
Target servers: [https://XXXXXXXXX.dualstack.awsglobalaccelerator.com]
Scenario:
 Name: keycloak.scenario.authentication.AuthorizationCode
Population:
  realms: 1
  users-per-realm: 20000
  clients-per-realm: 1
  realm-name: realm-0
  username: Not defined
  user-password: Not defined
Runtime:
  users-per-sec: 50.0 (Open Workload Model)
  ramp-up: 20
  warm-up: 0
  measurement: 600
  user-think-time: 0
  refresh-token-period: 0
Service Level Agreements:
  Max Error Percentage: 0.001
  Max Mean Response Time: 300
Timestamps:
  Start: 14:10:28
  Warm-Up Start: 14:10:48
...skipping...
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================


================================================================================
2024-08-30 14:39:49 GMT                                    1760s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=102452 KO=2091  )
> Browser to Log In Endpoint                               (OK=28413  KO=2087  )
> Browser posts correct credentials                        (OK=24681  KO=2     )
> Exchange Code                                            (OK=24679  KO=2     )
> Browser logout                                           (OK=24679  KO=0     )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException                                     2072 (99.09%)
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================

...skipping...
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================


================================================================================
2024-08-30 14:39:49 GMT                                    1760s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=102452 KO=2091  )
> Browser to Log In Endpoint                               (OK=28413  KO=2087  )
> Browser posts correct credentials                        (OK=24681  KO=2     )
> Exchange Code                                            (OK=24679  KO=2     )
> Browser logout                                           (OK=24679  KO=0     )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException                                     2072 (99.09%)
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================

...skipping...
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================


================================================================================
2024-08-30 14:39:49 GMT                                    1760s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=102452 KO=2091  )
> Browser to Log In Endpoint                               (OK=28413  KO=2087  )
> Browser posts correct credentials                        (OK=24681  KO=2     )
> Exchange Code                                            (OK=24679  KO=2     )
> Browser logout                                           (OK=24679  KO=0     )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException                                     2072 (99.09%)
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================

...skipping...
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================


================================================================================
2024-08-30 14:39:49 GMT                                    1760s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=102452 KO=2091  )
> Browser to Log In Endpoint                               (OK=28413  KO=2087  )
> Browser posts correct credentials                        (OK=24681  KO=2     )
> Exchange Code                                            (OK=24679  KO=2     )
> Browser logout                                           (OK=24679  KO=0     )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException                                     2072 (99.09%)
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================

...skipping...
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================


================================================================================
2024-08-30 14:39:49 GMT                                    1760s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=102452 KO=2091  )
> Browser to Log In Endpoint                               (OK=28413  KO=2087  )
> Browser posts correct credentials                        (OK=24681  KO=2     )
> Exchange Code                                            (OK=24679  KO=2     )
> Browser logout                                           (OK=24679  KO=0     )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException                                     2072 (99.09%)
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================

...skipping...
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================


================================================================================
2024-08-30 14:39:49 GMT                                    1760s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=102452 KO=2091  )
> Browser to Log In Endpoint                               (OK=28413  KO=2087  )
> Browser posts correct credentials                        (OK=24681  KO=2     )
> Exchange Code                                            (OK=24679  KO=2     )
> Browser logout                                           (OK=24679  KO=0     )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException                                     2072 (99.09%)
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================

...skipping...
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================


================================================================================
2024-08-30 14:39:54 GMT                                    1765s elapsed
---- Requests ------------------------------------------------------------------
> Global                                                   (OK=102452 KO=2091  )
> Browser to Log In Endpoint                               (OK=28413  KO=2087  )
> Browser posts correct credentials                        (OK=24681  KO=2     )
> Exchange Code                                            (OK=24679  KO=2     )
> Browser logout                                           (OK=24679  KO=0     )
---- Errors --------------------------------------------------------------------
> j.n.c.ClosedChannelException                                     2072 (99.09%)
> j.i.IOException: Premature close                                   17 ( 0.81%)
> status.find.is(200), but actually found 400                         2 ( 0.10%)

---- Authentication - Authorization Code Username/Password ---------------------
[################################################################----------] 87%
          waiting: 0      / active: 3730   / done: 26770
================================================================================

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
automation kind/bug Something isn't working status/triage
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@kami619 @ahus1