[nGrinder 3.3] agent log agent daemon: received a stop message

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

[nGrinder 3.3] agent log agent daemon: received a stop message

ihsong
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
Reply | Threaded
Open this post in threaded view
|

Re: [nGrinder 3.3] agent log agent daemon: received a stop message

Gisoo.Gwon
agent의 로그는 정상적인 상태입니다.
웹 서버에서 어떠한 이유로 agent에게 테스트 중지 명령을 보낸 것 같은데요.

ngrinder 웹에 접속하셔서 해당 테스트의 파란공(or 빨간공)에 마우스를 올려보시면 팝업이 나와요.
그 메세지를 한번 확인해주세요.
Reply | Threaded
Open this post in threaded view
|

Re: [nGrinder 3.3] agent log agent daemon: received a stop message

ihsong
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.                      



Reply | Threaded
Open this post in threaded view
|

Re: [nGrinder 3.3] agent log agent daemon: received a stop message

Gisoo.Gwon
문제점을 찾지못하겠네요.
웹에서 생성한 테스트의 설정과 스크립트도 알려주실 수 있나요?