まとめておく。コレも便利だぜ、とかあったら教えてください

1. [C] gdb

まずはなにはともあれ gdb。例えば指定スレッドのCレベルでのバックトレースを表示させるにはこんなかんじ。

$ sudo gdb -p <pid>
(gdb) info thread
(gdb) thread 14
(gdb) bt

core を吐かせておいてから追う場合はこう

$ sudo gcore <pid>
$ gdb /usr/lib64/fluent/ruby/bin/ruby core.22111
(gdb) info thread
(gdb) thread 14
(gdb) bt

出力端折ったけど、こんなかんじ https://gist.github.com/sonots/10803036

2. [C] gstack

gdb で全スレッドのバックトレースをダンプさせようと思うとめんどくさいが、gstack を使うとできる。

$ sudo gstack <pid>

ただし、core ファイルに対しては適用できない。

pstack というツールもあるらしいが、私の環境だと全く同じものだった(gstack へのシンボリックリンクだった)。

出力はこんなかんじ https://gist.github.com/sonots/f58f632c9e7a5786aa05

3. [C] strace

実行中プロセスのシステムコールを追い続けるには strace を使おう。

$ strace -s 1024 -f -p <pid>

スレッドを追いたい場合は -f をつける。瞬間のダンプではないので処理がすすめば出力は更新される。

出力はこんなかんじ https://gist.github.com/sonots/8020037

strace については以前書いたやつもあるのでそちらも見てもらえると良い => http://blog.livedoor.jp/sonots/archives/18193659.html 

4. [Ruby] gdbruby

https://github.com/gunyarakun/gdbruby

生きているプロセスならば次に記載している sigdump など、他にも ruby レベルのバックトレースを表示するツールがあるが、core ファイルから ruby レベルのバックトレースを表示できるのは gdbruby だけ。

gdbruby.rb core.24113 `rbenv which ruby`

出力サンプルは gunyarakun さんのブログをみると書いてある
=> http://blog.wktk.co.jp/ja/entry/2013/10/30/gdbruby

5. [Ruby] sigdump

https://github.com/frsyuki/sigdump

ruby レベルでの全スレッドのバックトレースをダンプすることができる。gstack の ruby レベル版と言えるか。ついでに、ObjectSpace の状態(どのクラスのインスタンスが何個存在しているかなど）もダンプできる。

使い方はダンプしたいアプリのコードで 

require 'sigdump/setup'

と require しておき、kill -CONT <pid> すると、/tmp/sigdump-<pid>.log のようなファイルに出力される。

出力はこんなかんじ https://gist.github.com/sonots/e05d8fbcd7ab39e4a5f8

なお、コードに仕込んで好きなところでダンプしたい場合は

Sigdump.dump

を呼び出せばできる。=> sigdump.rb#L13

特にコードを遅くするようなこともないので、とりあえず require しておいてよさそう。

6. [Ruby] rbtrace

https://github.com/tmm1/rbtrace

rbtrace は ruby レベルでの strace のようなもの、とのこと。strace 同様、処理が進めば更新される。

trace 対象のアプリで require しておき、

require 'rbtrace'

$ rbtrace -p <pid> --firehose

とかやると追える。※ require すると外から rbtrace で attach できるようになるようだ。内部的には POSIX message queue を使っているっぽい。

firehose は全出力のオプションで以下のようになる。

Kernel#proc <0.000006>

Proc#call
  Dir.chdir
    Dir.pwd <0.000004>
    Process.pid <0.000003>
    String#multiply_vowels
      String#gsub
        String#* <0.000192>
        String#* <0.000003>
      String#gsub <0.000585>
    String#multiply_vowels <0.000593>
    Kernel#rand <0.000003>
    Kernel#sleep <0.239254>
  Dir.chdir <0.239933>
Proc#call <0.239947> 

-m で特定メソッドにしぼったり、--slow で遅いやつだけ出力したりもできる。
=> 詳細は README を読もう https://github.com/tmm1/rbtrace

7. [Ruby] profile

どのメソッドを何回呼び出したのか、平均で何秒かかったのかプロファイリングするには、標準ライブラリの profile を利用できる。

普通に require すると、その瞬間にスタートして、終了時に print する動きをするので、任意の期間に仕込みたい場合は、 profile ではなく profiler を require して以下のようにする。

require 'profiler'
RubyVM::InstructionSequence.compile_option = {
  :trace_instruction => true,
  :specialized_instruction => false
}

# 好きなタイミングで start する
Profiler__::start_profile

# print して終了する
Profiler__::print_profile(STDERR)
Profiler__::stop_profile

出力はこんなかんじ

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
100.00     0.01      0.01        2     5.00     5.00  Hoge.fuga
  0.00     0.01      0.00        2     0.00     0.00  IO#puts
  0.00     0.01      0.00        1     0.00     0.00  TracePoint#enable
  0.00     0.01      0.00        4     0.00     0.00  IO#write
  0.00     0.01      0.00        2     0.00     0.00  Fixnum#to_s
  0.00     0.01      0.00        2     0.00     0.00  Kernel#puts
  0.00     0.01      0.00        4     0.00     2.50  nil#
  0.00     0.01      0.00        1     0.00    10.00  Range#each
  0.00     0.01      0.00        1     0.00     0.00  TracePoint#disable
  0.00     0.01      0.00        1     0.00    10.00  #toplevel

8. [Ruby] tracer

on してから off するまでの ruby レベルの実行をすべてトレース出力するには、 標準ライブラリ tracerを利用できる。

require 'tracer'

# 好きなタイミングでスタートする
Tracer.on

# 好きなタイミングで終了する
Tracer.off

処理が進むたびに逐次出力される。

試しに require 'uri' をトレース出力したのはこんなかんじ
=> https://gist.github.com/sonots/551689f166e9b3cf4aa4

9. [Ruby] stackprof

https://github.com/tmm1/stackprof

これも Ruby レベルのプロファイラ。Ruby 2.1 時代のプロファイラだそうで、ruby 2.1 から入った rb_profile_frames() API を使っているらしい。ruby 標準の profile は正直大分時間と負荷がかかるけれど、こちらだと本番でもイケるらしい。ホントか。

たとえば rack middleware としてこんなかんじで仕込んでおいて、1s ごとにプロファイリングしたりできるようだ。 もちろん普通に ruby コードとしてプロファイリングする箇所を指定して出力を得ることもできる。

# config.ru
use StackProf::Middleware, enabled: true,
                           mode: :cpu,
                           interval: 1000,
                           save_every: 5

コード区間を指定する場合

require 'stackprof'
StackProf.start

// code

StackProf.stop
StackProf.results('/tmp/stackprof.dump')

$ stackprof tmp/stackprof-cpu-*.dump
==================================
  Mode: cpu(1000)
  Samples: 711 (1.52% miss rate)
  GC: 119 (16.74%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       465  (65.4%)          95  (13.4%)     Coolio::IO#on_readable
       332  (46.7%)          70   (9.8%)     Fluent::MeasureTime#measure_time
       513  (72.2%)          48   (6.8%)     Coolio::Loop#run
        30   (4.2%)          30   (4.2%)     Fluent::EngineClass#now
     以下略

$ stackprof tmp/stackprof-cpu-*.dump --method 'String#blank?'

  String#blank? (gems/activesupport-2.3.14.github30/lib/active_support/core_ext/object/blank.rb:80)
    samples:  1595 self (2.6%)  /   1660 total (2.7%)
    callers:
       373  (   41.0%)  ApplicationHelper#current_user
       192  (   21.1%)  ApplicationHelper#current_repository
    callers:
       803  (   48.4%)  Object#present?
    code:
                                    |    80  |   def blank?
   1225    (2.0%) /  1225   (2.0%)  |    81  |     self !~ /[^[:space:]]/
                                    |    82  |   end

作者のこちらのブログで作者の職場である GitHub での事例を元に使い方を教えてくれていて、非常にわかりやすいので一読をすすめる => http://tmm1.net/ruby21-profiling/
rbtrace も同じ作者だけど、tmm1 氏はいろんなの持ってる。 

(追加) 10. [Ruby] memprof2

https://github.com/sonots/memprof2

Ruby レベルのヒープ(メモリ)プロファイラ。Ruby 2.1 から入った trace_object_allocations API を使っている。

使い方はこんな感じで、Memprof2.start と Memprof2.stop で囲った範囲内で、どの行がどのぐらいメモリを消費しているか調べることができる。

# example.rb
require 'memprof2'
Memprof2.start
foo = ["foo"] * 255 # 調べたいやつ
Memprof2.report
Memprof2.stop

$ ruby example.rb
2080 example.rb:3:Array
40 example.rb:3:Array
40 example.rb:3:String

詳細な説明については Ruby でラインメモリプロファイラ の記事に書いている。

def erb(template)
  ERB.new(File.read(File.expand_path("../#{template}", __FILE__))).result(binding)
end

gem 'strftime_logger'
gem 'rack-ltsv_logger'
gem 'rack-config_env'
gem 'switch_point'
gem 'activerecord-refresh_connection'
gem 'unicorn'
gem 'unicorn-worker-killer'
gem 'unicorn-log_error_one_liner' # Make error_log of unicorn to one line
gem 'settingslogic'
gem 'sigdump', require: 'sigdump/setup'

environment erb('config/application.rb')
insert_into_file 'config.ru', erb('config.ru'), after: "require ::File.expand_path('../config/environment',  __FILE__)\n"
file 'config/application.yml', erb('config/application.yml')
file 'config/database.yml', erb('config/database.yml')
file 'app/models/settings.rb', erb('app/models/settings.rb')
file 'config/unicorn.rb', erb('config/unicorn.rb')

デプロイサーバで bundle install してから rsync で ruby アプリを撒く capistrano 拡張作った

• https://github.com/sonots/capistrano-bundle_rsync

リモートホストそれぞれで git clone して bundle install とかやってると明らかにエコではないので、 デプロイサーバでアプリを git clone して bundle install したものを rsync で撒くやつ作った。リモートホストの数が多いようだと大分利いてくる。

あと、このやり方なら、C 拡張な gem のビルドはデプロイサーバでのみ実施できれば良いので、リモートホストに gcc とか xxx-devel とかいらないし、git すらいらないので、アプリサーバを綺麗な体に保てる。※ ただし、デプロイサーバとアプリサーバの arch は同じでなければならない。

使い方

使い方は README にも書いているのだけど、いちおう書いておくと

Gemfile に capistrano-bundle_rsync を追加してもらって、

gem 'capistrano'
gem 'capistrano-rbenv'
gem 'capistrano-bundle_rsync'

Capfile で require して、

# Load DSL and Setup Up Stages
require 'capistrano/setup'

# Includes default deployment tasks
require 'capistrano/deploy'

# Includes tasks from other gems included in your Gemfile
require 'capistrano/rbenv'
require 'capistrano/bundle_rsync'

# Loads custom tasks from `lib/capistrano/tasks' if you have any defined.
Dir.glob('lib/capistrano/tasks/*.rake').each { |r| import r }

例えば localhost ステージをいじる場合は、config/deploy/localhost.rb をこんなかんじにしてもらえると

set :branch, ENV['BRANCH'] || 'master'
set :rbenv_type, :user
set :linked_dirs, %w(bin log tmp/pids tmp/cache tmp/sockets vendor/bundle public/system tmp/run)
set :keep_releases, 5
set :scm, :bundle_rsync # Need this
set :bundle_rsync_max_parallels, ENV['PARA']

set :application, 'sample'
set :repo_url, "git@github.com:sonots/rails-sample.git"
set :deploy_to, "/home/sonots/sample"
set :rbenv_ruby, "2.1.2" # Required on both deploy machine and remote machines
set :ssh_options, user: 'sonots', keys: [File.expand_path('~/.ssh/id_rsa')]

role :app, ['127.0.0.1']

こんなかんじでデプロイできる

bundle exec cap localhost deploy

動作の流れ

内部では

1. デプロイサーバで git clone --mirror URL .local_repo/repo する
2. git archive ブランチ名 で、ブランチを .local_repo/release ディレクトリに展開する。
3. release ディレクトリをリモートサーバに rsync で転送する
4. デプロイサーバで bundle --without development test --path .local_repo/bundle する。
5. bundle ディレクトリを rsync で転送する

みたいなことをしている。

あとは、bundle_rsync_max_parallels オプションとかもあって並列スレッド数を制御することもできるので便利（デフォルト並列数は対象サーバ数）

おわりに

なお、本モジュールは前に @tohae 氏が作ってたものをベースに改造し、氏の承諾のもと公開しております。@tohae++

on(in: :parallel) { ... }
on(in: :sequence, wait: 5) { ... }
on(in: :groups, limit: 2, wait: 5) { ... }

on roles(:all), in: :groups, limit: 2 { ... }

module SSHKit
  class Coordinator
    private
      def default_options
        { in: :groups, limit: 5 }
      end
  end
end 

rack-ltsv_logger とか strftime_logger とか を使って自分が出したいアクセスログやアプリケーションログ(エラーログ)は自分で１行で出せるようにしたので、 もう rails が標準で出すログを止めてしまいたい。 ただし、Rails の Controller で例外を rescue しないでしまった時に出るあのログだけ、error.log に出したい。

TL; DR

config/initializers/tweak_logger.rb あたりに config/application.rb に

require 'logger'
require 'rack-config_env'

module MyAppName
  class Application < RailsApplication
    null_logger = Logger.new(nil).tap {|log| def log.write(msg); end }
    error_logger = Logger.new('error.log')

    config.logger = null_logger
    config.middleware.delete Rails::Rack::Logger # 必須ではないが無駄になるので消す
    config.middleware.insert_after(0, Rack::ConfigEnv, {
      'rack.errors' => null_logger,
      'action_dispatch.logger' => error_logger,
    }) 
  end
end 

のように書く。rack-config_env はこちら。 

Rails.logger を挿げ替える

Rails.logger を挿げ替えるには

config.logger = null_logger

とすればよい。

補足：config/initiailizers/* 以下は、Rails.logger が初期化されてから呼ばれるため(at railties/lib/rails/application/bootstrap.rb)、その時点では config.logger= を使っても挿げ替えることができないようだ。 config/application.rb もしくは config/environments/[env].rb のような早めに呼ばれる箇所で挿げ替える必要がある。

捕捉２：config/application.rb で Rails.logger のログレベルを変更するには config.log_level = 'WARN' のようにする必要がある。config.logger.level = Logger::WARN ではダメなので注意。railties/lib/rails/application/bootstrap.rb で config.logger.level を config.log_level の値(デフォルト debug) で上書きしているのでかき消されてしまう。

Rails::Rack::Logger を消す

デフォルトの rails 設定では Rails::Rack::Logger ミドルウェアを使うようになっており、 内部で Rails.logger を使ってごにょごにょ出力するようになっているが、 Rails.logger を null_logger に挿げ替えたのだからもはや意味がない。

残しておいてもなにも出力されないので、止めてしまってよさそう

cf. https://github.com/rails/rails/blob/master/railties/lib/rails/rack/logger.rb

env['action_dispatch.logger'] をすげ変える

controller で例外をおこした時に出るログを別のファイルに出すには、env['action_dispatch.logger'] を挿げかえる。

FYI: 追った際のログはこちら https://gist.github.com/sonots/0270cb58f14e75362c9b

任意の rack env を挿げ替えるには、拙作の rack-config_env を利用できるので、 それを使ってすげかえる（というか今回作った）。

使い方はこんなかんじ。

config.middleware.insert_after(0, Rack::ConfigEnv, {
  'action_dispatch.logger' => error_logger
})

env['rack.errors'] をすげ変える

rack env の中身を見てみると env['rack.errors'] が IO オブジェクトを握っていたので、念のためすげかえておく。 #write メソッドが必要なようなので、てきとうに生やしてすげかえるようにしてみた(本来は IO オブジェクトを渡せばよさそう)

null_logger = Logger.new('/dev/null').tap {|log| def log.write(msg); end }
config.middleware.insert_after(0, Rack::ConfigEnv, {
  'rack.errors' => null_logger,
})

LogSubscriber も消す

Rails.logger が null_logger になったので何も出ないはずだが、無駄処理になるので消したほうがよさそう。

LogSubscriber というのは、rails の ActiveSupport::Notifications および ActiveSupport::Subscriber が提供する instrumentation の仕組み。この辺の記事を読むと良い。

• http://d.hatena.ne.jp/koshigoeb/20110213/1297595759
• https://gist.github.com/mnutt/566725

subscriber を削除するには、

ActiveSupport::Notifications.unsubscribe "start_processing.action_controller"

のようにする。削除する対象を探すために subscriber 一覧を取得するには

irb>
notifier = ActiveSupport::Notifications.notifier
notifier.instance_variable_get("@subscribers").each {|s|
  klass = s.instance_variable_get(:@delegate).class
  pattern = s.instance_variable_get(:@pattern)
  p "#{klass} #{pattern}"
}
"ActiveRecord::LogSubscriber render_bind.active_record"
"ActiveRecord::LogSubscriber sql.active_record"
"ActiveRecord::LogSubscriber odd?.active_record"
...

のようにすればなんとかできる。※ instance_variable_get だらけでちょっと辛みある。

ただ、ちょっと注意点があって、rails は lazy loading するので、 ActionController::LogSubscriber なんかは controller の処理が入るまで require されていなかったりして、 rails c とか config/initializers/*.rb あたりではまだ登録されていなくて一覧にでてこなかったりする。

subscribe される前に unsubscribe しても当然意味がないので、

require 'actionpack/lib/action_controller/log_subscriber.rb'
ActiveSupport::Notifications.unsubscribe "start_processing.action_controller"

のように明示的に require してから unsubscribe する流れになる。 cf. https://gist.github.com/sonots/f46b2d1b1fb7ca6f5513

ちょっと辛みあるし、Rails.logger を null_logger に置き換えてなにも出なくはなっているので、自分はやらないことにしてしまった。

まだ出る

これでも rails s すると

I, [2014-07-02T02:47:26.090849 #12430]  INFO -- :   Rendered books/_form.html.erb (35.9ms)
I, [2014-07-02T02:47:26.091497 #12430]  INFO -- :   Rendered books/new.html.erb within layouts/application (49.5ms)
I, [2014-07-02T02:47:26.168202 #12430]  INFO -- : Completed 200 OK in 203ms (Views: 134.3ms | ActiveRecord: 1.3ms)

のようなログが性懲りもなく出て来る。が、結論としては気にしなくて良かった。

railties/lib/rails/commands/server.rb#L141-L143 において、rails s で起動した場合に、

      def log_to_stdout
        wrapped_app # touch the app so the logger is set up

        console = ActiveSupport::Logger.new($stdout)
        console.formatter = Rails.logger.formatter
        console.level = Rails.logger.level

        Rails.logger.extend(ActiveSupport::Logger.broadcast(console))
      end

のように $stdout 決め打ちで ActiveSupport::Logger を起動しているために表示されてしまうので、すげかえることが出来ないのだが、 この log_to_stdout メソッドは L43 の条件が示すように、

43:        options[:log_stdout] = options[:daemonize].blank? && (options[:environment] || Rails.env) == "development"

daemon じゃない && development の時にのみ呼ばれるもので、production 環境では表示されない。よって、気にしなくてよかった。

なお、ActiveSupport::Logger は $stdout と Rails.logger 両方に出力するためのラッパー。 どうしても気になる場合はモンキーパッチして止めるしかなさそう。

まとめ

めんどくさい。いちおう最後まで調べたが、ここまでする価値なさそう感ある。

追記：

似たようなことをして、rails の logger を挿げ替えて１行にしたりいらないログを削ったりしているプロジェクトを見つけた https://github.com/roidrage/lograge  参考になりそうだけど、仕組み的には同じなのでつらみありそう 

追記:

自分用メモ。結局 config/application.rb にこんな感じに書いてる。rails のログはいちおう出してるけど、基本見てない。rack-ltsv_logger と strftime_logger を使ってる。

  require_relative '../app/models/settings' # settingslogic

  access_logger = StrftimeLogger.new('/var/log/access_log.%Y%m%d')
  config.middleware.insert_after(0, Rack::LtsvLogger, access_logger)

  $logger = StrftimeLogger.new('/var/log/application_log.%Y%m%d')
  $logger.log_level = Settings.application_log_level

  rails_logger = StrftimeLogger.new('/var/log/rails_log.%Y%m%d')

  config.logger = rails_logger # this line must be at config/application.rb
  config.log_level = Settings.rails_log_level
  config.middleware.insert_after(0, Rack::ConfigEnv, {
    # switch log path for non-rescued exceptions on controller
    'action_dispatch.logger' => $logger,
  })