애플리케이션

스택

와탭은 10초(기본값) 간격으로 수집한 Thread Stack을 활용하여 메소드 레벨의 성능 지연 구간을 분석합니다.

Java와 Python 애플리케이션에서 스택 분석 기능을 사용할 수 있습니다.

st1
Figure 1. 액티브 스택

위 스택에서 탑 라인은 socketRead0입니다.

java.net.SocketInputStream.socketRead0(Native Method)
TOP STACK이란?

스택에서 탑 라인은 덤프를 수행할 스레드가 해당 메소드를 수행 중이라는 것을 의미합니다. 순간적으로 잡혔을 가능성도 있지만 확률적으로 해당 모듈의 처리시간의 합의 비율만큼 스택에 나타날 것입니다. 그래서 이 탑 라인 메소드의 빈도를 계산함으로써 메소드 레벨의 성능을 판단할 수 있습니다. 이 탑 라인의 빈도 통계를 와탭은 TOP STACK이라고 합니다.

Screenshot 2020 12 15 W JAVA DEMO 5490   Application Monitoring23
Figure 2. 스택의 탑 라인

TOP STACK 분석을 통해 도출된 메소드는 어떤 메소드가 호출했는지에 대한 빈도를 분석할 수 있습니다.

Screenshot 2020 12 15 W JAVA DEMO 5490   Application Monitoring24

TOP STACK의 계층 분석에서는 원래 액티브 스택을 확인하기 어려웠습니다. 따라서 Active Stack를 조회할 수 있도록 동일 스택을 모아서 Unique Stack이라는 조회 기능을 제공합니다.

탑 스택

Stack Trace 상의 각 Step 기준으로, Step과 Step 간의 호출 비율을 백분율로 분석한 정보를 제공합니다. 최상위 Step의 적체 빈도를 백분율로 산출하여 내림차순으로 정렬한 결과를 제시합니다.

각 Step을 클릭하면 해당 Step을 호출하는 상위 Step을 호출 빈도 기준 백분율로 산출하여 제공합니다.

Top 스택 통계는 충분히 많은 데이터를 가지고 판단하는 것이 좋습니다.
수집한 스택의 개수가 소수(10개 미만)인 경우 통계 의미를 갖기에 부족합니다.

Top 스택은 튜닝 시 인지하기 힘들었던 부분의 튜닝 포인트를 찾아내는데 유용합니다. 가장 빈번하게 나타난 스택은 현재 애플리케이션 서버에서 가장 많은 응답 지연을 발생하는 것이라고 판단할 수 있습니다. 가장 왼쪽의 나타나는 비율은 애플리케이션 서버 성능에 영향을 미치는 정도라고 할 수 있습니다.

안정적인 애플리케이션 서버일지라도 빈번하게 나타난 스택은 성능 저하를 일으킬 수 있는 가능성이 있으므로 해당 클래스는 유심히 보는 것이 좋습니다.

Top 스택 클릭 시 해당 최상위 스택에 대한 호출 빈도를 확인할 수 있습니다. Top 스택의 호출 관계는 1 대 1 관계이므로 depthTop 스택이 밑으로 내려갈수록 정보의 정확성이 떨어질 수 있습니다. 하위 depth에 대한 정보는 참고 용도로 사용하며 튜닝을 진행하시기 바랍니다.

애플리케이션 성능 개선을 위해 최상위 Step의 적체 비율이 높은 모듈의 병목 가능성을 검토해야 합니다. 적체 비율이 높은 모듈의 경우 작은 성능 개선도 애플리케이션 전체에 상당한 개선 효과를 가져올 수 있습니다.

Screenshot 2020 12 15 W JAVA DEMO 5490   Application Monitoring25
 whatap.util.ThreadUtil.sleep <- jdbc.Control.exec의 호출 비율은 87.10%
 jdbc.Control.exec <- jdbc.FakePreparedStatement.executeQuery의 호출 비율은 61.18%

whatap.util.ThreadUtil.sleep ← jdbc.Control.exec ← jdbc.FakePreparedStatement.executeQuery의 호출 비율이 87.10% * 61.18%를 의미하지는 않음.
(jdbc.Control.exec에서 타 모듈의 호출 가능성이 존재하기 때문)

Top Stack을 통해 호출 비율을 판단할 경우, 각 Step 간 호출 비율을 곱하여 전체 호출 관계 비율을 산출해서는 안 됩니다. Top Stack의 호출 비율은 Stack Trace 상에 노출된 정보의 Step 간 호출 비율의 산출 결과이기 때문에, Step 간 호출 비율로 전체 호출 비율을 도출할 경우 왜곡된 결과를 도출하게 됩니다.

탑 스택 통계에서는 일정 기간을 기준으로 시간에 따른 비율 변화와 수집 건수에 대한 히스토리를 제공합니다.

Screenshot 2020 12 15 W JAVA DEMO 5490   Application Monitoring27
퍼센트

조회 기간 선택된 탑 스택의 비율 변화를 나타냅니다.
장애 시점 현황 파악, 개선 전/후 비교에 유용하게 사용됩니다.

건수

수집되는 스택의 수는 액티브 트랜잭션 수에 비례합니다.
특정 구간에서 수집량이 증가했다면 서비스 지연이나 급격한 유입량 증가가 있었음을 알 수 있습니다.

다음과 같은 다이어그램으로도 확인이 가능합니다.

Screenshot 2020 12 15 W JAVA DEMO 5490   Application Monitoring26
Stack Chart

개별 탑 스택의 비율을 차트로 나타냅니다.

유니크 스택

Stack Trace 전체의 Hash 값 기준의 산출 결과로 전체 Step이 동일한 호출 비율을 백분율로 분석한 정보를 제공합니다. Top Stack은 Step 간의 호출 비율에 대한 정보를 제공합니다. 반면, Unique Stack은 Stack Trace 전체의 정확한 호출 정보를 기반으로 한 데이터를 제공합니다. 상세 호출 관계를 파악하는 데 유용한 정보를 제공합니다.

적체 비율이 높은 Stack Trace를 식별할 수 있습니다.

상세 호출 Step 검토를 통한 호출 경로 상에 이상 모듈의 존재 여부를 파악할 수 있습니다.

Screenshot 2020 12 15 W JAVA DEMO 5490   Application Monitoring27 Y8LaYJq

액티브 스택

진행 중인 트랜잭션을 액티브 트랜잭션이라고 합니다. 액티브 트랜잭션에서 정기적으로 덤프한 스택을 액티브 스택이라 합니다.

와탭 에이전트는 매 10초(옵션 가능)마다 액티브 트랜잭션에 대해서 액티브 스택을 덤프하고 이것을 서버에 전송합니다. (active_stack_second=10)

액티브 스택 메뉴를 선택하면 수집된 ActiveStack을 차트로 확인할 수 있습니다. 차트는 5분간의 단위 통계 데이터를 Active Transaction의 수를 막대로, TPS를 꺾은 선으로 표시합니다.

Screenshot 2020 12 15 W JAVA DEMO 5490   Application Monitoring28

막대를 클릭하면, 클릭한 시간대의 Active Transaction의 정보가 나오며, 그 정보를 클릭하면 해당 Transaction의 ActiveStack을 볼 수 있습니다.

Screenshot 2020 12 15 W JAVA DEMO 5490   Application Monitoring29

컴팩트한 액티브 스택 수집

액티브 스택은 스레드 덤프를 정기적으로 수행하기 때문에 잘못 구현되면 에이전트에 오버헤드가 커질 수 있습니다. 와탭은 에이전트 부하를 최소화하면서 액티브 스택을 수집하기 위해 다양한 옵션들을 가지고 있습니다.

서버 > 더보기 > 스레드 목록/덤프 메뉴에서 스레드 목록 중에 "WhaTap-ActiveStackDump" 스레드의 CPU Time을 확인하면 오버헤드를 판단할 수 있습니다.
액티브 스택의 예
java.lang.StringBuffer.append(StringBuffer.java:309)
java.util.regex.Matcher.appendReplacement(Matcher.java:839)
java.util.regex.Matcher.replaceAll(Matcher.java:906)
java.lang.String.replaceAll(String.java:2162)
core.log.triggers.TriggerRegister.changeNotify(TriggerRegister.java:114)
core.log.aop.handler.DaoInfo.log(DaoInfo.java:141)
core.log.aop.handler.DaoInfo.doAround(DaoInfo.java:102)
core.log.aop.reflection.profiler.AroundProfiler.invoke(AroundProfiler.java:19)
com.sun.proxy.$Proxy39.getUpdateCount(Unknown Source)
org.apache.ibatis.executor.resultset.DefaultResultSetHandler.getNextResultSet(DefaultResultSetHandler.java:256)
org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSets(DefaultResultSetHandler.java:193)
org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:64)

* * *

sun.reflect.GeneratedMethodAccessor140.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:606)
org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:221)
org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:136)
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:114)
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
최적화된 데이터 수집
  • 트랜잭션을 수행 중인 스레드에 대해서만 스택을 덤프합니다.

  • 액티브 스택 덤프 시간 간격을 조정할 수 있습니다. (active_stack_second=10)

  • 액티브 스택의 최대 라인에 제한되어 있습니다. Top 라인에서부터 기본 50라인을 수집합니다. (trace_active_callstack_depth=50)

  • 액티브 스택의 각 라인은 해쉬 처리되어 수집됩니다.(text는 한 번만)

  • 한 타임에 수집되는 최대 액티브 스택 개수도 제한되어 있습니다.(active_stack_count=100)

Background Thread에 대한 액티브 스택

@since v1.6.2
기본적으로 액티브 스택은 트랜잭션이 수행되고 있는 스레드의 스택을 말합니다. 하지만 일부 백그라운드 스레드에 대해서도 스택을 분석할 필요가 있을 수 있습니다. 이때 옵션을 통해서 백그라운드 스레드에 대한 액티브 스택을 확보할 수 있습니다.

async_stack_enabled=false

async_stack_enabled를 true로 설정하면 활성화됩니다.

active_stack_second=10

스택 덤프 간격은 포그라운드 액티브 스택 설정에 따라갑니다.

async_thread_match=http*,abc*

대상 스레드 이름을 지정할 때는 '*' 사용하여 문자열 패턴을 지정합니다.

스레드 이름으로 스택 덤프 대상을 식별합니다. ","를 사용하여 match를 여러 개를 지정할 수 있습니다.
async_thread_parking_class=sun.misc.Unsafe
async_thread_parking_method=park

스택의 Top 메소드가 async_thread_parking에 등록된 클래스/메소드일때 스레드가 파킹 상태에 있다고 판단하고 덤프를 생성하지 않습니다.

활용 예시

스택 - 탑스택 메뉴에서 특정 시간대 내역을 조회한 예입니다.
프로파일이나 트랜잭션 통계정보로는 알 수 없는 다양한 개선 포인트를 찾을 수 있습니다.

스택 - 탑스택 메뉴에서 탑스택 정보를 조회합니다.

Screenshot 2020 12 15 W JAVA DEMO 5490   Application Monitoring31
Figure 3. 스택 - 탑스택

점유율 순서대로 상위 항목부터 Class/Method 정보를 확인합니다.

최상위 79.92% 비율을 차지하는 탑스택은 org.apache.logging.log4j.core.layout.TextEncoderHelper.copyDataToDestination() 메소드입니다. (1)
두 번째로 높은 8.01% 비율을 차지하는 탑스택은 sun.misc.Unsafe.park() 메소드입니다. (2)

히스토리 기능으로 시간대 별 추이를 확인할 수 있습니다.

Screenshot 2020 12 15 W JAVA DEMO 5490   Application Monitoring30
Figure 4. 스택 - 탑스택 - 히스토리
06:00 시 경 TextEncoderHelper.copyDataToDestination() 비율이 감소한 것이 확인됩니다.
동 시간대 sun.misc.Unsafe.park는 감소된 TextEncoderHelper.copyDataToDestination() 비율만큼 증가했습니다.

상위 1,2 탑스택은 모두 Logging과 관련되어 있습니다. 즉, 이 시스템은 전체 업무에서 90% 가까운 수행 시간을 Logging에 소비하고 있는 것이 확인됩니다.

확인한 점유율을 바탕으로 개선 기대효과를 산정합니다.

개선 기대효과 산정

사례 중 copyDataToDestination() 79.92%, sun.misc.Unsafe.park() 8.01% 비율은 서비스 수행 중 점유된 시간 비율입니다.
즉, copyDataToDestination() 점유율을 반으로 낮춘다면 응답속도 기준으로 44%가량 성능이 개선된다고 기대할 수 있습니다.

탑스택 정보를 토대로 개선 방안을 검토합니다.

org.apache.logging.log4j.core.layout.TextEncoderHelper.copyDataToDestination()
private static void copyDataToDestination(final ByteBuffer temp, final ByteBufferDestination destination) {
        synchronized (destination) {
            ByteBuffer destinationBuffer = destination.getByteBuffer();
            if (destinationBuffer != temp) { // still need to write to the destination
                temp.flip();
                if (temp.remaining() > destinationBuffer.remaining()) {
                    destinationBuffer = destination.drain(destinationBuffer);
                }
                destinationBuffer.put(temp);
                temp.clear();
            }
        }
    }
1 TextEncoderHelper는 성능 문제를 비롯한 여러 가지 이유로 Deprecated 된 API입니다.
2 sun.misc.Unsafe.park()은 TextEncoderHelper 내부의 synchronized와 관련 있습니다.

트랜잭션

와탭 에이전트는 트랜잭션 정보, SQL과 같은 주요 프로파일 정보에 대해 통계정보를 수집합니다. 5분마다 목록을 만들고 서버로 전송합니다.

통계

트랜잭션 통계를 수집합니다. 5분마다 최대 5,000개의 URL 별 수행 통계를 수집하여 서버에 전송합니다. 만약 서로 다른 URL의 수가 5분 동안 5,000개가 넘으면 무시됩니다.

칼럼 설명 타입

hash

URL 해쉬

u4

count

건수

u4

error

에러건수

u4

time_sum

응답시간의 합

u8

time_max

최대 응답시간

u4

sql_count

SQL 수행 건수

u4

sql_time

SQL수행시간의 합

u8

sql_fetch

SQL 패치 건수

u4

sql_fetch_time

SQL 패치 시간의 합

u8

httpc_count

HTTP Call건수

u4

httpc_time

HTTP Call 시간의 합

u8

malloc_sum

메모리 사용량 SUM

u8

cpu_sum

CPU사용량 SUM

u8

malloc_sum은 trace_malloc_enabled=true로 변경해야 수집됩니다.(default: false)

SQL 수행 통계

5분 동안의 SQL 수행 통계를 수집합니다. 5분 동안 서로 다른 SQL 문장이 최대 5,000까지만 허용됩니다. 만약 하나의 Java 프로세스에서 한계를 넘는 SQL이 발생하면 통계 데이터에서는 버려집니다.

칼럼 설명 타입

dbc

DB연결 정보의 Hash

u4

sql

SQL문 Hash

u4

count_total

수행 건수

u4

count_error

에러건수

u4

time_sum

응답시간의 합

u8

time_max

최대 응답시간

u4

fetch_count

패치 건수

u4

fetch_time

패치 시간의 합

u8

service

SQL을 수행한 service중에 하나

u4

service(URL) hash는 5분 동안 해당 SQL을 호출한 URL 중 하나(마지막 호출 URL)를 분석 활용을 위해 수집합니다.

HTTPCall 수행 통계

5분 동안의 Http Call 수행 통계를 수집합니다. 5분 동안 서로 다른 Http Call 문장이 최대 5,000까지만 허용됩니다. 만약 하나의 node.js 프로세스에서 한계를 넘는 외부 Http Call이 발생하면 통계 데이터에서는 버려집니다.

칼럼 설명 타입

url

타겟 URL hash

u4

host

Host or ip

u4

port

Tcp Port

u4

count_total

수행 건수

u4

count_error

에러건수

u4

time_sum

응답시간의 합

u8

time_max

최대 응답시간

u4

service

Http Call을 수행한 service 중에 하나

u4

에러 통계

5분 동안 발생한 서비스 에러에 대한 통계입니다. 서로 다른 에러 + 트랜잭션 이름을 키로 발생 건수를 수집합니다. 5분 당 최대 1,000 가지 서로 다른 에러를 통계화합니다.

칼럼 설명 타입

classHash

에러 클래스

u4

service

트랜잭션 HASH

u4

snapSeq

스택 정보

u8

msg

메세지 hash

u4

count

발생 건수

u4

IP 별 호출 건수

IP 별로 호출한 트랜잭션 건수를 통계적으로 수집합니다. 5분 당 수집 가능한 서로 다른 IP 수는 인스턴스 당 최대 70,000개입니다.

칼럼 설명 타입

ip

ip 주소

u4

count

건수

u4

UserAgent 별 호출 건수

User Agnet 문자열의 Hash 별로 호출 건수를 수집합니다. 5분 당 수집 가능한 서로 다른 UserAgent Hash는 인스턴스 당 최대 500개입니다.

칼럼 설명 타입

hash

hash

u4

count

건수

u4

트랜잭션 Caller 통계

멀티 서버가 rest 호출로 연결된 경우 Caller와 Callee 간의 연관 통계를 수집할 수 있습니다. 이 데이터를 수집하기 위해서는 다음의 옵션을 설정해야 합니다.

whatap.conf
mtrace_rate=100
mtrace_spec=v1
stat_mtrace_enabled=true
msa
Figure 5. MSA 시스템

위와 같은 아키텍처에서 caller&callee 통계는 api1 api2에서만 조회할 수 있습니다. 사용자 브라우저에서 호출되는 시스템에서는 Caller 통계를 조회할 수 없습니다.

하지만 Caller 쪽 서버에서 데이터를 전송해야 하기 때문에 모든 서버에 적절한 설정이 들어가야 합니다.

whatap.conf of [front]
mtrace_rate=100
mtrace_spec=v1
stat_mtrace_enabled=true
whatap.conf of [api1] & [api2]
mtrace_spec=v1
stat_mtrace_enabled=true

수집되는 통계 데이터는 다음과 같습니다. Callee 쪽에서 조회되어야 합니다.

칼럼 설명 타입

caller_pcode

Caller의 프로젝트(와탭) 코드

u8

caller_spec

Caller의 버전 문자열 hash

u4

caller_url

Caller의 URL hash

u4

spec

Callee의 버전 문자열 hash

u4

url

Callee URL hash

u4

count

수행 건수

u4

error

에러 건수

u4

time

응답시간의 합

u8

트랜잭션 도메인 통계

와탭 에이전트는 도메인별 트랜잭션 통계를 수집할 수 있습니다. 하나의 서버에 여러 개의 도메인을 분리하여 서비스하는 시스템에서는 도메인 별 분석이 필요할 수 있습니다.

whatap.conf
stat_domain_enabled=true

수집되는 데이터는 도메인별 URL의 처리 현황을 파악할 수 있습니다.

칼럼 설명 타입

domain

서비스 도메인 hash

u4

url

트랜잭션 URL hash

u4

count

수행 건수

u4

error

에러 건수

u4

time

응답시간의 합

u8

트랜잭션 REFERER 통계

와탭 에이전트는 Referer 별 트랜잭션 통계를 수집할 수 있습니다.

whatap.conf
stat_referer_enabled=true

수집되는 데이터는 Referer 정보를 통계로 확인할 수 있습니다.

칼럼 설명 타입

referer

Referer hash

u4

url

트랜잭션 URL hash

u4

count

수행 건수

u4

error

에러 건수

u4

time

응답시간의 합

u8