(최적화 3) 저지연 로깅
컴파일 타임 로그 레벨 필터링, 클로저 기반 지연 평가, 전용 로거 스레드로 트레이딩 시스템의 로깅 오버헤드를 최소화합니다.
이전 글: 비트 패킹으로 주문 ID 최적화
이 글은 매매 시스템 시리즈의 최적화 파트 세 번째 글입니다.
다음 글: 코어 격리
로깅의 Trade-off
로깅은 디버깅과 모니터링에 필수입니다. 하지만 나노초를 다투는 HFT에서는 부담이 됩니다.
다음 로깅 코드를 살펴볼까요?
1
2
// 문제: 매 호출마다 문자열 생성 + 포맷팅
log::info!("Order filled: id={}, price={}, qty={}", order_id, price, qty);
겉보기엔 한 줄이지만, 이 매크로 안에서는 이런 일이 일어납니다.
- 로그 레벨 체크
- 문자열 생성 + 포맷팅
- 타임스탬프 생성
- 파일/콘솔 I/O
주문 처리 경로에서 이런 작업이 반복되면 지연이 누적됩니다. 포맷팅과 I/O는 생각보다 무거운 작업입니다. 그럼 이 비용을 어떻게 피할 수 있을까요? 위 한 줄을 구성하는 비용을 하나씩 줄여 봅시다.
먼저 쉬운 것부터 해보겠습니다. 로그 레벨 체크를 런타임이 아니라 컴파일 타임으로 옮겨서, 불필요한 로그 코드를 바이너리에서 아예 없애보겠습니다.
컴파일 타임 레벨 체크
런타임에 로그 레벨을 체크하는 대신, 컴파일 타임에 불필요한 로그를 완전히 제거합니다.
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
// compile_checker.rs
pub const TRACE: usize = 5;
pub const DEBUG: usize = 4;
pub const INFO: usize = 3;
pub const WARN: usize = 2;
pub const ERROR: usize = 1;
pub const OFF: usize = 0;
pub const MAX_LEVEL: usize = if cfg!(feature = "max-level-trace") {
TRACE
} else if cfg!(feature = "max-level-debug") {
DEBUG
} else if cfg!(feature = "max-level-info") {
INFO
} else if cfg!(feature = "max-level-warn") {
WARN
} else if cfg!(feature = "max-level-error") {
ERROR
} else if cfg!(feature = "max-level-off") {
OFF
} else {
TRACE // 기본값
};
매크로에서 이 상수를 사용합니다:
1
2
3
4
5
6
7
macro_rules! log_impl {
($level:expr, $($arg:tt)*) => {{
if $level <= MAX_LEVEL {
// 로깅 코드
}
}};
}
MAX_LEVEL이 INFO(3)이고 $level이 DEBUG(4)라면, if 4 <= 3은 컴파일 타임에 false로 평가됩니다. Rust 컴파일러는 dead code elimination으로 이 블록 전체를 제거합니다.
1
2
3
4
5
6
7
8
# Cargo.toml
[features]
max-level-off = []
max-level-error = []
max-level-warn = []
max-level-info = [] # 프로덕션에서 사용
max-level-debug = []
max-level-trace = [] # 개발 시 사용
결과: DEBUG/TRACE 로그는 프로덕션 바이너리에 아예 존재하지 않습니다. 런타임 오버헤드 제로입니다.
런타임에 로그 레벨을 체크한다면
가장 직관적인 방법은 런타임에 로그 레벨을 결정하는 겁니다. 트레이딩 스레드는 로그를 보내고, 로거 스레드는 로그를 처리하므로 다음과 같이 구현할 수 있습니다.
1
2
3
4
5
6
7
8
9
10
// 런타임 로그 레벨 체크
static LOG_LEVEL: AtomicUsize = AtomicUsize::new(INFO);
macro_rules! log_info {
($($arg:tt)*) => {{
if INFO <= LOG_LEVEL.load(Ordering::Relaxed) {
// 포맷팅 + I/O
}
}};
}
위 의사 코드에서 몇 가지 문제가 보입니다.
- 매 호출마다 atomic load 발생
- 사용하지 않는 로그 코드도 바이너리에 포함
- 컴파일러가 dead code elimination을 못 함 (런타임 값이라)
프로덕션에서는 LOG_LEVEL을 ERROR 혹은 WARN 등으로 올려서 지연을 줄일 수 있지만, 주문 로그는 반드시 남겨야 하기 때문에 HFT애서는 이런 작은 지연이 누적됩니다.
지연 평가: Clone + Closure
컴파일 타임 레벨 체크만으로는 충분하지 않습니다. 진짜 무거운 비용은 문자열 생성, 직렬화, I/O입니다. 다음 단계는 트레이딩 스레드에서 문자열을 만들지 않는 겁니다. 필요한 데이터만 clone해서 클로저로 감싸고, 이 클로저를 로거 스레드로 보냅니다.
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
pub struct LazyMessage {
data: Box<dyn (FnOnce() -> String) + Send + 'static>,
}
impl LazyMessage {
pub fn new<F>(data: F) -> LazyMessage
where
F: (FnOnce() -> String) + Send + 'static,
{
LazyMessage { data: Box::new(data) }
}
pub fn eval(self) -> String {
(self.data)()
}
}
매크로에서 데이터를 클론하고 클로저를 생성합니다:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
macro_rules! flash_info_ct {
($topic:expr; $($key:ident = $value:expr),+) => {{
if INFO <= MAX_LEVEL {
// 1. 필요한 데이터만 clone
$(
let $key = $value.clone();
)+
// 2. 클로저로 감싸기 (아직 문자열 생성 안 함)
let func = move || {
let json_obj = serde_json::json!({
$(stringify!($key): $key,)+
});
// ... 포맷팅은 여기서
json_obj.to_string() + "\n"
};
// 3. 로거 스레드로 전송
LOG_SENDER.try_send(LogMessage::LazyMessage(LazyMessage::new(func)));
}
}};
}
핵심 포인트:
$value.clone()으로 데이터 복제- 클로저는
move로 소유권 가져감 - 문자열 생성/포맷팅은
eval()호출 시점까지 지연
트레이딩 스레드는 clone과 channel send만 하고 바로 다음 작업으로 넘어갑니다.
로거 스레드 분리 + Core Affinity
모든 직렬화와 I/O를 별도 스레드에서 처리합니다.
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
pub static LOG_SENDER: Lazy<Sender<LogMessage>> = Lazy::new(|| {
let (sender, receiver) = unbounded();
*LOGGER_HANDLER.lock().unwrap() = Some(thread::spawn(move || {
let mut rolling_writer: Option<RollingFileWriter> = None;
let mut message_queue: Vec<String> = Vec::with_capacity(buffer_size);
while let Ok(msg) = receiver.recv() {
match msg {
LogMessage::LazyMessage(lazy) => {
// 여기서 비로소 문자열 생성
let message = lazy.eval();
message_queue.push(message);
if should_flush() {
let output = message_queue.join("");
write_output(&output);
message_queue.clear();
}
}
LogMessage::SetCore => {
// Core affinity 설정
if let Some(core_id) = get_target_core() {
core_affinity::set_for_current(core_id);
}
}
// ...
}
}
}));
sender
});
로거 스레드의 역할:
LazyMessage.eval()호출 → 문자열 생성- JSON 직렬화
- 버퍼링
- 파일/콘솔 I/O
- 로그 파일 롤링
Core affinity 설정으로 로거 스레드를 특정 CPU 코어에 고정할 수 있습니다:
1
2
3
4
let _guard = Logger::initialize()
.with_logger_core(7) // CPU 코어 7번에 고정
.with_console_report(true)
.launch();
핵심은 로거 스레드와 트레이딩 스레드를 분리해서, 로깅이 주문 처리 경로를 방해하지 않게 만드는 겁니다.
전체 흐름
1
2
3
4
5
6
7
8
9
10
Trading Thread Logger Thread (Core 7)
| |
| 1. clone data |
| 2. create closure |
| 3. channel.send() |
|-------- LazyMessage ------------>|
| | 4. eval() - string formatting
| (continues trading) | 5. JSON serialization
| | 6. buffering
| | 7. file I/O
트레이딩 스레드가 하는 일:
- 필요한 데이터 clone (비용은 데이터 크기/타입에 따라 달라짐)
- 클로저 생성
- channel send
나머지 무거운 작업은 전부 로거 스레드에서 처리합니다.
벤치마크와 실제 코드는 아래 저장소를 참고하세요:
https://github.com/JunbeomL22/flashlog
사용 예시
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
fn main() {
let _guard = Logger::initialize()
.with_console_report(true)
.with_timezone(TimeZone::Seoul)
.with_logger_core(7)
.with_file("./logs", "trading")?
.launch();
// 트레이딩 루프
loop {
let order = process_order();
// 가벼운 로깅 - clone + send만 발생
flash_info_ct!("Order";
order_id = order.id,
price = order.price,
qty = order.qty
);
}
}
출력 (JSON 형식):
1
{"date":"2026-01-21","time":"09:30:00.123456789","offset":9,"level":"Info","src":"main.rs:15","topic":"Order","data":{"order_id":12345,"price":50000,"qty":10},"message":""}
결론
저지연 로거의 핵심:
- 컴파일 타임 필터링: 불필요한 로그는 바이너리에서 완전히 제거. 런타임 오버헤드 제로.
- 지연 평가: clone + closure만 수행하고, 문자열 생성은 로거 스레드에서 처리.
- 스레드 분리: 직렬화/I/O는 별도 로거 스레드에서 처리해서 트레이딩 스레드를 방해하지 않음.
이렇게 하면 프로덕션에서도 INFO 레벨 로깅을 유지하면서 트레이딩 스레드의 지연을 최소화할 수 있습니다.
구현과 벤치마크는 flashlog에서 확인할 수 있습니다.