td-agentのprofiling
末端ノードでnginxのlogをtailしてparseしてごにょごにょしているtd-agent 2.3.1のCPU使用率が50%ぐらいになっていたので、下記を使ってprofilingしてみた。
https://github.com/sonots/fluent-stackprof
なおtd-agentのモニタリングには
https://github.com/matsumana/td-agent_exporter
を使いました。
いままでちゃんとモニタリングしてなくてし始めて気づいたけどピーク時は普通にCPU使用率100%いってた。。。
profiling対象マシンでstackprofをinstall
/usr/sbin/td-agent-gem install stackprof
in_debug_agentを有効化するために下記をtd-agent.confに追加してtd-agentを再起動する。
<source> type debug_agent port 24230 </source>
そうするとtd-agent.logに下記のようなログが出る。
2017-06-07 13:16:08 +0900 [info]: listening dRuby uri="druby://0.0.0.0:24230" object="Engine"
同じマシンの別ruby環境でfluent-stackprofとstackprofをinstall
$ gem install fluent-stackprof $ gem install stackprof
そしてprofilingスタート
$ fluent-stackprof start -h localhost -p 24230
1分後ぐらいにstop
$ fluent-stackprof stop -h localhost -p 24230 -o /tmp/fluent-stackprof.dump
fluent-stackprofがやっていることはdRuby経由でリモートのtd-agentに対してRPCしてます。
stackprofを実行している。なのでリモートのtd-agent側にもstackprofが必要
マジカルだ。
stackprofはrubyのprofilingツールです。
https://github.com/tmm1/stackprof
profilingしたデータを解析してみます。
$ stackprof /tmp/fluent-stackprof.dump --text
==================================
Mode: cpu(1000)
Samples: 40864 (0.06% miss rate)
GC: 4616 (11.30%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
8509 (20.8%) 8509 (20.8%) block in URI::Parser#unescape
13709 (33.5%) 5200 (12.7%) URI::Parser#unescape
34272 (83.9%) 4237 (10.4%) Fluent::NewTailInput::TailWatcher::IOHandler#on_notify
2500 (6.1%) 2500 (6.1%) Fluent::ParserFilter#handle_parsed
2426 (5.9%) 2426 (5.9%) block in Fluent::TextParser::LabeledTSVParser#parse
15309 (37.5%) 1399 (3.4%) block (2 levels) in Fluent::URIDecoder#emit
36174 (88.5%) 1282 (3.1%) Coolio::Loop#run
2279 (5.6%) 1051 (2.6%) Fluent::TextParser::ValuesParser#values_map
3544 (8.7%) 983 (2.4%) Fluent::TextParser::JSONParser#parse
909 (2.2%) 909 (2.2%) block in Fluent::GeoIP#create_placeholder
949 (2.3%) 859 (2.1%) block in Fluent::GeoIP#add_geoip_field
781 (1.9%) 781 (1.9%) block in Fluent::GeoIP#geolocate
584 (1.4%) 584 (1.4%) Fluent::NewTailInput::TailWatcher::RotateHandler#on_notify
582 (1.4%) 582 (1.4%) Fluent::NewTailInput::FilePositionEntry#update_pos
512 (1.3%) 512 (1.3%) block in Fluent::EventStream#to_msgpack_stream
410 (1.0%) 410 (1.0%) Fluent::TextParser::ValuesParser#convert_value_to_nil
386 (0.9%) 386 (0.9%) Fluent::MultiEventStream#initialize
546 (1.3%) 367 (0.9%) Fluent::TextParser::TypeConverter#convert_type
3914 (9.6%) 362 (0.9%) block in Fluent::ParserFilter#filter_stream
226 (0.6%) 226 (0.6%) Fluent::MemoryBufferChunk#<<
13910 (34.0%) 201 (0.5%) URI::Escape#unescape
200 (0.5%) 200 (0.5%) block in Fluent::GeoIP#get_address
179 (0.4%) 179 (0.4%) block in <module:TypeConverter>
179 (0.4%) 179 (0.4%) Fluent::EngineClass::DummyMessagePackFactory#packer
175 (0.4%) 175 (0.4%) Fluent::URIDecoder#tag_mangle
144 (0.4%) 144 (0.4%) MonitorMixin#mon_enter
681 (1.7%) 135 (0.3%) block in Fluent::TextParser::ValuesParser#convert_field_type!
133 (0.3%) 133 (0.3%) rescue in Fluent::NewTailInput::TailWatcher::IOHandler#on_notify
131 (0.3%) 131 (0.3%) Fluent::MultiEventStream#add
119 (0.3%) 119 (0.3%) Fluent::EventRouter::MatchCache#getParser#unescapeが一番使われているようなのでこれを呼び出しているメソッドを探します。
$ stackprof /tmp/fluent-stackprof.dump --method 'Parser#unescape'
block in URI::Parser#unescape (/opt/td-agent/embedded/lib/ruby/2.1.0/uri/common.rb:331)
samples: 8509 self (20.8%) / 8509 total (20.8%)
callers:
8509 ( 100.0%) URI::Parser#unescape
code:
8509 (20.8%) / 8509 (20.8%) | 331 | str.gsub(escaped) { [$&[1, 2].hex].pack('C') }.force_encoding(str.encoding)
| 332 | end
URI::Parser#unescape (/opt/td-agent/embedded/lib/ruby/2.1.0/uri/common.rb:330)
samples: 5200 self (12.7%) / 13709 total (33.5%)
callers:
13709 ( 100.0%) URI::Escape#unescape
callees (8509 total):
8509 ( 100.0%) block in URI::Parser#unescape
code:
| 330 | def unescape(str, escaped = @regexp[:ESCAPED])
13709 (33.5%) / 5200 (12.7%) | 331 | str.gsub(escaped) { [$&[1, 2].hex].pack('C') }.force_encoding(str.encoding)
| 332 | endEscape#unescapeだったのでさらにこれを呼んでいるメソッドを探します。
$ stackprof /tmp/fluent-stackprof.dump --method 'Escape#unescape'
URI::Escape#unescape (/opt/td-agent/embedded/lib/ruby/2.1.0/uri/common.rb:647)
samples: 201 self (0.5%) / 13910 total (34.0%)
callers:
13910 ( 100.0%) block (2 levels) in Fluent::URIDecoder#emit
callees (13709 total):
13709 ( 100.0%) URI::Parser#unescape
code:
| 647 | def unescape(*arg)
185 (0.5%) / 185 (0.5%) | 648 | warn "#{caller(1)[0]}: warning: URI.unescape is obsolete" if $VERBOSE
13725 (33.6%) / 16 (0.0%) | 649 | DEFAULT_PARSER.unescape(*arg)
| 650 | endURIDecoder#emitを呼んでいるメソッドを探します。
$ stackprof /tmp/fluent-stackprof.dump --method 'URIDecoder#emit'
block (2 levels) in Fluent::URIDecoder#emit (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-uri_decoder-0.2.0/lib/fluent/plugin/out_uri_decode.rb:61)
samples: 1399 self (3.4%) / 15309 total (37.5%)
callers:
15309 ( 100.0%) block in Fluent::URIDecoder#emit
callees (13910 total):
13910 ( 100.0%) URI::Escape#unescape
code:
| 61 | @_key_names.each do |key_name|
15309 (37.5%) / 1399 (3.4%) | 62 | record[key_name] = URI.decode(record[key_name] || '')
| 63 | end
Fluent::URIDecoder#emit (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-uri_decoder-0.2.0/lib/fluent/plugin/out_uri_decode.rb:53)
samples: 10 self (0.0%) / 24318 total (59.5%)
callers:
24318 ( 100.0%) Fluent::EventRouter#emit_stream
callees (24308 total):
24125 ( 99.2%) Fluent::MultiEventStream#each
175 ( 0.7%) Fluent::URIDecoder#tag_mangle
8 ( 0.0%) Fluent::NullOutputChain#next
code:
| 53 | def emit(tag, es, chain)
175 (0.4%) | 54 | tag = tag_mangle(tag)
| 55 |
8 (0.0%) / 8 (0.0%) | 56 | @_key_names ||= @key_names.split(/,\s*/)
| 57 | @_key_names << @key_name if @key_name
| 58 | @_key_names.uniq!
| 59 |
24125 (59.0%) | 60 | es.each do |time, record|
| 61 | @_key_names.each do |key_name|
| 62 | record[key_name] = URI.decode(record[key_name] || '')
| 63 | end
| 64 |
| 65 | Fluent::Engine.emit(tag, time, record)
| 66 | end
| 67 |
10 (0.0%) / 2 (0.0%) | 68 | chain.next
| 69 | end
block in Fluent::URIDecoder#emit (/opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-uri_decoder-0.2.0/lib/fluent/plugin/out_uri_decode.rb:60)
samples: 5 self (0.0%) / 24112 total (59.0%)
callers:
24112 ( 100.0%) block in Fluent::MultiEventStream#each
callees (24107 total):
15309 ( 63.5%) block (2 levels) in Fluent::URIDecoder#emit
8798 ( 36.5%) Fluent::EngineClass#emit
code:
| 60 | es.each do |time, record|
15309 (37.5%) | 61 | @_key_names.each do |key_name|
| 62 | record[key_name] = URI.decode(record[key_name] || '')
| 63 | end
| 64 |
8803 (21.5%) / 5 (0.0%) | 65 | Fluent::Engine.emit(tag, time, record)
| 66 | endfluent-plugin-uri_decoderのurl decode処理が重いようです。
諸事情があってurl decodeの処理が必要なのですが、どうすっかなあ。
rubyを最新にすれば早くなったりするかな。
