플레임 그래프를 활용한 트레이스 성능 분석¶

이 문서는 분산 추적(Trace)이 무엇인지, 그리고 트레이스 내 성능 병목을 분석하기 위해 도구를 사용하는 방법을 이해하는 데 도움을 줍니다.

기본 개념 및 도구¶

• 분산 추적(Trace)
• 분석 도구
  • 플레임 그래프(Flame Graph)
  • Span 목록
  • 서비스 호출 관계도
• 지속 시간 / 실행 시간

분산 추적¶

일반적으로 단일 추적(Trace)은 여러 Span으로 구성되며, 트리 또는 방향성 비순환 그래프(DAG) 형태를 가집니다. 각 Span은 Trace 내에서 명명되고 시간이 측정된 연속 실행 단위를 나타냅니다. 아래 그림과 같습니다. Span의 핵심은 해당 프로그램 실행 단위의 시작 시간과 종료 시간을 기록하는 것이며, 프로그램 실행 단위 간에는 호출의 부모-자식 관계가 존재하므로 Span은 논리적으로 트리 구조를 형성합니다.

참고: span의 부모-자식 관계는 자식 span의 parent_id가 부모 Span의 span_id와 동일한지 확인하여 연결할 수 있습니다.

플레임 그래프¶

플레임 그래프(Flame Graph)는 Linux 성능 최적화 전문가인 Brendan Gregg가 성능 병목 분석을 위해 고안한 시각화 차트입니다. 플레임 그래프는 전체적인 관점에서 시간 분포를 파악하며, 상단에서 하단으로 성능 병목을 유발할 수 있는 모든 Span을 나열합니다.

그리기 로직¶

• Y축은 호출 Span의 계층적 깊이를 나타내며, 프로그램 실행 단위 간의 호출 관계를 표현합니다. 위쪽의 Span은 아래쪽 Span의 부모 Span입니다(데이터 측면에서도 자식 span의 parent_id가 부모 Span의 span_id와 동일한지 확인하여 연결 가능).
• X축은 단일 Trace 내 Span의 지속 시간(duration)을 나타냅니다. 셀의 너비가 넓을수록 해당 Span의 시작부터 종료까지의 지속 시간이 길다는 것을 의미하며, 이는 성능 병목의 원인이 될 수 있습니다.

표시 설명¶

플레임 그래프

• 플레임 그래프 위의 각 Span 셀 색상은 해당 서비스(service)의 색상에 매핑됩니다.

따라서 플레임 그래프를 통해 현재 Trace에 어떤 서비스 요청이 실행 중인지 직관적으로 파악할 수 있습니다. (서비스 색상 생성 로직: 사용자가 워크스페이스에 로그인하여 APM(애플리케이션 성능 모니터링) 모듈에 접근하면 Guance가 서비스 이름을 기반으로 자동으로 색상을 생성하며, 이 색상은 트레이스 탐색기 등의 분석 페이지에 일관되게 적용됩니다.)

• Span 블록 기본 표시: 현재 Span의 리소스(resource) 또는 작업(operation), 지속 시간(duration), 그리고 오류 존재 여부(status = error)
• 각 Span 툴팁에는 현재 Span의 리소스(resource), 지속 시간(duration) 및 전체 소요 시간 대비 비율이 표시됩니다.

서비스 목록

플레임 그래프 우측의 서비스 목록은 현재 Trace 내에서 요청 호출이 발생한 서비스 이름, 색상 및 해당 서비스 실행 시간이 전체 실행 시간에서 차지하는 비율을 표시합니다.

참고: 서비스 이름이 None으로 표시되는 경우는 현재 trace에서 parent_id = 0인 최상위 Span을 찾을 수 없음을 의미합니다.

상호작용 설명¶

1. 전체 화면 보기/기본 크기 복원: 트레이스 상세 페이지 우측 상단의 전체 화면 아이콘을 클릭하여 트레이스 플레임 그래프를 가로로 확장하여 확인하고, 기본 크기 복원 아이콘을 클릭하면 상세 페이지로 돌아갑니다.
2. 미니맵 펼치기/접기: 트레이스 상세 페이지 좌측의 미니맵 펼치기/접기 아이콘을 클릭하고, 미니맵에서 구간 선택, 드래그, 스크롤을 통해 플레임 그래프를 빠르게 확인할 수 있습니다.
3. 전체 Trace 보기: 트레이스 상세 페이지 좌측의 전체 Trace 보기 아이콘을 클릭하여 플레임 그래프에서 전체 트레이스를 확인합니다.
4. 하단 Tab 상세 접기: 접기 버튼을 클릭하면 하단 Tab 상세 페이지 영역이 접힙니다.
5. Span 더블 클릭: 플레임 그래프에서 해당 Span을 중앙에 확대하여 표시하며, 컨텍스트와 관련된 Span을 빠르게 찾을 수 있습니다.
6. 우측 서비스 이름 클릭: 해당 Span을 강조 표시합니다. 서비스 이름을 다시 클릭하면 기본 전체 Span 선택 상태로 복원됩니다. 서비스 이름을 클릭하여 해당 서비스에 해당하는 Span만 빠르게 필터링하여 확인할 수 있습니다.

특별 설명¶

멀티스레드 또는 비동기 작업 등의 존재로 인해 플레임 그래프를 실제로 그릴 때 span 간의 관계는 다음과 같을 수 있습니다.

• 동일한 parent에 속하는 형제 span 간에 중복이 발생할 수 있음

Span 중복이 존재하기 때문에, 각 Span 및 하위 Span의 실행 상태를 더 직관적으로 확인할 수 있도록 프론트엔드에서는 플레임 그래프를 그릴 때 표시 처리를 수행합니다. 즉, 시간 + 공간 차원을 기준으로 Span 및 하위 Span이 서로 완전히 가려지지 않는 위치를 계산하여 표시합니다.

예시 1:

정상 Trace, 동일 계층 Span은 시간적으로 중복되지 않지만, 하위 자식 Span과 시간 중복이 있는 경우 연결선 형태로 부모-자식 Span 간의 관계를 연결합니다. 아래 자식 Span에 연결선이 존재하는 경우에도 이 로직에 따라 그리기 처리를 수행합니다.

예시 2:

비정상 Trace, 여전히 동일 계층 Span이 시간적으로 중복되지만, 실제 데이터에서 Trace의 최상위 Span(parent_id = 0)의 시작 시간(start)이 자식 Span의 시작 시간보다 큰 것을 발견했습니다.

분석 로직:

트레이스 내 프로그램 실행 부모-자식 관계에 따라 판단하면, 부모 Span의 시작 시간은 반드시 자식 Span의 시작 시간보다 작아야 합니다. 따라서 해당 플레임 그래프 표시를 보고 부모 Span과 자식 Span의 서비스가 다를 때, 두 서비스가 위치한 서버의 시스템 시간이 일치하지 않을 가능성이 있다고 판단할 수 있습니다. 이 경우 먼저 시간을 검증 및 보정한 후 실제 성능 병목을 분석해야 합니다.

Span 목록¶

표시 설명¶

목록 전체 접힘 상태

• 열 1: 서비스 유형, 서비스 이름, 서비스 색상 및 현재 서비스에 status = error인 Span 존재 여부 표시
• 열 2: 현재 서비스 아래의 Span 개수 표시
• 열 3: 현재 서비스 아래 Span 지속 시간(duration)의 평균값 표시
• 열 4: 현재 서비스 아래 Span의 실행 시간 합계 표시
• 열 5: 현재 서비스의 실행 시간이 전체 실행 시간에서 차지하는 비율 표시

서비스 행 펼쳐서 표시

• 열 1: 리소스 이름(resource), 해당 서비스 색상 및 현재 span에 status = error 존재 여부 표시
• 열 2: 비어 있음
• 열 3: 현재 Span 지속 시간(duration) 표시
• 열 4: 현재 Span의 실행 시간 표시
• 열 5: 현재 Span의 실행 시간이 전체 실행 시간에서 차지하는 비율 표시

상호작용 설명¶

• 검색: 리소스 이름(resource) 부분 일치 검색 지원
• Span 선택 후 플레임 그래프로 전환하여 해당 Span의 컨텍스트 관계 확인 지원

서비스 호출 관계도¶

표시 설명¶

현재 trace 하위의 서비스 간 호출 관계 토폴로지를 표시합니다.

• 리소스 이름(resource) 부분 일치 매칭을 지원하여 특정 리소스의 상하위 서비스 호출 관계를 찾을 수 있습니다.
• 서비스에 마우스 호버 시 표시: 현재 서비스의 Span 개수, 서비스 실행 시간 및 비율

지속 시간¶

Span은 프로그램 실행 단위의 시작 시간과 종료 시간에 해당하며, 일반적으로 Trace 데이터에서 duration 필드로 표시됩니다.

실행 시간¶

위의 특별 설명에서 부모-자식 Span의 종료 시간이 일치하지 않는 경우가 있을 수 있다고 언급했습니다. 실행 시간은 다음 로직에 따라 계산됩니다.

Span 실행 시간¶

1. 자식 span이 부모 span이 종료된 후에 종료될 수 있음

자식 Span의 실행 시간 = Children의 duration

전체 실행 시간 = Children의 종료 시간 - Parent의 시작 시간

부모 Span의 실행 시간 = 전체 실행 시간 - 자식 Span의 실행 시간

1. 자식 span이 부모 span이 종료된 후에 시작될 수 있음

자식 Span의 실행 시간 = Children의 duration

전체 실행 시간 = Children의 종료 시간 - Parent의 시작 시간

부모 Span의 실행 시간 = 전체 실행 시간 - 자식 Span의 실행 시간

1. 동일한 parent에 속하는 형제 span 간에 중복이 발생할 수 있음

부모 Span 실행 시간 = p(1) + p(2)

Children 1 Span 실행 시간 = c1(1) + c1(2)

Children 2 Span 실행 시간 = c2(1) + c2(2)

참고: Children 1 Span, Children 2 Span은 실제 실행 중 시간적으로 일부 중복되므로 이 부분의 시간은 두 Span이 균등하게 나누어 가집니다.

예시 설명

동기 작업의 경우, Span이 "Span1 시작 -> Span1 종료 -> Span2 시작 -> Span2 종료 -> ..." 순서로 실행될 때 각 Span의 실행 시간과 해당 부모 Span의 실행 시간은 다음과 같이 계산됩니다.

예시 1:

부모 Span = Couldcare SPAN1

자식 Span = MyDQL SPAN2, MyDQL SPAN3, MyDQL SPAN4, MyDQL SPAN5, MyDQL SPAN6, MyDQL SPAN7, MyDQL SPAN8, MyDQL SPAN9, MyDQL SPAN10, MyDQL SPAN11

계산 분석:

모든 자식 Span에는 더 하위 계층의 자식 Span이 없으므로, 아래 그림의 모든 자식 Span의 실행 시간은 해당 Span의 지속 시간과 같습니다. 부모 Span은 그 아래에 자식 Span 호출이 존재하므로 실제 부모 Span의 실행 시간은 부모 Span의 지속 시간에서 모든 자식 Span의 실행 시간을 빼서 얻어야 합니다.

서비스 실행 시간¶

각 서비스의 실행 시간 = Trace 내 해당 서비스에 속하는 모든 Span 실행 시간의 합계

전체 실행 시간¶

전체 실행 시간 = Trace 내 Span이 마지막으로 종료된 시간 - Span이 가장 처음 시작된 시간

트레이스 조회 분석 시나리오 예시¶

수집기 구성 (호스트 설치)¶

DataKit 설치 디렉토리 아래 conf.d/ddtrace 디렉토리로 이동하여 ddtrace.conf.sample을 복사하고 ddtrace.conf로 이름을 변경합니다. 예시는 다음과 같습니다.

[[inputs.ddtrace]]
  ## DDTrace Agent endpoints register by version respectively.
  ## Endpoints can be skipped listen by remove them from the list.
  ## Default value set as below. DO NOT MODIFY THESE ENDPOINTS if not necessary.
  endpoints = ["/v0.3/traces", "/v0.4/traces", "/v0.5/traces"]

  ## customer_tags is a list of keys contains keys set by client code like span.SetTag(key, value)
  ## that want to send to data center. Those keys set by client code will take precedence over
  ## keys in [inputs.ddtrace.tags]. DOT(.) IN KEY WILL BE REPLACED BY DASH(_) WHEN SENDING.
  # customer_tags = ["key1", "key2", ...]

  ## Keep rare tracing resources list switch.
  ## If some resources are rare enough(not presend in 1 hour), those resource will always send
  ## to data center and do not consider samplers and filters.
  # keep_rare_resource = false

  ## By default every error presents in span will be send to data center and omit any filters or
  ## sampler. If you want to get rid of some error status, you can set the error status list here.
  # omit_err_status = ["404"]

  ## Ignore tracing resources map like service:[resources...].
  ## The service name is the full service name in current application.
  ## The resource list is regular expressions uses to block resource names.
  ## If you want to block some resources universally under all services, you can set the
  ## service name as "*". Note: double quotes "" cannot be omitted.
  # [inputs.ddtrace.close_resource]
    # service1 = ["resource1", "resource2", ...]
    # service2 = ["resource1", "resource2", ...]
    # "*" = ["close_resource_under_all_services"]
    # ...

  ## Sampler config uses to set global sampling strategy.
  ## sampling_rate used to set global sampling rate.
  # [inputs.ddtrace.sampler]
    # sampling_rate = 1.0

  # [inputs.ddtrace.tags]
    # key1 = "value1"
    # key2 = "value2"
    # ...

  ## Threads config controls how many goroutines an agent cloud start.
  ## buffer is the size of jobs' buffering of worker channel.
  ## threads is the total number fo goroutines at running time.
  # [inputs.ddtrace.threads]
    # buffer = 100
    # threads = 8

  ## Storage config a local storage space in hard dirver to cache trace data.
  ## path is the local file path used to cache data.
  ## capacity is total space size(MB) used to store data.
  # [inputs.ddtrace.storage]
    # path = "./ddtrace_storage"
    # capacity = 5120

구성 완료 후 DataKit 재시작 하면 됩니다.

HTTP 설정¶

Trace 데이터가 원격 머신에서 전송되는 경우 DataKit의 HTTP 설정을 설정해야 합니다.

ddtrace 데이터가 DataKit으로 전송되면 DataKit의 monitor에서 확인할 수 있습니다.

DDtrace가 데이터를 /v0.4/traces 인터페이스로 전송

SDK 연동 (Go 예시)¶

의존성 설치¶

개발 디렉토리에서 ddtrace golang 라이브러리 설치를 위해 다음을 실행합니다.

go get -v github.com/DataDog/dd-trace-go

DataKit 설정¶

먼저 DataKit을 설치하고 시작한 후, ddtrace 수집기를 활성화해야 합니다.

코드 예시¶

다음 코드는 파일 열기 작업의 trace 데이터 수집을 보여줍니다.

main() 진입 코드에서 기본 trace 매개변수를 설정하고 trace를 시작합니다.

package main

import (
    "io/ioutil"
    "os"
    "time"

    "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/ext"
    "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer"
)

func main() {
    tracer.Start(
        tracer.WithEnv("prod"),
        tracer.WithService("test-file-read"),
        tracer.WithServiceVersion("1.2.3"),
        tracer.WithGlobalTag("project", "add-ddtrace-in-golang-project"),
    )

    // end of app exit, make sure tracer stopped
    defer tracer.Stop()

    tick := time.NewTicker(time.Second)
    defer tick.Stop()

    // your-app-main-entry...
    for {
        runApp()
        runAppWithError()

        select {
        case <-tick.C:
        }
    }
}

func runApp() {
    var err error
    // Start a root span.
    span := tracer.StartSpan("get.data")
    defer span.Finish(tracer.WithError(err))

    // Create a child of it, computing the time needed to read a file.
    child := tracer.StartSpan("read.file", tracer.ChildOf(span.Context()))
    child.SetTag(ext.ResourceName, os.Args[0])

    // Perform an operation.
    var bts []byte
    bts, err = ioutil.ReadFile(os.Args[0])
    span.SetTag("file_len", len(bts))
    child.Finish(tracer.WithError(err))
}

컴파일 및 실행¶

Linux/Mac 환경:

go build main.go -o my-app
DD_AGENT_HOST=localhost DD_TRACE_AGENT_PORT=9529 ./my-app

Windows 환경:

go build main.go -o my-app.exe
$env:DD_AGENT_HOST="localhost"; $env:DD_TRACE_AGENT_PORT="9529"; .\my-app.exe

프로그램을 일정 시간 실행한 후, Guance에서 다음과 유사한 trace 데이터를 확인할 수 있습니다.

Golang 프로그램 trace 데이터 표시

지원되는 환경 변수¶

다음 환경 변수는 프로그램 시작 시 ddtrace의 일부 구성 매개변수를 지정하는 것을 지원합니다. 기본 형식은 다음과 같습니다.

DD_XXX=<env-value> DD_YYY=<env-value> ./my-app

주의사항: 이러한 환경 변수는 코드에서 WithXXX()로 주입된 해당 필드에 의해 덮어쓰여집니다. 따라서 코드로 주입된 구성의 우선순위가 더 높으며, 이러한 ENV는 코드에서 해당 필드를 지정하지 않은 경우에만 적용됩니다.

실제 트레이스 데이터 분석¶

1. Guance 워크스페이스에 로그인하여 APM(애플리케이션 성능 모니터링) 모듈의 서비스 목록을 확인합니다. 서비스 페이지에서 이미 browser 서비스의 P90 응답 시간이 상대적으로 긴 것을 확인할 수 있습니다.

1. browser 서비스 이름을 클릭하여 해당 서비스의 개요 분석 뷰를 확인합니다. 현재 서비스 응답 시간에 가장 큰 영향을 미치는 핵심 리소스는 query_data 인터페이스임을 알 수 있습니다. 이 인터페이스는 Guance의 데이터 조회 인터페이스이므로, 이 인터페이스가 조회 과정에서 왜 시간이 오래 걸리는지 확인해 보겠습니다.

1. 리소스 이름을 클릭하여 탐색기로 이동하고, 지속 시간을 내림차순으로 정렬하여 응답 시간의 최대값을 확인합니다.

1. Span 데이터를 클릭하여 현재 Span의 전체 트레이스 내 실행 성능 및 기타 관련 정보를 확인하고 분석합니다.

1. 우측 상단의 [전체 화면] 모드 버튼을 클릭하여 플레임 그래프 관련 정보를 확대하여 확인합니다. 전체 트레이스와 함께 확인하면, browser 서비스가 전체 트레이스에서 차지하는 실행 시간 비율이 96.26%에 달하는 것을 알 수 있습니다. Span 목록에서도 이 결론을 얻을 수 있습니다. 플레임 그래프의 비율과 해당 트레이스 상세 정보를 종합하면, browser의 query_data Span이 전체 실행 과정에서 resource_ttfb(리소스 로드 요청 응답 시간)가 400ms 이상 소요되고, resource_first_byte(리소스 로드 첫 바이트 도달 시간)가 1.46초 소요되는 것을 확인할 수 있습니다. 또한 province 지리적 위치가 Singapore(싱가포르)로 확인된 반면, 사이트는 항저우 노드에 배포되어 있으므로, 지리적 위치 문제로 인해 데이터 전송 시간이 길어져 전체 소요 시간에 영향을 미친다는 결론을 내릴 수 있습니다.