제11부 도구·관측성

11.6 트레이싱 — ros2_tracing·LTTng

11.6.1 이 장에서 배우는 것 / 선수 지식

앞 장들의 도구는 밖에서 본 것을 보여준다 — 토픽이 몇 Hz로 오는지, 값이 어떻게 변하는지. 그런데 다음 질문들에는 답하지 못한다.

• 이 콜백이 실제로 얼마나 걸리는가?
• 메시지가 발행되고 콜백이 실행되기까지 얼마나 걸렸는가?
• 실행기가 여러 대기 중인 콜백 중 무엇을 먼저 골랐는가(2.2.5)?
• 왜 이 콜백이 지연됐는가 — 다른 콜백이 물고 있어서인가, 스케줄러 때문인가?

트레이싱은 실행 내부의 사건에 타임스탬프를 기록해 이 질문에 답한다. 2.2~2.6에서 설명한 실행기·콜백 그룹·대기 집합의 동작을 추측이 아니라 관측으로 확인하는 방법이다.

배우는 것:

• 왜 트레이싱인가 — 다른 도구의 한계.
• LTTng와 계측점 — 원리.
• 트레이스 수집 — 준비와 실행.
• 분석 — 콜백 지속·지연·메시지 흐름.
• 오버헤드 — 대가와 판단.
• 언제 쓰나 — 다른 수단과의 경계.

선수 지식: 2.2(실행기), 2.4(콜백 그룹), 2.5(주기·지터), 4.5(빌드 옵션), 6.6(실시간).

정직: 계측점 전수·기본 경로·명령 형태·패키지 이름은 Jazzy 컨테이너에서 실제로 트레이싱을 켜서 확인했다(실행 확인 — 11.6.11). Jazzy의 apt 바이너리에는 UST 계측이 활성화되어 있다(35개 이벤트가 켜지는 것을 확인). 다만 커널 트레이싱은 검증하지 못했다 — 컨테이너에 커널 모듈이 없다. 분석 API(tracetools_analysis)는 버전 의존이며 확인하지 않았다. 오버헤드 수치는 제시하지 않는다(3.6.1·목차 3).

11.6.2 왜 트레이싱인가

다른 도구가 답하지 못하는 것을 답한다.

견해: "어디서 시간이 갔는지"를 추측으로 좁히다 보면 오래 걸린다. 2.5.8에서 나열한 지터 원인들은 밖에서 보면 증상이 같다. 트레이싱은 한 번의 측정으로 구분한다 — 준비 비용이 있지만, 어려운 문제에서는 훨씬 빠르다.

견해: 다만 대부분의 문제는 트레이싱까지 안 가도 풀린다. 콜백에 시간 측정 코드를 넣는 것(11.7.4)만으로 해결되는 경우가 많다. 트레이싱은 그것으로 안 될 때 꺼내는 도구다.

11.6.3 LTTng와 계측점

LTTng는 Linux의 저오버헤드 트레이싱 프레임워크다.

ros2_tracing의 계측점 — 전수 목록은 11.6.11에 실측으로 실었다:

견해: "콜백 시작·종료"가 가장 유용한 계측점이다. 이것만으로 콜백별 지속 시간 분포·동시 실행 여부·점유 시간을 알 수 있고, 2.3의 콜백 그룹 동작을 실제로 확인할 수 있다.

계측 활성 확인:

# 트레이싱 지원 여부 — ros2 trace start 출력의 "UST tracing enabled (N events)" 로 안다 (실행 확인)
ros2 run tracetools status

함정: 배포판 바이너리 패키지에 계측이 컴파일되어 있지 않으면 트레이스가 비어 나온다. 이 경우 소스에서 계측을 켜고 빌드해야 한다(확인 필요: Jazzy 바이너리의 기본 상태). 이것이 트레이싱 진입의 최대 장벽이다.

11.6.4 트레이스 수집

# 설치 (실행 확인 — 네 패키지 모두 실재)
sudo apt install ros-jazzy-ros2trace lttng-tools liblttng-ust-dev

# launch에 트레이싱 포함
ros2 trace -s my_session

# 또는 launch 파일에 Trace 액션

# launch 파일에서 (확인 필요: API)
from tracetools_launch.action import Trace

def generate_launch_description():
    return LaunchDescription([
        Trace(session_name='my_session',
              events_ust=['ros2:*'],          # ROS 계측점
              events_kernel=['sched_switch']),  # 커널(선택)
        Node(package='my_pkg', executable='my_node'),
    ])

# 수동 세션 제어
lttng create my_session
lttng enable-event -u 'ros2:*'
lttng start
# ... 시스템 실행 ...
lttng stop
lttng destroy
# 트레이스는 ~/.ros/tracing/my_session 에 쌓인다 (실행 확인 — 기본 경로가 정확히 이것)

수집 시 고려:

함정: 트레이스 데이터가 매우 빠르게 커진다. 고빈도 콜백이 많은 시스템에서 몇 분만 수집해도 GB 단위가 될 수 있다. 문제가 재현되는 짧은 구간을 노려 수집하고, 커널 이벤트는 꼭 필요할 때만 켠다.

함정: 버퍼가 넘치면 이벤트가 손실된다. 손실 여부가 트레이스 메타데이터에 기록되므로(확인 필요), 분석 전에 손실을 확인해야 한다 — 손실된 트레이스로 내린 결론은 틀릴 수 있다.

11.6.5 분석

# 원시 이벤트 확인
babeltrace2 ~/.ros/tracing/my_session | head -50

# tracetools_analysis (개념 — 확인 필요: API)
from tracetools_analysis.loading import load_file
from tracetools_analysis.processor.ros2 import Ros2Handler

events = load_file('my_session')
handler = Ros2Handler.process(events)
# 콜백 지속 시간 · 발행-콜백 지연 등을 DataFrame으로

얻는 지표:

분석으로 답하는 질문:

견해: "타이머가 늦은 시각에 무엇이 실행 중이었나"가 트레이싱의 킬러 기능이다. 2.5.8에서 "긴 콜백이 타이머를 막는다"고 설명했는데, 트레이싱은 그 긴 콜백이 무엇인지 이름으로 알려준다. 다른 방법으로는 추측만 가능하다.

견해: 콜백 지속 시간의 최댓값과 분포를 보라(2.5.6의 원칙 반복). 평균이 1 ms여도 최댓값이 50 ms면 주기 10 ms 타이머는 깨진다. 꼬리가 문제를 만든다.

11.6.6 메시지 흐름 추적

한 메시지가 파이프라인을 통과하는 경로를 따라간다.

각 구간의 지연을 알면 병목이 특정된다.

견해: "도착→콜백 시작" 대기가 크면 실행기 구조 문제다(2.2·2.3). 스레드가 부족하거나 콜백 그룹 설계가 잘못됐거나 긴 콜백이 있다. 처리 시간을 최적화해도 안 풀리는 지연이 여기 숨는다.

정직: 메시지 단위 인과 추적(이 메시지가 저 메시지를 낳았다)은 도구 지원이 제한적일 수 있다(확인 필요). 시간 근접으로 추론하거나, 메시지 헤더에 상관 ID를 넣는 애플리케이션 수준 추적이 필요할 수 있다.

애플리케이션 수준 추적:

견해: header.stamp를 파이프라인 끝까지 전파하는 것이 가장 쉬운 종단 지연 측정법이다(11.7.4). 최종 단계에서 now() - msg.header.stamp가 곧 종단 지연이다. 트레이싱 없이도 되며, 이것으로 충분한 경우가 많다.

11.6.7 오버헤드

트레이싱에도 비용이 든다.

정직: 오버헤드 수치는 인용하지 않는다(3.6.1). 이벤트 빈도·하드웨어에 따라 자릿수가 다르다. 자신의 시스템에서 트레이싱 유무의 성능 차를 측정해야 한다.

함정: 관찰이 대상을 바꾼다(관찰자 효과). 트레이싱 오버헤드가 지터를 유발하면, 관측한 지터가 원래 있던 것인지 트레이싱 탓인지 모른다. 트레이싱 유무로 종단 지표를 비교해 영향이 작음을 확인한 뒤 결론을 내려야 한다.

견해: 실시간 시스템(6.6)에서 트레이싱은 신중해야 한다. 저오버헤드로 설계됐지만 0은 아니며, 하드 실시간 경로에서는 영향을 반드시 확인해야 한다. 개발·시험 환경에서 쓰고 운영에는 끄는 것이 일반적이다.

오버헤드 줄이기:

11.6.8 언제 쓰나

견해: "어느 콜백이 느린가"까지는 간단한 계측으로 알 수 있다. 콜백 안에서 시간을 재 진단 토픽으로 내보내면 된다(6.9.5). 트레이싱이 필요한 것은 "왜 이 콜백이 늦게 시작됐나" 같은, 애플리케이션 코드로는 관측 불가능한 질문이다.

견해: 함수 수준 프로파일링에는 다른 도구가 낫다 — perf·gprof·valgrind 계열. 트레이싱은 ROS 실행 구조를 보는 도구이고, 프로파일러는 코드 내부를 보는 도구다. 목적이 다르다.

대안 수단 정리:

11.6.11 계측점 전수와 실제 수집 — 실측

이 장이 (확인 필요: 정확한 이름·목록)로 남긴 계측점을 Jazzy 컨테이너에서 실제로 트레이싱을 켜서 확인했다(실행 확인).

11.6.11.1 컨테이너에서도 UST 트레이싱은 된다

ros2 trace start를 실행하면 첫 줄이 무엇을 켰는지 알려 준다:

UST tracing enabled (35 events)
kernel tracing disabled
context (3 fields)
writing tracing session to: /root/.ros/tracing/mysession

두 가지가 분리되어 있다는 점이 중요하다.

즉 ROS 2 계층의 인과 추적은 컨테이너·비특권 환경에서도 할 수 있다. 11.6.6이 다루는 "콜백이 언제 시작·종료했는가"류 분석은 UST만으로 충분하다. 커널 트레이싱이 필요한 것은 CPU 경합·선점·컨텍스트 스위치까지 봐야 할 때(12.2)다.

함정: "kernel tracing disabled"를 실패로 읽지 마라. 경고가 아니라 상태 보고다. 커널 이벤트를 명시적으로 요청(-k)하지 않으면 원래 꺼져 있다.

기본 저장 경로는 ~/.ros/tracing/<세션이름>이다(실행 확인). -p/--path로 바꿀 수 있다.

ros2 trace의 형태는 두 가지가 다 통한다(실행 확인):

ros2 trace -s my_session          # 옵션 방식
ros2 trace start my_session       # 동사 방식 — pause·resume·stop 과 짝을 이룬다

동사는 넷이다 — start · stop · pause · resume. 긴 실행 중 관심 구간만 잘라 담을 수 있다는 뜻이라, 버퍼 넘침(11.6.5)을 피하는 실용적 수단이다.

start의 주요 옵션: -u/--ust(UST 이벤트 선택) · -k/--kernel(커널 이벤트) · -c/--context(컨텍스트 필드) · -l/--list(켜진 목록 표시) · -a/--append-trace.

11.6.11.2 계측점 35종 — 이 책의 계층 그림이 그대로 나온다

기본으로 켜지는 UST 이벤트 전부다(실행 확인). 계층별로 묶으면 이 책이 개념으로 설명해 온 경로와 정확히 겹친다.

rmw 계층(4) — rmw_publisher_init · rmw_subscription_init · rmw_publish · rmw_take

rcl 계층(9) — rcl_init · rcl_node_init · rcl_publisher_init · rcl_subscription_init · rcl_service_init · rcl_client_init · rcl_timer_init · rcl_publish · rcl_take

rclcpp 계층(17) — rclcpp_publish · rclcpp_take · rclcpp_subscription_init · rclcpp_subscription_callback_added · rclcpp_service_callback_added · rclcpp_timer_callback_added · rclcpp_timer_link_node · rclcpp_callback_register · rclcpp_executor_execute · rclcpp_executor_wait_for_work · rclcpp_executor_get_next_ready · rclcpp_intra_publish · rclcpp_buffer_to_ipb · rclcpp_ipb_to_subscription · rclcpp_construct_ring_buffer · rclcpp_ring_buffer_enqueue · rclcpp_ring_buffer_dequeue · rclcpp_ring_buffer_clear

콜백 실행(2) — callback_start · callback_end

라이프사이클(2) — rcl_lifecycle_state_machine_init · rcl_lifecycle_transition

읽는 법 — 발행 한 번이 세 계층을 지난다. 1.4.2가 "publish()부터 와이어까지"로 설명한 경로가 이름으로 그대로 있다:

구독은 반대 방향이고 콜백이 뒤에 붙는다(1.4.3):

callback_start와 callback_end 사이가 곧 콜백 실행 시간이다. 2.3의 executor 분석, 11.7의 지연 측정이 결국 이 두 이벤트의 차이를 보는 일이다.

견해: 계측점 목록 자체가 좋은 학습 자료다. 미들웨어가 어디에 경계를 두었는지가 이름으로 드러나기 때문이다. 특히 intra-process 경로에 ring buffer 이벤트가 넷이나 있는 것은, 그 경로의 병목이 대개 버퍼 관리라는 뜻으로 읽힌다(2.7.4).

함정: rmw_take는 있지만 rmw_publish 이후 DDS 내부는 보이지 않는다. 직렬화·재전송·조각화(3.2)는 이 계측점 밖이다. 거기를 봐야 하면 DDS 벤더의 자체 트레이싱이나 패킷 캡처로 넘어가야 한다 — ros2_tracing의 경계가 정확히 rmw까지다.

11.6.9 함정 카탈로그

11.6.10 체크포인트

• 다른 도구가 답하지 못하고 트레이싱만 답하는 질문 네 가지를 들 수 있는가.
• LTTng의 특성 네 가지와, ros2_tracing 계측점 중 가장 유용한 것은?
• 트레이싱 진입의 최대 장벽은 무엇이며 어떻게 확인하는가.
• 트레이스 수집 시 고려할 다섯 항목과, 데이터량 급증을 막는 방법은?
• 버퍼 손실을 확인해야 하는 이유는?
• 트레이싱으로 얻는 지표 여섯 가지와, "킬러 기능"이라 할 만한 분석은?
• 메시지 흐름의 네 구간과, "도착→콜백 시작" 대기가 클 때의 해석은?
• header.stamp 전파가 왜 가장 쉬운 종단 지연 측정법인가.
• 관찰자 효과가 트레이싱에서 왜 문제이며, 어떻게 확인하는가.
• 실시간 시스템에서 트레이싱을 다루는 원칙은?
• 트레이싱이 적합한 상황 넷과 부적합한 상황 넷을 구분할 수 있는가.
• 트레이싱과 프로파일러의 목적 차이는?
• ros2_tracing의 계측점은 몇 개이며 어느 계층까지 덮는가. 커널 트레이싱 없이 무엇을 할 수 있는가(11.6.11).

다음 장 11.7은 이 관측 수단들을 성능 측정 방법론으로 묶는다 — 무엇을 어떻게 측정하고, 어떤 실수를 피하는가.