カジュアルに実行時間を計測する

go

isuconの予選で、カジュアルにここどれぐらい時間がかかっているか計測したい、ということで作った。
pprofは(使い方間違っているだけなのかもしれないけど)CPU時間での計測なので、io待ちとか、channel待ちとかの時間は出てこないので、web applicationのチューニングにはあまり適さないのかなという気がする。

https://github.com/walf443/stopwatch

やりたいこととしては、

  • 計測コードを簡単に無効にできる
  • ここから、ここまで、という指定以外に前回の実行からどれぐらいたったのか? というのも自動でとりたい

ということを達成したかった。

package main

import (
        "flag"
        "github.com/walf443/stopwatch"
        "time"
)

func main() {
        flag.Parse()

        stopwatch.Reset("start request")
        time.Sleep(100 * time.Millisecond)
        stopwatch.Watch("after something")
        time.Sleep(100 * time.Millisecond)
        stopwatch.Watch("after something 2")

}

こんな感じで、HTTPのサーバーであれば、リクエストの関数の冒頭で、Resetを呼びだし、あとは、計測したいタイミングで、Watchを呼びだしていけばよい

デフォルトでは無効になっているので、計測するには、--stopwatchフラグをつけながら起動すると、

$ go run example.go --stopwatch
stopwatch|2014/10/07 09:27:33 [             0][             0] start request at /Users/yoshimin/project/go/src/github.com/walf443/stopwatch/example/example.go:12
stopwatch|2014/10/07 09:27:33 [  100.892037ms][  100.892037ms] after something at /Users/yoshimin/project/go/src/github.com/walf443/stopwatch/example/example.go:14
stopwatch|2014/10/07 09:27:33 [  201.129537ms][    100.2375ms] after something 2 at /Users/yoshimin/project/go/src/github.com/walf443/stopwatch/example/example.go:16

こんな感じで標準出力にログが出てきて、Resetを呼びだしてからの時間と、前回Watchをしてからの時間がわかる。

グローバル変数で実現しているので、関数間でも、別のファイル間でもカジュアルにstopwatch.Watchとか呼べばよい。
もちろんその反面、HTTPサーバーのハンドラに仕込んでいるときに、同時にリクエストが来て、Resetが呼ばれたりすると、カウンタがおかしくなるが、手動で動作させつつ、大まかな時間を調べるのが目的なので、使い勝手のカジュアルさを重視した。

使い終わったら、stopwatchが書いてある行を削除すれば、だいたい消えてくれると思われる。

matsuuさんに、Practical Goで、Nitroの話を聞いたけど、何って名前だったか覚えてなかったので、適当に作った。あっちの方がライブラリとしてはよっぽどちゃんとしている。

config/routes.rbを分割する

とあるサービスのconfig/routes.rbが肥大化してきたので、分割したくなっていたので、調べていた。

ググってみると色々方法があるらしいが、バージョンごとにやり方が違ったりしてげんなりする。
よく出てくるconfig.paths["config/routes"]をいじる方法は、どうもRails4からは削除されていて動かないようだ

ということで黒魔術を使った。めでたしめでたし。

# config/routes/some_module.rb
module SomeModule
    def self.apply(context)
        context.instance_exec do
            # 実行させたい処理を書く
            #   resources :products do
            #     member do
            #       get 'short'
            #       post 'toggle'
            #     end
             #  end
        end
    end
end
# config.rb
Dir[Rails.root.join('config/routes/*.rb')].each do |file|
  load file
end

Your::Application.routes.draw do
    SomeModule.apply(self)
end

解説

Your::Application.routes.drawの実態は、ActionDispatch::Routing::RouteSet#drawというやつのようで、その実装は、次のようになっている。

# actionpack/lib/action_dispatch/routing/route_set.rb
      def draw(&block)
        clear! unless @disable_clear_and_finalize
        eval_block(block)
        finalize! unless @disable_clear_and_finalize
        nil
      end

#eval_blockの実装は、

      def eval_block(block)
        if block.arity == 1
          raise "You are using the old router DSL which has been removed in Rails 3.1. " <<
            "Please check how to update your routes file at: http://www.engineyard.com/blog/2010/the-lowdown-on-routes-in-rails-3/"
        end
        mapper = Mapper.new(self)
        if default_scope
          mapper.with_default_scope(default_scope, &block)
        else
          mapper.instance_exec(&block)
        end
      end
      private :eval_block

なので、drawしたときに作成する&blockの実態は、instance_execのコンテキストで実行されているようだ。

with_default_scopeするケースがあるが、こちらの実装は、

# actionpack/lib/action_dispatch/routing/mapper.rb
        def with_default_scope(scope, &block)
          scope(scope) do
            instance_exec(&block)
          end
        end

となっていて、こちらもinstance_execになっている。

なので、コンテキストを受けとって、コンテキストに対してinstance_execしてやれば同じコンテキストで実行できるので、instance_exec以降は通常のroutesと同じことが記述できる。

開発環境で再起動しなくても読みなおせるようにloadで読みこんでいるが、config/routes.rbのtimestampを更新しないと再読みこみしないのがどうしたもんかなーという感じではある。

続: CollectionViewで初回はemptyViewを表示しない

前のやつは、あまりよくない方法だなぁとは思っていたのですが、ちゃんとしたやり方っぽいのがあった。

"collection:rendered" triggerにフックすればよいようだ。Marionetteだと、triggerMethodというのがあって、triggerでも対応できるし、OnCamelCaseみたいなメソッドが生えていたらそれを自動で呼びだしてくれる。

var YourEmptyView = Marionette.ItemView.extend({
});
var  YourCollectionView = Marionette.CollectionView.extend({
    onCollectionRendered: function() {
        this.options.emptyView = YourEmptyView;
    }
});

CompositeViewだと、onCompositeRenderedになる。

fadeInアニメーションさせたいときとかも、初回はアニメーションさせたくないけど、動的に追加したタイミングではアニメーションさせたいので、このトリガ内で、

var  YourCollectionView = Marionette.CollectionView.extend({
    onCollectionRendered: function() {
        this.OnBeforeItemAdded = function(view) {
           view.$el.fadeIn('fast');
        };
    }
});

みたいにすると、良い感じ。

CollectionViewで初回はemptyViewを表示しない

あんまりよいやり方じゃないので、http://walf443.hatenablog.com/entry/2014/07/10/120223 を参照してください。

Marionette.jsのCollectionViewのemptyView機能は、collectionが0個になったら勝手に「データがありません」などの表示をしてくれて便利なのだけど、初回だけデータのロード待ちなどの関係で、emptyViewを表示したくない、ということが個人的には多いように思える。

そういうときは、showCollectionメソッドを上書きして、showCollectionが呼ばれたら初めて、options.emptyViewにemptyViewの設定が入るようにすればよい。

var YourEmptyView = Marionette.ItemView.extend({
});
var  YourCollectionView = Marionette.CollectionView.extend({
    showCollection: function() {
        this.options.emptyView = YourEmptyView;
        return Marionette.CollectionView.prototype.showCollection.apply(this, arguments);
    }
});

一度でもコンテンツが追加されたら、showCollectionが呼ばれることになるので、それ以降にデータがなくなったりすると、emptyViewを表示してくれるようになる、というわけ。

Unicornでslow restart

Unicornの同時接続数がわりと少ないのに気づいたので、えいやとworker_processesを増やしたら今度はdeploy時にちょっと詰まり気味になってしまった。

これは、deployのタイミングで重いシステムコールであるforkを連発するため、と思われる。

そこで、Startletの--spawn-intervalのようなことをunicornでもやりたい。

設定ファイルで、

# config/unicorn.rb
before_fork do
  # 起動時や再起動で一気にforkしまくると遅くなるので、intervalを加える
  if Unicorn::HttpServer::WORKERS.size > 10
    sleep 0.4
  end

end

のようにやれば、起動時に連発してforkしなくなってよくなったっぽい。

もちろんbefore_forkは起動時のみに呼ばれるわけではなく、子プロセスの数が減って調整したタイミングや、unicorn-killerとかで殺されて再度起動した、みたいなケースでも呼ばれうるので、そういう場合にsleepが挟まっても問題ないか、は考慮する必要がありそう。

TCPListenerのファイルディスクリプタを調べる

ListenしているSocketのfdを知りたいが、net.Listenerのインターフェースをみても取得する方法がないのでググったら、

http://naoina.plog.la/2013/11/12/235753683181

こんな記事をみつけた。

Socketからfdが取得できないのは、POSIX縛りになるからだと思われるが、ここで方法へどうやって辿りついたかよくわからなかったので調べてみた。

TCPListenerの定義を調べると、

// src/pkg/net/tcpsock_posix.go
type TCPListener struct {
  fd *netFD
}

となっているので、reflectパッケージを使えば、

 reflect.Indirect(reflect.Indirect(reflect.ValueOf(listener)).FieldByName("fd"))

で、fdの構造体が取得できる。

また、netFDの定義は、

// src/pkg/net/fd_unix.go
// Network file descriptor.
type netFD struct {
    // locking/lifetime of sysfd + serialize access to Read and Write methods
    fdmu fdMutex

    // immutable until Close
    sysfd       int
    family      int
    sotype      int
    isConnected bool
    net         string
    laddr       Addr
    raddr       Addr

    // wait server
    pd pollDesc
}

となっているから、

 uintptr(fdValue.FieldByName("sysfd").Int())

で、ファイルディスクリプタの値が取得できる、ということのようだ。

動いているVMにNatのポートフォワードの設定をCLIから変更する

Dockerをローカルで実行できるようになっても、ポート転送を手動で設定しないといけないのがつらいので、コマンドでやれるようにするのを調べた。

VBoxManage controlvm boot2docker-vm natpf1 "node,tcp,127.0.0.1,49160,,49160"
VBoxManage controlvm boot2docker-vm natpf1 delete node

というようにすると、ポートフォワードの設定が変更できるので、ブラウザから立ちあげたコンテナへアクセスすることができます。

boot2docker-vmのマシンが起動していないときは、

VBoxManage modifyvm -boot2docker-vm natpf1 "node,tcp,127.0.0.1,49160,,49160"
VBoxManage modifyvm -boot2docker-vm natpf1 delete node

boot2dockerへwrapperを書いてみたのだけど、既に色々このあたりを楽にしよう、というのは議論されているようなので、そのうち入るでしょう。