[nGrinder 3.3] agent log agent daemon: received a stop message
Locked
 
|
This post was updated on .
테스트 스크립트를 실제 테스트 하려는 서비스와 유사하게 로그인 후 로그 아웃 사이에 사용자가 발생시키는 이벤트를 캡쳐 해서 30 개 이상의 http request 를 보내도록 작성 했습니다.
agent 를 1개만 띄운 상태에서 controller 에서 테스트 1회만 실행을 하면 agent 측 로그에 아래와 같은 메시지를 출력하고 종료 됩니다. 테스트를 시작 하자 마자 종료 되는 것이 아니고, 테스트 스크립트를 정상적으로 실행 하면서 대상 서버에 테스트 스크립트 안에 있는 request 를 정상적으로 주고 받다가 아래와 같은 로그를 남기고 테스트가 종료 됩니다. 문제는 테스트 스크립트를 끝까지 실행하지 않은 상태에서 controller 에서 stop 메시지를 agent 에 보낸 것 같은 로그가 남았다는 것입니다. 테스트 스크립트를 "스크립트 검증"으로 실행하면 정상적으로 스크립트를 끝까지 실행합니다. agent 의 스펙에 문제가 있을 수도 있을 것 같아서 메모리를 4GB 에서 8GB 로 증설 했는데도 결과는 4GB 일 때나 8 GB 일 때나 같습니다. 어떤 것을 확인 해 볼 수 있을지요? ----------- agent 로그 ----------- 2015-10-19 14:11:57,547 INFO agent daemon: received a stop message 2015-10-19 14:11:57,547 INFO agent daemon: Don't start anymore by message from controller. 2015-10-19 14:11:57,549 INFO Review-Node-0: Waiting for threads to terminate 2015-10-19 14:11:57,624 INFO Review-Node-0: Finished 2015-10-19 14:11:58,004 INFO agent daemon: All workers are finished 2015-10-19 14:11:58,007 INFO agent daemon: communication shut down 2015-10-19 14:11:58,009 INFO agent daemon: Test shuts down. 2015-10-19 14:11:58,010 INFO agent controller: Send log for test_796 2015-10-19 14:11:58,019 INFO agent controller: Clean up the perftest logs |
Re: [nGrinder 3.3] agent log agent daemon: received a stop message
|
agent의 로그는 정상적인 상태입니다.
웹 서버에서 어떠한 이유로 agent에게 테스트 중지 명령을 보낸 것 같은데요. ngrinder 웹에 접속하셔서 해당 테스트의 파란공(or 빨간공)에 마우스를 올려보시면 팝업이 나와요. 그 메세지를 한번 확인해주세요. |
|
|
This post was updated on .
답변 감사합니다. 정확한 전달을 위해서 현상을 좀 더 자세하게 기술 하겠습니다.
테스트 스크립트의 "스크립트 검증" 을 수행하고 결과를 보면 테스트 스크립트 안에서 테스트 request 23 회를 모두 호출하였습니다. 같은 스크립트를 "성능 테스트" 에서 "테스트 실행" 을 이용하여 agent 로 실행 하도록 테스트 했습니다. 에이전트 수를 1로 하고, 에이전트별 가상사용자 수 1, 실행 횟수도 1로 해서 "스크립트 검증"과 같이 1회만 테스트 스크립트가 수행 되도록 했습니다. 답변 주신 테스트의 파란 공의 메시지 내용을 보면 정상적으로 종료 된 것처럼 보이는데, agent 콘솔 로그나 로그 파일을 보면 controller 로 부터 stop message(agent daemon: received a stop message)를 받았다고 나옵니다. agent 의 로그를 콘솔에서 파일로 받은 Review-Node-NONE-log.zip 를 보면 테스트 스크립트에서 실행해야 할 총 23 회의 request 중 12 회까지만 정상이고, 마지막 1 번은 에러(ERROR [PSW] Error occured : net.grinder.engine.process.ShutdownException: Thread has been shut down)가 나면서 중지 된 것을 확인 할 수 있습니다. 어떤 이유로 controller 에서 agent 에 "stop message" 를 보낸 것일까요? 혹시나 해서 controller 의 로그를 찾아봤는데, ".ngrinder/logs/ngrinder.log" 파일에는 agent 에게 메시지를 발송하는 로그 같은 것 없어 보입니다.(다른 로그를 검토해 볼 수 있는 것이 있을까요?) 테스트 스크립트를 작성 할 때 groovy 로 했는데, request 의 파라미터를 암호화 해야 해서 jar 를 만들어서 import 하여 사용 했습니다. 이런 것도 영향이 있을 수 있을 지 몰라 기술 합니다. ===== 테스트 스크립트의 "스크립트 검증" 결과 (ip는 지웠습니다) ============ 2015-10-21 13:06:20,110 INFO The Grinder version 3.9.1 2015-10-21 13:06:20,114 INFO Java(TM) SE Runtime Environment 1.6.0_34-b04: Java HotSpot(TM) 64-Bit Server VM (20.9-b04, mixed mode) on Linux amd64 2.6.32-431.11.2.el6.x86_64 2015-10-21 13:06:20,118 INFO time zone is KST (+0900) 2015-10-21 13:06:20,194 INFO worker process 0 of agent number 0 2015-10-21 13:06:20,214 INFO Instrumentation agents: byte code transforming instrumenter for Java; byte code transforming instrumenter for Java 2015-10-21 13:06:21,906 INFO registered plug-in net.grinder.plugin.http.HTTPPlugin 2015-10-21 13:06:21,966 INFO before process. 2015-10-21 13:06:21,968 INFO Running "TestRunner.groovy" using GroovyScriptEngine running with groovy version: 2.2.1 2015-10-21 13:06:21,988 INFO before thread. 2015-10-21 13:06:21,989 INFO starting, will do 1 run 2015-10-21 13:06:21,989 INFO Start time is 1445400381989 ms since Epoch 2015-10-21 13:06:23,321 INFO http://127.0.0.1/user_session/on -> 200 OK, 90 bytes 2015-10-21 13:06:24,040 INFO http://127.0.0.1/user_init_info -> 200 OK, 5430 bytes 2015-10-21 13:06:26,763 INFO http://127.0.0.1/user_init_info -> 200 OK, 5430 bytes 2015-10-21 13:06:26,878 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:06:28,511 INFO http://127.0.0.1/user_init_info -> 200 OK, 5430 bytes 2015-10-21 13:06:28,608 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:06:30,234 INFO http://127.0.0.1/user_init_info -> 200 OK, 5430 bytes 2015-10-21 13:06:30,323 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:06:33,968 INFO http://127.0.0.1/user_init_info -> 200 OK, 5430 bytes 2015-10-21 13:06:35,066 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:06:36,715 INFO http://127.0.0.1/user_init_info -> 200 OK, 5430 bytes 2015-10-21 13:06:36,810 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:06:44,435 INFO http://127.0.0.1/user_init_info -> 200 OK, 5430 bytes 2015-10-21 13:06:44,528 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:06:48,198 INFO http://127.0.0.1/user_init_info -> 200 OK, 5430 bytes 2015-10-21 13:06:48,295 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:06:51,951 INFO http://127.0.0.1/user_init_info -> 200 OK, 5430 bytes 2015-10-21 13:06:52,043 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:06:53,670 INFO http://127.0.0.1/user_init_info -> 200 OK, 5430 bytes 2015-10-21 13:06:53,759 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:06:56,362 INFO http://127.0.0.1/user_init_info -> 200 OK, 5430 bytes 2015-10-21 13:06:56,447 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:06:56,527 INFO http://127.0.0.1/user_session/off -> 200 OK, 18 bytes 2015-10-21 13:06:56,528 INFO finished 1 run 2015-10-21 13:06:56,529 INFO elapsed time is 34541 ms 2015-10-21 13:06:56,529 INFO Final statistics for this process: 2015-10-21 13:06:56,536 INFO Tests Errors Mean Test Test Time TPS Mean Response Response Mean time to Mean time to Mean time to Time (ms) Standard response bytes per errors resolve host establish first byte Deviation length second connection (ms) Test 1 23 0 1495.30 1804.94 0.67 2639.04 1757.27 0 0.00 3.00 1494.30 "Test1" Totals 23 0 1495.30 1804.94 0.67 2639.04 1757.27 0 0.00 3.00 1494.30 Tests resulting in error only contribute to the Errors column. Statistics for individual tests can be found in the data file, including (possibly incomplete) statistics for erroneous tests. Composite tests are marked with () and not included in the totals. =========== agent 의 콘솔 로그 ============ 2015-10-21 13:18:41,797 INFO agent controller: Received a start agent message 2015-10-21 13:18:41,797 INFO agent controller: Starting agent... for test_816 2015-10-21 13:18:41,798 INFO agent daemon: Agent daemon connecting to port 12004 is started. 2015-10-21 13:18:41,798 INFO agent controller: Agent is started. Waiting for agent controller signal 2015-10-21 13:18:41,798 INFO agent daemon: The Grinder 3.9.1 2015-10-21 13:18:41,800 INFO agent daemon: Connect to console at /10.1.1.1:12004 2015-10-21 13:18:41,801 INFO agent daemon: Waiting for console signal 2015-10-21 13:18:42,797 INFO agent daemon: Clearing file store 2015-10-21 13:18:42,800 INFO agent daemon: Updating file store: "TestRunner.groovy" (92115 bytes) 2015-10-21 13:18:47,824 INFO agent daemon: Updating file store: "lib/jc-ngrinder-common.jar" (639715 bytes) 2015-10-21 13:18:52,842 INFO agent daemon: Updating file store: "lib/log4j-1.2.9.jar" (352291 bytes) 2015-10-21 13:18:57,866 INFO agent daemon: received a start message 2015-10-21 13:18:57,873 INFO agent daemon: log file : /root/.ngrinder_agent/log/test_816/Review-Node-0.log 2015-10-21 13:18:57,875 INFO agent daemon: grinder properties {grinder.security=false, grinder.ignoreSampleCount=0, grinder.numberOfOldLogs=1, grinder.script=TestRunner.groovy, grinder.consoleHost=10.1.1.1, grinder.runs=1, grinder.logProcessStreams=true, grinder.jvm=java, grinder.sleepTimeFactor=1, grinder.reportToConsole.interval=500, grinder.dcrinstrumentation=true, grinder.reportTimesToConsole=true, grinder.processes=1, grinder.threads=1, grinder.useConsole=true, grinder.test.id=test_816, grinder.debug.singleprocess=false, grinder.agents=1, grinder.consolePort=12004, grinder.jvm.classpath= 중략... 2015-10-21 13:18:57,875 INFO agent daemon: jvm arguments -Djna.library.path=/root/.ngrinder_agent/file-store/half/current/lib -Dpython.path=/root/.ngrinder_agent/file-store/half/current/lib -Dpython.cachedir=/tmp/jython -Dngrinder.etc.hosts=Review-Node:127.0.0.1,localhost:127.0.0.1 -Dsun.net.spi.nameservice.provider.1=dns,LocalManagedDns -XX:MaxPermSize=512m -Xms3379m -Xmx3379m -XX:PermSize=128m -XX:MaxPermSize=128m 2015-10-21 13:18:57,877 INFO agent daemon: Worker process command line: java '-javaagent:/svc/tools/ngrinder-agent/lib/grinder-dcr-agent-3.9.1.jar' '-Djna.library.path=/root/.ngrinder_agent/file-store/half/current/lib' '-Dpython.path=/root/.ngrinder_agent/file-store/half/current/lib' '-Dpython.cachedir=/tmp/jython' '-Dngrinder.etc.hosts=Review-Node:127.0.0.1,localhost:127.0.0.1' '-Dsun.net.spi.nameservice.provider.1=dns,LocalManagedDns' '-XX:MaxPermSize=512m' '-Xms3379m' '-Xmx3379m' '-XX:PermSize=128m' '-XX:MaxPermSize=128m' -classpath '/svc/tools/ngrinder-agent/lib/ngrinder-runtime-3.3.jar:... 중략... net.grinder.engine.process.WorkerProcessEntryPoint 2015-10-21 13:18:57,881 INFO agent daemon: worker Review-Node-0 started 2015-10-21 13:19:01,205 INFO Review-Node-0: Starting threads ===> loginId : zztest101, chClass : 1, heroIndex : 101 ===> sessionKey : MTEwMTc3MDIsMTQ0NTQwMTE0Mg== ==> serverUrl : http://127.0.0.1/user_init_info ==> 부하 테스트 케이스 스크립트 수행 ==> serverUrl : http://127.0.0.1/user_init_info ==> serverUrl : http://127.0.0.1/user_game/daily_dungeon_seq ==> serverUrl : http://127.0.0.1/user_init_info ==> serverUrl : http://127.0.0.1/user_game/daily_dungeon_seq ==> serverUrl : http://127.0.0.1/user_init_info ==> serverUrl : http://127.0.0.1/user_game/daily_dungeon_seq ==> serverUrl : http://127.0.0.1/user_init_info ==> serverUrl : http://127.0.0.1/user_game/daily_dungeon_seq ==> serverUrl : http://127.0.0.1/user_init_info ==> serverUrl : http://127.0.0.1/user_game/daily_dungeon_seq 2015-10-21 13:19:04,185 INFO agent daemon: received a stop message 2015-10-21 13:19:04,186 INFO agent daemon: Don't start anymore by message from controller. 2015-10-21 13:19:04,189 INFO Review-Node-0: Waiting for threads to terminate ==> serverUrl : http://127.0.0.1/user_init_info 2015-10-21 13:19:04,371 INFO Review-Node-0: Finished 2015-10-21 13:19:04,750 INFO agent daemon: All workers are finished 2015-10-21 13:19:04,752 INFO agent daemon: communication shut down 2015-10-21 13:19:04,753 INFO agent daemon: Test shuts down. 2015-10-21 13:19:04,753 INFO agent controller: Send log for test_816 2015-10-21 13:19:04,754 INFO agent controller: Clean up the perftest logs =========== agent 의 로그 파일 ============ 2015-10-21 13:18:41,797 INFO agent controller : Received a start agent message 2015-10-21 13:18:41,797 INFO agent controller : Starting agent... for test_816 2015-10-21 13:18:41,798 INFO agent daemon : Agent daemon connecting to port 12004 is started. 2015-10-21 13:18:41,798 INFO agent controller : Agent is started. Waiting for agent controller signal 2015-10-21 13:18:41,798 INFO agent daemon : The Grinder 3.9.1 2015-10-21 13:18:41,800 INFO agent daemon : Connect to console at /61.43.45.160:12004 2015-10-21 13:18:41,801 INFO agent daemon : Waiting for console signal 2015-10-21 13:18:42,797 INFO agent daemon : Clearing file store 2015-10-21 13:18:42,800 INFO agent daemon : Updating file store: "TestRunner.groovy" (92115 bytes) 2015-10-21 13:18:47,824 INFO agent daemon : Updating file store: "lib/jc-ngrinder-common.jar" (639715 bytes) 2015-10-21 13:18:52,842 INFO agent daemon : Updating file store: "lib/log4j-1.2.9.jar" (352291 bytes) 2015-10-21 13:18:57,866 INFO agent daemon : received a start message 2015-10-21 13:18:57,873 INFO agent daemon : log file : /root/.ngrinder_agent/log/test_816/Review-Node-0.log 2015-10-21 13:18:57,875 INFO agent daemon : grinder properties {grinder.security=false, grinder.ignoreSampleCount=0, ..중략.. 2015-10-21 13:18:57,875 INFO agent daemon : jvm arguments -Djna.library.path=/root/.ngrinder_agent/file-store/half/current/lib .. 중략.. 2015-10-21 13:18:57,877 INFO agent daemon : Worker process command line: java '-javaagent:/svc/tools/ngrinder-agent/lib/grinder-dcr-agent-3.9.1.jar' .. 중략.. 2015-10-21 13:18:57,881 INFO agent daemon : worker Review-Node-0 started 2015-10-21 13:19:04,185 INFO agent daemon : received a stop message 2015-10-21 13:19:04,186 INFO agent daemon : Don't start anymore by message from controller. 2015-10-21 13:19:04,750 INFO agent daemon : All workers are finished 2015-10-21 13:19:04,752 INFO agent daemon : communication shut down 2015-10-21 13:19:04,753 INFO agent daemon : Test shuts down. 2015-10-21 13:19:04,753 INFO agent controller : Send log for test_816 2015-10-21 13:19:04,754 INFO agent controller : Clean up the perftest logs =========== 답변 주신 테스트의 파란 공의 메시지 내용 ============ Console is being prepared. Console is started on port 12004 1 agents are starting. 1 agents are ready. All necessary files are being distributed. The total size of distributed files is over 976.6KBB. - Safe file distribution mode is enabled by force. - TestRunner.groovy - lib/jc-ngrinder-common.jar - lib/log4j-1.2.9.jar All necessary files are distributed. The test is ready to start. The test is started. The test is successfully finished. ======= Review-Node-NONE-log.zip =========== java '-javaagent:/svc/tools/ngrinder-agent/lib/grinder-dcr-agent-3.9.1.jar' 중략 .. 2015-10-21 13:18:58,499 INFO The Grinder version 3.9.1 2015-10-21 13:18:58,506 INFO Java(TM) SE Runtime Environment 1.7.0_79-b15: Java HotSpot(TM) 64-Bit Server VM (24.79-b02, mixed mode) on Linux amd64 2.6.32-431.29.2.el6.x86_64 2015-10-21 13:18:58,512 INFO time zone is KST (+0900) 2015-10-21 13:18:58,660 INFO worker process 0 of agent number 0 2015-10-21 13:18:58,692 INFO Instrumentation agents: byte code transforming instrumenter for Java; byte code transforming instrumenter for Java 2015-10-21 13:19:01,116 INFO registered plug-in net.grinder.plugin.http.HTTPPlugin 2015-10-21 13:19:01,195 INFO before process. 2015-10-21 13:19:01,199 INFO Running "TestRunner.groovy" using GroovyScriptEngine running with groovy version: 2.2.1 2015-10-21 13:19:01,231 INFO before thread. 2015-10-21 13:19:01,231 INFO starting, will do 1 run 2015-10-21 13:19:01,231 INFO Start time is 1445401141230 ms since Epoch 2015-10-21 13:19:01,642 INFO http://127.0.0.1/user_session/on -> 200 OK, 90 bytes 2015-10-21 13:19:02,018 INFO http://127.0.0.1/user_init_info -> 200 OK, 5623 bytes 2015-10-21 13:19:02,303 INFO http://127.0.0.1/user_init_info -> 200 OK, 5623 bytes 2015-10-21 13:19:02,435 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:19:02,745 INFO http://127.0.0.1/user_init_info -> 200 OK, 5623 bytes 2015-10-21 13:19:02,868 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:19:03,149 INFO http://127.0.0.1/user_init_info -> 200 OK, 5623 bytes 2015-10-21 13:19:03,274 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:19:03,540 INFO http://127.0.0.1/user_init_info -> 200 OK, 5623 bytes 2015-10-21 13:19:03,663 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:19:03,919 INFO http://127.0.0.1/user_init_info -> 200 OK, 5623 bytes 2015-10-21 13:19:04,041 INFO http://127.0.0.1/user_game/daily_dungeon_seq -> 200 OK, 86 bytes 2015-10-21 13:19:04,189 INFO received a stop message 2015-10-21 13:19:04,335 INFO http://127.0.0.1/user_init_info -> 200 OK, 5623 bytes 2015-10-21 13:19:04,346 ERROR [PSW] Error occured : net.grinder.engine.process.ShutdownException: Thread has been shut down 2015-10-21 13:19:04,354 ERROR java.lang.AssertionError: at TestRunner.postSubmit(TestRunner.groovy:168) ~[na:na] at TestRunner.dailyDungeonSeq(TestRunner.groovy:312) ~[na:na] at TestRunner.testCase1(TestRunner.groovy:1889) ~[na:na] at TestRunner.this$2$testCase1(TestRunner.groovy) ~[na:na] at TestRunner$this$2$testCase1.callCurrent(Unknown Source) ~[na:na] at TestRunner.testCase(TestRunner.groovy:1432) ~[na:na] at net.grinder.scriptengine.groovy.junit.GrinderRunner.run(GrinderRunner.java:170) ~[ngrinder-groovy-3.3.jar:na] at net.grinder.scriptengine.groovy.GroovyScriptEngine$GroovyWorkerRunnable.run(GroovyScriptEngine.java:148) ~[ngrinder-groovy-3.3.jar:na] at net.grinder.engine.process.GrinderThread.run(GrinderThread.java:118) ~[grinder-core-3.9.1.jar:na] 2015-10-21 13:19:04,355 INFO finished 1 run 2015-10-21 13:19:04,359 INFO elapsed time is 3129 ms 2015-10-21 13:19:04,359 INFO Final statistics for this process: 2015-10-21 13:19:04,371 INFO Tests Errors Mean Test Test Time TPS Mean Response Response Mean time to Mean time to Mean time to Time (ms) Standard response bytes per errors resolve host establish first byte Deviation length second connection (ms) Test 1 12 1 217.83 83.74 3.84 2854.83 10948.55 0 85.00 130.00 216.33 "Test1" Totals 12 1 217.83 83.74 3.84 2854.83 10948.55 0 85.00 130.00 216.33 Tests resulting in error only contribute to the Errors column. Statistics for individual tests can be found in the data file, including (possibly incomplete) statistics for erroneous tests. Composite tests are marked with () and not included in the totals. |
Re: [nGrinder 3.3] agent log agent daemon: received a stop message
|
|
문제점을 찾지못하겠네요.
웹에서 생성한 테스트의 설정과 스크립트도 알려주실 수 있나요? |
«
Return to ngrinder-user-kr
|
1 view|%1 views
| Free forum by Nabble | Edit this page |