에이전트 pc의 cpu 부하가 테스트 실행 후 낮아지지 않습니다

[unokim-dev]

테스트 환경

• MacBook Pro (Apple M1 pro, 32GB ram), macOs Ventura 13.0.1
• ngrinder 3.5.7 (docker setup)
  • https://hub.docker.com/r/ngrinder/controller
  • https://hub.docker.com/r/ngrinder/agent
• docker desktop: 4.14.1
  • engine: 20.10.21
  • resource: 8 cpus, 16GB mem, 2GB swap, 32GB disk image size

안녕하세요,
도커로 설치한 컨트롤러와 에이전트를 이용해 테스트를 하는 중인데요,
테스트를 실행시키면 정상적으로 테스트가 종료된 이후에도 cpu에 부하가 걸려있습니다.

2022-11-25 08:51:55,684 INFO  agent controller: Agent is started. Waiting for agent controller signal
2022-11-25 08:51:55,689 INFO  agent daemon: The Grinder 3.9.1
2022-11-25 08:51:55,736 INFO  agent daemon: Send digest of cached files to controller.
2022-11-25 08:51:55,740 INFO  agent daemon: Connect to console at /10.8.30.124:12004
2022-11-25 08:51:55,743 INFO  agent daemon: Waiting for console signal
2022-11-25 08:51:56,669 INFO  agent daemon: Refresh cached file store
2022-11-25 08:51:56,700 INFO  agent daemon: Updating file store: "InventoryTravels.groovy" (2565 bytes)
2022-11-25 08:51:58,238 INFO  agent daemon: received a start message
2022-11-25 08:51:58,252 INFO  agent daemon: log file : /opt/ngrinder-agent/.ngrinder-agent/log/test_59/91527f24bbb9-0.log
2022-11-25 08:51:58,262 INFO  agent daemon: grinder properties {grinder.jvm=java, ngrinder.etc.hosts=, grinder.threads=5, grinder.user=admin, grinder.security.level=normal, grinder.runs=20, grinder.logProcessStreams=true, grinder.processes=2, grinder.numberOfOldLogs=1, grinder.security=false, grinder.sleepTimeFactor=1, grinder.test.id=test_59, grinder.dcrinstrumentation=true, grinder.ignoreSampleCount=0, grinder.jvm.user.library.classpath=., grinder.reportTimesToConsole=true, grinder.debug.singleprocess=false, grinder.script=InventoryTravels.groovy, grinder.processIncrement=0, grinder.useConsole=true, grinder.reportToConsole.interval=500, grinder.consolePort=12004, grinder.jvm.classpath=/opt/ngrinder-agent/lib/ngrinder-runtime-3.5.7.jar::/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current/, grinder.agents=1, grinder.connectionReset=true, grinder.sleepTimeVariation=0.2, grinder.logDirectory=/opt/ngrinder-agent/.ngrinder-agent/log/test_59, grinder.consoleHost=10.8.30.124}
2022-11-25 08:51:58,263 INFO  agent daemon: jvm arguments  -Djna.library.path=/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current/lib  -Dngrinder.connection.reset.on.each.test.run=true  -Dpython.path=/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current/lib  -Dpython.cachedir=/tmp/jython  -Dngrinder.etc.hosts=91527f24bbb9:127.0.0.1,localhost:127.0.0.1 -Dngrinder.enable.local-dns=true  -Duser.dir=/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current  -Dngrinder.context=agent  -Dhttps.protocols=SSLv3,TLSv1,TLSv1.1,TLSv1.2  -Djsse.enableSNIExtension=false  -Xms1024m -Xmx1024m 
2022-11-25 08:51:58,273 INFO  agent daemon: Worker process command line: java '-javaagent:../../../../lib/grinder-dcr-agent-3.9.1.jar' '-Djna.library.path=/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current/lib' '-Dngrinder.connection.reset.on.each.test.run=true' '-Dpython.path=/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current/lib' '-Dpython.cachedir=/tmp/jython' '-Dngrinder.etc.hosts=91527f24bbb9:127.0.0.1,localhost:127.0.0.1' '-Dngrinder.enable.local-dns=true' '-Duser.dir=/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current' '-Dngrinder.context=agent' '-Dhttps.protocols=SSLv3,TLSv1,TLSv1.1,TLSv1.2' '-Djsse.enableSNIExtension=false' '-Xms1024m' '-Xmx1024m' -classpath '../../../../lib/ngrinder-runtime-3.5.7.jar:../../../..:.:../../../../lib/ngrinder-runime-3.5.7.jar:../../../../lib/commons-io-2.6.jar:../../../../lib/groovy-json-3.0.5.jar:../../../../lib/grinder-dcr-agent-3.9.1.jar:../../../../lib/grinder-httpclient-3.9.1.jar:../../../../lib/groovy-datetime-3.0.5.jar:../../../../lib/groovy-templates-3.0.5.jar:../../../../lib/commons-lang-2.6.jar:../../../../lib/grinder-http-3.9.1.jar:../../../../lib/hamcrest-core-2.2.jar:../../../../lib/ngrinder-runtime-3.5.7.jar:../../../../lib/jna-5.11.0.jar:../../../../lib/httpcore5-5.0.3.jar:../../../../lib/logback-classic-1.2.3.jar:../../../../lib/groovy-xml-3.0.5.jar:../../../../lib/ngrinder-groovy-3.5.7.jar:../../../../lib/groovy-3.0.5.jar:../../../../lib/groovy-sql-3.0.5.jar:../../../../lib/slf4j-api-1.7.30.jar:../../../../lib/hamcrest-all-1.1.jar:../../../../lib/junit-4.13.1.jar:../../../../lib/asm-9.0.jar:../../../../lib/json-20090211.jar:../../../../lib/grinder-core-3.9.1.jar:../../../../lib/picocontainer-2.13.6.jar:../../../../lib/dnsjava-3.2.2.jar:../../../../lib/httpcore5-h2-5.0.3.jar:../../../../lib/jna-platform-5.11.0.jar:../../../../lib/logback-core-1.2.3.jar' net.grinder.engine.process.WorkerProcessEntryPoint
2022-11-25 08:51:58,307 INFO  agent daemon: worker 91527f24bbb9-0 started
2022-11-25 08:51:58,330 INFO  agent daemon: worker 91527f24bbb9-1 started
2022-11-25 08:52:10,119 INFO  91527f24bbb9-1: Starting threads
2022-11-25 08:52:36,570 INFO  91527f24bbb9-1: Finished
2022-11-25 08:53:08,017 INFO  agent controller: Received a stop agent message
2022-11-25 08:53:08,237 INFO  agent daemon: Agent is terminated by force
2022-11-25 08:53:08,237 INFO  agent daemon: Don't start anymore by message from controller.
2022-11-25 08:53:10,691 INFO  agent daemon: communication shut down
2022-11-25 08:53:10,693 INFO  agent daemon: Test shuts down.
2022-11-25 08:53:10,695 INFO  agent controller: Send log for test_59
2022-11-25 08:53:10,713 INFO  agent controller: Clean up the perftest logs
2022-11-25 08:53:10,717 INFO  agent controller: Waiting for agent controller server signal

이유를 모르겠네요. 에이전트 실행이 완전히 중단된 것도 확인했지만, 테스트를 수행한 뒤마다 cpu 로드가 점점 증가합니다.
에이전트 컨테이너를 껐다 키는 것으로 일단 cpu를 정상화시킬 수는 있지만, 명확한 원인을 알 수 없는 상태입니다.
또한 다른 에이전트들은 제가 마음대로 서버에 들어가서 컨테이너를 조작할 수 없는 상황이라 대응하기도 어렵네요.

때로는 테스트가 끝난 뒤에 에이전트가 제대로 끝을 보지 못하고 다음과 같이 로그를 출력하기도 합니다.

2022-11-25 09:01:49,804 INFO  agent daemon: received a start message
2022-11-25 09:01:49,836 INFO  agent daemon: log file : /opt/ngrinder-agent/.ngrinder-agent/log/test_60/91527f24bbb9-0.log
2022-11-25 09:01:50,692 INFO  agent daemon: grinder properties {grinder.jvm=java, ngrinder.etc.hosts=, grinder.threads=5, grinder.user=admin, grinder.security.level=normal, grinder.runs=20, grinder.logProcessStreams=true, grinder.processes=2, grinder.numberOfOldLogs=1, grinder.security=false, grinder.sleepTimeFactor=1, grinder.test.id=test_60, grinder.dcrinstrumentation=true, grinder.ignoreSampleCount=0, grinder.jvm.user.library.classpath=., grinder.reportTimesToConsole=true, grinder.debug.singleprocess=false, grinder.script=InventoryTravels.groovy, grinder.processIncrement=0, grinder.useConsole=true, grinder.reportToConsole.interval=500, grinder.consolePort=12005, grinder.jvm.classpath=/opt/ngrinder-agent/lib/ngrinder-runtime-3.5.7.jar::/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current/, grinder.agents=1, grinder.connectionReset=true, grinder.sleepTimeVariation=0.2, grinder.logDirectory=/opt/ngrinder-agent/.ngrinder-agent/log/test_60, grinder.consoleHost=10.8.30.124}
2022-11-25 09:01:50,697 INFO  agent daemon: jvm arguments  -Djna.library.path=/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current/lib  -Dngrinder.connection.reset.on.each.test.run=true  -Dpython.path=/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current/lib  -Dpython.cachedir=/tmp/jython  -Dngrinder.etc.hosts=91527f24bbb9:127.0.0.1,localhost:127.0.0.1 -Dngrinder.enable.local-dns=true  -Duser.dir=/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current  -Dngrinder.context=agent  -Dhttps.protocols=SSLv3,TLSv1,TLSv1.1,TLSv1.2  -Djsse.enableSNIExtension=false  -Xms1024m -Xmx1024m 
2022-11-25 09:01:50,715 INFO  agent daemon: Worker process command line: java '-javaagent:../../../../lib/grinder-dcr-agent-3.9.1.jar' '-Djna.library.path=/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current/lib' '-Dngrinder.connection.reset.on.each.test.run=true' '-Dpython.path=/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current/lib' '-Dpython.cachedir=/tmp/jython' '-Dngrinder.etc.hosts=91527f24bbb9:127.0.0.1,localhost:127.0.0.1' '-Dngrinder.enable.local-dns=true' '-Duser.dir=/opt/ngrinder-agent/.ngrinder-agent/file-store/admin/current' '-Dngrinder.context=agent' '-Dhttps.protocols=SSLv3,TLSv1,TLSv1.1,TLSv1.2' '-Djsse.enableSNIExtension=false' '-Xms1024m' '-Xmx1024m' -classpath '../../../../lib/ngrinder-runtime-3.5.7.jar:../../../..:.:../../../../lib/ngrinder-runime-3.5.7.jar:../../../../lib/commons-io-2.6.jar:../../../../lib/groovy-json-3.0.5.jar:../../../../lib/grinder-dcr-agent-3.9.1.jar:../../../../lib/grinder-httpclient-3.9.1.jar:../../../../lib/groovy-datetime-3.0.5.jar:../../../../lib/groovy-templates-3.0.5.jar:../../../../lib/commons-lang-2.6.jar:../../../../lib/grinder-http-3.9.1.jar:../../../../lib/hamcrest-core-2.2.jar:../../../../lib/ngrinder-runtime-3.5.7.jar:../../../../lib/jna-5.11.0.jar:../../../../lib/httpcore5-5.0.3.jar:../../../../lib/logback-classic-1.2.3.jar:../../../../lib/groovy-xml-3.0.5.jar:../../../../lib/ngrinder-groovy-3.5.7.jar:../../../../lib/groovy-3.0.5.jar:../../../../lib/groovy-sql-3.0.5.jar:../../../../lib/slf4j-api-1.7.30.jar:../../../../lib/hamcrest-all-1.1.jar:../../../../lib/junit-4.13.1.jar:../../../../lib/asm-9.0.jar:../../../../lib/json-20090211.jar:../../../../lib/grinder-core-3.9.1.jar:../../../../lib/picocontainer-2.13.6.jar:../../../../lib/dnsjava-3.2.2.jar:../../../../lib/httpcore5-h2-5.0.3.jar:../../../../lib/jna-platform-5.11.0.jar:../../../../lib/logback-core-1.2.3.jar' net.grinder.engine.process.WorkerProcessEntryPoint
Picked up JAVA_TOOL_OPTIONS: -Dfile.encoding=UTF-8
2022-11-25 09:01:50,798 INFO  agent daemon: worker 91527f24bbb9-0 started
2022-11-25 09:01:50,826 INFO  agent daemon: worker 91527f24bbb9-1 started
Picked up JAVA_TOOL_OPTIONS: -Dfile.encoding=UTF-8
2022-11-25 09:02:02,176 INFO  91527f24bbb9-0: Starting threads
2022-11-25 09:02:22,898 INFO  91527f24bbb9-0: Finished
2022-11-25 09:03:26,419 INFO  agent daemon: received a stop message
2022-11-25 09:03:26,428 INFO  agent daemon: Don't start anymore by message from controller.
2022-11-25 09:03:26,476 INFO  agent daemon: communication shut down
2022-11-25 09:03:26,567 ERROR agent daemon: Error while pumping up the AgentProcessReportMessage
2022-11-25 09:03:31,484 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:03:36,591 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:03:41,694 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:03:46,798 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:03:51,902 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:03:57,005 INFO  agent daemon: Terminating unresponsive processes by force

도움 부탁드립니다.

[unokim-dev]

테스트의 최종 성공 실패 여부에 상관 없이 문제가 발생하는 것 같습니다.
정상이라면 테스트 시작 시에 worker 수만큼 Starting threads 로그가 찍히는 것 같은데,
간혹 그러지 않고 특정 테스트 스레드가 시작되지 못하거나, 종료되지 못하고 계속 cpu 리소스를 차지하고 있는 느낌이네요.

2022-11-25 09:43:29,123 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:43:34,331 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:43:39,536 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:43:44,739 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:43:49,943 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:43:55,153 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:44:00,363 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:44:05,568 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:44:10,622 INFO  agent controller: Received a stop agent message
2022-11-25 09:44:10,839 INFO  agent daemon: Terminating unresponsive processes by force
2022-11-25 09:44:10,839 INFO  agent daemon: Agent is terminated by force
2022-11-25 09:44:12,879 ERROR agent daemon: Exception occurred in the agent message loop
net.grinder.common.UncheckedInterruptedException: Thread interrupted
        at net.grinder.util.thread.Condition.waitNoInterrruptException(Condition.java:68)
        at net.grinder.engine.agent.AgentImplementationEx.run(AgentImplementationEx.java:305)
        at net.grinder.AgentDaemon$AgentThreadRunnable.run(AgentDaemon.java:131)
        at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.InterruptedException: null
        at java.lang.Object.wait(Native Method)
        at net.grinder.util.thread.Condition.waitNoInterrruptException(Condition.java:65)
        ... 3 common frames omitted
2022-11-25 09:44:12,884 INFO  agent daemon: Test shuts down.
2022-11-25 09:44:12,886 INFO  agent controller: Send log for test_65
2022-11-25 09:44:12,895 INFO  agent controller: Clean up the perftest logs
2022-11-25 09:44:12,898 INFO  agent controller: Waiting for agent controller server signal