실행 중인 프로세스에서 발생하는 모든 메서드 호출을 실시간으로 기록할 수 있다는 사실을 알고 계셨나요? 심지어 실행 중인 프로세스 내부에 코드를 주입해 실행하는 것도 가능합니다. 이 모든 것이 바로 rbtrace 젬의 마법 덕분입니다.
rbtrace의 구조
rbtrace 젬은 크게 두 부분으로 구성됩니다.
- 추적 라이브러리: 추적하고자 하는 코드에 포함시켜 사용하는 라이브러리
- 명령줄 유틸리티: 수집된 추적 데이터를 조회하는 CLI 도구
간단한 예제로 살펴보기
먼저 아주 간단한 예제를 통해 동작 방식을 확인해 보겠습니다. 추적 대상 코드는 매우 단순하며, rbtrace 젬만 require 하면 됩니다.
require 'rbtrace'
require 'digest'
require 'securerandom'
# 무한 루프
while true
# 약간의 작업 수행
Digest::SHA256.digest SecureRandom.random_bytes(2**8)
# 반복마다 1초 대기
sleep 1
end
이제 프로그램을 백그라운드로 실행해 보겠습니다.
$ ruby trace.rb &
[1] 12345
출력된 프로세스 ID(12345)를 rbtrace 명령줄 도구에 전달합니다. 여기서 -f 옵션은 "firehose" 모드를 의미하며, 발생하는 모든 것을 화면에 출력합니다.
$ rbtrace -p 12345 -f
*** attached to process 12345
Fixnum#** <0.000010>
SecureRandom.random_bytes
Integer#to_int <0.000005>
SecureRandom.gen_random
OpenSSL::Random.random_bytes <0.002223>
SecureRandom.gen_random <0.002243>
SecureRandom.random_bytes <0.002290>
Digest::SHA256.digest
Digest::Class#initialize <0.000004>
Digest::Instance#digest
Digest::Base#reset <0.000005>
Digest::Base#update <0.000210>
Digest::Base#finish <0.000006>
Digest::Base#reset <0.000005>
Digest::Instance#digest <0.000267>
Digest::SHA256.digest <0.000308>
Kernel#rand
Kernel#respond_to_missing? <0.000008>
Kernel#rand <0.000071>
Kernel#sleep <1.003233>
정말 놀랍지 않나요? 호출되는 모든 메서드와 해당 메서드가 소요한 시간까지 한눈에 확인할 수 있습니다.
특정 메서드만 집중적으로 추적하기
모든 호출이 아닌 특정 메서드만 집중적으로 추적하고 싶다면 -m 옵션을 사용하면 됩니다.
$ rbtrace -p 12345 -m digest
*** attached to process 12345
Digest::SHA256.digest
Digest::Instance#digest <0.000201>
Digest::SHA256.digest <0.000220>
Digest::SHA256.digest
Digest::Instance#digest <0.000287>
Digest::SHA256.digest <0.000343>
실행 중인 웹 서버에서 힙 덤프 추출하기
이 젬의 가장 강력한 활용 사례는 바로 실행 중인 웹 서버에서 힙 덤프(heap dump)를 추출하는 것입니다. 힙 덤프에는 메모리에 존재하는 모든 객체와 다양한 메타데이터가 담겨 있어, 프로덕션 환경에서 발생하는 메모리 누수를 디버깅할 때 매우 유용합니다.
힙 덤프를 얻으려면 Sam Saffron의 포스트에서 가져온 아래와 같은 명령어를 사용하면 됩니다.
$ bundle exec rbtrace -p <SERVER PID HERE> -e 'Thread.new{GC.start;require "objspace";io=File.open("/tmp/ruby-heap.dump", "w"); ObjectSpace.dump_all(output: io); io.close}'
단, 주의할 점이 있습니다. 힙 덤프는 용량이 상당히 클 수 있습니다. Rails 프로세스의 경우 수백 메가바이트에 달하기도 합니다. 다음은 그중 아주 작은 일부 샘플입니다.
[
{
"type": "ROOT",
"root": "vm",
"references": [
"0x7fb7d38bc3f0",
"0x7fb7d38b79b8",
"0x7fb7d38dff80",
"0x7fb7d38bff50",
"0x7fb7d38bff00",
"0x7fb7d38b4bf0",
"0x7fb7d38bfe88",
"0x7fb7d38bfe60",
"0x7fb7d38ddc80",
"0x7fb7d38dffa8",
"0x7fb7d382fbd0",
"0x7fb7d382fbf8"
]
},
{
"type": "ROOT",
"root": "machine_context",
"references": [
"0x7fb7d382fbf8",
"0x7fb7d382fbf8",
"0x7fb7d3827d40",
"0x7fb7d3827a70",
"0x7fb7d38becb8",
"0x7fb7d38bed08",
"0x7fb7d38ddc80",
"0x7fb7d3827e58",
"0x7fb7d3827e58",
"0x7fb7d38becb8",
"0x7fb7d38becb8",
"0x7fb7d38bc328",
"0x7fb7d38bc378",
"0x7fb7d38ddc80",
"0x7fb7d3835008",
"0x7fb7d3835008",
"0x7fb7d3835008",
"0x7fb7d3835008",
"0x7fb7d3835008"
]
},
{
"type": "ROOT",
"root": "global_list",
"references": [
"0x7fb7d38dff58"
]
},
{
"type": "ROOT",
"root": "global_tbl",
"references": [
"0x7fb7d38c6dc8",
"0x7fb7d38c6dc8",
"0x7fb7d38c65f8",
"0x7fb7d38c6580",
"0x7fb7d38c6508",
"0x7fb7d38c6580",
"0x7fb7d38c6288",
"0x7fb7d38c6288",
"0x7fb7d38c6288",
"0x7fb7d38c6288",
"0x7fb7d38c6288",
"0x7fb7d38bc418",
"0x7fb7d38bc418",
"0x7fb7d38bc418",
"0x7fb7d3835328",
"0x7fb7d3835328"
]
},
{
"address": "0x7fb7d300c5e8",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"embedded": true,
"fstring": true,
"bytesize": 10,
"value": "@exit_code",
"encoding": "US-ASCII",
"memsize": 40,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300c7a0",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"embedded": true,
"fstring": true,
"bytesize": 9,
"value": "exit_code",
"encoding": "US-ASCII",
"memsize": 40,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300c908",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"embedded": true,
"fstring": true,
"bytesize": 19,
"value": "SystemExitException",
"encoding": "US-ASCII",
"memsize": 40,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300cb60",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"embedded": true,
"fstring": true,
"bytesize": 17,
"value": "VerificationError",
"encoding": "US-ASCII",
"memsize": 40,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300cd90",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"embedded": true,
"fstring": true,
"bytesize": 19,
"value": "RubyVersionMismatch",
"encoding": "US-ASCII",
"memsize": 40,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300cfe8",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"embedded": true,
"fstring": true,
"bytesize": 21,
"value": "RemoteSourceException",
"encoding": "US-ASCII",
"memsize": 40,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300d1f0",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"fstring": true,
"bytesize": 25,
"value": "RemoteInstallationSkipped",
"encoding": "US-ASCII",
"memsize": 66,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300d3a8",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"fstring": true,
"bytesize": 27,
"value": "RemoteInstallationCancelled",
"encoding": "US-ASCII",
"memsize": 68,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300d560",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"embedded": true,
"fstring": true,
"bytesize": 11,
"value": "RemoteError",
"encoding": "US-ASCII",
"memsize": 40,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300d830",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"fstring": true,
"bytesize": 26,
"value": "OperationNotSupportedError",
"encoding": "US-ASCII",
"memsize": 67,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300dbc8",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"embedded": true,
"fstring": true,
"bytesize": 12,
"value": "InstallError",
"encoding": "US-ASCII",
"memsize": 40,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300e898",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"embedded": true,
"fstring": true,
"bytesize": 9,
"value": "requester",
"encoding": "US-ASCII",
"memsize": 40,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300eaa0",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"embedded": true,
"fstring": true,
"bytesize": 13,
"value": "build_message",
"encoding": "US-ASCII",
"memsize": 40,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300ec30",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"embedded": true,
"fstring": true,
"bytesize": 8,
"value": "@request",
"encoding": "US-ASCII",
"memsize": 40,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300ede8",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"embedded": true,
"fstring": true,
"bytesize": 7,
"value": "request",
"encoding": "US-ASCII",
"memsize": 40,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
},
{
"address": "0x7fb7d300efa0",
"type": "STRING",
"class": "0x7fb7d38dcee8",
"frozen": true,
"fstring": true,
"bytesize": 27,
"value": "ImpossibleDependenciesError",
"encoding": "US-ASCII",
"memsize": 68,
"flags": {
"wb_protected": true,
"old": true,
"long_lived": true,
"marked": true
}
}
]