TCP 로 DB 문제 확인하기 - 2
서버가 튀는 순간 SCOUTER 를 사용하여, 해당 클래스의 위치를 찾습니다.
hook_method_patterns 를 참고하여 찾습니다.
hook_method_patterns=net.sf.ehcache.*.*,redis.clients.jedis.*.*
redis와 ehcache 문제로 접근하고자 해당 클래스와 그 클래스의 모든 클래스를 찾도록 했습니다. 위와같은 명령을 날렸을 때 다음과 같은 메시지가 출력되었습니다.
- [000227] 20:42:33.042 0 0 JedisCluster#exists() [293ms] -- redis.clients.jedis.JedisCluster.exists(Ljava/lang/String;)Ljava/lang/Boolean;
[000227] [000228] 20:42:33.042 0 0 JedisClusterCommand#run() [293ms] -- redis.clients.jedis.JedisClusterCommand.run(Ljava/lang/String;)Ljava/lang/Object;
[000228] [000229] 20:42:33.042 0 0 JedisFactory#activateObject() [0ms] -- redis.clients.jedis.JedisFactory.activateObject(Lorg/apache/commons/pool2/PooledObject;)V
[000228] [000230] 20:42:33.042 0 0 JedisCluster$4#execute() [293ms] -- redis.clients.jedis.JedisCluster$4.execute(Lredis/clients/jedis/Jedis;)Ljava/lang/Object;
[000230] [000231] 20:42:33.042 0 0 JedisCluster$4#execute() [293ms] -- redis.clients.jedis.JedisCluster$4.execute(Lredis/clients/jedis/Jedis;)Ljava/lang/Boolean;
[000231] [000232] 20:42:33.042 0 0 Jedis#exists() [293ms] -- redis.clients.jedis.Jedis.exists(Ljava/lang/String;)Ljava/lang/Boolean;
[000232] [000233] 20:42:33.042 0 0 BinaryClient#isInMulti() [0ms] -- redis.clients.jedis.BinaryClient.isInMulti()Z
[000232] [000234] 20:42:33.042 0 0 Client#exists() [0ms] -- redis.clients.jedis.Client.exists(Ljava/lang/String;)V
[000234] [000235] 20:42:33.042 0 0 BinaryClient#exists() [0ms] -- redis.clients.jedis.BinaryClient.exists([[B)V
[000235] [000236] 20:42:33.042 0 0 BinaryClient#connect() [0ms] -- redis.clients.jedis.BinaryClient.connect()V
[000236] [000237] 20:42:33.042 0 0 Connection#isConnected() [0ms] -- redis.clients.jedis.Connection.isConnected()Z
[000235] [000238] 20:42:33.042 0 0 Protocol#sendCommand() [0ms] -- redis.clients.jedis.Protocol.sendCommand(Lredis/clients/util/RedisOutputStream;Lredis/clients/jedis/Protocol$Command;[[B)V
[000232] [000239] 20:42:33.043 1 0 Protocol#read() [292ms] -- redis.clients.jedis.Protocol.read(Lredis/clients/util/RedisInputStream;)Ljava/lang/Object;
[000228] [000240] 20:42:33.335 292 0 Jedis#close() [0ms] -- redis.clients.jedis.Jedis.close()V
~~~~~~~~~~~~~~~~~~ 중략
- [000253] 20:42:33.568 232 0 Cache#put() [0ms] -- net.sf.ehcache.Cache.put(Lnet/sf/ehcache/Element;)V
ehcache의 경우 T-GAP이 발생했으나, 실질적인 ehcahe 는 0ms 이므로, 그 앞단의 뭔가가 지연이 된 것으로 보이며, 우선은 바로 나온 redis 에 대해 확인하고자 했습니다. 결국 ehcache 보다 jedis에 지연이 되는 건이 많은 것을 확인하고, 해당 내용을 조금더 상세하게 확인하고자 호출을 변경하였습니다. RedisInputStream 의 read 를 사용하는 부분을 보기 위해 Java의 io 쪽까지 포함한 hook_method를 셋팅했습니다.
hook_method_patterns=java.io.InputStream.*,redis.clients.util.RedisInputStream.*,redis.clients.util.RedisOutputStream.*,java.io.OutputStream.*
해당 메소드를 체크했을 때 결과적으로 다음과 같은 지연이 발생했습니다.
- [000017] 11:32:33.820 0 0 RedisInputStream#readByte() [220ms] -- redis.clients.util.RedisInputStream.readByte()B
- [000018] 11:32:34.040 220 0 RedisInputStream#readLongCrLf() [0ms] -- redis.clients.util.RedisInputStream.readLongCrLf()J
혹시 몰라 java.io.InputStream.* 를 적용했으나 상속받은 RedisInputStream Method 만 scouter xLog에 나왔습니다. RedisOutputStream 은 빠르나, read 발생할때 지연되는 것을 확인할 수 있었습니다.
결론
불필요한 레디스 삭제 및, 클러스터 서버 추가, 레디스 사용을 최소화할 방안 고민으로 결론이 났습니다. 실제로, 레디스는 대부분을 GET, SET 을 json 형태로 저장하는 용도로만 사용하고 있으며, 해당 HGET Key field 는 (Time complexity: O(1)) 로 복잡도 자체가 1:1 인데, read 하는데 지연이 발생하는 부분은 확인이 필요하나, 실서버에서의 이슈를 계속 확인하기 위해 내버려둘 수 없어, 언발의 오줌누기 스킬을 써야할 거 같습니다.