Jun 4, 2018 - PINPOINT quickstart 설치시 유의했던 점

외부 인터넷이 막혀있는 환경

해당 서버에는 내부 IP는 허용하나 외부 IP를 차단한 경우로,
quickstart의 s tart-collector,
start-web,
start-testapp 스크립트 모두 mvnw를 통해 실행되도록 되어 있어,
mvn 실행하도록 수정해서 처리해합니다.

start-collector.sh 예)

pid=`nohup ${bin}/../../mvnw -f $COLLECTOR_DIR/pom.xml clean package tomcat7:run -D$IDENTIFIER -Dmaven.pinpoint.version=$version > $LOGS_DIR/$LOG_FILE 2>&1 & echo $!`
->
pid=`nohup mvn -f $COLLECTOR_DIR/pom.xml clean package tomcat7:run -D$IDENTIFIER -Dmaven.pinpoint.version=$version > $LOGS_DIR/$LOG_FILE 2>&1 & echo $!`

log4j LOG 수정

quickstart 시 생성되는 모든 log4j.xml 은 debug 옵션으로 보여지게 되어있습니다.
그걸 그대로 agent 및 서버에서 동작시키면, 1분에 8기가의 데이터가 쌓이는 아주 놀라운 경험을 할수 있었습니다.
해당 옵션을 자신의 상황에 맞게 수정하시면 됩니다.
저는 단순한 지연현상을 찾기 위해서, DEBUG > ERROR, INFO > ERROR 로 변경하였습니다.

./agent/lib/log4j.xml
./web/src/main/resources/log4j.xml

형태의 모든 xml 을 수정 했습니다.
혹시 몰라 logs 폴더 또한 /data/ 폴더로 심볼릭 링크를 걸었습니다.

./quickstart/hbase/hbase/logs
./quickstart/logs

추가적으로 필요하면 hbase 에 대한 data 용량도 확인하는 것이 좋을 거 같습니다.

./quickstart/data

테스트 시 특정 서버의 경우 하루에 5G까지 쌓이는 경우를 봐서, 초기화 관련된 부분도 고민해봐야할 거 같습니다.
우선은 scouter를 대체하는 용도는 아니었기 때문에, 여기까지만 정의했습니다.

jdk 버젼 추가

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

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

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