はてブの X-Runtime レスポンスヘッダ

はてブのクライアントサイドでの処理時間を示すことのできる #benchmark ハッシュなんて話もありましたが（→2009-01-21 - 聴く耳を持たない(片方しか)），サーバサイドでどれくらい処理時間がかかったか（を反映していると思われる）示すレスポンスヘッダをサーバがだしてました。たぶん新はてブになってからですかね。

その名も X-Runtime: ヘッダです。

$ telnet b.hatena.ne.jp http
Trying xxx.xxx.xxx.xxx...
Connected to b.hatena.ne.jp.
Escape character is '^]'.
HEAD / HTTP/1.0
Host: b.hatena.ne.jp

HTTP/1.0 200 OK
Connection: close
Date: Fri, 06 Feb 2009 03:04:26 GMT
Server: Apache/2.2.3 (CentOS)
X-Framework: Ridge/0.05
X-Runtime: 12ms
Content-Length: 97864
Content-Type: text/html;charset=utf-8
Age: 23
X-Cache: HIT from squid.hatena.ne.jp
X-Cache-Lookup: HIT from squid.hatena.ne.jp:80
Via: 1.1 squid.hatena.ne.jp:80 (squid/2.7.STABLE5)
Set-Cookie: b=xxx; path=/; expires=xxx; domain=.hatena.ne.jp
Vary: Accept-Encoding

Connection closed by foreign host.

12ms なんて速っ，と思いますが，これは手打ちでやった……すなわち，未ログインの状態だから。

Firefox 3.0 + Live HTTP Headers ではてなにログインした状態でキャプチャした結果が下記のとおり。

HTTP/1.1 200 OK
Transfer-Encoding: chunked
Date: Fri, 06 Feb 2009 03:02:43 GMT
Server: Apache/2.2.3 (CentOS)
X-Framework: Ridge/0.05
X-Runtime: 3161ms
Content-Type: text/html;charset=utf-8
Vary: Accept-Encoding
Content-Encoding: gzip

こっちだと squid の Via がでませんね。なんでだろ。

つうことで，ログイン時には今回の例だと 3161ms です。そこまでかかっている体感はないですけどね。

未ログインの場合だと，どんなユーザに対しても同じコンテンツを返せばいいので，キャッシュしているみたいです。それを Squid だけにまかせているのか，ウェブアプリ側でもやっているのか，はわかりませんが，X-Runtime というヘッダをわざわざだしているということはたぶんウェブアプリ側でもキャッシュしてるんじゃないですかね*1。

ちなみに twitter のサーバも X-Runtime を返すらしいですが，こちらは単位はなく，たしか秒だったかなと思います。

レスポンスにかかった時間を（開発者が）知るためには CustomLog の %D や %T を使えばわかるのでやや露出がすぎる気もしますが，

ウェブサーバ内部の処理時間を無視して純粋にウェブアプリの処理時間を知ることができる((r->request_time を使えばウェブサーバ内部の処理時間も込みで計測はできます。))
デバッグ中にログ出力と自分のリクエストを紐づけするのはめんどう
わざと少なめの処理時間を提示して「けっしてウェブアプリが遅いわけじゃないんだよ，たぶんネットワークの問題だよ」とユーザに告知できる ;-P

などのメリットがあるかなと思います。

各サービス用の `X-Framework` を探ってみる

これだけだとなんなので，各サービスのトップページに HEAD リクエストを発行して X-Framework を調べてみました。なんという出歯亀。

service	`X-Framework`
a	-
b	Ridge/0.05
d	-
f	Hatena/2.0
g	Hatena/2.0
h	-
i	Hatena/2.0
m	-
q	Hatena/2.0
r	Hatena/2.0
s	-
counter	Hatena/2.0
graph	Hatena/2.0
search	Hatena/2.0
ring	Hatena/2.0
ugomemo	-

hatelabo はめんどうだったので調べていません。

ログインせずにトップページにアクセスした結果なので，下位リソースの取得によっては違うかもしれません。
LWP によるアクセスなので HTTP/1.0。一応 User Agent は Windows の IE7 を偽装しましたけど。

その他メモ。

X-Framework: Ridge（つまり b）だけ X-Runtime フィールドがつく
b, d, m では HTTP/1.1 時に Transfer-Encoding が chunked になってる

以下コード。当然ながら連射するとはてなに迷惑がかかるので自己責任？で。

#!/usr/bin/perl

use strict;
use warnings;

use URI;
use LWP::UserAgent;

our @DOMAINS = grep  { $_ ne q{} }
               map   { s{ (?: ^ \s+ | \s+ $ | \s* \# .*? $ ) }{}gxmso; $_ }
               split /\n+/, <<'END_DOMAINS';
#=====================================================================
    a           # Hatena Antenna
    b           # Hatena Bookmark
    d           # Hatena Diary
    f           # Hatena Fotolife
    g           # Hatena Group
    h           # Hatena Haiku
    i           # Hatena Idea
    m           # Hatena Message
    q           # Hatena Question
    r           # Hatena RSS
    s           # Hatena Star
    counter     # Hatena Counter
    graph       # Hatena Graph
    search      # Hatena Search
    ring        # Hatena Ring
    ugomemo     # Ugomemo Hatena
#=====================================================================
END_DOMAINS

my $ua = LWP::UserAgent->new();
$ua->agent('Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1)');

foreach my $domain (@DOMAINS) {
    my $uri = URI->new('/', 'http');
    $uri->scheme('http');
    $uri->host("${domain}.hatena.ne.jp");

    print "[${uri}]", "\n";

    my $res = $ua->head($uri);  # $ua->get($uri);

    if (! $res->is_success) {
        print $res->status_line, "\n";
        next;
    }

    foreach my $field (qw( Server X-Framework X-Runtime )) {
        my $value = $res->header($field);
        next  if ! defined $value;

        print "${field}: ${value}", "\n";
    }
    print "\n";
}

*1:Squid に実行時計測・出力機能があるのか（あるいははてなが仕込んでいるのか）もしれないですけどよく知りません。

各サービス用の X-Framework を探ってみる

各サービス用の `X-Framework` を探ってみる