애플리케이션
스택
와탭은 10초(기본값) 간격으로 수집한 Thread Stack을 활용하여 메소드 레벨의 성능 지연 구간을 분석합니다.
Java와 Python 애플리케이션에서 스택 분석 기능을 사용할 수 있습니다.
위 스택에서 탑 라인은 socketRead0입니다.
java.net.SocketInputStream.socketRead0(Native Method)
TOP STACK 분석을 통해 도출된 메소드는 어떤 메소드가 호출했는지에 대한 빈도를 분석할 수 있습니다.
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의 적체 비율이 높은 모듈의 병목 가능성을 검토해야 합니다. 적체 비율이 높은 모듈의 경우 작은 성능 개선도 애플리케이션 전체에 상당한 개선 효과를 가져올 수 있습니다.
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 간 호출 비율로 전체 호출 비율을 도출할 경우 왜곡된 결과를 도출하게 됩니다. |
탑 스택 통계에서는 일정 기간을 기준으로 시간에 따른 비율 변화와 수집 건수에 대한 히스토리를 제공합니다.
- 퍼센트
-
조회 기간 선택된 탑 스택의 비율 변화를 나타냅니다.
장애 시점 현황 파악, 개선 전/후 비교에 유용하게 사용됩니다. - 건수
-
수집되는 스택의 수는 액티브 트랜잭션 수에 비례합니다.
특정 구간에서 수집량이 증가했다면 서비스 지연이나 급격한 유입량 증가가 있었음을 알 수 있습니다.
다음과 같은 다이어그램으로도 확인이 가능합니다.
- Stack Chart
-
개별 탑 스택의 비율을 차트로 나타냅니다.
유니크 스택
Stack Trace 전체의 Hash 값 기준의 산출 결과로 전체 Step이 동일한 호출 비율을 백분율로 분석한 정보를 제공합니다. Top Stack은 Step 간의 호출 비율에 대한 정보를 제공합니다. 반면, Unique Stack은 Stack Trace 전체의 정확한 호출 정보를 기반으로 한 데이터를 제공합니다. 상세 호출 관계를 파악하는 데 유용한 정보를 제공합니다.
| 적체 비율이 높은 Stack Trace를 식별할 수 있습니다. |
상세 호출 Step 검토를 통한 호출 경로 상에 이상 모듈의 존재 여부를 파악할 수 있습니다.
액티브 스택
진행 중인 트랜잭션을 액티브 트랜잭션이라고 합니다. 액티브 트랜잭션에서 정기적으로 덤프한 스택을 액티브 스택이라 합니다.
| 와탭 에이전트는 매 10초(옵션 가능)마다 액티브 트랜잭션에 대해서 액티브 스택을 덤프하고 이것을 서버에 전송합니다. (active_stack_second=10) |
액티브 스택 메뉴를 선택하면 수집된 ActiveStack을 차트로 확인할 수 있습니다. 차트는 5분간의 단위 통계 데이터를 Active Transaction의 수를 막대로, TPS를 꺾은 선으로 표시합니다.
막대를 클릭하면, 클릭한 시간대의 Active Transaction의 정보가 나오며, 그 정보를 클릭하면 해당 Transaction의 ActiveStack을 볼 수 있습니다.
컴팩트한 액티브 스택 수집
액티브 스택은 스레드 덤프를 정기적으로 수행하기 때문에 잘못 구현되면 에이전트에 오버헤드가 커질 수 있습니다. 와탭은 에이전트 부하를 최소화하면서 액티브 스택을 수집하기 위해 다양한 옵션들을 가지고 있습니다.
| 서버 > 더보기 > 스레드 목록/덤프 메뉴에서 스레드 목록 중에 "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에 등록된 클래스/메소드일때 스레드가 파킹 상태에 있다고 판단하고 덤프를 생성하지 않습니다.
활용 예시
스택 - 탑스택 메뉴에서 특정 시간대 내역을 조회한 예입니다.
프로파일이나 트랜잭션 통계정보로는 알 수 없는 다양한 개선 포인트를 찾을 수 있습니다.
스택 - 탑스택 메뉴에서 탑스택 정보를 조회합니다.
점유율 순서대로 상위 항목부터 Class/Method 정보를 확인합니다.
최상위 79.92% 비율을 차지하는 탑스택은 org.apache.logging.log4j.core.layout.TextEncoderHelper.copyDataToDestination() 메소드입니다. (1) 두 번째로 높은 8.01% 비율을 차지하는 탑스택은 sun.misc.Unsafe.park() 메소드입니다. (2)
히스토리 기능으로 시간대 별 추이를 확인할 수 있습니다.
06:00 시 경 TextEncoderHelper.copyDataToDestination() 비율이 감소한 것이 확인됩니다. 동 시간대 sun.misc.Unsafe.park는 감소된 TextEncoderHelper.copyDataToDestination() 비율만큼 증가했습니다.
상위 1,2 탑스택은 모두 Logging과 관련되어 있습니다. 즉, 이 시스템은 전체 업무에서 90% 가까운 수행 시간을 Logging에 소비하고 있는 것이 확인됩니다.
확인한 점유율을 바탕으로 개선 기대효과를 산정합니다.
탑스택 정보를 토대로 개선 방안을 검토합니다.
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 간의 연관 통계를 수집할 수 있습니다. 이 데이터를 수집하기 위해서는 다음의 옵션을 설정해야 합니다.
mtrace_rate=100 mtrace_spec=v1 stat_mtrace_enabled=true
위와 같은 아키텍처에서 caller&callee 통계는 api1 api2에서만 조회할 수 있습니다. 사용자 브라우저에서 호출되는 시스템에서는 Caller 통계를 조회할 수 없습니다.
하지만 Caller 쪽 서버에서 데이터를 전송해야 하기 때문에 모든 서버에 적절한 설정이 들어가야 합니다.
mtrace_rate=100 mtrace_spec=v1 stat_mtrace_enabled=true
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 |