‘Message Filter dropping message: frame laser’ 로그가 뜰 때: 레이저 타임스탬프와 tf 시각이 다른 시계에서 왔는지 뺄셈으로 확인하기
레이저 토픽도 들어오고 tf도 발행되는데 메시지 필터가 Message Filter dropping message: frame 'laser' at time ...을 계속 찍으며 스캔을 버린다. Robotics Stack Exchange에 2023-08-22 올라온 질문은 이때 로그의 시각과 tf 시각을 어떻게 비교해야 원인을 좁힐 수 있느냐고 묻는다. 이 상황을 ROS 2 Jazzy 컨테이너에서 레이저 노드와 tf 노드의 시계 조합 다섯 가지로 재현하는 동안 스크립트를 고친 곳은 측정 출력 한 군데였다. 같은 시계에서도 tf2는 Lookup would require extrapolation into the future를 남기는데, 외삽(extrapolation)은 가진 데이터 범위 밖의 시각을 추정해야 한다는 뜻이고 여기서는 버퍼에 있는 tf보다 나중 시각을 요청했다는 말이다. 실험 전 예측표에 적어 둔 대로 잠깐 기다렸다 통과하는 경우였지만, 첫 시험 실행의 출력에는 통과 합계만 있어 곧바로 통과한 스캔과 기다렸다 통과한 스캔이 구분되지 않았다. 그래서 대기 후 통과 수를 따로 세도록 고쳐 다시 돌렸다.
고친 스크립트를 다섯 번 돌리자 같은 시계 두 경우는 매번 스캔 40개가 모두 통과했다. 같은 미래 외삽 문구는 레이저만 시스템 시계를 쓴 경우에도 나왔고, 그때는 한 개도 통과하지 못했다. 문구로는 두 경우가 갈리지 않는다. 갈리는 것은 숫자다. 레이저 스탬프에서 tf 최신 스탬프를 빼면 같은 시계일 때는 많아야 0.01초 남짓, 한쪽만 시스템 시계일 때는 17.9억 초 규모였고, 부호가 어느 쪽 노드인지 알려 줬다. 이 글을 읽고 나면 그 뺄셈 한 번으로 시계 혼동인지 아닌지를 가르고, 어느 노드의 use_sim_time부터 볼지 정할 수 있다. 토픽과 header.stamp, 그리고 ROS 2에서 tf2가 맡는 역할 정도를 알고 있으면 따라올 수 있다.
드롭 로그의 at time은 레이저 스탬프이고, 대괄호 시각은 시스템 시각이다
먼저 용어 하나. 메시지 필터(message filter, tf2_ros::MessageFilter)는 센서 메시지를 잠시 붙잡아 두는 대기실이다. 메시지에 적힌 시각의 좌표 변환이 tf 버퍼에 준비되면 콜백으로 넘기고, 준비될 가망이 없거나 대기실이 꽉 차면 버린다. RViz, slam_toolbox, costmap 같은 노드가 스캔을 받을 때 이 필터를 거친다. 메시지에 적힌 시각은 타임스탬프(timestamp)라고 부르며, header.stamp에 초(sec)와 나노초(nanosec) 정수 두 개로 들어 있다. 데이터가 언제 측정됐는지를 적어 둔 값이다.
실제 드롭 로그 한 줄에는 시각이 두 개 있다. ros2/ros2#1653에 올라온 줄을 보면 이렇다.
[INFO] [1741356033.165430673] [rviz]: Message Filter dropping message: frame 'sualan36/odom' at time 3.960 for reason '...'
at time 3.960은 버려진 메시지의 header.stamp다. MessageFilter::signalFailure가 소수 셋째 자리까지 찍는다(message_filter.hpp L704-L717). 앞쪽 대괄호의 1741356033.165430673은 rcutils 로깅이 rcutils_system_time_now()로 찍는 출력 시각이라 노드의 use_sim_time과 상관이 없다(rcutils logging.c L1200-L1205).
그러니 tf 쪽 시각은 이 로그 어디에도 없다. 대괄호 시각을 tf 시각으로 착각해 at time과 빼면, 시뮬레이션 환경에서는 시계가 멀쩡해도 언제나 수십억 초 차이가 나온다. 위 줄도 그 모양이다. 아래 측정에서 sim time 노드가 같은 형식으로 찍은 로그의 대괄호 시각도 실제 시스템 시각과 맞았다. 뺄셈의 두 번째 값은 로그 밖에서 따로 구해야 한다.
같은 순간을 두 시계는 다른 숫자로 센다
시스템 시각(system time)은 운영체제의 달력 시계다. 1970-01-01 UTC부터 센 초라서 2026년에는 약 17.9억 초다. 시뮬레이션 시각(simulation time)은 Gazebo 같은 시뮬레이터나 bag 재생기가 /clock 토픽으로 알려 주는 시각이고, 보통 0 근처에서 출발한다. 노드가 now()로 받는 ROS 시각(ROS time)은 이 둘 중 하나를 따른다. ROS 2 설계 문서에 따르면 use_sim_time이 꺼진 노드의 ROS 시각은 시스템 시각과 같고, 켜진 노드는 마지막으로 받은 /clock 값을 쓴다. 아직 /clock을 하나도 받지 못했다면 0을 돌려주며, 이 0은 “초기화되지 않음”으로 다뤄야 한다(ROS 2 Design: Clock and Time).
입문자가 놓치기 쉬운 부분은 use_sim_time이 시스템 전체 스위치가 아니라는 점이다. ROS 2 튜토리얼은 “Every node has the parameter use_sim_time”이라고 적는다(Understanding parameters, Jazzy). 시뮬레이터를 띄우고 RViz에만 use_sim_time:=true를 주면, 레이저 드라이버나 tf 발행 노드는 여전히 시스템 시각으로 스탬프를 찍을 수 있다.
tf2는 좌표계 사이의 변환을 시간 축으로 쌓아 둔 버퍼에서 “요청한 시각의 변환”을 찾아 준다(About tf2, Jazzy). 보관 길이, 즉 캐시 길이(cache time)의 기본값은 10초다(buffer_core.hpp L74). 레이저 스탬프가 다른 시계로 찍혀 버퍼의 tf 시각과 17.9억 초 떨어져 있으면, 10초짜리 창 안에서 그 시각을 찾을 방법이 없다.
출발 시각이 다른 스톱워치 두 개를 떠올리면 쉽다. 하나는 1970년에 눌렀고 하나는 시뮬레이터를 켤 때 눌렀다. 같은 순간을 재도 두 숫자는 출발점 차이만큼 벌어진다. 다만 비유는 여기까지만 맞다. 시뮬레이션 시계는 실제보다 빠르거나 느리게 갈 수 있고, 멈추거나 bag을 다시 틀면 뒤로 돌아가기도 한다. 그래서 두 시계 사이의 차이는 고정된 상수가 아니다. 시계 종류의 구분은 ROS 2 시뮬레이션 시간이 뒤로 점프할 때 타이머 문제를 다룬 글에서 더 자세히 다뤘다.
측정 전에 산술로 먼저 예측해 두었다. tf 버퍼의 최신 스탬프를 125.25초로 두고, 시스템 시각은 설명용으로 1790000000초라고 가정했다(실제 값이 아니라 고른 값이다).
| 경우 | 레이저 스탬프 | tf 최신 스탬프 | 레이저 − tf |
|---|---|---|---|
둘 다 /clock |
125.5 | 125.25 | +0.25 s |
| 둘 다 시스템 시계 | 1790000000.5 | 1790000000.25 | +0.25 s |
| 레이저만 시스템 시계 | 1790000000 | 125.25 | +1789999874.75 s |
| tf만 시스템 시계 | 125.5 | 1790000000 | −1789999874.5 s |
레이저가 /clock 수신 전 |
0 | 125.25 | −125.25 s |
둘째 줄이 중요한 반례다. 스탬프가 17.9억처럼 커 보여도 두 값이 같은 시계에서 왔으면 차이는 0.25초다. 숫자의 크기가 아니라 같은 시계인지가 기준이다. 이 산술은 example.py로 작성했고, Python 3.12.3에서 python3 -I example.py로 실행해 종료 상태 0과 일곱 사례의 기대값 일치를 verification.json에 남겼다. 뺄셈이 맞는지만 확인하는 검산이며, ROS 노드를 돌린 결과는 아니다.
시계 조합 다섯 가지를 실제 tf2 버퍼에 넣은 결과
예측이 실제 tf2에서도 그대로 나오는지는 2026년 10월 3일(KST) 컨테이너 안의 자동 실행으로 확인했다. 환경은 ros:jazzy-ros-base 이미지(digest sha256:066420e0…48ca), Python 3.12.3, rclpy 7.1.12-1noble.20260902.053513, 기본 RMW인 rmw_fastrtps_cpp이고, 네트워크 없이 CPU 1개와 메모리 1 GiB로 제한했다. 같은 스크립트를 다섯 번 실행했고 다섯 번 모두 종료 코드 0으로, 한 번에 약 14.6초 걸렸다. 실물 라이다, 시뮬레이터, RViz나 slam_toolbox는 쓰지 않았다.
한 프로세스 안에 노드를 띄웠다. clock_src는 10 ms마다 /clock에 “120초 + 경과 시간”을 발행하고, 같은 타이머로 tf(50 Hz)와 스캔(20 Hz) 발행 시점을 구동한다. 스탬프는 각 발행 노드가 자기 get_clock().now()로 찍는다. 경우마다 use_sim_time 조합만 바꾼 레이저 노드와 tf 노드(동적 odom→base_link, 정적 base_link→laser)를 새로 만든다. 받는 쪽 consumer는 시뮬레이션 속 RViz 자리에 해당해 use_sim_time=True이고, 캐시 10초짜리 tf2_ros.Buffer를 쓴다. 스탬프 0 경우는 레이저 노드의 /clock 구독을 아무도 발행하지 않는 이름으로 돌려 “아직 /clock을 못 받은 레이저 노드”를 만들었다.
드롭 여부는 C++ MessageFilter를 직접 돌린 것이 아니라 그 분기를 Python으로 단순화해 옮긴 판정기가 정했다. 변환이 되는지와 오류 문자열은 실제 tf2 버퍼의 답이고, 대기열 크기 5는 실험에서 고른 값이다. 판정기의 핵심 분기는 다음과 같다.
def add(self, frame, stamp):
if self._can(frame, stamp):
self.passed += 1
return
try:
latest = sec(self.buffer.get_latest_common_time(self.target, frame))
except Exception: # 경로가 아직 없으면 최신 시각을 알 수 없다 -> 대기
latest = 0.0
if latest != 0.0 and sec(stamp) + CACHE_SEC < latest:
self.dropped_immediate += 1
return
self.queue.append((frame, stamp))
if len(self.queue) > QUEUE:
self.queue.pop(0)
self.dropped_queue_full += 1
판정기는 같은 스캔을 두 목적지로 동시에 판정했다. 하나는 동적 변환을 거치는 odom, 다른 하나는 정적 변환만 거치는 base_link다. 측정 창은 경우마다 2초(시스템 시계)이고, 한 번을 빼면 그동안 스캔 40개가 들어왔다.
| 경우 (레이저 / tf) | 계산으로 예측한 차이 | 측정한 레이저 − tf (중앙값, 5회 범위) | 목적지 odom (동적 경로) |
목적지 base_link (정적 경로만) |
|---|---|---|---|---|
/clock / /clock |
작은 양수 | 0.0047 ~ 0.005 s | 40개 모두 통과, 그중 20개는 대기 후 통과 | 40개 즉시 통과 |
| 시스템 / 시스템 | 작은 양수(스탬프 자체는 수십억) | 0.005 ~ 0.0051 s | 40개 모두 통과, 40개 전부 대기 후 통과 | 40개 즉시 통과 |
시스템 / /clock |
양수, 수십억 초 | +1791021145.3394 (1회차) ~ +1791021203.6683 (5회차) | 통과 0, 대기열 넘침 드롭 35, 창 종료 시 대기 5 (3회차는 스캔 35개, 넘침 30) | 모두 통과 |
/clock / 시스템 |
음수, 수십억 초 | -1791021145.3294 (1회차) ~ -1791021203.6582 (5회차) | 통과 0, 즉시 드롭 40 | 40개 즉시 통과 |
스탬프 0 / /clock |
음수, 그 순간의 sim 시각만큼 | -131.5831 ~ -131.563 s | 40개 즉시 통과. 시각 0으로 조회해 돌려받은 변환의 스탬프가 그 순간 tf 최신 스탬프와 같음(1회차 130.5931) | 40개 즉시 통과 |
같은 시계 두 경우에서 스캔별 차이는 최소 0.0 s, 최대 0.0118 s였다. 시계가 섞인 두 경우의 절댓값은 실행할 때마다 커졌다. 실행마다 sim 시각은 120초에서 다시 출발하지만 시스템 시각은 계속 흘렀기 때문이다. 부호와 규모는 다섯 번 모두 같았다.
로그 대괄호 시각도 따로 쟀다. use_sim_time=True 노드가 /clock(120초)을 받은 뒤 드롭 로그와 같은 형식의 INFO 한 줄을 찍게 했다. 1회차에서 at time은 120.0, 대괄호는 1791021265.1012058이었다. 대괄호 시각에서 로그 직전 time.time()을 뺀 값은 다섯 번 동안 0.0165 ~ 0.0194 s였고, 매번 로그 직전·직후 time.time() 간격(0.0166 ~ 0.0195 s) 안에 들어갔다.
1회차 원본 출력 가운데 판단을 바꾼 네 줄이다.
{"kind": "log_bracket", "child_exit": 0, "bracket_time": 1791021265.1012058, "at_time": 120.0, "bracket_minus_at_time": 1791021145.101, "bracket_minus_system_time_s": 0.0194, "system_time_window_s": 0.0195}
{"kind": "case", "case": "same_sim", "laser_use_sim_time": true, "tf_use_sim_time": true, "laser_clock_blocked": false, "laser_clock_now_s": 120.913, "tf_clock_now_s": 120.913, "scans": 40, "first_scan_stamp_s": 120.943, "tf_latest_at_first_scan_s": 120.933, "diff_laser_minus_tf_median_s": 0.005, "diff_min_s": 0.0, "diff_max_s": 0.0118, "judges": {"target_odom_dynamic": {"passed": 40, "passed_after_wait": 20, "drop_immediate": 0, "drop_queue_full": 0, "pending": 0, "first_tf2_error": "Lookup would require extrapolation into the future. Requested time 120.943139 but the latest data is at time 120.933150, when looking up transform from frame [same_sim/l"}, "target_base_link_static_only": {"passed": 40, "passed_after_wait": 0, "drop_immediate": 0, "drop_queue_full": 0, "pending": 0, "first_tf2_error": null}}}
{"kind": "case", "case": "laser_system_tf_sim", "laser_use_sim_time": false, "tf_use_sim_time": true, "laser_clock_blocked": false, "laser_clock_now_s": 1791021271.088, "tf_clock_now_s": 125.763, "scans": 40, "first_scan_stamp_s": 1791021271.128, "tf_latest_at_first_scan_s": 125.793, "diff_laser_minus_tf_median_s": 1791021145.3394, "diff_min_s": 1791021145.3344, "diff_max_s": 1791021145.3445, "judges": {"target_odom_dynamic": {"passed": 0, "passed_after_wait": 0, "drop_immediate": 0, "drop_queue_full": 35, "pending": 5, "first_tf2_error": "Lookup would require extrapolation into the future. Requested time 1791021271.127658 but the latest data is at time 125.793160, when looking up transform from frame [las"}, "target_base_link_static_only": {"passed": 40, "passed_after_wait": 0, "drop_immediate": 0, "drop_queue_full": 0, "pending": 0, "first_tf2_error": null}}}
{"kind": "case", "case": "laser_sim_tf_system", "laser_use_sim_time": true, "tf_use_sim_time": false, "laser_clock_blocked": false, "laser_clock_now_s": 128.183, "tf_clock_now_s": 1791021273.508, "scans": 40, "first_scan_stamp_s": 128.193, "tf_latest_at_first_scan_s": 1791021273.527, "diff_laser_minus_tf_median_s": -1791021145.3294, "diff_min_s": -1791021145.3345, "diff_max_s": -1791021145.3244, "judges": {"target_odom_dynamic": {"passed": 0, "passed_after_wait": 0, "drop_immediate": 40, "drop_queue_full": 0, "pending": 0, "first_tf2_error": "Lookup would require extrapolation into the past. Requested time 128.193093 but the earliest data is at time 1791021273.107409, when looking up transform from frame [las"}, "target_base_link_static_only": {"passed": 40, "passed_after_wait": 0, "drop_immediate": 0, "drop_queue_full": 0, "pending": 0, "first_tf2_error": null}}}
예측과 측정이 갈린 곳은 절댓값뿐이다. 실험의 시뮬레이션 시각은 120초에서 출발했고 시스템 시각은 가정값이 아니라 실제 시각이었으니 숫자가 다른 것은 당연하다. 부호, 그리고 “작은 값 대 수십억 초”라는 규모의 구분은 다섯 경우 모두 예측대로였다.
부호가 드롭 경로를 가른다
차이가 양수로 수십억 초라면 레이저 스탬프가 tf보다 한참 미래에 있다는 뜻이고, 레이저 노드가 시스템 시계를 쓰는 경우다. tf2는 extrapolation into the future, 즉 “가진 데이터보다 미래를 요청했다”고 답한다. 메시지 필터 입장에서 미래 스탬프는 tf가 곧 따라올 수도 있는 정상적인 대기 상황이라 버리지 않고 붙잡아 둔다. 하지만 /clock을 따르는 tf가 17.9억 초에 도달할 일은 없으니, 측정에서도 대기열이 다섯 칸을 넘을 때마다 가장 오래된 스캔이 밀려 나갔다. geometry2 jazzy 소스에서 MessageFilter의 buffer_timeout 기본값은 duration::max()라 사실상 시간 초과가 없고(L166-L171), 대기열이 차면 'discarding message because the queue is full' 사유로 버린다(L412-L424).
음수로 수십억 초라면 반대다. tf 발행 노드가 시스템 시계를 쓰고, 레이저 스탬프는 버퍼의 가장 오래된 데이터보다도 한참 과거다. tf2는 extrapolation into the past로 답하고, “요청 시각 + 캐시 길이”가 최신 시각보다 작으면 기다려도 소용없으므로 바로 버린다. 측정에서 40개가 대기 없이 모두 즉시 드롭됐다. 소스에서는 addTransformableRequest가 이 조건에서 즉시 “변환 불가”를 돌려주고(buffer_core.cpp L1326-L1335), Buffer가 예외를 넣으면(buffer.cpp L228-L239) 메시지 필터가 이를 OutTheBack 사유, 즉 'the timestamp on the message is earlier than all the data in the transform cache'로 기록한다(L551-L557).
이 두 사유 문구는 판정기가 아니라 소스에서 읽은 것이고, 실험에서 C++ 메시지 필터가 찍는 문구를 직접 관측하지는 않았다. 그리고 사유 문구는 원인보다 좁게 쓰여 있다. 같은 catch (...)가 시간 초과 예외까지 OutTheBack으로 분류하므로, 사용하는 노드가 유한한 buffer_timeout을 넘기면 미래 스탬프인데도 “earlier than all the data”가 찍힐 수 있다(buffer.cpp L288-L294). 방향은 문구보다 뺄셈의 부호로 판단하는 편이 안전하다.
같은 시계에서 나온 “미래 외삽”은 예측표대로였다. 스캔 스탬프가 그 순간의 tf 최신 스탬프보다 몇 ms 앞섰다는 뜻이었고, 다음 tf가 오자 통과했다. 메시지 필터가 원래 하라고 만든 일이 이 기다림이다. 스크립트 구조로 보면 sim 시각은 10 ms마다 한 번 바뀌므로 tf와 같은 순간에 찍힌 스캔은 스탬프가 같아 곧바로 통과하고, 나머지 절반만 기다린 것으로 보인다. 시스템 시각은 스캔이 tf보다 미세하게 늦게 찍혀 40개 모두 기다렸다. 어느 쪽이든 오류 문자열의 종류는 시계를 섞은 경우와 같았고, 둘을 가른 것은 차이의 규모뿐이었다.
로그가 조용한데도 틀린 두 경우
레이저 노드가 /clock을 받기 전에 찍은 스탬프 0은 드롭되지 않았다. 처음 기획에서는 이 경우를 드롭 원인 가운데 하나로 봤지만, tf2는 조회 시각이 0이면 “가장 최근 공통 시각”으로 바꿔 찾는다(buffer_core.cpp L345-L351). 측정에서도 40개가 즉시 통과했고, 시각 0으로 조회한 변환의 스탬프는 그 순간 tf 최신 스탬프였다. 차이가 -131초 남짓이라 10초 캐시 창을 한참 벗어났는데도 통과한 이유가 이것이다.
로그가 없다고 안심할 일은 아니다. 스캔은 실제로 측정된 순간이 아니라 “지금 가장 최신”인 로봇 자세와 짝지어진다. 로봇이 움직이는 중이라면 스캔이 엉뚱한 위치에 그려질 수 있다. 확인은 ros2 topic echo /scan --field header.stamp에서 0이 보이는지로 한다. 다만 사용하는 노드가 setTolerance()로 허용 오차를 지정했다면 필터가 “스탬프 + tolerance” 시각으로 두 번째 요청을 만들고(tolerance 설정 L332-L336, 두 번째 요청 L397-L401), 그 요청은 0이 아니라서 at time 0.000으로 드롭될 수 있다. 이 tolerance 경로는 소스로만 확인했고 실험에서는 재현하지 않았다.
다른 하나는 정적 변환만 있는 경로다. 목적지를 base_link로 두면 base_link→laser 정적 변환 하나만 거치는데, 시계가 섞인 두 경우에서도 스캔이 모두 통과했다. 정적 변환은 시각 이력이 없고, StaticCache는 요청 시각을 무시하고(static_cache.cpp L37-L43) 최신 시각을 0으로 보고한다(L73-L76). 시계 혼동이 드롭으로 드러나는 것은 경로에 odom→base_link 같은 동적 변환이 끼어 있을 때다. 그래서 RViz의 Fixed Frame을 base_link로 두면 조용하다가 odom이나 map으로 바꾸면 드롭이 쏟아지는 식의 차이가 생길 수 있다. 이 문장은 측정과 소스에서 끌어낸 추론이며 RViz로 확인한 것은 아니다. 뺄셈에 쓸 tf 시각도 정적 변환이 아니라 그 경로의 동적 변환 스탬프여야 한다.
내 로봇에서 뺄셈할 두 값을 구하는 순서
필요한 값은 둘이다. 드롭 로그의 at time(또는 레이저 토픽의 header.stamp)과, 메시지 필터 경로에 있는 동적 변환의 최신 스탬프다. 아래 명령은 ROS 2 공식 CLI 문법이다. 이 글의 컨테이너 실험에서 실행한 명령은 아니므로 출력 예시는 붙이지 않는다.
# 레이저 스탬프 한 번 읽기 (--field, --once는 humble·jazzy ros2topic echo에 있음)
ros2 topic echo /scan --field header.stamp --once
# 경로상 동적 변환의 최신 시각 읽기 (출력의 'At time sec.nanosec')
ros2 run tf2_ros tf2_echo odom base_link
# 관련 노드마다 시계 설정 대조 (<노드 이름>은 레이저 드라이버, tf 발행 노드, RViz 등으로 바꿔 넣는다)
ros2 param get /<노드 이름> use_sim_time
tf2_echo 출력은 한 번 더 확인해야 한다. 이 도구는 sec와 nanosec 정수를 .으로 이어 붙이고 nanosec 앞자리를 0으로 채우지 않는다(tf2_echo.cpp L198-L199). sec=125, nanosec=5000000이면 125.5000000으로 찍히지만 실제 값은 125.005초다. 소수 부분이 아홉 자리인지 보거나 ros2 topic echo /tf에서 sec·nanosec를 따로 읽는다.
빼고 나면 이렇게 나눈다.
- 스캔·tf 주기 수준의 작은 차이: 시계 문제가 아니다. 같은 드롭 로그가 계속되면 tf 트리가 끊겼는지,
frame_id가 트리에 있는 이름인지 본다. 원래 질문의 답변과 ros2/rviz#1615의 답변이 가리킨 곳도 tf 트리였다. - 양수 수십억 초: 레이저 드라이버의
use_sim_time이 꺼져 있다. 드롭 사유는 대개queue is full이다. - 음수 수십억 초: tf 발행 노드(
robot_state_publisher, odom 발행 노드 등)의use_sim_time이 꺼져 있다. 즉시 판정 경로라면 사유는earlier than all the data in the transform cache다. - 레이저 스탬프 0: 레이저 노드가 아직
/clock을 받지 못했다. 드롭보다 잘못된 짝짓기를 의심한다. - 둘 다 시스템 시각인데 수 초 이상 차이: 라이다는 라즈베리 파이에서, tf는 다른 PC에서 나오는 실물 구성이라면 컴퓨터 사이 시계가 어긋났을 수 있다. turtlebot4#611에서 유지보수자는 Pi·Create3·원격 PC의 시간 불일치를 의심하고 chrony(NTP) 설정을 안내했다. 이 경우는 이 글의 실험이 한 컴퓨터 안에서만 돌아 재현하지 못했다.
1초를 경계로 삼는 설명도 보이지만 이는 공식 기준이 아니다. 소스가 정한 경계는 캐시 길이(기본 10초)이고, 시계가 섞였을 때의 차이는 그보다 여덟 자리 이상 크다. 그러니 대기열이나 tf 캐시를 늘리는 처방은 시계를 맞춘 다음에 따질 일이다. 10초 창을 몇 배로 키워도 17.9억 초는 메워지지 않는다.
실물 로봇이라면 두 가지를 덧붙인다. 하나, /clock을 발행하는 시뮬레이터나 bag 재생이 없는 장비에서 use_sim_time을 켜면 ROS 시각이 0에 머문다. 실물 장비에서는 원칙적으로 켜지 않고, 시뮬레이션·bag 재생일 때는 관련 노드 모두에 같은 값을 준다. 둘, 드롭이 이어지는 동안 스캔은 SLAM이나 costmap에 반영되지 않아 장애물 정보가 갱신되지 않을 수 있다. 원인을 고치기 전에는 정지 상태에서 진단하고, 움직여야 한다면 비상정지 버튼에 손이 닿는 상태에서 저속으로만 움직인다. 이는 일반적인 운용 주의이며 특정 장비로 검증한 절차가 아니다.
두 로그로 판정해 보기
문제 1. 드롭 로그가 at time 2936.389 for reason 'the timestamp on the message is earlier than all the data in the transform cache'이고, tf2_echo odom base_link의 시각이 1659319692대라고 하자. 어느 노드부터 볼까?
답: 레이저 − tf가 음수이고 수십억 초 규모다. 레이저는 /clock을, tf 발행 노드는 시스템 시계를 쓰고 있으니 tf 발행 노드의 use_sim_time부터 확인한다. 측정의 /clock / 시스템 경우와 같은 모양이다.
문제 2. 레이저 스탬프와 tf 스탬프가 모두 1761521468대이고 차이가 0.1초인데 discarding message because the queue is full이 계속 찍힌다. 시계를 의심해야 할까?
답: 아니다. 둘 다 시스템 시각 범위이고 차이도 작으니 시계 혼동은 배제된다. 큰 스탬프 자체는 오류가 아니다. frame 'laser'가 tf 트리에 실제로 있는지, 목적지 프레임까지 경로가 이어지는지를 본다. 같은 숫자 범위의 로그가 ros2/rviz#1615에 있지만, 그 사례의 원인을 이 판정으로 단정하지는 않는다.
이 측정이 보여 주지 못한 것
판정기는 C++ MessageFilter 자체가 아니라 분기를 옮긴 단순화다. tolerance, 유한한 buffer_timeout, 다중 스레드 콜백은 재현하지 않았다. 대기열 크기 5도 실험에서 고른 값이라, RViz·slam_toolbox·Nav2 costmap이 실제로 쓰는 대기열 크기와 timeout은 확인하지 않았다. 따라서 “35개 넘침, 5개 대기” 같은 개수는 이 설정에서의 값이고, 사유 문구는 소스 읽기에 근거한다. Foxy 시절 slam_toolbox#491처럼 사유가 'Unknown'으로 찍힌 사례도 있지만 그 버전의 코드 경로는 확인하지 않았다. 모든 노드가 한 컴퓨터의 한 프로세스에 있었으므로 네트워크 지연이나 컴퓨터 사이 시계 어긋남도 측정 범위 밖이다. 실험 스크립트는 이 글에 공개 링크로 싣지 않았다. 독자가 직접 실행할 수 있는 자료는 위의 산술 검산 파일까지다.
이 한계 안에서도 뺄셈 한 번은 드롭 로그를 처음 만났을 때의 첫 갈림길로 쓸 만하다. 차이가 수십억 초면 노드별 use_sim_time을 맞추는 것으로 시작하고, 작으면 시계는 제쳐 두고 tf 트리와 프레임 이름으로 넘어간다. 아무 로그 없이 스캔 위치만 어긋난다면 레이저 스탬프가 0인지부터 본다. /clock 수신 전 시각 0이 타이머와 첫 dt에서 어떤 문제를 만드는지는 시각 0 문제를 다룬 글에서 이어서 확인할 수 있다.
확인한 자료 (2026-10-03 기준)
- ROS 2 Design — Clock and Time: 시스템 시각과 ROS 시각,
/clock, 수신 전 0의 의미 - ROS 2 Jazzy — About tf2: 시간 축으로 버퍼링한 좌표계 트리
- geometry2 jazzy — message_filter.hpp: 드롭 사유 문자열. 같은 파일의 드롭 로그·대기열·예외 분류 줄은 본문에 연결했다. humble·lyrical·rolling 브랜치에서도 같은 문구와 분기를 확인했다.
- geometry2 jazzy — buffer_core.cpp: 즉시 변환 불가 조건
- rcutils jazzy — logging.c: 콘솔 로그 시각의 출처
- 공개 사례(현상 예시이며 원인 단정 근거가 아님): ros2/ros2#1653, ros2/rviz#1615, turtlebot4#611, slam_toolbox#491
