1293.75 Tick 실행 흐름의 로깅

1. Tick 로깅의 목적

Tick 실행 흐름의 로깅이란, 행동 트리의 Tick 실행 과정에서 발생하는 노드 방문, 상태 전이, 반환 값 등의 이벤트를 시간 순서대로 기록하는 것을 의미한다. 로깅은 디버깅, 성능 분석, 동작 검증, 사후 분석(post-mortem analysis)을 위한 기본적 도구이다. BehaviorTree.CPP v4는 내장 로깅 인프라를 제공하여 트리의 실행 흐름을 체계적으로 기록할 수 있다(Faconti, 2022).

2. BehaviorTree.CPP의 로깅 인프라

2.1 StatusChangeLogger

BehaviorTree.CPP는 StatusChangeLogger 기반 클래스를 제공하여, 노드의 상태 변화를 감지하고 기록하는 로거를 구현할 수 있다.

class TickFlowLogger : public BT::StatusChangeLogger {
public:
    TickFlowLogger(const BT::Tree& tree) : StatusChangeLogger(tree.rootNode()) {}

    void callback(BT::Duration timestamp,
                  const BT::TreeNode& node,
                  BT::NodeStatus prev_status,
                  BT::NodeStatus status) override {
        auto ms = std::chrono::duration_cast<
            std::chrono::milliseconds>(timestamp).count();
        
        printf("[%ld ms] %s: %s -> %s\n",
               ms,
               node.name().c_str(),
               toStr(prev_status).c_str(),
               toStr(status).c_str());
    }

    void flush() override {
        // 버퍼 플러시
    }
};

2.2 FileLogger

BehaviorTree.CPP v4는 FileLogger2를 기본 제공하여, Tick 실행 흐름을 바이너리 파일로 기록한다. 이 파일은 Groot2 시각화 도구에서 재생할 수 있다.

auto tree = factory.createTreeFromFile("tree.xml");
BT::FileLogger2 logger(tree, "bt_trace.btlog");

while (rclcpp::ok()) {
    tree.tickOnce();
    // logger가 자동으로 상태 변화를 기록
}

2.3 MinitraceLogger

MinitraceLogger는 Chrome Tracing 형식으로 실행 흐름을 기록하여, 크롬 브라우저의 chrome://tracing에서 시각화할 수 있다.

BT::MinitraceLogger minitrace_logger(tree, "bt_trace.json");

3. 로깅 항목

3.1 기본 로깅 항목

3.2 확장 로깅 항목

void callback(BT::Duration timestamp,
              const BT::TreeNode& node,
              BT::NodeStatus prev_status,
              BT::NodeStatus status) override {
    LogEntry entry;
    entry.timestamp = timestamp;
    entry.tick_number = current_tick_;
    entry.node_name = node.name();
    entry.node_uid = node.UID();
    entry.prev_status = prev_status;
    entry.new_status = status;
    entry.tree_path = getTreePath(node);  // 루트부터의 경로
    
    log_buffer_.push_back(entry);
}

4. ROS2 로깅 통합

행동 트리의 로깅을 ROS2의 로깅 시스템과 통합하면, 다른 ROS2 노드의 로그와 함께 시간순으로 분석할 수 있다.

class ROS2Logger : public BT::StatusChangeLogger {
public:
    ROS2Logger(const BT::Tree& tree, rclcpp::Node::SharedPtr node)
        : StatusChangeLogger(tree.rootNode()), node_(node) {}

    void callback(BT::Duration timestamp,
                  const BT::TreeNode& bt_node,
                  BT::NodeStatus prev_status,
                  BT::NodeStatus status) override {
        RCLCPP_INFO(node_->get_logger(),
            "[BT] %s: %s -> %s",
            bt_node.name().c_str(),
            BT::toStr(prev_status).c_str(),
            BT::toStr(status).c_str());
    }

    void flush() override {}

private:
    rclcpp::Node::SharedPtr node_;
};

5. 토픽 기반 로깅

행동 트리의 상태 변화를 ROS2 토픽으로 발행하여, 외부 모니터링 시스템에서 실시간으로 구독할 수 있다.

void callback(BT::Duration timestamp,
              const BT::TreeNode& node,
              BT::NodeStatus prev_status,
              BT::NodeStatus status) override {
    auto msg = bt_interfaces::msg::NodeStatus();
    msg.header.stamp = ros_node_->now();
    msg.node_name = node.name();
    msg.previous_status = statusToString(prev_status);
    msg.current_status = statusToString(status);
    msg.tick_number = current_tick_;
    
    status_pub_->publish(msg);
}

6. 로깅 성능 고려 사항

로깅 자체가 Tick 실행 시간에 영향을 미치므로, 로깅의 오버헤드를 최소화해야 한다.

6.1 로그 수준 제어

상세 로깅은 디버깅 시에만 활성화하고, 운영 환경에서는 오류와 경고만 기록한다.

void callback(BT::Duration timestamp,
              const BT::TreeNode& node,
              BT::NodeStatus prev_status,
              BT::NodeStatus status) override {
    if (log_level_ == LogLevel::VERBOSE) {
        // 모든 상태 변화 기록
        logEntry(timestamp, node, prev_status, status);
    } else if (log_level_ == LogLevel::NORMAL) {
        // 주요 상태 변화만 기록 (RUNNING→SUCCESS, RUNNING→FAILURE)
        if (prev_status == BT::NodeStatus::RUNNING && 
            status != BT::NodeStatus::RUNNING) {
            logEntry(timestamp, node, prev_status, status);
        }
    }
}

6.2 비동기 로깅

로그 기록을 별도 스레드에서 수행하여 Tick 스레드의 실행 시간에 대한 영향을 최소화한다.

void callback(BT::Duration timestamp,
              const BT::TreeNode& node,
              BT::NodeStatus prev_status,
              BT::NodeStatus status) override {
    // 로그 엔트리를 락-프리 큐에 삽입 (비차단)
    log_queue_.push({timestamp, node.name(), prev_status, status});
    // 별도 스레드가 큐에서 꺼내어 파일에 기록
}

7. 로그 파일 관리

장시간 운영 시 로그 파일의 크기가 증가하므로, 순환 로깅(rotating log) 또는 시간 기반 분할을 적용한다. 바이너리 형식의 로그는 텍스트 형식보다 저장 효율이 높으며, BehaviorTree.CPP의 FileLogger2가 이 방식을 채택한다.

참고 문헌

• Colledanchise, M., & Ogren, P. (2018). Behavior Trees in Robotics and AI: An Introduction. CRC Press.
• Faconti, D. (2022). BehaviorTree.CPP documentation and API reference. https://www.behaviortree.dev/