태그 글목록: java.util.concurrent.TimeoutException: Timed out(5000 milliseconds) waiting for operation while connected to 000.000.000.000:11211

[문제해결] MemcachedClient getClient Exception : java.lang.IllegalStateException: Shutdown in progress 2015-10-15

1. 문제상황

> (Was(Tomcat) * 2) + DB(Mysql)*2 + memcached*1 구성의 게임서버환경에서 서비스가 정지되어 버리는 현상이 발생하였다. 접속시간대 로그는 다음과 같이 Xmemcached가 멈췄다는 에러를 출력하고 있었다. 그리고 이상한건 WAS가 죽어있었다.

ERROR ({http-bio-80-exec-40} MemcachedConnection.java[getClient]:252) [2015-10-14 18:49:45,948] - ==> MemcachedClient getClient Exception : java.lang.IllegalStateException: Shutdown in progress
...
Exception : net.rubyeye.xmemcached.exception.MemcachedException: Xmemcached is stopped

급한대로 WAS를 시작하여 서비스를 재개하였다. 다음날 똑같은 피크타임에 다시 서비스가 정지 되었다. 로그에 보여지는 에러는 다음과 같이 어제와 달랐다.

Exception : net.rubyeye.xmemcached.exception.MemcachedException: There is no available connection at this moment
Exception : java.util.concurrent.TimeoutException: Timed out(5000 milliseconds) waiting for operation while connected to 000.000.000.000:11211

2. 문제확인

> 첫째날은 커넥션이 실패 하였고 둘째날은 가능한 커넥션이 없으며 타임아웃이 발생하였다. 다음과 같은 부분을 의심해 보았다.

* 부하가 몰리는 시간에 타임아웃이 발생한 것으로 보아 서버 1대로 충분하지 않다.
  ==> CBT 기간이었으므로 부족한건 무리가 있어보인다.
* 너무 무분별한 캐시로딩을 시도 했다.
  ==> for문에서 계속 캐시로딩을 시도한부분 발견
* 자바에서 사용하는 Xmemcached 버그이다. (구글링)
  ==> 첫날 WAS가 멈춘 것은 Xmemcached의 버그인것으로 보인다. 로그를 남기지 않았기에 정확하지는 않다.
* 사용자가 너무 몰려 Memcached에 설정된 MAX_CONNECTION을 넘었다.
  ==> 회원 1명당 친구가 최대 50인데 이것을 건건이 조회 했다면 넘을 수도 있다고 판단된다.

3. 문제해결

> 이러한 문제에 대하여 여러가지 대처 사항을 적용하였다.

* 가장 현명한 것은 무분별한 Call을 프로그램 상에서 막는 것으로 보인다.
* 프로그램 상에서 힘들다면 서버를 늘려 부하를 분산시킨다.
* 서버의 스팩을 고려하여 최대 접속 수를 늘려준다.
* 정확한 문제 파악을 위하여 memcached 로그 설정 옵션 (파일크기가 너무 커질 수 있음에 주의하자)
  ==> OPTIONS="-vv >> /var/log/memcached 2>&1"
* 피크타임때 MEMCACHED 상태를 수시로 확인한다. (다음 내용을 파일에 받아 tail로 확인)
  ==> /usr/bin/memcached-tool 127.0.0.1:11211 stats