nGrinder Controller 3.2.1 Test Stop 관련 문의

[jung youngseok]

안녕하세요. nGrinder 3.2.1을 사용하고 있는 사용자 입니다.

nGrinder 테스트 수행 중 중지가 되어 문의 드립니다.

nGrinder를 이용하여 12시간 안정성 테스트를 진행하는데 11시간 53분 쯤 진행되었을 때 Controller 로부터
Stop 메시지를 받고 테스트가 중지 되었습니다.

기존에는 12시간 스케줄 걸어놓으면 문제 없이 진행되었는데
어제 결과를 확인해보니 근본적인 원인을 찾기 어려운 로그만 남아 있어서 문의 드립니다.

== nGrinder Agent 로그 입니다. ==

2013-07-12 17:29:48,389 INFO  net.grinder.AgentDaemon  :  worker pclmq02-0 started
2013-07-12 17:29:48,399 INFO  net.grinder.AgentDaemon  :  worker pclmq02-1 started
2013-07-12 17:29:48,410 INFO  net.grinder.AgentDaemon  :  worker pclmq02-2 started
2013-07-12 17:29:48,421 INFO  net.grinder.AgentDaemon  :  worker pclmq02-3 started
2013-07-12 17:29:48,431 INFO  net.grinder.AgentDaemon  :  worker pclmq02-4 started
2013-07-13 05:23:33,326 INFO  net.grinder.AgentDaemon  :  received a stop message
2013-07-13 05:23:33,327 INFO  net.grinder.AgentDaemon  :  dont start anymore by message from controller.
2013-07-13 05:23:36,281 INFO  net.grinder.AgentDaemon  :  received a stop message
2013-07-13 05:23:39,292 INFO  net.grinder.AgentDaemon  :  received a stop message
2013-07-13 05:23:39,293 INFO  net.grinder.AgentDaemon  :  forcibly terminating unresponsive processes
2013-07-13 05:23:40,172 INFO  net.grinder.AgentDaemon  :  all workers are finished
2013-07-13 05:23:40,174 INFO  net.grinder.AgentDaemon  :  communication shut down
2013-07-13 05:23:40,175 INFO  net.grinder.AgentDaemon  :  finished
2013-07-13 05:23:40,175 INFO  agent controller  :  send log for test_2220

nGrinder Controller 로 부터 중지 명령을 받은것 같고....
----------------------------------------------------------------------------------------------
== nGrinder Controller Log ==
2013-07-12 17:26:05,742 INFO  AgentManager.java:393 :  1 agents are starting for user admin
2013-07-12 17:26:05,742 INFO  AgentManager.java:395 :  - Agent pclmq02
2013-07-12 17:29:47,965 INFO  SingleConsole.java:1285 :  Sampling is started
2013-07-13 05:23:32,668 ERROR PerfTestRunnable.java:476 :  Terminate 2220
2013-07-13 05:23:32,670 INFO  SingleConsole.java:1298 :  Sampling is stopped
2013-07-13 05:23:32,671 INFO  MonitorCollectorListener.java:92 :  remove monitors on [org.ngrinder.model.AgentInfo@2d4955fd[ip=192.168.254.80,port=13243,agentIdentity=<null>,hostName=,status=<null>,systemStat=<null>,region=<null>,number=0,approved=false,id=<null>], org.ngrinder.model.AgentInfo@29ac6c45[ip=192.168.254.85,port=13243,agentIdentity=<null>,hostName=,status=<null>,systemStat=<null>,region=<null>,number=0,approved=false,id=<null>], org.ngrinder.model.AgentInfo@76f83b62[ip=192.168.254.70,port=13243,agentIdentity=<null>,hostName=,status=<null>,systemStat=<null>,region=<null>,number=0,approved=false,id=<null>], org.ngrinder.model.AgentInfo@2302dbf3[ip=192.168.254.84,port=13243,agentIdentity=<null>,hostName=,status=<null>,systemStat=<null>,region=<null>,number=0,approved=false,id=<null>], org.ngrinder.model.AgentInfo@10b6407a[ip=192.168.254.71,port=13243,agentIdentity=<null>,hostName=,status=<null>,systemStat=<null>,region=<null>,number=0,approved=false,id=<null>], org.ngrinder.model.AgentInfo@2d431228[ip=192.168.254.75,port=13243,agentIdentity=<null>,hostName=,status=<null>,systemStat=<null>,region=<null>,number=0,approved=false,id=<null>], org.ngrinder.model.AgentInfo@e5d174f[ip=192.168.254.74,port=13243,agentIdentity=<null>,hostName=,status=<null>,systemStat=<null>,region=<null>,number=0,approved=false,id=<null>], org.ngrinder.model.AgentInfo@1a54ae7[ip=192.168.254.79,port=13243,agentIdentity=<null>,hostName=,status=<null>,systemStat=<null>,region=<null>,number=0,approved=false,id=<null>]]
2013-07-13 05:23:32,676 INFO  PerfTestService.java:1168 :  Total Statistics for test 2220  is {Peak_TPS=358.0, Tests=7002102.0, Mean_time_to_first_byte=299.88911715367755, Response_bytes_per_second=164345.97208171018, Errors=21.0, TPS=163.54833904155902, Mean_Test_Time_(ms)=1431.3526085452625}



2013-07-12 17:26:05,742 에 테스트를 시작하여
(250 Thread = 5 Process x 50 thread, 1 agent 환경)

2013-07-13 05:23:32,668 ERROR PerfTestRunnable.java:476 :  Terminate 2220
에러 출력 후 테스트가 중지된걸로 보입니다.  (7분 만 더 수행되면 12시간 완료)
결과 그래프를 봤을때 Too Low TPS 상황은 아닌것 같습니다.
nGrinder Controller 와 Agent 모두 CentOS5.8  jvm1.6  환경에서 동작 중 입니다.

위와 같은 문제 발생 시 테스트 환경상 처리 해줘야 할 것이 있는지 문의 드립니다.
감사합니다.

[junoyoon]

딱 두가지 상황이 의심스러운데요.

1. 네트웍 순간 장애로 인한, 에이전트 커넥션이 끊긴 것으로 판단..
    에이전트는 매초마다 heartbeat 를 서버로 보내는 데,  heatbeat가 4회 정도 이상 유실되면 에이전트가 disconnection 된것으로 판단하고, 테스트를 중단합니다.
    해당 시점에 다른 네트웍 문제로 인하여, 하트비트가 전달되지 않아 생긴 문제일 수 있습니다.

2. 에이전트의 메모리 사용량이 98% 을 초과.
   에이전트중 하나 이상이 메모리 사용량이 98%가 넘어가게 되면, 자동으로 중단합니다. 250 vuser 정도를 9시간 정도 돌리면 메모리 사용량에 따른 문제 발생 가능성이 없지는 않습니다. 메모리가 지속적으로 증가하는 현상은 저희도 이미 확인하고 있는데, 에이전트의 메모리 릭이 아닌 OS의 버그로 판단하고 있습니다.

위 두가지 상황 모두 테스트안에 있는 상태 "공"에 마우스를 올려 보면 상세 에러 메시지가 출력됩니다.

   

[jung youngseok]

답변 감사 드립니다.

말씀하신대로 빨간 풍선 위에 마우스를 올려보니 다음과 같은 에러 메시지가 있네요.
"[ERROR] agent is about to die due to lack of free memory"
그래서 Agent monitoring 상태를 보니 아래 처럼 16GB Full에 도달했습니다.
(Agent 사양 : 6 core CPU, 16GB MEM, CentOS 5.8)


다만 이상한점은 Physical memory는 아래와 같이 16GB에 도달하였으나 Cache 메모리가 7GB 있었으므로,
Free 메모리로 판단해서 얻어왔어야 할것 같은데.. 못 얻어온것 처럼 보이네요...

아래 이미지는 Cacti에서 테스트 시간대의 그래프를 발췌 하였습니다.



6개월 정도 nGrinder를 사용하면서 이런 문제를 경험하지 못했는데,
최근 nGrinder Controller 3.2.1 업그레드한 후 2번정도 경험한것 같습니다. (agent는 3.1.2 그대로 사용 중 입니다)

혹시 모르니, nGrinder Agent도 Controller와 버전을 맞춰서 해봐야 겠습니다.
감사합니다.

[junoyoon]

ngrinder 에이전트 과거 버전은 actually free(말씀하신 cache를 제외한) 가 아닌 free (cache로 할당된) 메모리를 메모리 계산에 사용합니다.

3.2.1 에이전트부터 actually free를 사용하여 현재 메모리 상태를 계산합니다.

따라서 에이전트를 업그레이드 하시면 되겠습니다.

[jung youngseok]

3.2.1로 Agent Upgrade 하고 약 4주 정도 지났는데,
아직은 같은 문제가 발생하지 않네요.

감사합니다.