Ruby는 개발자에게 높은 생산성을 제공하는 언어로 오랫동안 알려져 왔습니다. 우아한 문법, 강력한 메타프로그래밍 지원처럼 코드 작성 단계에서 생산성을 높여 주는 기능들과 더불어, Ruby에는 TracePoint라는 숨겨진 무기가 있어 "디버깅" 속도를 획기적으로 끌어올릴 수 있습니다.
이 글에서는 간단한 예제를 통해 디버깅에 관해 발견한 두 가지 흥미로운 사실을 먼저 소개하겠습니다.
- 대부분의 경우 버그 자체를 찾는 일은 어렵지 않습니다. 진짜 어려운 것은 프로그램이 어떻게 동작하는지 세부 수준까지 이해하는 것이며, 여기까지 도달하면 대개 버그는 곧바로 눈에 들어옵니다.
- 프로그램을 메서드 호출 수준까지 관찰하는 작업은 시간이 많이 소요되며, 디버깅 과정 전체의 주요 병목 지점입니다.
이어서 TracePoint를 활용해 프로그램이 "스스로 자신의 동작을 말하게" 만듦으로써 디버깅 접근 방식을 어떻게 혁신할 수 있는지 살펴보겠습니다.
디버깅은 프로그램과 설계에 대한 이해에서 출발합니다
plus_1이라는 Ruby 프로그램이 올바르게 동작하지 않는다고 가정해 봅시다. 어떻게 디버깅해야 할까요?
# plus_1.rb
def plus_1(n)
n + 2
end
input = ARGV[0].to_i
puts(plus_1(input))$ ruby plus_1.rb 1
3이상적으로는 다음 3단계만 거치면 버그를 해결할 수 있어야 합니다.
- 설계에서 요구 사항 파악하기
- 현재 구현 내용 이해하기
- 버그 추적하기
1단계: 설계에서 요구 사항 파악하기
기대되는 동작은 무엇일까요? plus_1은 인자로 받은 값에 1을 더해야 합니다. 즉, 커맨드라인에서 입력받은 값에 1을 더하는 것이죠. 그런데 우리는 이것을 어떻게 "알 수" 있을까요?
실무에서는 테스트 케이스, 문서, 목업(mockup)을 읽거나 동료에게 피드백을 요청하는 등의 방식으로 기대 동작을 파악합니다. 결국 우리의 이해는 프로그램이 "어떻게 설계되었는가"에 달려 있습니다.
이 단계가 디버깅 과정에서 가장 중요한 부분입니다. 프로그램이 어떻게 동작해야 하는지 모른다면, 아무리 노력해도 버그를 잡을 수 없습니다.
다만 이 단계에는 팀 커뮤니케이션, 개발 워크플로우 등 여러 요소가 얽혀 있습니다. TracePoint가 이런 문제를 해결해 주지는 못하므로, 오늘은 이 부분을 깊게 다루지 않겠습니다.
2단계: 현재 구현 내용 이해하기
기대 동작을 파악했다면, 이제 프로그램이 실제로 어떻게 동작하는지 알아내야 합니다.
대체로 프로그램의 동작을 완전히 이해하려면 다음 정보들이 필요합니다.
- 프로그램 실행 중 호출된 메서드 목록
- 메서드 호출과 반환의 순서
- 각 메서드 호출에 전달된 인자
- 각 메서드 호출이 반환한 값
- 각 메서드 호출 중 발생한 부수 효과(사이드 이펙트). 예: 데이터 변경, 데이터베이스 요청 등
위 정보를 바탕으로 예제 프로그램의 실행 흐름을 서술해 보겠습니다.
# plus_1.rb
def plus_1(n)
n + 2
end
input = ARGV[0].to_i
puts(plus_1(input))$ ruby plus_1.rb 1
3plus_1이라는 메서드를 정의합니다.ARGV에서 입력값("1")을 가져옵니다."1"에to_i를 호출하여1을 반환받습니다.1을 지역 변수input에 할당합니다.input(1)을 인자로plus_1메서드를 호출합니다. 매개변수n은 이제1을 담고 있습니다.1에 인자2로+메서드를 호출하고, 결과3을 반환합니다.- 5단계의 결과로
3을 반환합니다. puts를 호출합니다.3에to_s를 호출하여"3"을 반환받습니다.- 8단계의
puts호출에"3"을 전달하면, 문자열이 표준 출력(stdout)에 출력되는 부수 효과가 발생합니다. 이후nil을 반환합니다.
이 서술은 100% 정확하지는 않지만, 개념을 설명하기에는 충분합니다.
3단계: 버그 추적하기
이제 프로그램이 "어떻게 동작해야 하는지"와 "실제로 어떻게 동작하는지"를 모두 알았으니, 버그를 찾을 차례입니다. 확보한 정보를 바탕으로 메서드 호출 체인을 위로(10단계부터) 또는 아래로(1단계부터) 따라가며 버그를 추적할 수 있습니다. 이 예제에서는 처음 3을 반환한 지점, 즉 6단계의 1 + 2까지 역추적하면 됩니다.
현실은 이렇게 단순하지 않습니다!
물론 실제 디버깅이 예제처럼 단순하지 않다는 것은 모두 잘 압니다. 실무 프로그램과 이 예제의 결정적인 차이는 바로 규모입니다. 5줄짜리 프로그램을 설명하는 데 10단계나 필요했습니다. 그렇다면 작은 Rails 앱 하나를 분해하려면 몇 단계가 필요할까요? 실제 프로그램을 예제 수준으로 상세히 분해하는 것은 사실상 불가능합니다.
프로그램에 대한 상세한 이해 없이는 명확한 경로를 따라 버그를 추적할 수 없고, 결국 가정과 추측에 의존할 수밖에 없습니다.
정보는 비싸다
눈치채셨겠지만, 디버깅의 핵심 변수는 "얼마나 많은 정보를 확보했는가"입니다. 그런데 그만큼의 정보를 얻으려면 무엇이 필요할까요? 직접 확인해 보겠습니다.
# plus_1_with_tracing.rb
def plus_1(n)
puts("n = #{n}")
n + 2
end
raw_input = ARGV[0]
puts("raw_input: #{raw_input}")
input = raw_input.to_i
puts("input: #{input}")
result = plus_1(input)
puts("result of plus_1 #{result}")
puts(result)$ ruby plus_1_with_tracing.rb 1
raw_input: 1
input: 1
n = 1
result of plus_1: 3
3
보시다시피 이렇게 얻을 수 있는 정보는 두 종류뿐입니다. 일부 변수의 값, 그리고 puts의 평가 순서(즉, 프로그램의 실행 순서)입니다.
그렇다면 이 정보를 얻는 데 드는 비용은 얼마일까요?
def plus_1(n)
+ puts("n = #{n}")
n + 2
end
-input = ARGV[0].to_i
-puts(plus_1(input))
+raw_input = ARGV[0]
+puts("raw_input: #{raw_input}")
+input = raw_input.to_i
+puts("input: #{input}")
+
+result = plus_1(input)
+puts("result of plus_1: #{result}")
+
+puts(result)코드에 puts를 4개 추가해야 했을 뿐만 아니라, 값을 개별적으로 출력하기 위해 로직을 분해해서 중간 상태의 값에 접근할 수 있도록 만들어야 했습니다. 결과적으로 8줄의 변경으로 내부 상태 정보 4개를 얻었습니다. 평균적으로 출력 1줄당 코드 변경 2줄씩 드는 셈입니다! 게다가 변경량은 프로그램 크기에 비례해 선형적으로 늘어나므로, 이를 O(n) 연산에 비유할 수 있습니다.
디버깅은 왜 비쌀까?
프로그램은 유지보수성, 성능, 단순성 등 다양한 목표를 염두에 두고 작성되지만, "추적 용이성(Traceability)", 즉 검사를 위한 값을 손쉽게 꺼낼 수 있도록 설계되는 경우는 드뭅니다. 값을 확인하려면 대개 연결된 메서드 체인을 분리하는 식으로 코드를 수정해야 합니다.
- 확보하는 정보가 많아질수록 코드 추가/변경량도 늘어납니다.
그런데 정보량이 일정 수준을 넘으면 사람이 효율적으로 처리할 수 없게 됩니다. 따라서 정보를 필터링하거나 라벨을 붙여 이해를 돕는 장치가 필요해집니다.
- 정보가 정밀할수록 코드 추가/변경량도 늘어납니다.
마지막으로, 이 작업은 코드베이스를 직접 건드려야 한다는 점에서 자동화가 어렵습니다. 버그마다 코드 영역이 다르기 때문입니다(예: 컨트롤러 vs 모델 로직). 코드베이스가 "데메테르의 법칙(Law of Demeter)"을 엄격히 준수하는 등 추적에 친화적이더라도, 대부분의 경우 변수명과 메서드명을 직접 타이핑해야 합니다.
(사실 Ruby에는 __method__ 같은 트릭으로 이 부담을 줄이는 방법도 있습니다. 하지만 여기서는 복잡하게 만들지 않겠습니다.)
TracePoint: 구원자의 등장
그러나 Ruby는 이 비용을 크게 줄여 주는 탁월한 도구를 제공합니다. 바로 TracePoint입니다. 이미 들어보았거나 사용해 본 분들이 많을 텐데요, 제 경험상 이 강력한 도구를 일상적인 디버깅에 적극 활용하는 개발자는 많지 않습니다.
이 도구로 정보를 빠르게 수집하는 방법을 보여 드리겠습니다. 이번에는 기존 로직을 전혀 건드리지 않고, 앞쪽에 몇 줄의 코드만 추가하면 됩니다.
TracePoint.trace(:call, :return, :c_call, :c_return) do |tp|
event = tp.event.to_s.sub(/(.+(call|return))/, '\2').rjust(6, " ")
message = "#{event} of #{tp.defined_class}##{tp.callee_id} on #{tp.self.inspect}"
# return이 아닌 이벤트에서 `return`을 호출하면 에러가 발생합니다
message += " => #{tp.return_value.inspect}" if tp.event == :return || tp.event == :c_return
puts(message)
end
def plus_1(n)
n + 2
end
input = ARGV[0].to_i
puts(plus_1(input))이 코드를 실행하면 다음과 같은 출력을 볼 수 있습니다.
return of #<Class:TracePoint>#trace on TracePoint => #<TracePoint:c_return `trace'@plus_1_with_trace_point.rb:1>
call of Module#method_added on Object
return of Module#method_added on Object => nil
call of String#to_i on "1"
return of String#to_i on "1" => 1
call of Object#plus_1 on main
return of Object#plus_1 on main => 3
call of Kernel#puts on main
call of IO#puts on #<IO:<STDOUT>>
call of Integer#to_s on 3
return of Integer#to_s on 3 => "3"
call of IO#write on #<IO:<STDOUT>>
3
return of IO#write on #<IO:<STDOUT>> => 2
return of IO#puts on #<IO:<STDOUT>> => nil
return of Kernel#puts on main => nil
코드가 훨씬 읽기 쉬워졌습니다. 놀랍지 않나요? 프로그램의 실행 과정 대부분을 상세한 정보와 함께 출력해 줍니다! 심지어 앞서 만든 실행 단계 분석과도 그대로 매핑할 수 있습니다.
# 이 줄은 무시해도 됩니다. TracePoint가 스스로를 추적한 것입니다 ;D
return of #<Class:TracePoint>#trace on TracePoint => #<TracePoint:c_return `trace'@plus_1_with_trace_point.rb:1>
call of Module#method_added on Object # 1. `plus_1` 메서드를 정의함
return of Module#method_added on Object => nil
call of String#to_i on "1" # 3-1. `"1"`에 `to_i`를 호출
return of String#to_i on "1" => 1 # 3-2. `1`을 반환
call of Object#plus_1 on main # 5. `input`(`1`)을 인자로 `plus_1` 메서드 호출
return of Object#plus_1 on main => 3 # 7. 5단계의 결과로 `3` 반환
call of Kernel#puts on main # 8. `puts` 호출
call of IO#puts on #<IO:<STDOUT>>
call of Integer#to_s on 3 # 9. `3`에 `to_s`를 호출하여 `"3"` 반환
return of Integer#to_s on 3 => "3"
call of IO#write on #<IO:<STDOUT>> # 10-1. 8단계의 `puts` 호출에 `"3"` 전달
# 10-2. 문자열이 표준 출력에 기록되는 부수 효과 발생
3 # 원본 출력
return of IO#write on #<IO:<STDOUT>> => 2
return of IO#puts on #<IO:<STDOUT>> => nil
return of Kernel#puts on main => nil # 10-3. 이후 `nil` 반환
심지어 제가 앞서 설명한 것보다 더 상세하다고 할 수 있습니다! 다만 출력에서 2, 4, 6단계가 빠져 있다는 점을 눈치채셨을 겁니다. 안타깝게도 이 단계들은 다음 이유로 현재 TracePoint로 추적할 수 없습니다.
- 2단계 —
ARGV에서 입력("1") 가져오기- 현재
ARGV와 이어지는[]호출은 call/c_call 이벤트로 간주되지 않습니다.
- 현재
- 4단계 — 지역 변수
input에1할당- 현재 변수 할당에 대응하는 이벤트가 없습니다.
line이벤트 + 정규식으로 (어느 정도는) 추적할 수 있지만 정확하지 않습니다.
- 현재 변수 할당에 대응하는 이벤트가 없습니다.
- 6단계 —
1에 인자2로+메서드를 호출하여3반환- 내장
+연산자나 attribute accessor 메서드처럼 일부 메서드 호출은 현재 추적할 수 없습니다.
- 내장
O(n)에서 O(log n)으로
앞선 예제에서 보셨듯이, TracePoint를 적절히 활용하면 프로그램이 "스스로 자신의 동작을 말하게" 만들 수 있습니다. 필요한 코드 줄 수가 프로그램 크기에 선형적으로 비례하지 않기 때문에, 이제 전체 과정은 O(log(n)) 연산에 가깝다고 할 수 있습니다.
다음 단계
이 글에서는 디버깅의 핵심 난제를 짚어 보았고, TracePoint가 어떻게 게임 체인저가 될 수 있는지 설득해 드렸기를 바랍니다. 다만 지금 당장 TracePoint를 써 보면, 도움보다는 오히려 좌절감을 느끼실 가능성이 높습니다.
TracePoint가 뿜어내는 방대한 정보 속에서 곧 노이즈에 파묻히게 되기 때문입니다. 이제 새로운 과제는 노이즈를 걸러내고 가치 있는 정보만 남기는 것입니다. 예를 들어 대부분의 경우 특정 모델이나 서비스 객체에만 관심이 있을 텐데, 이럴 때는 다음과 같이 수신자(receiver)의 클래스를 기준으로 호출을 필터링할 수 있습니다.
TracePoint.trace(:call) do |tp|
next unless tp.self.is_a?(Order)
# tracing logic
end또 한 가지 유념할 점은 TracePoint에 정의한 블록이 수만 번 평가될 수 있다는 사실입니다. 이런 규모에서는 필터링 로직을 어떻게 구현하느냐에 따라 애플리케이션 성능에 큰 영향을 미칩니다. 예를 들어 다음 방식은 권장하지 않습니다.
TracePoint.trace(:call) do |tp|
trace = caller[0]
next unless trace.match?("app")
# tracing logic
end이 두 가지 문제에 대해서는 별도의 글에서, 제가 발견한 트릭과 주의 사항, 그리고 일반적인 Ruby/Rails 애플리케이션에 바로 쓸 수 있는 보일러플레이트를 소개할 예정입니다.
그리고 이 컨셉이 흥미롭게 느껴지신다면, 구현의 번거로움을 모두 감춰 주는 tapping_device라는 gem도 만들어 두었으니 참고해 보세요.
결론
디버거와 트레이싱은 모두 훌륭한 디버깅 도구이며, 우리는 오랫동안 이들을 사용해 왔습니다. 하지만 이 글에서 보여 드렸듯이, 이 도구들을 활용하려면 디버깅 과정에서 상당한 수작업이 필요합니다. 반면 TracePoint를 활용하면 그중 많은 부분을 자동화할 수 있고, 그만큼 디버깅 효율이 크게 향상됩니다. 이제 TracePoint를 여러분의 디버깅 도구 상자에 추가하고 직접 사용해 보시길 바랍니다.