Jun 4, 2018 - PINPOINT로 원인 분석

TCP 로 DB 문제 확인하기 - 3

SCOUTER 는 어플리케이션 성능 모니터링 툴로 오픈소스 APM 입니다. 해당 현상을 분석하기 위해 저번주에 계속 모니터링 한 경과 최종적으로 3가의 의심스러운 패턴을 찾을 수 있었는데,

  1. Protocol.read 시에 지연이 발생.
  2. DB에서 지연이 발생.
  3. 레디스의 데이러를 JSON Mapper 를 통해 객체를 할 때 지연이 발생.

SCOUTER 에서 지연되는 내역이 다음과 같이 나왔는데, 해당 현상에 대해서는 확신을 할 수없어, 또다른 APM 인 네이버 pinpoint로 분석하고자 했습니다.

설치하는 방법은 QuickStart를 참고했습니다.

예전에 서버에 바로 올렸다가, 1분마다 8기가의 데이터가 쌓이는 공포를 겪었기 때문에, 반영하는 모든 log4j.xml 의 DEBUG를 ERROR 로 변경하였습니다. 혹시 나중에 또 필요할 수 있어 간단하게 설정한 내역을 정리합니다.

JAVA 설치

vi /etc/profile

export JAVA_6_HOME=/usr/lib/jvm/java-1.6.0
export JAVA_7_HOME=/usr/lib/jvm/java-1.7.0
export JAVA_8_HOME=/usr/lib/jvm/java-1.8.0
export JAVA_9_HOME=/usr/lib/jvm/java-1.9.0

하단에 JAVA_6_HOME 및 추가된 jdk 경로 설정합니다. jdk 가 없을 시 download 하거나 yum install 로 설치합니다. 수정 후 꼭 ssh 재접속해야합니다. 실제로 가이드 문서에는 jdk 9 (JAVA_9_HOME) 을 넣으라는 글이 없었는데, 해당 버젼이 없으면, 에러가 나네요.

[INFO] -------------------------------------------------------------
[ERROR] COMPILATION ERROR : 
[INFO] -------------------------------------------------------------
[ERROR] javac: invalid target release: 9
Usage: javac <options> <source files>
use -help for a list of possible options

jdk9 가 없어 도중에 에러가 납니다.

[DEBUG] Goal:          org.apache.maven.plugins:maven-enforcer-plugin:1.4.1:enforce (enforce-pinpoint-build-requirements)
[DEBUG] Style:         Regular
[DEBUG] Configuration: <?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <fail default-value="true">true</fail>
  <failFast default-value="false">${enforcer.failFast}</failFast>
  <ignoreCache default-value="false">${enforcer.ignoreCache}</ignoreCache>
  <mojoExecution default-value="${mojoExecution}"/>
  <project default-value="${project}"/>
  <rules>
    <requireMavenVersion>
      <version>3.2</version>
    </requireMavenVersion>
    <requireJavaVersion>
      <version>1.7</version>
    </requireJavaVersion>
    <requireEnvironmentVariable>
      <variableName>JAVA_6_HOME</variableName>
    </requireEnvironmentVariable>
    <requireEnvironmentVariable>
      <variableName>JAVA_7_HOME</variableName>
    </requireEnvironmentVariable>
    <requireEnvironmentVariable>
      <variableName>JAVA_8_HOME</variableName>
    </requireEnvironmentVariable>
    <requireEnvironmentVariable>
      <variableName>JAVA_9_HOME</variableName>
    </requireEnvironmentVariable>
  </rules>
  <session default-value="${session}"/>
  <skip default-value="false">${enforcer.skip}</skip>
</configuration>
[DEBUG] -----------------------------------------------------------------------

JAVA_9_HOME 가 필수적으로 필요했는데, 해당 내용이 없어서, pom.xml 을 변경하려다가 그냥 jdk 9 를 설치해버렸습니다.

MAVEN 설치

http://maven.apache.org/download.cgi 에서 최신 maven 다운로드
설치 경로에서 tar xvf apache-maven-3.5.0-bin.tar.gz

MAVEN 홈페이지에 가서, maven 을 설치합니다. 저는 그냥 최신 버젼 설치했습니다. maven 로 yum install 로 설정하려고 했는데 기존 설치되어있는 거랑 뭔가 안맞아서, 강제로 환경설정을 셋팅했습니다.

# vi /etc/profile.d/maven.sh


#!/bin/bash
MAVEN_HOME=/설치경로/apache-maven-3.5.0 /usr/local/maven/bin/mvn
PATH=$MAVEN_HOME/bin:$PATH
export PATH MAVEN_HOME
export CLASSPATH=.

쉘스크립트 작성후, 해당 쉘스크립트에 실행권한을 부여했습니다.

# chmod +x /etc/profile.d/maven.sh
# source /etc/profile.d/maven.sh

설치여부 확인

[root@localhost apache-maven-3.5.3]# mvn -version
Apache Maven 3.5.3 (3383c37e1f9e9b3bc3df5050c29c8aff9f295297; 2018-02-25T04:49:05+09:00)
Maven home: /home/pinpoint/apache-maven-3.5.3
Java version: 1.8.0_161, vendor: Oracle Corporation
Java home: /usr/lib/jvm/java-1.8.0-openjdk-1.8.0.161-0.b14.el7_4.x86_64/jre
Default locale: ko_KR, platform encoding: UTF-8
OS name: "linux", version: "3.10.0-693.17.1.el7.x86_64", arch: "amd64", family: "unix"

GIT 설치


[root@localhost pinpoint]# git --version
git version 1.8.3.1
[root@localhost pinpoint]# java -version
openjdk version "1.8.0_161"
OpenJDK Runtime Environment (build 1.8.0_161-b14)
OpenJDK 64-Bit Server VM (build 25.161-b14, mixed mode)
[root@localhost pinpoint]# 

git 은 그냥 귀찮아서 yum install 로 설치했습니다.

설치 완료 후

./mvnw install -Dmaven.test.skip=true

해당 파일을 설치합니다.

저는 서버에 설치된 파일과, 클라이언트 서버가 틀리므로, quickstart 폴더의 agent 폴더를 다운받아, 클라이언트 서버에 해당 파일을 올립니다. 물론 log4j.xml 의 모든 내용은 DEBUG -> ERROR, INFO -> ERROR 로 바꿉니다.

./quickstart/lib/log4j.xml

해당 파일의 내용을 수정합니다. [QuickStart]에서 알려준 대로, 순서대로 실행합니다.

quickstart/bin/start-hbase.sh
quickstart/bin/init-hbase.sh
quickstart/bin/start-collector.sh
quickstart/bin/start-web.sh

http://host:28080 로 해당 web 페이지가 정상적으로 뜨는지 확인합니다.

결론

scouter 의 hook_method_patterns 로 분석하였던 내용과 비슷한 내용이 pinpoint 에도 나왔습니다.

레디스의 Json 형태의 String을 Json 라이브러리를 통해 객체화 하는 대서 200 (ms) 의 지연이 간혈적으로 발생.

Method Gap(ms) Class Api
toJSON(Object object, JsonConfig jsonConfig) 211 JSONSerializer JSON-LIB

mysql 의 excute 에서 미약한 지연 발생

Method Gap(ms) Class Api
execute() 139 PreparedStatement MYSQL(xxxx)

레디스에서 해당 데이터를 읽을 때 지연이 발생

Method Argument Gap(ms) Class Api
exists(String key) write: 0ms, read: 587ms 585 Jedis REDIS

위 3가지 항목으로 우선적으로 redis 서버를 증설 및 분리했습니다. 분리됨에 따라 레디스에서 해당 데이터를 읽을 때 지연이 발생하는 현상에 대한 해결은 어느정도 된 것으로 파악됩니다. 이제 Redis 에 해당 데이터를 write 할떄, Json 이 아니라 Object를 바이너리화하여 바로 넣고 사용하는 형태로 변경하는 작업을 진행하고자 합니다.

변경할 작업은 다음과 같습니다.

  1. JSONObject를 그냥 Object 로 바이너리로 레디스 저장.
  2. kakao 에 맞는 성능의 별도의 JSON-Lib 적용 참고 주소
  3. 레디스 및 ehcache 시간 및 기능 변경

참조


May 29, 2018 - SCOUTER 로 원인 분석

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 하는데 지연이 발생하는 부분은 확인이 필요하나, 실서버에서의 이슈를 계속 확인하기 위해 내버려둘 수 없어, 언발의 오줌누기 스킬을 써야할 거 같습니다.

May 28, 2018 - TCP 로 원인 분석

TCP 로 DB 문제 확인하기 - 1

서버가 튀는 순간 DB의 ESTABLISHED 상태를 점검하였다.

사용한 명령어

[WAS-03:root]/root>#netstat -tonp | grep '.250:3306'

db는 MariaDB 를 사용하고 있고, 현재 확인하는 것은 마스터 서버의 insert 구문으로 인한 TCP ESTABLISHED 상태였습니다. 치솟기(뒤기) 전에는 CLOSE_WAIT 가 24~27 정도를 유지하고 있다가, 튀기 바로 직전에 0~1로 변경됩니다. 치솟는 순간 250번 DB의 커넥션이 전부 ESTABLISHED 상태로 변경되는 것까지 눈으로 확인했습니다.

tcp      196      0 xx.xxx.x.x:54330            xxx.xxx.x.250:3306          ESTABLISHED 22388/java          keepalive (6587.96/0/0)
tcp        7      0 xx.xxx.x.x:38082            xxx.xxx.x.250:3306          ESTABLISHED 22388/java          keepalive (5745.34/0/0)
tcp        0      0 xx.xxx.x.x:50672            xxx.xxx.x.250:3306          ESTABLISHED 22388/java          keepalive (7039.22/0/0)
tcp        0      0 xx.xxx.x.x:50670            xxx.xxx.x.250:3306          ESTABLISHED 22388/java          keepalive (7039.17/0/0)
tcp        0      0 xx.xxx.x.x:50642            xxx.xxx.x.250:3306          ESTABLISHED 22388/java          keepalive (7038.88/0/0)
tcp        0      0 xx.xxx.x.x:51210            xxx.xxx.x.250:3306          ESTABLISHED 22388/java          keepalive (7043.51/0/0)
tcp        0      0 xx.xxx.x.x:50488            xxx.xxx.x.250:3306          ESTABLISHED 22388/java          keepalive (7037.79/0/0)
tcp        0     57 xx.xxx.x.x:38166            xxx.xxx.x.250:3306          ESTABLISHED 22388/java          on (0.19/0/0)
tcp        0      0 xx.xxx.x.x:50688            xxx.xxx.x.250:3306          ESTABLISHED 22388/java          keepalive (7039.35/0/0)
tcp        0     11 xx.xxx.x.x:57636            xxx.xxx.x.250:3306          ESTABLISHED 20882/java          on (0.20/0/0)
tcp        0    667 xx.xxx.x.x:56624            xxx.xxx.x.250:3306          ESTABLISHED 20882/java          on (0.19/0/0)
~~~~~ 중략 ~~~~~~~~~~

처음에는 ESTABLISHED 상태가 커넥션 풀 갯수만큼 차면서 당연히 db가 밀리거나 lock 이 걸릴 것으로 판단했으나, 실질적인 DBA는 db가 안정적이라고 하여, 혹시 네트워크 커넥션에 관련된 문제인지 확인하고자 하였습니다.

현재 DB는 3분마다 자동으로 커넥션이 끊도록 셋팅되어있다고 하였습니다.

사용한 명령어

해당 명령은 250 마스터 서버의 3306 포트를 1초 간격으로 숫자를 카운트 하는 명령어를 사용하여, 로그를 분석하고자 하였습니다.

```shell script [WAS-03:root]/root>#while true; do date; netstat -an | grep ‘.250:3306’ | grep ESTABLISHED | wc -l; sleep 1; done



      1. (월) 16:15:39 KST 88
      1. (월) 16:15:49 KST 99
      1. (월) 16:16:02 KST 88
      1. (월) 16:16:13 KST 88
      1. (월) 16:16:22 KST 99
      1. (월) 16:16:34 KST 97
      1. (월) 16:16:45 KST 89 ~~~~~ 중략 ~~~~~~~~~~ ```

실제 요청콜에 의해 99를 치다가, 88로 내려갔다 다시 치는 현상이 반복되었습니다.

실제 server.xml 에서, minimumIdle=”100”, maximumPoolSize=”100” 으로 되어있으며, 해당 셋팅을 한 이유는, minmunIdle 와 maximumPoolSize의 수를 같게 하여, 항상 커넥션을 유지하게 하기 위한 설정으로 알고 있습니다.

<Resource name="dreamdb" auth="Container"
     factory="com.zaxxer.hikari.HikariJNDIFactory"
     type="javax.sql.DataSource"
     minimumIdle="50"
     maximumPoolSize="50"
     maxLifetime="3600000"
     connectionTimeout="3000"
     dataSourceClassName="com.mysql.jdbc.jdbc2.optional.MysqlDataSource"
     dataSource.cachePrepStmts="true"
     dataSource.prepStmtCacheSize="250"
     dataSource.prepStmtCacheSqlLimit="2048"
     registerMbeans="true"
     poolName="dreamdb"
     dataSource.logger="com.mysql.jdbc.log.StandardLogger"
     dataSource.logSlowQueries="false"
     dataSource.dumpQueriesOnException="false"
     dataSource.user="xxxx"
     dataSource.password="xxxx"
     dataSource.url="jdbc:mysql://mpstdbm1:3306/xxxxx?autoReconnect=true"
     validationQuery="SELECT 1"
     validationInterval="240000"
     testWhileIdle="true" />

해당 설정값으론 SELECT 1을 계속 연결하여, 커넥션을 유지할 것으로 판단하였으나, 실제로는 3분간격으로 CLOSE WAIT 가 발생하는 것으로 보입니다.

원인은?

DB 쪽에서 강제적으로 3분 간격으로 커넥션을 끊는다고 합니다.

결론…

DB 쪽 이슈라고만 하기에는,

while true; do date; netstat -an | grep '.250:3306' | grep ESTABLISHED | wc -l; sleep 1; done

해당 명령어를 호출할 때 sleep 을 1초에 걸렸음에도 12~14초가 걸리도록 서버에 지연이 있는 상태였으므로, 전반적인 다른 부분을 파악해야하는 걸로 결론이 났습니다.


참조


문제를 분석하는데 많은 도움을 받았습니다.

[리눅스 서버의 TCP 네트워크 성능을 결정짓는 커널 파라미터 이야기 - 1편]을 통해 위의 설정으로 실제 tcp 메모리가 얼마만큼을 사용하는지 확인해봤습니다.

[WAS-03:root]/root>#sysctl net.ipv4.tcp_mem
net.ipv4.tcp_mem = 3067296	4089728	6134592

min / pressure / max 값을 지정할 수 있다고 하는데, 현재 우리 서버의 메모리는 32기가로 참고한 내용에 별 문제 없음을 확인할 수 있었습니다.

[WAS-03:root]/root>#sysctl fs.file-nr
fs.file-nr = 5984	0	3251359

세 값은 각각 현재 열려 있는 파일의 수, 현재 열려 있으나 사용되지 않는 파일의 수, 열 수 있는 파일의 최대 개수를 뜻합니다. 물론 시스템 전체에 대한 수치입니다. 라고 [리눅스 서버의 TCP 네트워크 성능을 결정짓는 커널 파라미터 이야기 - 2편]을 통해 알 수 있었습니다.

이것도 문제가 없습니다. 예전에 이미 Too many open files 에러로 인해 설정을 변경했던 겁니다!

[리눅스 서버의 TCP 네트워크 성능을 결정짓는 커널 파라미터 이야기 - 3편]에서 볼때,

[WAS-03:root]/root>#sysctl net.ipv4.tcp_max_tw_buckets
net.ipv4.tcp_max_tw_buckets = 262144

TIME_WAIT 상태의 소켓은 위 설정된 값 보다 많아질 수 없다고 합니다. 이미 이 설정값 만큼의 TIME_WAIT 상태의 소켓이 있다면, TIME_WAIT 상태로 전이되어야 할 소켓은 더이상 대기하지 않고 파괴(destroy)되어 버린다고 하네요. 이것도 문제가 없을 같습니다.

다음은 레디스에 대해 분석합니다.


참조