花粉の飛散量を取得する Ruby スクリプト
動機
ちょっと前に見かけていた記事ですが、自分も花粉症に苦しんでいるということもあり、Nadoka さんの IRC Bot に仕込もうと思って Ruby で書いてみました。 :-p
環境省が運用する花粉観測システム(はなこさん)では１時間毎の花粉飛散データが公開されています。 1時間毎に花粉飛散データが更新されるため外出のタイミングを決定するのに役立ちます。 プログラマであれば、このデータを cron で定期的に監視して警告メールを送ったり、Shell のプロンプトやemacs のミニバッファに表示させたい、と思うはずです。
そこで、この花粉観測システムはなこさんから花粉飛散データを取得する perl module を作成しました。
花粉情報にしか興味がなかったので、風向や風速情報はとっていません。ほんとは scraping したほうがよかったのかもしれませんが、そこも手を抜いちゃいました。
自分としては、Net::HTTP での Cookie の使い方と、Ruby 1.9 での Array#to_s の動きが勉強になったかな、と。
# Nadoka さんを Ruby 1.9 で動かしてるわけじゃないんですが、そのままポーティングするのも芸がなかったので、なんとなく 1.9 対応...
動作確認
東京の観測所は以下となります。今の季節はまだ、都内はさほどではないですが、多摩森林科学園の花粉量はハンパないです。
| エリアコード | 観測所コード | 観測所 |
|---|---|---|
| 3 | 51310200 | 東京都多摩小平保健所 |
| 3 | 51320100 | 独立行政法人森林総研多摩森林科学園 |
| 3 | 51300100 | 日本医科大学付属多摩永山病院 |
| 3 | 51300200 | 日本医科大学付属病院 |
12時時点で動かしてみたら、以下の結果でした。飛散量が 1000 を越えると相当危険らしいです。
# 自分は 100個未満の都市部でも、かなりむずがゆいですが...。
% ruby191 hanako.rb 51310200 3 最新の花粉飛散量は、32 [個/m3] 9 時の花粉飛散量は、24 [個/m3] % ruby191 hanako.rb 51320100 3 最新の花粉飛散量は、520 [個/m3] 9 時の花粉飛散量は、61 [個/m3] % ruby191 hanako.rb 51300100 3 最新の花粉飛散量は、86 [個/m3] 9 時の花粉飛散量は、20 [個/m3] % ruby191 hanako.rb 51300200 3 最新の花粉飛散量は、69 [個/m3] 9 時の花粉飛散量は、8 [個/m3]
Array#to_s の挙動
Ruby 1.8 では Array#join、Ruby 1.9 では Array#inspect と同じ動きになります。
% irb186 >> %w(a b).to_s => "ab" >> %w(a b).inspect => "[\"a\", \"b\"]" >> %w(a b).join => "ab" >> exit % irb191 >> %w(a b).to_s => "[\"a\", \"b\"]" >> %w(a b).inspect => "[\"a\", \"b\"]" >> %w(a b).join => "ab" >> exit
スクリプト
Ruby 1.9 じゃないと動きません。
プロキシの設定ができるようにしてますが、経由の必要がなければ適宜書きかえてください。
# coding: utf-8 require 'net/http' class Hanako Net::HTTP.version_1_2 PROXY_HOST = "xxx" PROXY_PORT = yyy HANAKO_BASE_HOST = "kafun.taiki.go.jp" attr_reader :kafun, :mst_code, :area_code def initialize(mst_code = "51300200", area_code = "3") @kafun = { } @mst_code = mst_code @area_code = area_code request_and_parse(mst_code, area_code) end def now now = @kafun.keys.sort.last @kafun[now] end private def request_and_parse(mst_code, area_code) cookie = nil Net::HTTP::Proxy(PROXY_HOST, PROXY_PORT).start(HANAKO_BASE_HOST) do |http| response, = http.get("/Hyou0.aspx?MstCode=#{mst_code}&AreaCode=#{area_code.rjust(2,"0")}") response.error! unless response.is_a? Net::HTTPOK cookie = response.get_fields("Set-Cookie").join.split(";").first end Net::HTTP::Proxy(PROXY_HOST, PROXY_PORT).start(HANAKO_BASE_HOST) do |http| response, = http.get("/Hyou2.aspx", "Cookie" => cookie) response.error! unless response.is_a? Net::HTTPOK parse(response) end end def parse(response) response.body.each_line do |line| if /<td><font size=\"2\">([0-9]*)時<\/font><\/td><td align=\"Right\"><font size=\"2\">([0-9]*)<\/font><\/td>/ =~ line.force_encoding("UTF-8") @kafun[$1.to_i] = $2.to_i end end end end # == how to use == hanako = Hanako.new ARGV[0], ARGV[1] puts "最新の花粉飛散量は、#{hanako.now} [個/m3]" puts "9 時の花粉飛散量は、#{hanako.kafun[9]} [個/m3]"
Rails から AP4R サーバへの接続の可用性とか、負荷分散とか...
AP4R について書くのはずいぶん久しぶりな気がしますが... (^^;
Rails で AP4R を使っている場合、以下の流れでメッセージを介して非同期が実現されています。
# ユーザーからのリクエストで、1,2 が同期的に実行され、3 以降が非同期で実行されます。
0. AP4R の Rails プラグインの導入
1. アクションのなかで、ap4r.async_to(message, ...) すると、
2. Rails から AP4R サーバ上のキューにメッセージを PUT (dRuby プロトコル)
3. AP4R から指定された宛先に送信 (HTTP など)
4. 宛先でメッセージを処理 (宛先が Rails であれば、通常のリクエストと同様に処理可能)
可用性の高いシステムを考えるとき、この流れのなかで 1->2 の部分が SPoF (Single Point of Failure) になってしまっていました。
リバースプロキシ構成であれば、バックエンドの Rails インスタンスのどれかがこけても、フロントエンドでうまいこと振りわけることで、縮退しつつもシステムは動きつづけます。しかしながら、メッセージを PUT する先の AP4R サーバが落ちていると、アクションはエラーとなってしまいます。
# 確実に非同期処理が実行される必要があれば、業務データベースへのコミットと AP4R へのメッセージの PUT はアトミックにしないと駄目ですよね?
個々の Rails インスタンスごとに AP4R を個別に用意すれば、すべての処理がとまることはないでしょうが、やたらとサーバが増えてしまいそうで、管理を考えるとそれも悩ましいです。
というわけで、Rails から AP4R サーバへの接続に失敗したときに、別の AP4R サーバにフェイルオーバーするようにしてみました。(まだ、リリースはしてませんが...。)
最低 2つの AP4R サーバを起動して設定をしておけば、一方への接続に失敗したとき、他方に接続を切り替えます。両方とも落ちてるときはどうしようもないですが、そうでなければ生きている AP4R サーバにメッセージを PUT できます。
environment.rb のなかで、以下のように設定します。
uris = %w(6438 6439 6440).map {|port| "druby://localhost:#{port}"} ::Ap4r::AsyncHelper::Base.druby_uris(uris, :fail_over => true)
最初は、druby://localhost:6438 に接続しにいきますが、そことの接続ができなければ、druby://localhost:6439 との接続を試みます。そして、そこも駄目だと druby://localhost:6440 に接続しにいきます。カスケード フェイルオーバーっていうみたいですね。
# environment.rb のなかで、druby URI の配列の並び順を Rails インスタンスごとに変えるようにしておけば (ポートでわけたり、ランダムにしたり?)、Active-Standby のたすき掛け構成みたいになりますね。
ちなみに、オプションはもう 2つ、用意しています。
uris = %w(6438 6439 6440).map {|port| "druby://localhost:#{port}"} ::Ap4r::AsyncHelper::Base.druby_uris(uris, :rotate => true)
この設定では、接続先の AP4R が落ちてなくても、メッセージを PUT するごとに、接続先の AP4R サーバを切り替えていきます。ロードバランサのラウンドロビン的な動きです。:fail_over オプションを設定してなければ、フェイルオーバーはしません。逆に、:fail_over オプションと組み合わせれば、正常時でも接続先の AP4R サーバを切り替え、異常時でもフェイルオーバーして AP4R サーバを切り替えることになります。
接続できなかった AP4R サーバは、接続先 URI のリストから削られます。なので、いったん接続できなかった AP4R サーバは、Rails インスタンスを再起動するまで利用されません。これが嫌な場合もありそうなので...
uris = %w(6438 6439 6440).map {|port| "druby://localhost:#{port}"} ::Ap4r::AsyncHelper::Base.druby_uris(uris, :fail_over => true, :fail_reuse => true)
としておくと、いったん接続できなかった AP4R サーバにも、(ローテーションやフェイルオーバーを繰り返していくなかで) 接続しにいきます。ほんとは keep alive 的な仕組みも入れて、生き返ってたら接続先の URI リストに戻すほうがよいのかもしれませんが、今回はこんな風にしてみました。
# 落ちたままのサーバに接続を何度も繰り返すのはまずいので、URI リストすべてに接続を試みて駄目であればエラーとなります。
いろいろ考えてはみたんですが、このあたりの可用性や負荷分散の動きってのは、ケースバイケースなんだろうなぁと思い至りました。その個別の動きを DSL ライクに設定 (実装) できるようにしようかとも思ったのですが、なんだか余計に複雑になってしまいそうだったので、シンプルな動きのみを提供するだけにとどめてみました。
それがぼくには楽しかったから
言わずと知れた、Linux の開発者である Linus Torvalds の自伝です。
それがぼくには楽しかったから 全世界を巻き込んだリナックス革命の真実 (小プロ・ブックス)
- 作者: リーナストーバルズ,デビッドダイヤモンド,風見潤,中島洋
- 出版社/メーカー: 小学館プロダクション
- 発売日: 2001/05/10
- メディア: 単行本
- 購入: 20人 クリック: 282回
- この商品を含むブログ (139件) を見る
# Amazon のマーケットプレースで 1円(!) で売られていたので思わず買ってしまいました。でも、読んでみたら、定価でも全然高くない良書でした。 :-p
# カバーが丸くくり抜かれていて、そこからペンギン (例のくちばしの黄色いやつ) が顔をのぞかせているとってもかわいい本です。カバーをとるとペンギンがわらわらといますw
リーナス自身がどんな風に育ち、どのように Linux が開発され、そして世界に広まっていったのか? それが、家族や本人、そしてジャーナリストであるデイビッド ダイヤモンドによって語られています。もちろん自伝なので、本人による語りがもっとも多く、リーナスによる主観的な語りが 9割、デイビッドや家族による客観的なエピソード紹介が 1割といった配分でしょうか。かなり赤裸々です。
タネンバウム教授との論争や、スティーブ ジョブズやビル ジョイとの会談、また、リチャード ストールマンやエリック レイモンドらへの考えが、若干シニカルながら、リーナスの人柄全開で書かれていて、まさにリーナスとはこういう人なんだというのが伝わってきます。話の流れ上、技術的なことにも若干は触れていますが、哲学書をいった趣きですね。
# 同じく OS 開発つながりとして、以前、Windows の開発の舞台裏をまとめた「闘うプログラマー」を読んだ記憶があります。こちらは、企業におけるソフトウェア開発の現実、企業文化の衝突や人間同士の協調と対立、そのなかでのプログラマーたちの苦悩が描かれていたと思いますが、あわせて読んでみるのもまた面白いかと。
- 作者: G.パスカルザカリー,G.Pascal Zachary,山岡洋一
- 出版社/メーカー: 日経BP社
- 発売日: 1994/12/07
- メディア: 単行本
- 購入: 14人 クリック: 599回
- この商品を含むブログ (107件) を見る
以下、印象に残った部分の抄録です。
いっぱいありすぎですね... (^^;
人生にとって意義のあることは3つある。3つの原動力だ。人の営みのすべてのこと...いや、人はもちろん、生きとし生けるものが行うすべてのことの原動力だ。
1つめは生き延びること。2つめは社会秩序を保つこと。3つめは楽しむこと。(中略)
人生の意味は、この第三ステージにたどり着くことだといえる。つまり、第三ステージにたどり着けば、あがりってこと。ただし、まず前の2つのステージを経験しないとだめだけどね。
フロッピーコントローラについてきたドライバがよくなかったので、自分で作ることにした。そのプログラムを書いてるうちに、このOSにいくつかのバグがあることを見つけた。というか、マニュアルに書いてあるOSの動作と、実際の動作とに相違があったんだ。自分で書いたプログラムが動かなかったので、その事実に気づいたんだ。
だって、ぼくの書くコードはいつでも、エヘン、完璧だからね。だから、原因はほかにあると思ったわけだ。そういう経緯から、ぼくは OS に手を入れることにした。つまり、OS を逆アセンブルることにしたんだ。
コンピュータサイエンスと物理学には共通点がたくさんあると思っている。どちらも、かなり根本的なレベルで、世界がどのように動いているかを考えるものだ。もちらん、相違点もある。物理学では、世界がどのように作られているかを見つけ出そうとするけど、コンピュータサイエンスでは、自分で世界を作るのだ。コンピュータという世界の中では、君は創造主だ。君はその中で起こることのすべてを支配する。君がそれなりに有能なら、神になることも可能だ。ちっぽけな世界の神様だけど。
お金が欲しくなかった理由は、いろいろあった。初めてリナックスをアップしたとき、ぼくは、他人の築いた基礎の上に、アイザックニュートンのいう「巨人の肩」に、みずからの研究を重ねていく何世紀にも及ぶ科学者たちの足跡をたどっている気分だった。みんなもこれは便利だと思ってくれるように、みんなとぼくの OS を共有したかった。それだけじゃなく、フィードバックも(それから、賞賛も)欲しかった。もしかしたら、ぼくのOSを改良してくれるかもしれない相手からお金を取るのはおかしいと思っていた。
トーベは15人いた生徒のうちの一人だった。(中略)
とにかく、ぼくは言ったのだ。「宿題として、ぼくにメールをください」と。他の学生のメールは、簡単なテストメッセージや、あまり記憶に残らない授業の感想などだった。
ところが、トーベは、デートしてください、と書いてよこしたのだ。ぼくは、電子的にアプローチしてきた最初の女性と結婚したのである。
わたしはペンギンはどうかしらって思ったわ。リーナスは、オーストラリアの動物園でコビトペンギンに嚼まれたことがあるの。彼はなんにでも触るのが好きで、ガラガラヘビだって棒でつついたりするのよ。動物園にいたそのペンギンは背丈が30センチくらいで、彼は触ろうとして檻の中に手を入れたの。指を魚みたいに動かしてみせたら、ペンギンが彼のところに来て、嚼みつき、それで魚じゃないってわかったみたい。リーナスはペンギンに嚼みつかれたけど、それでもペンギンを嫌いにならなかった。それ以来、彼はペンギンに夢中なの。ペンギンがいるところなら、どこへでも見に行きたがるのよ。
レッドハットはぼくにストックオプションをくれた。(中略)
ぼくのストックオプションは魔法みたいに倍に増えていた。50万ドルが100万ドルになていたのだ。
マスコミに描かれていたイメージはどこへやら、清貧を誓った無私無欲の庶民の英雄は、率直なところを言えば、有頂天になってしまった。よーし、正直に言ったぞ。
ここで僕の黄金律を披露しよう。
一つ目は「自分がして欲しいことを人にもしてあげよう」。このルールを遵守すれば、どんな状況にあっても自分がどんな行動をとるべきかちゃんとわかるというわけ。二つ目は「自分のすることに誇りを持て」三つは「そして楽しめ」
誰でもゲームに参加できるようにした GPL は素晴しいものだ。それが人類にとってどれほどの進歩か、考えてみてほしい。でも、だからといって、どんな新しいものでも GPL にしなくちゃいけないってことなのか? (中略)
ぼくは、さまざまな理由から、遠くからリチャードを賞賛することにしている。それに、ぼくはリチャードのような確固たる道徳的意見をもっている人を尊敬するタチらしい。だけど、どうして彼らは、そういう信念を内に秘めておくことができないのだろう? ぼくが一番嫌いなのは、人からああしろこうしろ、あれはするなと言われることだ。ぼく自身が決めたことに対して、文句を言う権利があると思っている人は大嫌いだ (ただし、多分、ぼくの奥さんは除く)。
ぼくは、著作権者として、自分なりの権利を持っている。しかし、権利とともに義務、ある地域の人が言う、高い身分にともなう義務 (ノブレス オブリージュ) も発生する。だから、ぼくは自分の義務を、責任あるやり方で権利を講師する義務のことだと思っている。権利を持っていない人への武器をして使いはしない。あるアメリカの偉人が「あなたの著作権があなたのために何をなしうるかではなく、あなたが、あなたの著作権のために何をなしうるかを問いなさい」と言ったように、である。
ぼくらは理念があって、オープンソースを売り込んだわけじゃない。オープンソースこそ最高のテクノロジーを開発し、改良する最良の方法だとわかってきたので、その理念が世間の注目を集めだしたのだ。(中略)
オープンソースモデルは、人々に情熱的な生活を送るチャンスを与える。楽しむチャンスも。さらに、たまたま同じ会社で机を並べている数人の仲間とではなく、世界で最も優秀なプログラマーたちと仕事をするチャンスも。オープンソースの開発者たちは、仲間からいい評価を得ようと懸命に努力する。こうしたことは大きな原動力になるに違いない。
オープンソースは外部の才能を採り入れる最善の手段だ。とはいえ、会社のニーズを把握している社内の人間も必要だ。その人物がプロジェクトのリーダーでなくてもかまわない。(中略)
ただ、外部の人間が会社のニーズにあわせた方向にプロジェクトを進めないかもしれないという問題はある。だから、会社は自分たちのニーズにはちゃんと気を配らなくちゃいけない。外部の資源はより安上がりで、より完璧な、よりバランスのとれたシステムを作るけれど、逆効果の面もある。肥大したシステムはもはや会社のニーズだけを考慮するわけにはいかなくなるのだ。(中略)このリーダーはオープンースを実行することで給料をもらっている。社内の仲間に同意することではなく、ただプロジェクトを遂行するために給料をもらっている。そのことは、本人も他の誰もが承知している。会社とあまりに緊密な関係にあるリーダーには、危険が伴う。仲間たちは、リーダーの技術力は信頼しても、それ以外の判断については信頼しないかもしれないからだ。
ぼくはテクノロジー屋として、テクノロジーが何も動かさないことを知っている。社会がテクノロジーを変化させるのであって、その反対じゃないんだ。テクノロジーは、ぼくたちにできることとできないことの境界を引くだけだ。どのくらい安くできるかという境界を引くだけなのだ。
テクノロジーは、それが生み出した機器同様、少なくともいままでのところ、本質的には面白くもなんともないものだ。そのテクノロジーを使ってできることが面白いだけの話だ。その推進力になっているのは、人間の欲求と関心だ。(中略)
生存。社会化。娯楽。これが進歩だ。ぼくちがやっていることはどんなことでも、結局は自分自身の楽しみおためであるように思えるからだ。少なくとも、ずっと未来まで進歩する可能性を取りあげられずにいたら、最後に娯楽が来るだろう。
Rails-1.2.3、2.1.2、2.2.2、2.3 の性能の変遷 (render :text にて)
Rails-2.3 の RC1 をまだ触ってなかったので、インストールがてら試してみました。
render :text => "Hello World!" なアプリに対して、Apache Bench から負荷をかけ、スループットの平均 (5回計測し、最大と最小を除いて平均値を算出) をとっています。
2.1 に比べて 2.2 でスループット性能がかなり落ちたのが、2.3 RC1 では少し復活しているようですね。また、threadsafe オプションの効能はここではあまり見られませんでした。
# 1.x 系から 2.x 系は大きな飛躍がありましたが、Merb ベースとなる 3.x 系にも期待できると嬉しいですね。 :-p
結果
| バージョン | 平均値 [#/sec] | すべての計測値 [#/sec] |
|---|---|---|
| Rails-2.3 RC1 | 377.75 | 350.03, 381.57, 375.1, 376.57, 381.83 |
| Rails-2.3 RC1 (threadsafe!) | 322.07 | 315.51, 320.87, 317.72, 327.63, 330.15 |
| Rails-2.2.2 | 329.04 | 326.77, 335.3, 326.37, 328.55, 331.8 |
| Rails-2.2.2 (threadsafe!) | 333.12 | 336.42, 338.0, 337.36, 325.58, 276.85 |
| Rails-2.1.2 | 440.97 | 435.08, 440.06, 445.48, 441.13, 441.72 |
| Rails-1.2.3 | 59.86 | 79.98, 63.47, 58.56, 57.56, 56.1 |
環境
- iMac (intel Core 2 Duo 2.33GHz)
- Mac OS X 10.5.6
- 処理系、ライブラリのバージョンは以下のとおり
% ruby186 -v ruby 1.8.6 (2008-08-11 patchlevel 287) [i686-darwin9.6.0] % gem list --local rails *** LOCAL GEMS *** rails (2.3.0, 2.2.2, 2.1.2, 1.2.3) mongrel (1.1.5)
- HelloWorld アプリ
% rails _x.x.x_ helloworld # x.x.x には Rails のバージョン
% cd helloworld
% ruby186 script/generate controller tests
% vi app/controllers/tests_controller.rb
class TestsController < ApplicationController
def index
render :text => "Hello World!"
end
end
a
% ruby186 script/server -e production
% curl http://127.0.0.1:3000/tests
Hello World!%
% ab -n 10000 -c 10 http://127.0.0.1:3000/tests
scaffold アプリのなかでコストの高いメソッド
ちょっと前に、性能をみるために用意した ActiveScaffold とふつうの scaffold によるアプリに、DTrace をかけてみました。50 リクエストを処理するのに、数百万のメソッド呼び出しが観測されます。(DTrace の変数領域の都合上、あまり多くのリクエストはかけられませんでした...)
実行回数が多く、トータルとしてコストがかかっているメソッド、あるいは 1回あたりのコストが大きいので、呼び出される回数は少ないものの性能に寄与してくるメソッドなどがわかると思います。ひとまず、上位 10メソッドを並べてみました。
絶対値としてはあまり意味がないでしょうが、相対的にボトルネックとなっている箇所は見えてくる...かと?
# はてな記法の表形式が左寄せになってしまうのをなんとかしたい... orz
ActiceScaffold アプリ
- メソッドの実行時間の合計
| クラス | メソッド | 回数[#] | 合計時間[us] |
|---|---|---|---|
| Class | connection | 10072 | 12129396 |
| Object | sleep | 26 | 12587050 |
| ActiveScaffold::DataStru | field_name | 9464 | 14661475 |
| Array | select | 9420 | 16179970 |
| Hash | [] | 374137 | 18212681 |
| Object | respond_to? | 157024 | 18807037 |
| Class | authorized_for? | 7103 | 21688979 |
| Object | authorized_for? | 9349 | 25392729 |
| Array | each | 45242 | 26868825 |
| Object | send | 17841 | 28908327 |
- メソッドの実行時間の平均 (1回の呼び出しあたりの時間)
| クラス | メソッド | 回数[#] | 平均時間[us] |
|---|---|---|---|
| Array | collect! | 49 | 9505 |
| Class | read | 1222 | 9783 |
| Object | javascript_include_tag | 98 | 15536 |
| ActiveRecord::Connection | result_as_array | 97 | 16389 |
| Object | active_scaffold_include | 49 | 24731 |
| PostgresPR::RowDescripti | parse | 119 | 28505 |
| Object | _run_erb_app47views47la | 47 | 44197 |
| Object | render | 47 | 46681 |
| ActionView::Template | render_template | 47 | 46747 |
| Object | sleep | 24 | 478806 |
- メソッドの CPU 使用時間の合計
| クラス | メソッド | 回数[#] | 合計時間[us] |
|---|---|---|---|
| Class | read | 1220 | 3795811 |
| Range | each | 1947 | 4184595 |
| Object | respond_to? | 157015 | 4378954 |
| Array | each_index | 780 | 4507770 |
| Hash | [] | 374134 | 4588348 |
| PGresult | ftype | 4881 | 4771809 |
| Class | authorized_for? | 7103 | 5178246 |
| Object | authorized_for? | 9346 | 6037146 |
| Object | send | 17835 | 6743344 |
| Array | each | 45226 | 8896915 |
- メソッドの CPU 使用時間の平均 (1回の呼び出しあたりの時間)
| クラス | メソッド | 回数[#] | 平均時間[us] |
|---|---|---|---|
| Class | read | 1219 | 3232 |
| Object | collect | 953 | 3371 |
| Object | javascript_include_tag | 98 | 3478 |
| Object | active_scaffold_include | 47 | 5746 |
| Array | each_index | 777 | 5767 |
| ActiveRecord::Connection | result_as_array | 99 | 6845 |
| Object | _run_erb_app47views47la | 45 | 10198 |
| Object | render | 44 | 10748 |
| ActionView::Template | render_template | 44 | 10761 |
| PostgresPR::RowDescripti | parse | 117 | 17140 |
ふつうの scaffold アプリ
- メソッドの実行時間の合計
| クラス | メソッド | 回数[#] | 合計時間[us] |
|---|---|---|---|
| Object | person_path | 1467 | 11946751 |
| Object | __send__ | 5014 | 12988984 |
| ActionController::UrlRew | rewrite_url | 2217 | 13000439 |
| ActionController::UrlRew | rewrite | 2215 | 13172309 |
| ActionController::Base | url_for | 2211 | 13883287 |
| Object | send | 5352 | 15917858 |
| Object | polymorphic_url | 1464 | 16378164 |
| Object | polymorphic_path | 1464 | 16528890 |
| Object | link_to | 2401 | 20567438 |
| Object | url_for | 4617 | 33290132 |
-
- メソッドの実行時間の平均 (1回の呼び出しあたりの時間)
| クラス | メソッド | 回数[#] | 平均時間[us] |
|---|---|---|---|
| Object | collect | 956 | 8772 |
| Object | render | 50 | 9185 |
| ActionView::Template | render_template | 50 | 9252 |
| Array | collect! | 47 | 9534 |
| Class | read | 1219 | 9816 |
| Object | polymorphic_url | 1456 | 11211 |
| Object | polymorphic_path | 1455 | 11315 |
| ActiveRecord::Connection | result_as_array | 93 | 15871 |
| PostgresPR::RowDescripti | parse | 121 | 27688 |
| Object | sleep | 19 | 461348 |
-
- メソッドの CPU 使用時間の合計
| クラス | メソッド | 回数[#] | 合計時間[us] |
|---|---|---|---|
| Object | send | 5366 | 3633977 |
| Class | read | 1220 | 3864177 |
| Range | each | 1986 | 3936521 |
| Object | polymorphic_url | 1464 | 3938339 |
| Object | polymorphic_path | 1463 | 3971707 |
| Array | each_index | 781 | 4374570 |
| PGresult | ftype | 4879 | 4611030 |
| Array | each | 11184 | 4764152 |
| Object | link_to | 2398 | 5037025 |
| Object | url_for | 4624 | 7931197 |
-
- メソッドの CPU 使用時間の平均 (1回の呼び出しあたりの時間)
| クラス | メソッド | 回数[#] | 平均時間[us] |
|---|---|---|---|
| Class | create | 1281 | 2666 |
| PostgresPR::Message | parse | 1233 | 2729 |
| Object | polymorphic_url | 1458 | 2735 |
| Object | polymorphic_path | 1458 | 2759 |
| PGresult | initialize | 150 | 2837 |
| Class | read | 1212 | 3184 |
| Object | collect | 944 | 3372 |
| Array | each_index | 783 | 5575 |
| ActiveRecord::Connection | result_as_array | 99 | 6782 |
| PostgresPR::RowDescripti | parse | 116 | 15876 |
以下、作業ログです。
まずは ActiveScaffold の場合。
DTrace なしで ab を実行
ab -c 10 -n 50 http://127.0.0.1:3000/addressbooks This is ApacheBench, Version 2.3 <$Revision: 655654 $> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Licensed to The Apache Software Foundation, http://www.apache.org/ Benchmarking 127.0.0.1 (be patient).....done Server Software: Mongrel Server Hostname: 127.0.0.1 Server Port: 3000 Document Path: /addressbooks Document Length: 35564 bytes Concurrency Level: 10 Time taken for tests: 4.241 seconds Complete requests: 50 Failed requests: 0 Write errors: 0 Total transferred: 1806412 bytes HTML transferred: 1778200 bytes Requests per second: 11.79 [#/sec] (mean) Time per request: 848.207 [ms] (mean) Time per request: 84.821 [ms] (mean, across all concurrent requests) Transfer rate: 415.95 [Kbytes/sec] received
DTrace ありで ab を実行
% ab -c 10 -n 50 http://127.0.0.1:3000/addressbooks This is ApacheBench, Version 2.3 <$Revision: 655654 $> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Licensed to The Apache Software Foundation, http://www.apache.org/ Benchmarking 127.0.0.1 (be patient).....done Server Software: Mongrel Server Hostname: 127.0.0.1 Server Port: 3000 Document Path: /addressbooks Document Length: 35564 bytes Concurrency Level: 10 Time taken for tests: 239.593 seconds Complete requests: 50 Failed requests: 0 Write errors: 0 Total transferred: 1806500 bytes HTML transferred: 1778200 bytes Requests per second: 0.21 [#/sec] (mean) Time per request: 47918.642 [ms] (mean) Time per request: 4791.864 [ms] (mean, across all concurrent requests) Transfer rate: 7.36 [Kbytes/sec] received
メソッド呼び出しの timestamp の合計をトレースした結果
% sudo dtrace -s rb_functime_ext2.d -p 91372 -x dynvarsize=200000000 dtrace: script 'rb_functime_ext2.d' matched 4 probes CPU ID FUNCTION:NAME 0 1 :BEGIN Tracing... Hit Ctrl-C to end. ^C 0 2 :END ELAPSED TIME DISTRIBUTION, ___ OVERLAP TIMES: ___ ______ ELAPSED ______ CLASS METHOD COUNT SUM(us) Mongrel::HttpResponse send_header 1 340 Mongrel::HttpResponse send_status 1 607 Time sec 50 819 ... (snip) ... Object sort_by 3998 1929457 Object _run_erb_app47views47la 44 1947405 HashWithIndifferentAcces include? 10045 2010132 String concat 101950 2039496 Object render 44 2056458 ActionView::Template render_template 44 2059361 ActiveRecord::Connection type_cast 1493 2077280 ActionController::Routin extra_keys 3997 2093944 Array map 8092 2117290 Object find 4595 2120321 Buffer read 12739 2194795 Person updated_at 744 2210650 HashWithIndifferentAcces convert_value 18543 2225686 Person created_at 746 2235688 ActiveSupport::TimeWithZ time 2994 2239695 HashWithIndifferentAcces []= 5495 2307979 Object active_scaffold_config 16644 2373210 String to_s 131350 2447820 #<Class:0x20e0bd0> type_oid 4900 2475849 Module camelize 12341 2479162 ActiveScaffold::Config:: sorting 3846 2484856 ActiveSupport::TimeWithZ respond_to? 1494 2586702 Object to_query 5743 2642831 Array include? 23749 2721977 Symbol to_s 142001 2742388 Object readn 8133 2774000 PostgresPR::RowDescripti parse 112 2801539 HashWithIndifferentAcces initialize 2834 2988097 ActiveScaffold::DataStru get_clause 4496 2991373 Object == 100194 3116201 Array pack 12050 3127508 Object read_attribute 1491 3146788 ActiveRecord::Connection connection 10096 3155768 ActionController::Routin build_expiry 3995 3205052 HashWithIndifferentAcces dup 2745 3232613 HashWithIndifferentAcces convert_key 31486 3268178 Class generated_methods? 18895 3282978 String gsub 120597 3354551 ActiveSupport::Multibyte [] 1091 3369642 ActiveScaffold::DataStru sorts_on? 4246 3425501 Module underscore 12292 3503161 ActionController::Routin generate_raw 3996 3554555 ActiveSupport::CoreExten camelcase 12291 3949552 ActionController::Routin build_query_string 3989 4085062 Object image_tag 846 4098640 Object underscore 12288 4151591 ActionController::Routin append_query_string 3989 4497852 Object loading_indicator_tag 845 4532138 BinaryReaderMixin read_int32_network 5779 4659796 Object symbolize_keys 9339 4750525 Object params_for 1839 4832794 HashWithIndifferentAcces default 17737 4996812 ActionView::Base params_for 1839 5036220 HashWithIndifferentAcces update 5530 5226183 ActiveScaffold::DataStru == 21889 5276140 PGresult ftype 4887 5304703 ApplicationController authorized_for? 2391 5387647 Array each_index 782 5482011 Object tag_options 4133 5573572 Object ru_swap 7971 5938866 PostgresPR::DataRow parse 834 5962661 HashWithIndifferentAcces merge 2688 6173230 ActiveRecord::Connection retrieve_connection_poo 20241 6393593 Module constantize 12331 6953826 Class new 19256 7043262 Object truncate 1483 7290802 Object constantize 12328 7598050 Hash each 16886 7738805 Object collect 949 7751311 Object inject 15936 7957787 Object active_scaffold_column_ 1483 8135723 PostgresPR::Message parse 1245 8916104 Class create 1445 9248525 Object get_column_value 1483 9541063 Hash each_pair 9565 9552417 ActiveRecord::Connection retrieve_connection 10077 9968233 Range each 1936 10320188 ActionController::Routin generate 3980 10885970 Class retrieve_connection 10073 11557242 Class read 1215 11617862 Object __send__ 9130 11851207 Class connection 10072 12129396 Object sleep 26 12587050 ActiveScaffold::DataStru field_name 9464 14661475 Array select 9420 16179970 Hash [] 374137 18212681 Object respond_to? 157024 18807037 Class authorized_for? 7103 21688979 Object authorized_for? 9349 25392729 Array each 45242 26868825 Object send 17841 28908327 Total out 4450882 757583541 Total in 4627510 757583541
メソッド呼び出しの timestamp の平均をトレースした結果
% sudo dtrace -s rb_functime_ext2.d -p 91372 -x dynvarsize=200000000 dtrace: script 'rb_functime_ext2.d' matched 4 probes CPU ID FUNCTION:NAME 0 1 :BEGIN Tracing... Hit Ctrl-C to end. ^C 1 2 :END ELAPSED TIME DISTRIBUTION, ___ OVERLAP TIMES: ___ ______ ELAPSED ______ CLASS METHOD COUNT AVG(us) Float + 250 16 Time sec 50 16 Fixnum * 250 16 ... (snip) ... Object loading_indicator_tag 843 5372 ActionController::Abstra prepare! 50 5425 Object active_scaffold_column_ 1484 5433 ActionController::MimeRe method_missing 250 5439 ActionController::CgiReq stale_session_check! 32 5443 ActionController::Routin recognize 26 5446 ActionController::CgiReq session 32 5578 Range each 1950 5588 ActionController::Base send_response 50 5656 Array reverse_each 48 5841 ActionController::Base assign_shortcuts_withou 30 5922 Object get_column_value 1481 6377 Class create 1448 6779 Array each_index 780 6934 PostgresPR::DataRow parse 829 7159 Object assign_shortcuts 25 7196 PostgresPR::Message parse 1248 7599 ActionController::Base log_processing 30 7960 Object collect 956 8638 Class construct_calculation_s 50 8798 Class construct_finder_sql 50 8869 Proc call 149 9095 Array collect! 49 9505 Class read 1222 9783 Object javascript_include_tag 98 15536 ActiveRecord::Connection result_as_array 97 16389 Object active_scaffold_include 49 24731 PostgresPR::RowDescripti parse 119 28505 Object _run_erb_app47views47la 47 44197 Object render 47 46681 ActionView::Template render_template 47 46747 Object sleep 24 478806
メソッド呼び出しの vtimestamp の合計をトレースした結果
% sudo dtrace -s rb_functime_ext2.d -p 91372 -x dynvarsize=200000000 dtrace: script 'rb_functime_ext2.d' matched 4 probes CPU ID FUNCTION:NAME 0 1 :BEGIN Tracing... Hit Ctrl-C to end. ^C 0 2 :END ELAPSED TIME DISTRIBUTION, ___ OVERLAP TIMES: ___ ______ ELAPSED ______ CLASS METHOD COUNT SUM(us) Mongrel::HttpResponse send_header 1 139 Mongrel::HttpResponse send_status 1 156 Exception exception 50 238 ... (snip) ... HashWithIndifferentAcces default 17734 1035481 Object params_for 1834 1048529 ActionController::Routin build_query_string 3992 1071147 Object underscore 12290 1074070 String gsub 120600 1075977 Object loading_indicator_tag 843 1095558 ActionView::Base params_for 1832 1101977 HashWithIndifferentAcces update 5527 1120125 ActionController::Routin append_query_string 3991 1130348 ActiveScaffold::DataStru == 21891 1136120 BinaryReaderMixin read_int32_network 5780 1169999 Object symbolize_keys 9341 1272903 ActiveRecord::Connection retrieve_connection_poo 20244 1275769 ApplicationController authorized_for? 2390 1297371 HashWithIndifferentAcces merge 2684 1303440 Object tag_options 4138 1458747 PostgresPR::DataRow parse 835 1497952 Object ru_swap 7967 1525183 ActiveRecord::Connection retrieve_connection 10087 1660413 Module constantize 12327 1687978 Object truncate 1485 1728485 Object constantize 12327 1826855 PostgresPR::RowDescripti parse 111 1842758 Class retrieve_connection 10083 1892302 Class new 19255 1909816 Object active_scaffold_column_ 1483 1947303 Class connection 10081 2005320 Hash each 16877 2092661 Object inject 15928 2142388 Object get_column_value 1480 2253958 Hash each_pair 9568 2270442 #<Class:0x20e0bd0> type_oid 4900 2336779 ActiveScaffold::DataStru field_name 9475 2359203 ActionController::Routin generate 3980 2652835 Object __send__ 9129 2850685 Object collect 953 3245131 PostgresPR::Message parse 1245 3384283 Class create 1445 3461615 Array select 9416 3762721 Class read 1220 3795811 Range each 1947 4184595 Object respond_to? 157015 4378954 Array each_index 780 4507770 Hash [] 374134 4588348 PGresult ftype 4881 4771809 Class authorized_for? 7103 5178246 Object authorized_for? 9346 6037146 Object send 17835 6743344 Array each 45226 8896915 Total out 4450850 197006005 Total in 4627489 197006005
メソッド呼び出しの vtimestamp の平均をトレースした結果
% sudo dtrace -s rb_functime_ext2.d -p 91372 -x dynvarsize=200000000 dtrace: script 'rb_functime_ext2.d' matched 4 probes CPU ID FUNCTION:NAME 0 1 :BEGIN Tracing... Hit Ctrl-C to end. ^C 0 2 :END ELAPSED TIME DISTRIBUTION, ___ OVERLAP TIMES: ___ ______ ELAPSED ______ CLASS METHOD COUNT AVG(us) Struct::Tms cstime 100 4 Struct::Tms cutime 100 4 Struct::Tms stime 100 4 String empty? 22750 4 ... (snip) ... Object options_for_ajax 396 1057 Object truncate 1487 1165 Object image_tag 841 1165 ActionController::Routin recognize 23 1187 Mongrel::HttpResponse send_body 2 1246 ActionController::CgiReq stale_session_check! 33 1247 Array reverse_each 49 1261 ActionController::Abstra prepare! 48 1265 Mongrel::HttpResponse finished 1 1275 ActionController::CgiReq session 33 1275 Object loading_indicator_tag 840 1299 ActionController::Base send_response 48 1302 Object active_scaffold_column_ 1487 1313 ActionController::Base assign_shortcuts_withou 33 1331 Object get_column_value 1484 1525 Object assign_shortcuts 26 1605 ActionController::MimeRe method_missing 245 1621 Class digest 50 1699 ActionController::Base log_processing 24 1742 CGI::Cookie initialize 50 1791 Class construct_finder_sql 46 1791 PostgresPR::DataRow parse 836 1799 CGI::Session::CookieStor write_cookie 50 1885 Class construct_calculation_s 49 1914 Array collect! 49 2039 Range each 1950 2135 CGI::Session::CookieStor close 50 2158 CGI::Session close 50 2182 ActionController::Base close_session 50 2207 ActionController::Base process_cleanup_without 50 2220 Object process_cleanup_without 49 2331 Object process_cleanup 49 2344 Class create 1451 2500 Proc call 145 2655 PostgresPR::Message parse 1253 2835 PGresult initialize 149 2903 Class read 1219 3232 Object collect 953 3371 Object javascript_include_tag 98 3478 Object active_scaffold_include 47 5746 Array each_index 777 5767 ActiveRecord::Connection result_as_array 99 6845 Object _run_erb_app47views47la 45 10198 Object render 44 10748 ActionView::Template render_template 44 10761 PostgresPR::RowDescripti parse 117 17140
次にふつう scaffold の場合。
DTrace なしで ab を実行
% ab -c 10 -n 50 http://127.0.0.1:3000/people This is ApacheBench, Version 2.3 <$Revision: 655654 $> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Licensed to The Apache Software Foundation, http://www.apache.org/ Benchmarking 127.0.0.1 (be patient).....done Server Software: Mongrel Server Hostname: 127.0.0.1 Server Port: 3000 Document Path: /people Document Length: 15165 bytes Concurrency Level: 10 Time taken for tests: 1.485 seconds Complete requests: 50 Failed requests: 0 Write errors: 0 Total transferred: 784651 bytes HTML transferred: 758250 bytes Requests per second: 33.67 [#/sec] (mean) Time per request: 297.004 [ms] (mean) Time per request: 29.700 [ms] (mean, across all concurrent requests) Transfer rate: 515.99 [Kbytes/sec] received
DTrace ありで ab を実行
% ab -c 10 -n 50 http://127.0.0.1:3000/people This is ApacheBench, Version 2.3 <$Revision: 655654 $> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Licensed to The Apache Software Foundation, http://www.apache.org/ Benchmarking 127.0.0.1 (be patient).....done Server Software: Mongrel Server Hostname: 127.0.0.1 Server Port: 3000 Document Path: /people Document Length: 15165 bytes Concurrency Level: 10 Time taken for tests: 66.607 seconds Complete requests: 50 Failed requests: 0 Write errors: 0 Total transferred: 784750 bytes HTML transferred: 758250 bytes Requests per second: 0.75 [#/sec] (mean) Time per request: 13321.302 [ms] (mean) Time per request: 1332.130 [ms] (mean, across all concurrent requests) Transfer rate: 11.51 [Kbytes/sec] received
メソッド呼び出しの timestamp の合計をトレースした結果
% sudo dtrace -s rb_functime_ext2.d -p 92157 -x dynvarsize=200000000 dtrace: script 'rb_functime_ext2.d' matched 4 probes CPU ID FUNCTION:NAME 1 1 :BEGIN Tracing... Hit Ctrl-C to end. ^C 1 2 :END ELAPSED TIME DISTRIBUTION, ___ OVERLAP TIMES: ___ ______ ELAPSED ______ CLASS METHOD COUNT SUM(us) Thread initialize 1 228 Mongrel::HttpResponse send_header 1 311 Mongrel::HttpResponse send_status 1 469 Float / 50 796 ... (snip) ... Buffer write 4499 986509 Object pw 2897 1023068 ActiveRecord::Connection type_cast 749 1038280 ActiveSupport::TimeWithZ time 742 1089951 ActionController::Routin extra_keys 2300 1152680 ByteOrder byteorder 7997 1251414 ActiveSupport::TimeWithZ to_s 741 1441976 Object method_javascript_funct 745 1444529 Object read_attribute 749 1574240 ActiveRecord::Connection result_as_array 97 1593731 ActionController::Routin generate_raw 2296 1746928 BinaryReaderMixin read_int16_network 2194 1796596 Object build_named_route_call 1499 1817282 ActionController::Routin build_expiry 2297 1881047 Object convert_options_to_java 895 1891441 Class new 7251 2057934 ERB::Util h 2989 2143881 Buffer read 12737 2219477 Person created_at 747 2226666 #<Class:0x20d8a48> type_oid 4900 2385054 Object symbolize_keys 4791 2497200 Object readn 8133 2809972 Hash [] 84948 2934306 PostgresPR::RowDescripti parse 119 3202265 ActionController::Routin generate 2294 3911035 Hash each 8535 3989012 Object inject 10335 4439279 BinaryReaderMixin read_int32_network 5771 4705483 PGresult ftype 4886 5089918 Array each_index 785 5301481 PostgresPR::DataRow parse 827 5972588 Object ru_swap 7968 6010549 Object edit_person_path 733 6021765 Object collect 951 8153286 ActionController::Routin generate 2232 8989920 Object sleep 22 9064493 PostgresPR::Message parse 1245 9326013 Class create 1294 9568962 Array each 11186 9880625 Range each 1997 10849185 ActionController::UrlRew rewrite_path 2220 11788786 Class read 1216 11942478 Object person_path 1467 11946751 Object __send__ 5014 12988984 ActionController::UrlRew rewrite_url 2217 13000439 ActionController::UrlRew rewrite 2215 13172309 ActionController::Base url_for 2211 13883287 Object send 5352 15917858 Object polymorphic_url 1464 16378164 Object polymorphic_path 1464 16528890 Object link_to 2401 20567438 Object url_for 4617 33290132 Total out 1205969 416820493 Total in 1214823 416820493
メソッド呼び出しの timestamp の平均をトレースした結果
% sudo dtrace -s rb_functime_ext2.d -p 92157 -x dynvarsize=200000000 Password: dtrace: script 'rb_functime_ext2.d' matched 4 probes CPU ID FUNCTION:NAME 0 1 :BEGIN Tracing... Hit Ctrl-C to end. ^C 0 2 :END ELAPSED TIME DISTRIBUTION, ___ OVERLAP TIMES: ___ ______ ELAPSED ______ CLASS METHOD COUNT AVG(us) Float + 250 15 Float / 50 16 Fixnum < 8550 16 ... (snip) ... Object set_session_options 31 4675 ActionController::CgiReq stale_session_check! 34 5221 ActionController::UrlRew rewrite_path 2219 5293 ActionController::CgiReq session 34 5356 ActionController::Routin recognize 26 5357 ActionController::Abstra prepare! 50 5385 Range each 1998 5528 ActionController::Base send_response 50 5620 ActionController::Base assign_shortcuts_withou 34 5684 ActionController::UrlRew rewrite_url 2215 5845 ActionController::UrlRew rewrite 2213 5929 Array reverse_each 48 5931 ActionController::Base url_for 2208 6262 Object _run_erb_app47views47la 50 6665 Array each_index 784 6777 Object assign_shortcuts 29 6872 Class construct_finder_sql 47 7189 Object url_for 4605 7198 PostgresPR::DataRow parse 827 7224 Class create 1297 7496 PostgresPR::Message parse 1247 7599 ActionController::Base log_processing 30 8094 Object edit_person_path 734 8139 Object person_path 1467 8158 Class construct_calculation_s 48 8272 Object link_to 2394 8512 Object collect 956 8772 Object render 50 9185 ActionView::Template render_template 50 9252 Array collect! 47 9534 Class read 1219 9816 Object polymorphic_url 1456 11211 Object polymorphic_path 1455 11315 ActiveRecord::Connection result_as_array 93 15871 PostgresPR::RowDescripti parse 121 27688 Object sleep 19 461348
メソッド呼び出しの vtimestamp の合計をトレースした結果
% sudo dtrace -s rb_functime_ext2.d -p 92157 -x dynvarsize=200000000 dtrace: script 'rb_functime_ext2.d' matched 4 probes CPU ID FUNCTION:NAME 0 1 :BEGIN Tracing... Hit Ctrl-C to end. ^C 0 2 :END ELAPSED TIME DISTRIBUTION, ___ OVERLAP TIMES: ___ ______ ELAPSED ______ CLASS METHOD COUNT SUM(us) Mongrel::HttpResponse send_header 1 98 Mongrel::HttpResponse send_status 1 168 Fixnum <= 50 239 ... (snip) ... PGresult initialize 148 411874 Object build_named_route_call 1497 441301 BinaryReaderMixin read_int16_network 2191 454190 ActionController::Routin generate_raw 2298 459932 ActionController::Routin build_expiry 2294 477907 ERB::Util h 2992 491816 Array map 2447 497894 Person created_at 743 545922 Buffer read 12740 612775 ActiveRecord::Connection result_as_array 98 667425 Object symbolize_keys 4790 679480 Object readn 8132 746697 Hash [] 84950 803011 ActionController::Routin generate 2295 873134 Class new 7256 874521 Hash each 8536 1085655 BinaryReaderMixin read_int32_network 5762 1176401 Object inject 10336 1205810 Object edit_person_path 735 1416156 PostgresPR::DataRow parse 821 1483268 Object ru_swap 7956 1537059 PostgresPR::RowDescripti parse 113 1738528 ActionController::Routin generate 2231 2079986 #<Class:0x20d8a48> type_oid 4900 2260592 ActionController::UrlRew rewrite_path 2224 2765001 Object person_path 1474 2863491 Object collect 938 2984373 ActionController::UrlRew rewrite_url 2223 3055872 ActionController::UrlRew rewrite 2223 3081932 Object __send__ 5024 3082082 ActionController::Base url_for 2221 3212055 PostgresPR::Message parse 1233 3264624 Class create 1282 3318057 Object send 5366 3633977 Class read 1220 3864177 Range each 1986 3936521 Object polymorphic_url 1464 3938339 Object polymorphic_path 1463 3971707 Array each_index 781 4374570 PGresult ftype 4879 4611030 Array each 11184 4764152 Object link_to 2398 5037025 Object url_for 4624 7931197 Total out 1205922 118370056 Total in 1214781 118370056
メソッド呼び出しの vtimestamp の平均をトレースした結果
% sudo dtrace -s rb_functime_ext2.d -p 92157 -x dynvarsize=200000000 dtrace: script 'rb_functime_ext2.d' matched 4 probes CPU ID FUNCTION:NAME 1 1 :BEGIN Tracing... Hit Ctrl-C to end. ^C 0 2 :END ELAPSED TIME DISTRIBUTION, ___ OVERLAP TIMES: ___ ______ ELAPSED ______ CLASS METHOD COUNT AVG(us) Fixnum <=> 150 4 Fixnum > 22100 4 Struct::Tms cutime 100 4 ... (snip) ... Object set_session_options 37 1012 Object stylesheet_link_tag 50 1042 ActionController::Abstra prepare! 49 1179 ActionController::Routin recognize 20 1198 ActionController::Base send_response 49 1215 Array reverse_each 49 1260 ActionController::CgiReq stale_session_check! 27 1263 ActionController::UrlRew rewrite_path 2224 1273 ActionController::CgiReq session 26 1293 ActionController::Base assign_shortcuts_withou 26 1353 ActionController::UrlRew rewrite_url 2221 1404 ActionController::UrlRew rewrite 2220 1416 ActionController::Base url_for 2219 1476 Class construct_finder_sql 49 1509 Object _run_erb_app47views47la 49 1585 Object assign_shortcuts 20 1642 Class construct_calculation_s 48 1727 Object url_for 4621 1743 CGI::Cookie initialize 50 1748 ActionController::Base log_processing 35 1761 PostgresPR::DataRow parse 820 1806 CGI::Session::CookieStor write_cookie 50 1844 Object edit_person_path 739 1924 Object person_path 1467 1988 Array collect! 47 2045 Object link_to 2397 2068 Range each 1993 2077 CGI::Session::CookieStor close 50 2110 CGI::Session close 50 2136 Object render 49 2149 ActionController::Base close_session 50 2160 ActionView::Template render_template 49 2161 ActionController::Base process_cleanup_without 50 2172 Object process_cleanup_without 50 2265 Object process_cleanup 50 2279 Object sleep 36 2496 Class create 1281 2666 PostgresPR::Message parse 1233 2729 Object polymorphic_url 1458 2735 Object polymorphic_path 1458 2759 PGresult initialize 150 2837 Class read 1212 3184 Object collect 944 3372 Array each_index 783 5575 ActiveRecord::Connection result_as_array 99 6782 PostgresPR::RowDescripti parse 116 15876
Rails 実行中に GC にかかっている時間
前回の記事では Rails 実行中のメソッド呼び出しすべてをトレースしてみましたが、今回のターゲットは Garbage Collection に要している CPU 時間です。前と同じく、render :text => "Hello World!" なアプリに対して Apache Bench から 1万リクエストの負荷を与え、その間の GC 時間をトレースしました。
DTrace の結果をみると、計 75 回の GC が確認され、合計で約 5 秒程度 の CPU 時間を消費しているようです。ab の実行されていた約 40 秒間は、(アクティビティモニタで見ていると) ruby プロセスの CPU 使用率がほぼ 100% 近くに張り付いていたので、そのうちの約 1/8 が GC に使われていたということでしょうか。
# メソッド呼び出しのときと違い、トレース対象をひっかける回数も多くはないので、 DTrace をしかけたことによるオーバーヘッドの影響はほとんどありませんでした。(DTrace をしかけたときとそうでないときで、ab の結果はほとんど同じでした)
以下、作業ログです。
環境
- MacBook (intel Core 2 Duo 2GHz)
- Mac OS X 10.5.6
- 処理系、ライブラリのバージョンは以下のとおり
% /usr/bin/ruby -v ruby 1.8.6 (2008-03-03 patchlevel 114) [universal-darwin9.0] % dtrace -V dtrace: Sun D 1.2.2 % rails -v Rails 2.2.2 # 単純に render :text => "Hello World!" するだけのアプリを用意 % curl http://127.0.0.1:3000/posts Hello World!%
Ruby の GC 時間をトレースする DTrace スクリプト
- rb_gc.d
ruby$target:::gc-begin
{
self->start = vtimestamp;
}
ruby$target:::gc-end
/self->start/
{
this->elapsed = vtimestamp - self->start;
@count["COUNT"] = count();
@sum["SUM[us]"] = sum(this->elapsed);
@avg["AVG[us]"] = avg(this->elapsed);
self->start = 0;
}
dtrace:::END
{
normalize(@sum, 1000);
normalize(@avg, 1000);
printf("\n");
printa("%-15s %10@d\n", @count);
printa("%-15s %10@d\n", @sum);
printa("%-15s %10@d\n", @avg);
}
DTrace をしかけずに ab だけ実行
- まぁこんなものでしょう
% ab -c 10 -n 10000 http://127.0.0.1:3000/posts This is ApacheBench, Version 2.3 <$Revision: 655654 $> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Licensed to The Apache Software Foundation, http://www.apache.org/ Benchmarking 127.0.0.1 (be patient) (snip) Server Software: Mongrel Server Hostname: 127.0.0.1 Server Port: 3000 Document Path: /post Document Length: 12 bytes Concurrency Level: 10 Time taken for tests: 38.598 seconds Complete requests: 10000 Failed requests: 0 Write errors: 0 Total transferred: 4730018 bytes HTML transferred: 120000 bytes Requests per second: 259.08 [#/sec] (mean) Time per request: 38.598 [ms] (mean) Time per request: 3.860 [ms] (mean, across all concurrent requests) Transfer rate: 119.67 [Kbytes/sec] received
今度は、Dtrace をしかけておいて...
% sudo dtrace -s rb_gc.d -p 40211 dtrace: script 'rb_gc.d' matched 3 probes
再び ab を実行
- DTrace をしかけてないときとほとんど同じ結果です
- GC のはじまりと終わりをひっかけているだけなので、ほとんどオーバーヘッドはかかっていないようですね
% ab -c 10 -n 10000 http://127.0.0.1:3000/posts This is ApacheBench, Version 2.3 <$Revision: 655654 $> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Licensed to The Apache Software Foundation, http://www.apache.org/ Benchmarking 127.0.0.1 (be patient) (snip) Server Software: Mongrel Server Hostname: 127.0.0.1 Server Port: 3000 Document Path: /post Document Length: 12 bytes Concurrency Level: 10 Time taken for tests: 39.412 seconds Complete requests: 10000 Failed requests: 0 Write errors: 0 Total transferred: 4730018 bytes HTML transferred: 120000 bytes Requests per second: 253.73 [#/sec] (mean) Time per request: 39.412 [ms] (mean) Time per request: 3.941 [ms] (mean, across all concurrent requests) Transfer rate: 117.20 [Kbytes/sec] received
DTrace の結果
- 5373989 マイクロ秒、すなわち 約 5 秒程度、GC の実行に CPU 時間が消費されています
% sudo dtrace -s rb_gc.d -p 40211 dtrace: script 'rb_gc.d' matched 3 probes ^C CPU ID FUNCTION:NAME 0 2 :END COUNT 75 SUM[us] 5373989 AVG[us] 71653
DTrace をためしてみました
Rails 実行時の CPU 使用率がけっこう高いので、DTrace でなにかわからないものかと使ってみました。
以下のような環境のもとで、ここのサンプルをちょっと改良して、Apache Bench (以下、ab) で負荷をかけている Rails アプリをトレースしてみました。関数呼び出しごとの回数、平均処理時間、合計処理時間なんかをみています。GC にかかった CPU 時間なんかもトレースできるので、DTrace、面白いですね。
DTrace は軽いはずなんですが、関数呼び出しをすべてひろって集計とかをゴリゴリしているので、さすがにトレースの負荷が高かったです。 (^^;
# アプリの監視という意味では、もっと粗粒度のもの、リクエストごととか、データベース問い合わせごとでみるはずなので、そのくらいであればオーバヘッドはほとんど無視できるのでしょう。
ちなみに、DTrace のスレッドローカル変数の領域はデフォルトではけっこう小さいので、オプションをつけずに実行すると取りこぼしがわらわらとでてしまいました。ここらへんは注意が必要ですね。
(追記: 2009-2-12)
timestamp/vtimestamp で取得したメソッド呼び出し時間の合計値が明らかに実際の経過時間より大きくなっていましたが、DTrace の副作用である旨が資料に書かれていました。詳細は最後のほうに載せています。
環境
- iMac (intel Core 2 Duo 2.33GHz)
- Mac OS X 10.5.6
- 処理系、ライブラリのバージョンは以下のとおり
% /usr/bin/ruby -v ruby 1.8.6 (2008-03-03 patchlevel 114) [universal-darwin9.0] % dtrace -V dtrace: Sun D 1.2.2 % rails -v Rails 2.2.2 # 単純に render :text => "Hello World!" するだけのアプリを用意 % curl http://127.0.0.1:3000/posts Hello World!%
DTrace のスクリプト
- rb_functime_ext.d
- ほとんど、ここのパクリで、CPU時間と全関数呼び出しのサマリを出すようにしています
this string class;
this string method;
dtrace:::BEGIN
{
printf("Tracing... Hit Ctrl-C to end.\n");
depth = 0;
}
ruby$target:::function-entry
{
self->depth++;
self->start[copyinstr(arg0), copyinstr(arg1), self->depth] = vtimestamp;
@num["Total", "in"] = count();
}
ruby$target:::function-return
/(this->class = copyinstr(arg0)) != NULL && (this->method = copyinstr(arg1)) != NULL && self->start[this->class, this->method, self->depth]/
{
this->elapsed = vtimestamp - self->start[this->class, this->method, self->depth];
@num[this->class, this->method] = count();
@eavg[this->class, this->method] = avg(this->elapsed);
@esum[this->class, this->method] = sum(this->elapsed);
@edist[this->class, this->method] = quantize(this->elapsed);
@num["Total", "out"] = count();
@eavg["Total", "out"] = avg(this->elapsed);
@esum["Total", "in"] = sum(this->elapsed);
@esum["Total", "out"] = sum(this->elapsed);
self->start[this->class, this->method, self->depth] = 0;
self->depth--;
}
dtrace:::END
{
normalize(@eavg, 1000);
normalize(@esum, 1000);
printf("ELAPSED TIME DISTRIBUTION,\n");
printa(@edist);
setopt("aggsortpos", "2");
printf("%-33s %45s\n", "___ OVERLAP TIMES: ___", "______ ELAPSED ______");
printf("%-24s %-23s %6s %10s %12s\n", "CLASS", "METHOD", "COUNT", "AVG(us)", "SUM(us)");
printa("%-24.24s %-23.23s %@6d %@10d %@12d\n", @num, @eavg, @esum);
}
DTrace をしかけずに ab だけ実行
- たった、100回の実行なので、あっという間です!
% ab -c 10 -n 100 http://127.0.0.1:3000/posts This is ApacheBench, Version 2.3 <$Revision: 655654 $> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Licensed to The Apache Software Foundation, http://www.apache.org/ Benchmarking 127.0.0.1 (be patient).....done Server Software: Mongrel Server Hostname: 127.0.0.1 Server Port: 3000 Document Path: /posts Document Length: 12 bytes Concurrency Level: 10 Time taken for tests: 0.460 seconds Complete requests: 100 Failed requests: 0 Write errors: 0 Total transferred: 47201 bytes HTML transferred: 1200 bytes Requests per second: 217.20 [#/sec] (mean) Time per request: 46.040 [ms] (mean) Time per request: 4.604 [ms] (mean, across all concurrent requests) Transfer rate: 100.12 [Kbytes/sec] received
DTrace をしかけたときの ab の結果
- かなーり時間がかかっています... ざっと 20 倍くらい
% ab -c 10 -n 100 http://127.0.0.1:3000/posts This is ApacheBench, Version 2.3 <$Revision: 655654 $> Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/ Licensed to The Apache Software Foundation, http://www.apache.org/ Benchmarking 127.0.0.1 (be patient).....done Server Software: Mongrel Server Hostname: 127.0.0.1 Server Port: 3000 Document Path: /posts Document Length: 12 bytes Concurrency Level: 10 Time taken for tests: 10.095 seconds Complete requests: 100 Failed requests: 0 Write errors: 0 Total transferred: 47300 bytes HTML transferred: 1200 bytes Requests per second: 9.91 [#/sec] (mean) Time per request: 1009.509 [ms] (mean) Time per request: 100.951 [ms] (mean, across all concurrent requests) Transfer rate: 4.58 [Kbytes/sec] received
そのときの DTrace の結果
- 妙なログ "xxx dynamic variable drops" がたくさんでています、うまく測れてなさそう?
- 3万近い関数呼び出しをトレースしてるので、オーバヘッドも馬鹿にならないのかな...
- でも、合計 CPU 時間は 2秒くらいしかなくてなんか変!?
% sudo dtrace -s rb_functime_ext.d -p 74473 dtrace: script 'rb_functime_ext.d' matched 4 probes CPU ID FUNCTION:NAME 1 1 :BEGIN Tracing... Hit Ctrl-C to end. dtrace: 538 dynamic variable drops with non-empty dirty list dtrace: 28791 dynamic variable drops dtrace: 4624 dynamic variable drops with non-empty dirty list dtrace: 35199 dynamic variable drops dtrace: 35204 dynamic variable drops dtrace: 21923 dynamic variable drops dtrace: 17 dynamic variable drops dtrace: 11 dynamic variable drops dtrace: 11 dynamic variable drops dtrace: 11 dynamic variable drops ... (snip) ... ___ OVERLAP TIMES: ___ ______ ELAPSED ______ CLASS METHOD COUNT AVG(us) SUM(us) Time compare_without_coercio 8 5 46 Module included 18 4 87 Array blank? 18 4 88 ... (snip) ... ActionController::Base close_session 17 2251 38279 ActionController::Base process_cleanup_without 17 2264 38503 Object process_cleanup_without 17 2350 39951 Object process_cleanup 17 2364 40192 Object run_callbacks 70 578 40514 Object send 239 266 63719 Class new 702 158 110978 Mutex synchronize 33 3560 117487 Total out 29161 65 1922062 Total in 30683 0 1922062
"xxx dynamic variable drops" ってなに?
- Sun に DTrace - dynamic variable drop なページがあり、ここで紹介されている PDF の P22
- 変数用の領域がデフォルトでは小さいので、正しい結果が得られないことがあるみたい
- オプションを設定するべし、と...ふむふむ
Gotcha: Dynamic variable drops
- DTrace has a finite dynamic variable space for use by thread-local variables and associative array variables
- When exhausted, subsequent allocation will induce a dynamic variable drop, e.g.:
- dtrace: 103 dynamic variable drops
- These drops are often caused by failureto zero dead dynamic variables
- Must be eliminated for correct results!
Tip: Tuning away dynamic drops
- If a program correctly zeroes dead dynamic variables, drops must be eliminated by tuning
- Size tuned via the dynvarsize option
- In some cases, “dirty” "r “rin" dynamic variable drops may be seen:
- dtrace: 73 dynamic variable drops with non-empty dirty list
- These drops can be eliminated byincreasing cleanrate
というわけで、オプションをつけて DTrace を実行
- 今度は妙なログはでなかった
- CPU 時間も10秒で妥当そう?
- でも、関数の入口と出口でカウントをとってるはずなのに、なぜか差が生じてる... orz
% sudo dtrace -s rb_functime_ext.d -p 74473 -x dynvarsize=20000000 dtrace: script 'rb_functime_ext.d' matched 4 probes CPU ID FUNCTION:NAME 1 1 :BEGIN Tracing... Hit Ctrl-C to end. ... (snip) ... ___ OVERLAP TIMES: ___ ______ ELAPSED ______ CLASS METHOD COUNT AVG(us) SUM(us) IO read 1 56 56 Mongrel::HttpResponse send_body 1 78 78 Mongrel::HttpResponse send_header 1 93 93 TCPServer accept 3 35 105 Mongrel::HttpResponse send_status 1 144 144 Mongrel::HttpResponse write 3 49 147 Time compare_without_coercio 29 5 162 IO readpartial 2 120 241 Mongrel::HttpResponse finished 1 353 353 Fixnum * 100 4 480 Module included 100 4 481 ... (snip) ... ActiveSupport::Callbacks run 386 392 151470 Hash [] 13998 10 152694 ActionController::Base log_processing 88 1811 159408 CGI::Cookie initialize 100 1759 175919 ActiveSupport::Callbacks call 291 608 177066 CGI::Session::CookieStor write_cookie 100 1858 185827 CGI::Session::CookieStor close 100 2125 212568 CGI::Session close 100 2151 215142 ActionController::Base close_session 100 2175 217563 Object run_callbacks 378 578 218638 ActionController::Base process_cleanup_without 100 2188 218808 Object process_cleanup_without 100 2270 227099 Object process_cleanup 100 2284 228412 Object send 1286 278 357680 Class new 3300 156 516029 Mutex synchronize 177 3549 628291 Total out 150258 72 10859498 Total in 157439 0 10859498
今回のスクリプトでは、時間をとるのに timestamp ではなく、vtimestamp を使用しました。
D 言語を使ったスクリプトの作成 (DTrace ユーザーガイド) - Sun Microsystems によると、それぞれの意味は次のとおりです。
- uint64_t timestamp
ナノ秒タイムスタンプカウンタの現在の値です。このカウンタの値は、過去の任意の時点から増分しています。そのため、このカウンタは、相対計算専用です。
- uint64_t vtimestamp
ナノ秒タイムスタンプカウンタの現在の値です。このカウンタは、現在のスレッドの CPU 上での実行時間を示します。これには、DTrace の述語やアクションの実行にかかる時間は含まれません。このカウンタの値は、過去の任意の時点から増分しています。そのため、このカウンタは、相対時間計算専用です。
vtimestamp での関数呼び出しの合計値は 10859498 マイクロ秒、すなわち 約 11秒でしたが、timestamp を使って同様に合計値を求めてみると、40秒近くになってしまいました。
ab で 10秒程度負荷をかけていたのにその結果って...? 誤差の詰み重ねにしては微妙なような...?
# 相対的な時間の配分はわかるので、その用途でなら今の結果で十分なのですが。うーん。
(追記: 2009-2-12)
"xxx dynamic variable drops" について書かれていた PDF をよくよく見ていたら、理由と思われる記述がありました。やはり避けられない副作用があるみたいですね。
なので、とくに今回のようなオーバーヘッドの大きくなるようなトレースでは、絶対値はほとんど意味がないものと思ったほうがよいでしょう。
Gotcha: vtimestamp
- vtimestamp represents the number of nanoseconds that the current thread has spent on CPU since some arbitrary time in the past
- vtimestamp factors out time spent in DTrace – the explicit probe effect
- There is no way to factor out the implicit probe effect: cache effects, TLB effects, etc. due to DTrace
- Use the absolute numbers carefully!
今回は、Mongrel で Rails を動かしてますが、近いうちに Thin とかでもトレースをとってみようと思います。あとは、もう少し複雑なアプリでも結果をみてみたいと思います。
