제1부 계산 그래프의 코어
1.11 로깅 — 로거 계층·구성·rosout
1.11.1 이 장에서 배우는 것 / 선수 지식
로그는 현장에서 유일하게 남는 증거다. 로봇이 새벽 3시에 이상 동작을 했을 때 디버거를 연결할 수는 없고, 남은 것은 로그뿐이다. 그런데 로깅은 동시에 실시간 경로를 무너뜨리는 흔한 원인이기도 하다 — 파일 I/O, 락, 문자열 포매팅, 그리고 /rosout 발행까지가 콜백 안에서 일어난다.
이 장은 ROS 2 로깅을 관측 수단이자 성능 위험의 양면에서 다룬다.
배우는 것:
- 로거 계층 구조 — 이름으로 계층이 만들어지고 레벨이 상속된다.
- 출력 경로 세 갈래 — 콘솔·
/rosout·파일, 각각의 성질과 비용. - 레벨 제어의 모든 방법 — 코드·실행 인자·환경변수·실행 중 서비스.
- 조건부 매크로 —
THROTTLE·ONCE·SKIPFIRST·EXPRESSION의 정확한 의미. - 출력 포맷 커스터마이즈 —
RCUTILS_CONSOLE_OUTPUT_FORMAT. - 실시간 경로에서의 로깅 — 무엇이 위험하고 어떻게 피하는가.
- 로그 설계 원칙 — 무엇을 어느 레벨로 남길 것인가.
- 비용과 API 실측(1.11.12) — 억제·출력의 차이, 그리고
{time}의 정체.
선수 지식: 1.10(시간 — 로그 타임스탬프), 1.9(파라미터 — 레벨을 파라미터로 다루는 경우), 1.4(토픽 — /rosout도 토픽이다).
정직: 환경변수 이름과 로그 파일 기본 경로는
rcutils·rcl_logging구현에 근거한다. 로깅 백엔드는 빌드 구성에 따라 달라질 수 있고(spdlog 기반이 일반적), 그에 따라 파일 출력 동작이 다를 수 있다(확인 필요). 이 환경에서 실행 검증하지 않았다(목차 3).검증 상태(추가): 이 장의 서술 가운데 5곳은 이후 회차에서 Jazzy 실물과 대조해 확인했다 — 본문의 (실행 확인) 표기가 그것이다. 표기가 없는 서술은 위 고지가 그대로 적용된다(목차 3의 검증 범위 표).
1.11.2 로거 계층 — 이름이 곧 구조다
RCLCPP_DEBUG(get_logger(), "상세 정보: %d", value);
RCLCPP_INFO(get_logger(), "정상 진행");
RCLCPP_WARN(get_logger(), "이상하지만 계속함");
RCLCPP_ERROR(get_logger(), "실패했음");
RCLCPP_FATAL(get_logger(), "복구 불가");
node->get_logger()는 노드 이름과 같은 이름의 로거를 준다. 여기에 자식 로거를 만들 수 있다.
auto child = get_logger().get_child("motor"); // "my_node.motor"
RCLCPP_INFO(child, "모터 초기화");
auto grand = child.get_child("left"); // "my_node.motor.left"
계층은 점(.)으로 표현되고, 레벨은 상속된다.
이것이 실무에서 강력한 이유: 문제가 의심되는 서브시스템만 골라 DEBUG로 내릴 수 있다. 노드 전체를 DEBUG로 켜면 로그가 홍수가 되고, 그 자체로 시스템이 느려져 문제가 재현되지 않는다(관측이 대상을 바꾸는 전형적 사례 — 0.7.4).
견해: 드라이버·제어처럼 내부 구조가 있는 노드는 처음부터 자식 로거로 나눠 두라. 비용은 몇 줄이고, 현장에서 "이 부분만 자세히 보기"가 가능해진다. 노드 전체를
DEBUG로 켜야만 하는 상황은 설계가 그것을 강요한 결과다.
1.11.3 출력 경로 세 갈래
| 경로 | 성질 | 비용 | 끄는 법 |
|---|---|---|---|
| 콘솔 | stderr로 출력. 색상 지원 | 터미널·리다이렉트에 따라 다름. 파이프가 막히면 블로킹 | RCUTILS_LOGGING_USE_STDOUT 등으로 조정 |
/rosout | rcl_interfaces/msg/Log 토픽 | 직렬화 + DDS 발행 — 네트워크 부하 | --ros-args --disable-rosout-logs |
| 파일 | ~/.ros/log/<날짜-시각-호스트-pid>/ | 디스크 I/O | --ros-args --disable-stdout-logs·--disable-external-lib-logs — 두 플래그 모두 실재·수용 확인(실행 확인). 대응하는 --enable-* 형태도 있다 |
/rosout이 토픽이라는 사실의 함의:
- QoS가 있다.
RosoutQoS()는RELIABLE+TRANSIENT_LOCAL+ depth 1000(1.5.5) — 늦게 참여한 로그 뷰어도 과거 로그를 본다. - 네트워크를 경유한다. 무선 링크에서 로그가 대역을 소모한다. 로그 폭주가 제어 데이터를 밀어내는 사고가 가능하다.
TRANSIENT_LOCAL이므로 발행자가 1000개를 계속 들고 있다. 메모리를 쓴다.- 끌 수 있다. 필드 로봇에서 무선 대역이 빠듯하면
/rosout을 끄고 파일 로그만 남기는 것이 합리적 선택이다.
ros2 run my_pkg my_node --ros-args --disable-rosout-logs
ros2 topic echo /rosout # 시스템 전체 로그를 한곳에서 보기
로그 파일 위치:
ls ~/.ros/log/ # 실행마다 디렉터리 하나
export ROS_LOG_DIR=/var/log/robot # 위치 변경
export ROS_HOME=/opt/robot # ~/.ros 자체를 옮김
함정:
~/.ros/log는 자동으로 정리되지 않는다. 장시간 운용되는 로봇에서 디스크를 채우는 흔한 원인이다.logrotate나 정기 정리 작업을 배포에 포함해야 한다(14.8). 임베디드 보드에서 디스크가 차면 시스템 전체가 비정상적으로 동작한다.
1.11.4 레벨 제어 — 네 가지 방법
① 코드에서
get_logger().set_level(rclcpp::Logger::Level::Debug);
rcutils_logging_set_logger_level("my_node.motor", RCUTILS_LOG_SEVERITY_DEBUG);
② 실행 인자로
ros2 run my_pkg my_node --ros-args --log-level DEBUG # 전체
ros2 run my_pkg my_node --ros-args --log-level my_node.motor:=DEBUG # 특정 로거
ros2 run my_pkg my_node --ros-args --log-level WARN --log-level my_node.motor:=DEBUG
마지막 형태가 실무에서 가장 유용하다 — 전체는 조용히, 관심 부분만 상세히.
③ 환경변수로
export RCUTILS_COLORIZED_OUTPUT=1 # 색상 강제
export RCUTILS_CONSOLE_OUTPUT_FORMAT="[{severity}] [{time}] [{name}]: {message}"
export RCUTILS_LOGGING_BUFFERED_STREAM=1 # 버퍼링 (성능↑, 크래시 시 유실↑)
export RCUTILS_LOGGING_USE_STDOUT=1 # 전부 stdout으로 (기본은 심각도별 분기)
export ROS_LOG_DIR=/var/log/robot # 로그 파일 위치 (실행 확인)
함정 — 기본 로그 레벨을 바꾸는 환경변수는 없다(실행 확인).
RCUTILS_LOGGING_SEVERITY같은 이름을 흔히 보게 되지만 Jazzy에는 존재하지 않는다. 실측으로 확인했다 —RCUTILS_LOGGING_SEVERITY=DEBUG로 노드를 실행하면 DEBUG 로그가 한 줄도 나오지 않고, 같은 노드를--ros-args --log-level debug로 실행하면 나온다.librcutils.so가 읽는 환경변수는 위 네 개(RCUTILS_COLORIZED_OUTPUT·RCUTILS_CONSOLE_OUTPUT_FORMAT·RCUTILS_LOGGING_BUFFERED_STREAM·RCUTILS_LOGGING_USE_STDOUT)와RCUTILS_CONSOLE_STDOUT_LINE_BUFFERED뿐이다. 레벨은 ②의--log-level또는 ④의 서비스로 바꾼다. 환경변수로 통일하고 싶다면 launch나 systemd 유닛에서--log-level인자를 주입하는 편이 표준적 방법이다.
④ 실행 중에 — 서비스로 (가장 유용하지만, 켜야 쓴다)
함정 — 이 서비스는 기본으로 꺼져 있다(실행 확인 2026-08-16). 노드를 별도 설정 없이 실행하면
set_logger_levels서비스가 없다. 실측했다 —rclpy노드의 서비스 서버 목록에는 파라미터 6종과~/get_type_description뿐이고 로거 서비스는 나타나지 않는다. 헤더도 같은 말을 한다:rclcpp의NodeOptions는enable_logger_service_ {false},rclpy의Node도enable_logger_service: bool = False가 기본이다.켜려면 노드를 만들 때 명시해야 한다.
auto node = std::make_shared<rclcpp::Node>( "my_node", rclcpp::NodeOptions().enable_logger_service(true));node = Node("my_node", enable_logger_service=True)즉 "현장에서 재시작 없이 로그를 켠다"는 운영 전략을 쓰려면, 그 준비를 출하 전에 코드에 넣어 두어야 한다. 문제가 발생한 뒤에는 늦다 — 그 노드를 다시 빌드해야 하기 때문이다. 이것이 아래 견해의 전제다.
켜 두면 노드가 로거 레벨 제어 서비스를 노출한다.
ros2 service call /my_node/set_logger_levels \
rcl_interfaces/srv/SetLoggerLevels \
"{levels: [{name: 'my_node.motor', level: 10}]}"
레벨 값은 rcl_interfaces/msg/Log의 상수를 따른다 — DEBUG=10·INFO=20·WARN=30·ERROR=40·FATAL=50, 실물과 일치함을 확인했다(실행 확인).
견해: ④는 운영 진단의 핵심 도구다. 재시작 없이 로그를 켜고 끌 수 있다는 것은, 재현하기 어려운 간헐적 문제를 검출할 때 결정적이다 — 문제가 나타난 순간에 상세 로그를 켤 수 있다. 다만
/rosout이 켜져 있는 상태에서DEBUG를 켜면 네트워크 부하가 급증하므로, 무선 환경에서는 파일 로그만 켜는 조합을 미리 준비해 두는 편이 좋다.
1.11.5 조건부 로깅 매크로
로그 폭주를 막는 장치들이다. 고빈도 콜백에서는 이것을 쓰지 않으면 로그가 시스템을 마비시킨다.
// 주기 제한 — 지정 간격(ms) 안에서 한 번만
RCLCPP_WARN_THROTTLE(get_logger(), *get_clock(), 1000,
"센서 값 이상: %.2f", value);
// 최초 한 번만
RCLCPP_INFO_ONCE(get_logger(), "초기화 완료");
// 첫 호출은 건너뛰고 이후부터
RCLCPP_WARN_SKIPFIRST(get_logger(), "재시도 중");
// 조건부
RCLCPP_ERROR_EXPRESSION(get_logger(), value < 0, "음수 값: %.2f", value);
// 함수 조건
RCLCPP_DEBUG_FUNCTION(get_logger(), &is_verbose_mode, "상세 정보");
// 조합
RCLCPP_WARN_THROTTLE_SKIPFIRST(get_logger(), *get_clock(), 5000, "…");
THROTTLE의 시계 인자가 중요하다. *get_clock()을 넘기면 ROS 시간을 쓴다 — 시뮬레이션에서 시간이 느리게 가면 throttle 간격도 함께 늘어난다(1.10). 벽시계 기준으로 제한하고 싶으면 steady clock을 넘겨야 한다.
함정:
THROTTLE은 메시지 단위가 아니라 호출 지점(코드 위치) 단위로 제한한다. 같은 매크로 호출이 여러 다른 상황에서 실행되면, 다른 내용의 로그가 서로를 억제한다. 서로 다른 원인의 경고는 다른 호출 지점에 두어야 한다.
함정: 레벨이 걸러져도 인자 평가는 일어날 수 있다. 매크로는 레벨 검사를 먼저 하도록 설계되어 있지만, 인자로 넘긴 함수 호출은 매크로에 진입하기 전 평가되는 경우가 있다. 비용이 큰 함수를 로그 인자로 넘기지 말라.
// ❌ expensive_dump()가 DEBUG가 꺼져 있어도 호출될 수 있다
RCLCPP_DEBUG(get_logger(), "상태: %s", expensive_dump().c_str());
// ✅ 조건으로 감싼다
if (get_logger().get_effective_level() <= rclcpp::Logger::Level::Debug) {
RCLCPP_DEBUG(get_logger(), "상태: %s", expensive_dump().c_str());
}
둘 다 확인했다(실행 확인, 1.11.12.2) — get_effective_level()은 있고 is_enabled_for는 rclcpp에 없으므로 rcutils_logging_logger_is_enabled_for를 쓴다.
1.11.6 출력 포맷 커스터마이즈
export RCUTILS_CONSOLE_OUTPUT_FORMAT="[{severity}] [{time}] [{name}]: {message}"
| 토큰 | 내용 |
|---|---|
{severity} | 레벨 |
{name} | 로거 이름 |
{message} | 본문 |
{time} | 초.나노초 |
{time_as_nanoseconds} | 나노초 정수 |
{function_name}·{file_name}·{line_number} | 소스 위치 |
실무에 유용한 조합:
# 개발 — 소스 위치까지
export RCUTILS_CONSOLE_OUTPUT_FORMAT="[{severity}] [{time}] [{name}] [{function_name}:{line_number}]: {message}"
# 운영 — 파싱하기 쉬운 형태
export RCUTILS_CONSOLE_OUTPUT_FORMAT="{time}|{severity}|{name}|{message}"
두 번째 형태는 로그를 기계가 읽는 경우(중앙 수집·알림)를 위한 것이다. 파이프 구분자로 두면 후처리가 단순해진다.
정직: 사용 가능한 토큰 목록과 이름은
rcutils버전에 따라 다를 수 있다(확인 필요). 지원하지 않는 토큰은 그대로 출력되거나 무시된다.
시간 표기 주의: 로그의 {time}은 벽시계다(실행 확인 — use_sim_time을 켜도 바뀌지 않는다, 1.11.12.4). 시뮬레이션에서 로그 시각과 데이터 스탬프가 안 맞으면 이 지점을 확인해야 한다(1.10.3).
1.11.7 실시간 경로에서의 로깅
로깅은 실시간 안전하지 않다. 제어 루프(6.6·12.1)에서 무심코 로그를 남기면 다음이 일어난다.
| 위험 | 설명 |
|---|---|
| 동적 할당 | 문자열 포매팅이 힙을 쓴다 → 지연 지터(12.3) |
| 락 경합 | 로깅 구현이 내부 뮤텍스를 획득한다 |
| I/O 블로킹 | 콘솔·파일 쓰기가 블로킹될 수 있다. 파이프가 막히면 무한정 |
| DDS 발행 | /rosout은 토픽이다 — 직렬화 + 네트워크 |
| 우선순위 역전 | 낮은 우선순위 스레드가 로깅 락을 쥐고 있으면 RT 스레드가 대기 |
대응 전략:
① 실시간 경로에서 로그를 전혀 안 쓴다. 대신 카운터·플래그를 원자적으로 갱신하고, 별도의 저우선순위 타이머가 그것을 읽어 로그를 남긴다.
// 실시간 루프
if (error) error_count_.fetch_add(1, std::memory_order_relaxed);
// 별도 진단 타이머 (10 Hz, 비실시간)
diag_timer_ = create_wall_timer(100ms, [this]() {
auto n = error_count_.exchange(0);
if (n > 0) RCLCPP_WARN(get_logger(), "지난 100 ms 동안 오류 %u회", n);
});
② 무조건 THROTTLE을 적용한다. 완전히 없앨 수 없으면 최소한 빈도를 제한한다.
③ 실시간 안전 로깅 라이브러리를 쓴다. 락프리 링버퍼에 기록하고 별도 스레드가 배출하는 방식. ros2_control 생태계에서 이런 접근을 볼 수 있다 — 패키지 이름은 realtime_tools(ros-jazzy-realtime-tools, 88차 실행 확인). apt 설명이 그 목적을 그대로 말한다: "하드 실시간 스레드에서 실시간 동작을 깨지 않고 쓸 수 있는 도구 모음". ros-base에는 없으므로 따로 설치해야 한다.
④ /rosout을 끈다. 실시간 노드에서는 네트워크 발행 경로를 제거하는 것만으로도 지터가 크게 줄어든다.
견해: "제어 루프 안에 로그가 하나라도 있으면 그것은 실시간 코드가 아니다" 를 팀 규칙으로 두는 것이 안전하다. 예외를 허용하기 시작하면 어느 로그가 지터의 원인인지 추적할 수 없게 된다. 진단은 위 ①의 카운터 방식으로 충분히 할 수 있다(6.9).
1.11.8 로그 설계 원칙 — 무엇을 어느 레벨로
| 레벨 | 기준 | 예 |
|---|---|---|
FATAL | 노드가 계속할 수 없다 | 하드웨어 초기화 완전 실패 |
ERROR | 기능이 실패했다. 조치가 필요하다 | 서비스 호출 실패, 센서 연결 끊김 |
WARN | 비정상이지만 계속한다 | 값이 범위 밖, 재시도 중, 데이터가 오래됨 |
INFO | 정상 동작의 이정표 | 초기화 완료, 모드 전환, 목표 수락 |
DEBUG | 개발자용 상세 | 루프 내부 값, 상태 전이 세부 |
실전 규칙:
INFO는 사람이 읽을 수 있는 빈도여야 한다. 정상 동작 중 초당 수십 줄이 나오면 그것은DEBUG다.ERROR는 반드시 행동을 시사해야 한다. "무엇이 실패했고, 그래서 무엇을 안 하게 됐는지"를 적는다. 원인을 알 수 있으면 함께.- 상태 전이는 항상 남긴다. 라이프사이클 전이(1.12), 모드 변경, 목표 수락·완료(1.8). 사후 분석에서 가장 유용한 정보다.
- 값을 함께 남긴다. "센서 값 이상"보다 "센서 값 이상: 15.3 (허용 0~10)"이 낫다. 임계값도 함께.
- 시작 시 구성을 남긴다. 주요 파라미터·장치 경로·버전을
INFO로 한 번. 현장 로그만 보고 어떤 설정으로 실행됐는지 알 수 있어야 한다. - 비밀 값을 남기지 않는다. 로그는 수집·전송·보관된다(13.4).
// 시작 시 구성 기록 — 사후 분석의 출발점
RCLCPP_INFO(get_logger(),
"시작: device=%s, rate=%.1f Hz, frame=%s, sim_time=%s",
device_path_.c_str(), rate_hz_, frame_id_.c_str(),
get_parameter("use_sim_time").as_bool() ? "true" : "false");
1.11.9 로그를 실제로 활용하기
여러 노드의 로그를 한곳에서:
ros2 topic echo /rosout # 전체
ros2 run rqt_console rqt_console # GUI 필터링
rqt_console은 레벨·노드·문자열로 필터링할 수 있어 노드가 많을 때 유용하다(11.5).
bag에 로그 함께 기록:
ros2 bag record /rosout /scan /odom /tf
/rosout을 bag에 함께 기록하는 것은 매우 권할 만하다 — 사후 분석에서 "이 시점에 노드가 무슨 생각을 하고 있었나"를 데이터와 나란히 볼 수 있다(11.3). 다만 TRANSIENT_LOCAL이므로 기록 시작 시 과거 로그가 한꺼번에 들어올 수 있다는 점은 유의한다.
중앙 수집: systemd로 실행한 노드는 stderr가 journald로 간다.
journalctl -u my_robot.service -f
journalctl -u my_robot.service --since "1 hour ago" | grep ERROR
운영에서는 이쪽이 /rosout보다 신뢰할 만하다 — 노드가 종료되는 순간의 로그도 남기 때문이다(14.8).
1.11.12 로깅의 비용과 API를 확인했다 — 실측
이 장이 남긴 (확인 필요) 넷을 확인했다(실행 확인, Jazzy, -O2).
1.11.12.1 호출 비용 — 억제된 로그는 사실상 무비용, 출력되는 로그는 비용이 크다
각 2,000회 호출, 마이크로초.
| 호출 | 평균 | p50 | p99 | 최대 | 회당 할당 |
|---|---|---|---|---|---|
| 기준선(빈 루프) | 0.029 | 0.029 | 0.030 | 0.090 | 0 |
RCLCPP_DEBUG(레벨상 억제) | 0.053 | 0.053 | 0.054 | 0.649 | 0 |
RCLCPP_INFO(출력됨) | 7.508 | 7.203 | 14.477 | 187.727 | 0.31 |
RCLCPP_INFO_THROTTLE(대부분 억제) | 0.128 | 0.119 | 0.134 | 11.847 | 0 |
세 가지가 확인된다.
① 억제된 로그의 비용은 기준선의 2배 수준(0.05 µs)이고 할당이 0이다. 1.11.5가 말한 "C++ 매크로는 레벨이 꺼져 있으면 인자를 평가하지 않는다"가 비용으로 드러난다 — RT 경로에 RCLCPP_DEBUG를 남겨 두는 것은 안전하다.
② 출력되는 로그는 평균 7.5 µs, 최대 188 µs다. 평균의 25배까지 급증한다.
1 kHz 제어 루프(주기 1,000 µs)에서 최대 188 µs는 예산의 19%다. 1.11.7이 "실시간 경로에서 로깅을 조심하라"고 한 것이 이 숫자다. 평균만 보면 7.5 µs는 작아 보이지만 꼬리가 문제이며, 2.5.13.1에서 본 타이머 지터(p99가 목표의 +0.05 µs)와 견주면 로깅 한 줄이 지터의 지배 요인이 될 수 있다.
③ THROTTLE은 억제될 때 0.128 µs로 비용이 낮다. 조건 검사만 하고 빠져나간다 — 주기 루프에 THROTTLE을 쓰는 것이 실용적인 이유다. 다만 실제로 출력되는 순간에는 똑같이 비용이 크므로(최대 11.8 µs) 주기가 촘촘하면 그 순간이 지터로 나타난다.
견해: RT 경로의 로그는 "억제되는 것"만 남기라.
DEBUG는 그대로 두어도 되고,THROTTLE은 주기를 충분히 길게 설정한다. 꼭 출력해야 하는 것은 링버퍼에 넣고 다른 스레드가 배출하는 방식이 답이며(1.11.7-③), 위 숫자가 그 필요를 뒷받침한다.
1.11.12.2 레벨 조회 API — rclcpp에는 is_enabled_for가 없다
이 장은 "(확인 필요: get_effective_level() API의 정확한 이름) — 없으면 rcutils_logging_logger_is_enabled_for를 쓴다"고 적었다. 둘 다 맞았다.
rclcpp::Logger의 멤버 전수: get_name · get_child · get_effective_level · set_level · c_str.
auto lg = get_logger();
lg.get_effective_level(); // ✅ 있다 (기본 20 = INFO)
// lg.is_enabled_for(...); // ❌ 없다
rcutils_logging_logger_is_enabled_for(lg.get_name(), RCUTILS_LOG_SEVERITY_DEBUG); // ✅ C 폴백
rclpy와 다르다. Python 쪽에는get_effective_level()과is_enabled_for()가 둘 다 있다(2.8.11.3). 같은 개념의 API가 두 언어에서 비대칭이며, C++에서는 C 레벨 함수를 직접 부르는 것이 유일한 방법이다.
1.11.12.3 출력 포맷 토큰 — 책의 목록이 전부 동작한다
| 토큰 | 출력 예 |
|---|---|
{message} | 본문 |
{name} | fmt |
{severity} | INFO |
{time} | 1786978114.105253319 |
{time_as_nanoseconds} | 1786978113972699401 |
{function_name} | main |
{file_name} | /tmp/emit.cpp |
{line_number} | 4 |
1.11.6의 표에 있는 것이 전부 동작한다. 그리고 이 장이 "지원하지 않는 토큰은 그대로 출력되거나 무시된다"고 한 것 중 "그대로 출력"이 맞다 — 없는 토큰({made_up_token})을 주면 {made_up_token} 문자열이 그대로 출력된다.
오타가 조용히 넘어가지 않는다는 뜻이라 다행이다. 포맷을 바꿨는데 로그에 중괄호가 보이면 토큰 이름이 틀린 것이다.
1.11.12.4 {time}은 벽시계다 — ROS 시간을 따르지 않는다
이 장이 "로그의 {time}이 ROS 시간인지 벽시계인지는 구성에 따라 다르다"(확인 필요)고 남긴 항목이다. 확정했다.
| 조건 | {time} 출력 |
|---|---|
벽시계(date +%s) | 1786978095 |
use_sim_time 없이 | 1786978095.903… |
use_sim_time:=true + /clock에 1000초 발행 | 1786978099.036… |
시뮬 시각을 1000초로 주어도 로그 시각은 벽시계 그대로다.
시뮬레이션에서 로그와 데이터의 시각이 어긋난다. bag의 메시지 스탬프는 시뮬 시간인데(1.10.3) 로그 줄의 시각은 벽시계이므로, "로그를 보고 그 시점의 데이터를 찾는" 작업이 시뮬에서는 성립하지 않는다.
대처는 메시지에 시각을 넣는 것이다 — 로그 본문에
get_clock()->now()를 직접 출력하면 ROS 시간이 남는다.RCLCPP_INFO(get_logger(), "[t=%.3f] 상태 전환", now().seconds());
1.11.12.5 확인하지 못한 것
- 로그 파일 기본 경로와 백엔드(
rcl_logging_spdlog)의 동작은 측정하지 않았다(확인 필요)— 2.1.12.2에서librcl_logging_spdlog.so가rcl의 의존으로 링크되는 것만 확인했다. rclpy의 로깅 비용은 이후 회차에 측정했다(2.8.12.1) — 억제 0.713 µs·출력 127.6 µs로 C++의 13~17배이며,throttle은 Python에서 비용이 낮지 않다(128 µs).- 링버퍼 기반 실시간 로깅(1.11.7-③)의 실제 구현은 시험하지 않았다.
1.11.10 함정 카탈로그
| # | 함정 | 증상 | 대처 |
|---|---|---|---|
| 1 | 고빈도 콜백에서 무제한 로그 | 로그 폭주·성능 붕괴 | THROTTLE |
| 2 | 실시간 루프에서 로깅 | 지터·우선순위 역전 | 카운터 방식(1.11.7) |
| 3 | ~/.ros/log 미정리 | 디스크 포화 | logrotate·정기 정리 |
| 4 | 무선에서 /rosout + DEBUG | 대역 잠식 | --disable-rosout-logs |
| 5 | 노드 전체를 DEBUG로 | 재현 안 됨(관측이 대상 변경) | 자식 로거로 부분 활성화 |
| 6 | 로그 인자에 비용이 큰 함수 | 꺼도 비용 발생 | 조건 검사로 감쌈 |
| 7 | THROTTLE이 다른 내용을 억제 | 중요한 경고 유실 | 호출 지점 분리 |
| 8 | 시뮬에서 THROTTLE 간격이 늘어남 | 로그가 거의 안 나옴 | 시계 선택 확인(1.10) |
| 9 | ERROR에 원인·영향 없음 | 사후 분석 불가 | 값·임계·결과 함께 |
| 10 | 시작 구성 미기록 | 어떤 설정이었는지 모름 | 시작 시 INFO |
| 11 | 비밀 값 로깅 | 보안 노출 | 마스킹·미기록(13.4) |
| 12 | 콘솔 파이프 블로킹 | 노드 전체가 멈춤 | 리다이렉트 대상 확인 |
| 13 | 시뮬에서 로그 시각으로 데이터를 찾음 | {time}은 벽시계 | 본문에 now()를 출력하라(1.11.12.4) |
| 14 | 출력 로그를 RT 루프에 남김 | 최대 188 µs — 1 kHz 예산의 19% | 억제되는 것만 남기라(1.11.12.1) |
| 15 | C++에서 is_enabled_for 를 찾음 | rclcpp에는 없다 | rcutils_logging_logger_is_enabled_for(1.11.12.2) |
12번은 드물지만 치명적이다. stderr를 읽는 쪽이 멈추면(파이프 버퍼가 참) 쓰는 쪽이 블로킹된다. 노드를 파이프로 넘겨 처리하는 스크립트에서 발생할 수 있다.
1.11.11 체크포인트
- 로거 계층이 이름으로 만들어진다는 사실이 왜 실무에서 유용한가. 노드 전체를 DEBUG로 켜는 것이 왜 위험한가.
- 로그가 나가는 세 경로와 각각의 비용을 말할 수 있는가.
/rosout이 토픽이라는 사실에서 나오는 결과 네 가지는? - 특정 서브시스템만 상세 로그로 보려면 어떤 실행 인자를 쓰는가.
- 재시작 없이 실행 중 로그 레벨을 바꾸는 방법과, 그때 주의할 부하 문제는?
THROTTLE이 무엇을 단위로 제한하는지, 그로 인한 함정은 무엇인지 말할 수 있는가.- 시뮬레이션에서
THROTTLE간격이 예상과 다르게 동작하는 이유는? - 로그 매크로가 꺼져 있어도 비용이 발생할 수 있는 경우와 그 회피법은?
- 실시간 제어 루프에서 로깅이 위험한 이유 다섯 가지를 들고, 대안 패턴을 코드로 쓸 수 있는가.
ERROR로그에 반드시 담아야 할 내용은 무엇인가. 시작 시 남겨야 할 것은?/rosout을 bag에 함께 기록하는 것의 이점과 주의점은?- 운영 환경에서
/rosout보다 journald가 신뢰할 만한 이유는? - 억제된 로그와 출력되는 로그의 비용 차이는 얼마인가. RT 경로에 무엇을 남길 수 있는가(1.11.12.1).
- 시뮬레이션에서 로그 시각과 메시지 스탬프가 어긋나는 이유는(1.11.12.4).
- C++에서 레벨을 조회하는 두 방법과, Python과의 차이는(1.11.12.2).
다음 장 1.12는 노드에 표준 상태기계를 부여하는 라이프사이클 노드를 다룬다 — 시스템 부팅 순서, 부분 실패 처리, 그리고 Nav2가 그것을 어떻게 쓰는지.