2016年06月24日

Python に現在実装中の Compact dict の紹介

はてなブックマークに登録

背景

2015年1月に、 PyPy の開発者Blogにこんな記事がポストされました。

Faster, more memory efficient and more ordered dictionaries on PyPy

その後リリースされた PyPy 2.5.1 から dict は挿入順を維持するようになり、メモリ使用量も削減されました。

一方 CPython では、 PEP 468 で、キーワード引数を **kwargs という形式の仮引数で受け取るときに、引数の順序を保存しようという提案がされました。

例えば、 SQLAlchemy のクエリーで .filter_by(name="methane", age=32) と書いたときに生成されるクエリーが WHERE name = "methane" AND age = 32 になるか WHERE age = 32 AND name="methane" になるか不定だったのが、ちゃんと順序を維持するようになるといったメリットがあります。

(filter_by は等式専用のショートカット関数であって、キーワード引数を使わない filter というメソッドを使えば順序も維持されます。)

この提案者は pure Python だった OrderedDict クラスをCで再実装して、 Python 3.5 から OrderedDict がより高速かつ省メモリになりました。 (dict の方の修正を避けたのは、それだけ dict が Python インタプリタのために複雑に最適化されているからです。)

しかし、Cで再実装されたとは言え、双方向リンクリストで順序を管理された OrderedDict はそれなりにオーバーヘッドがあります。特にメモリ使用量については、倍近い差があります。

Python 3.5.1 (default, Dec  7 2015, 17:23:22)
[GCC 4.2.1 Compatible Apple LLVM 7.0.0 (clang-700.1.76)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import sys
>>> d = {i:i for i in range(100)}
>>> from collections import OrderedDict
>>> od = OrderedDict((i,i) for i in range(100))
>>> sys.getsizeof(d), sys.getsizeof(od)
(6240, 11816)

そのせいもあり、まだ PEP 468 は止まったままになっています。

私も、一部のユースケースで便利だからといって、全てのキーワード引数の性能を落とす可能性がある変更には抵抗があり、また PyPy の実装した dict に興味があったので、 Python 3.6 にギリギリ間に合う今のうちに挑戦することにしました。

(予定では9月前半に beta リリースされ機能追加できなくなるので、それまでに実装、評価検証、MLでの議論などを経てマージされる必要があります)

データ構造

変更した構造体は PyDictKeysObject だけです。ただし、以前よりメモリレイアウトがより動的になります。

struct _dictkeysobject {
    Py_ssize_t dk_refcnt;
    Py_ssize_t dk_size;
    dict_lookup_func dk_lookup;
    Py_ssize_t dk_usable;
    Py_ssize_t dk_nentries;  /* How many entries is used. */
    char dk_indices[8];      /* dynamically sized. 8 is minimum. */
};

#define DK_SIZE(dk) ((dk)->dk_size)
#define DK_IXSIZE(dk) (DK_SIZE(dk) <= 0xff ? 1 : DK_SIZE(dk) <= 0xffff ? 2 : \
                       DK_SIZE(dk) <= 0xffffffff ? 4 : sizeof(Py_ssize_t))
#define DK_ENTRIES(dk) ((PyDictKeyEntry*)(&(dk)->dk_indices[DK_SIZE(dk) * \
                        DK_IXSIZE(dk)]))

dk_get_index(PyDictKeysObject *keys, Py_ssize_t i)
{
    Py_ssize_t s = DK_SIZE(keys);
    if (s <= 0xff) {
        return ((char*) &keys->dk_indices[0])[i];
    }
    else if (s <= 0xffff) {
        return ((PY_INT16_T*)&keys->dk_indices[0])[i];
    }
    else if (s <= 0xffffffff) {
        return ((PY_INT32_T*)&keys->dk_indices[0])[i];
    }
    else {
        return ((Py_ssize_t*)&keys->dk_indices[0])[i];
    }
}

dk_set_index(PyDictKeysObject *keys, Py_ssize_t i)
{
...

以前のハッシュテーブルは 3word (hash, key, value) の PyDictKeyEntry 構造体の配列でしたが、こちらの方式ではハッシュテーブルの要素をただの整数型にしています。 構造体の宣言では char dk_index[8] になっていますが、これは最小の dk_size が8の時の大きさで、実際にはアロケート時により大きいサイズを確保します。さらに、この整数型自体も dk_size が 128 までは char ですが 256 からは int16_t になります。このようにしてギリギリまでハッシュテーブルのサイズを小さくします。

さらに、 dk_indices のサイズが動的なので構造体に直接宣言できませんが、この構造体の後ろに PyDictKeyEntry 構造体の配列を置いています。この配列のサイズは dk_size ではなくその 2/3 (前回の記事で紹介した、このハッシュテーブルに挿入可能な最大要素数) にしています。新しい要素を挿入するときは、この配列に追記していき、そのインデックスを dk_indices に保存します。 dk_nentries は配列中の要素数になります。

挿入時の操作を、同じキーがまだ存在しないと仮定した擬似コードで示すとこうなります。

// dk_indices 内の挿入位置を検索
pos = lookup(keys, key, hash);

// エントリ配列にエントリを追記する
DK_ENTRIES(mp)[keys->dk_nentries].me_hash = hash;
DK_ENTRIES(mp)[keys->dk_nentries].me_key = key;
DK_ENTRIES(mp)[keys->dk_nentries].me_value = value;

// dk_indices にそのエントリのインデックスを保存
dk_set_index(keys, pos, keys->dk_nentries);

// 最後に使用済みエントリ数をインクリメント
mp->dk_nentries++;

削除

この dict からアイテムを削除するには、 dk_indices の該当位置にダミー要素を代入しておきます。 (各インデックスが1バイトで扱えるエントリー数が256までではなく128までなのは、マイナスの値をダミーと空を表すために利用しているからです。)

エントリーからの削除については2つの方式があります。

最初に compact dict のアイデアが Python の開発者MLに投稿されたときは、最後の要素を削除された要素があった位置に移動することで、エントリー配列を密に保っていました。この方式では最後の要素が前に来るので、「挿入順を保存する」という特性が要素を削除したときに失われます。

一方、 PyPy や今回僕が採用したのは、単に空いた場所に NULL を入れておくというものです。

// dk_indices 内の削除する要素のインデックスがある位置を検索
pos = lookup(keys, key, hash);
// 削除する要素のエントリー配列内の位置を取得する
index = dk_get_index(keys, pos);

// 要素を削除する
DK_ENTRIES(mp)[index].me_key = NULL;
DK_ENTRIES(mp)[index].me_value = NULL;

// dk_indices にダミーを登録
dk_set_index(keys, pos, DUMMY);

こちらの方式は、挿入と削除を繰り返したときにエントリー配列がダミーでいっぱいになってコンパクションを実行する必要があるというデメリットがあります。 しかし、実は最初に提案された方式でも、挿入と削除を繰り返すうちにハッシュテーブルがダミーで埋まってしまい検索ができなくなってしまう可能性があるので、どちらにしろコンパクションは必要になります。そのため、挿入順を維持する方が良いと判断しました。

ちなみに、 .popitem() は、エントリー配列のうち最後の要素を削除し、 dk_nentries をデクリメントすることで、平均計算量を O(1) に保っています。 この場合も dk_usable という「残り挿入可能数」をインクリメントしないので、削除と挿入を繰り返すとコンパクションを実行してハッシュテーブルを再構成します。

Shared-Key dict

さて、問題の shared key dict です。

最初は、 compact dict を実装する前と同じように、ハッシュテーブルにダミー要素を挿入せず、エントリー配列側が NULL になっていたらダミーと判断すれば良いと思っていました。

しかし、これでは shared key に最初に要素を追加した dict の挿入順しか保存することができません。

>>> class A:
...     pass
...
>>> a = A()
>>> b = A()
>>> a.a = 1
>>> a.b = 2
>>> b.b = 1
>>> b.a = 2
>>> a.__dict__.items()
dict_items([('a', 1), ('b', 2)])
>>> b.__dict__.items()  # 挿入順は b, a なのに、、、
dict_items([('a', 2), ('b', 1)])

この問題について、次の3つの方針を考えていますが、MLで議論した上でGuidoかGuidoが委任したコア開発者が最終決定するまでどれになるか分かりません。

(1) ありのままを受け入れる

今の Python の言語仕様では、 dict の順序は不定です。なので、「インスタンスの属性を管理する dict を除いて挿入順を保存する」という今の動作も、言語仕様的には問題ないことになります。

compact dict になると shared key dict も ma_values 配列のサイズが dk_keys からその 2/3 になってよりコンパクトになるので、その恩恵を完全に受ける事ができます。

一方、デメリットとしては、殆どのケースで挿入順を保存するように振る舞うので、言語仕様を確認しない人はそれが仕様だと誤解してしまうことがあります。 この問題は「誤解するほうが悪い」とするのは不親切です。 たとえば Go はこのデメリットを避けるために、 map をイテレートするときの順序を意図的に (高速な擬似乱数を使って) 不定にしています。

(2) 挿入順が違ったら shared key をやめる

shared key が持っている順序と違う順序で挿入されようとしたらすぐに shared key をやめるという方法があります。

一番無難な方法に見えますが、どれくらい shared key を維持できるのかわかりにくくてリソース消費が予測しにくくなるとか、稀に通るパスで挿入順が通常と違い、 shared key が解除されてしまうと、同じサイズの dict を同じくらい利用し続けてるのにメモリ使用量がじわじわ増えてくる、といった問題があります。

実行時間が長い Web アプリケーションなどのプログラムで、メモリ消費量が予測しづらく、じわじわ増えるのは、あまりうれしくありません。 なので私はこの方式に乗り気では無いです。

(3) Shared Key Dict をやめる

shared key dict は、ハマったときはとても効率がいいものの、 compact ordered dict の方が安定して効率がいいです。 しかも shared key dict をサポートするために、 dict の実装がだいぶ複雑になってしまっています。

実際に shared key dict を実装から削ってみた所、4100行中500行くらいを削除することができました。簡単に削除しただけなので、さらにリファクタリングして削れると思います。

一方効率は、 Python のドキュメントを Sphinx でビルドするときの maxrss を /usr/bin/time で計測した所、

  • shared: 176312k
  • compact + shared: 158104k
  • compact only: 166888k

という感じで、 shared key をやめても compact dict の効果によるメモリ削減の方が大きいという結果がでました。

(もちろんこれは1つのアプリケーションにおける結果でしか無いので、他に計測に適した、クラスやインスタンスをそこそこ使って実行時間とメモリ使用量が安定している現実のアプリケーションがあれば教えてください。)

また、 shared key を削除して実装を削れた分、別の効率のいい特殊化 dict を実装して、 compact + shared よりも高い効率を狙うこともできます。 今はあるアイデアのPOCを実装中なので、採用されたらまた紹介します。

OrderedDict

OrderedDict を compact dict を使って高速化する方法についても補足しておきます。

Python 3 には、 Python 2.7 には無かった move_to_end(key, last=True) というメソッドがあります。このキーワード引数がクセモノで、 move_to_end(key, last=False) とすると先頭に移動することができます。(機能はともかくメソッドの命名についてはとてもセンスが悪いと思います。 move_to_front(key) でええやん。)

この機能を実装するために、 dk_entries 配列をキャパシティ固定の動的配列ではなく、キャパシチィ固定の deque として扱うというアイデアを持っています。 つまり、今は dk_entries[0] から dk_entries[dk_nentries-1] までを使っているのですが、それに加えて先頭に要素を追加するときは dk_entries の後ろから先頭に向かって挿入していきます。

これを実現するには dk_nentries の反対版を作って、ハッシューテーブルの走査やリサイズがその部分を扱うように改造すれば良いです。 OrderedDict 1つあたり 1word (8byte) を追加するだけで、消費メモリを半減させることが可能なはずです。

ですが、Shared-Key 問題で手一杯なうえ、 dict が挿入順を保存するようになったら OrderedDict の利用機会も減ってしまうので、このアイデアを実装するモチベーションがありません。少なくとも Python 3.6 には(誰かが僕の代わりに実装してくれない限り)間に合わないでしょう。


@methane


songofacandy at 16:02
この記事のURLComments(0)TrackBack(0)Python 
2016年06月22日

Python の dict の実装詳解

はてなブックマークに登録

@methane です。

最近 Python の dict をハックしているので、その紹介をしたいと思います。 ですが、まずこの記事では現在 (Python 3.6a2) の dict の実装を詳解します。

データ構造

基本となる構造体は3つです。(Python 3.6a2 のソースより引用)

typedef struct _dictkeysobject PyDictKeysObject;

typedef struct {
    PyObject_HEAD
    Py_ssize_t ma_used;
    PyDictKeysObject *ma_keys;
    PyObject **ma_values;
} PyDictObject;

typedef struct {
    /* Cached hash code of me_key. */
    Py_hash_t me_hash;
    PyObject *me_key;
    PyObject *me_value; /* This field is only meaningful for combined tables */
} PyDictKeyEntry;

typedef PyDictKeyEntry *(*dict_lookup_func)
(PyDictObject *mp, PyObject *key, Py_hash_t hash, PyObject ***value_addr);

struct _dictkeysobject {
    Py_ssize_t dk_refcnt;
    Py_ssize_t dk_size;
    dict_lookup_func dk_lookup;
    Py_ssize_t dk_usable;
    PyDictKeyEntry dk_entries[1];
};

PyDictObject が dict のインスタンスを表すオブジェクトです。 PyObject_HEAD は Python のオブジェクトすべてが持っている共通の管理用データ(参照カウント等)を定義するマクロで、通常ビルドでは3ワード(64bit環境では24バイト)になります。

ma_used がその dict に入っている要素数、 ma_keys が動的に確保されるハッシュテーブルです。 ma_values については後述します。

PyDictKeyEntry はハッシュテーブルの各エントリとなる構造体です。 me_key, me_value が名前のままキーと対応する値となる Python オブジェクトへのポインタで、 me_hash は me_key のハッシュ値です。探索やハッシュテーブルの再構築のときに必要になるので毎回計算するのではなくてエントリーに持ってしまっています。

PyDictKeysObject がハッシュテーブルです。 dk_size がハッシュテーブルのサイズ、 dk_usable があと何要素ハッシュテーブルに入れられるかを示すカウンタです。 dk_usable が 0 のときに挿入しようとするとハッシュテーブルが再構築され、必要に応じて拡張されます。 dk_refcnt については ma_values とともに後で解説します。

dk_lookup は探索関数への関数ポインタです。 dict は例えば関数呼び出しのときに名前から関数を探索したりと、主に文字列をキーとして Python の言語の基本を支えているので、 key の型が文字列の dict に特殊化して高速にした関数を最初に入れておき、文字列以外のキーを挿入した段階で汎用の関数へのポインタに差し替えるなどを行っています。

dk_entries はハッシュテーブルの実態です。構造体の宣言では1要素の配列になっていますが、実際には次のように PyDictKeysEntry をアロケートすることで dk_size の長さを持つ配列になります。

    dk = PyObject_MALLOC(sizeof(PyDictKeysObject) +
                      sizeof(PyDictKeyEntry) * (size-1));

オープンアドレス法

ハッシュテーブルのサイズ (dk_size) は 2^n になっています。また、そのハッシュテーブルに格納できる要素数 (dk_usable の初期値) は (2*dk_size+1)/3 になっています。

dk_size が 2^n なので、ハッシュテーブルに要素を挿入したり、探索する場合は、ハッシュ値 & (dk_size-1) で場所を決めます。 (dk_size が 8 なら2進数で表すと 0b1000 で、 dk_size-1 が 7 = 0b0111 になり、ハッシュ値の下位3bitを利用することになる)

dk_usable が 0 になりハッシュテーブルを再構築する際、(削除操作がなく純粋に追加してきた場合は)dk_sizeが2倍になり、ハッシュテーブルの「密度」は 2/3 から 1/3 になります。なのでハッシュテーブルの密度は下限がだいたい 1/3 、上限が 2/3 になります。

さて、ハッシュ値が綺麗に分散しているとしたら、挿入時に利用されるハッシュ値の下位ビットの衝突率は 1/3 と 2/3 の平均で 1/2 程度になるでしょう。 実際にはハッシュ値は綺麗に分散しているとは限らないので、これより悪くなるはずです。

ハッシュ法で衝突に対処する方法としては、要素をハッシュテーブル外のリストなどに置いてハッシュテーブルにはそこへの参照を格納する方法(オープンハッシュ法)と、ハッシュテーブル内の別の場所に格納する方法(クローズドハッシュ法、またはオープンアドレス法。「オープン」が全く逆のオープンハッシュ法と被るので紛らわしいです)がありますが、 Python はクローズドハッシュ法を採用しています。

クローズドハッシュ法では、「衝突したら次はどこを使うか」というアルゴリズムを決めておいて、挿入も探索も同じ方法を使わなければなりません。 メモリアクセスの効率を考えると衝突した場所の隣の場所を使うのが良いのですが、ハッシュ値が良くなくて衝突が頻発したときや、ハッシュテーブル内に偏りが発生した場合に、次も、その次も、その次も、という感じに衝突する可能性が高くなります。

ハッシュテーブル内を飛び飛びに巡回し、最終的にはテーブル内の全要素を1回ずつ走査する関数が欲しいのですが、その関数として Python は (5*i+1) mod dk_size を採用しています。 例えば dk_size が 8 で ハッシュ値の下位3bitが 3 なら、ハッシュテーブルを 3, 0, 1, 6, 7, 4, 5, 2, 3 という形で、 0~7 を1度ずつ通って最初の 3 に戻ってきます。

しかし、この方法ではハッシュテーブル内の密度の偏りの影響を避けられるものの、ハッシュ値の下位ビットが衝突する key は同じ順番に巡回するので線形探索になってしまい効率が悪いという欠点があります。そこで、先程の関数を改造して、次のようにしています。

    for (perturb = hash; ; perturb >>= PERTURB_SHIFT) {
        i = i * 5 + perturb + 1;

これで、最初のうちはハッシュ値の上位ビットを使って次の位置を決定していき、ハッシュ値を右シフト仕切ったら先ほどのアルゴリズムで確実に巡回する、というハイブリッド型の巡回アルゴリズムになります。

(ちなみに、このforループには最初の衝突のあとにくるので、 perturb の初期値が hash のままだと、hash 値の下位ビットが衝突する key と1つ目だけでなく2つ目も衝突してしまいますね…)

(なお、 dict よりも最近に改良された set 型では、最初はキャッシュ効率を重視して近くの要素を探すといった改良がされています。)

削除

オープンアドレス法での要素の削除には注意が必要です。というのは、探索や挿入のときの巡回は、同じキーか空きを発見したときに停止するからです。

あるキーAを挿入するときに別のキーBと衝突して別の場所に挿入したのに、その別のキーBが削除されて空きになってしまうと、キーAをまた探索するときに、キーBがあった場所に空きを見つけて、キーAはハッシュテーブルに存在しないと判断してしまいます。

これを避けるために、削除するときはハッシュテーブルを空きに戻すのではなく、ダミー要素に入れ替えます。

また、 popitem() という dict の中の任意の (key, value) を取得しつつ削除するメソッドの実装にも注意が必要です。 ハッシュテーブルを線形探索して、最初に見つけた要素を返し、その場所をダミーに置き換えるのですが、これを繰り返すとハッシュテーブルがダミー要素だらけになっていって、次のようなアルゴリズムの実行時間が O(n**2) になってしまいます。

while d:
    k, v = d.popitem()
    do_something(k, v)

popitem() の平均計算量を O(1) にするために、ハッシュテーブルの先頭に要素があればそれを返し、無かった場合は線形探索した後に、次に線形探索を開始する場所を(空、あるいはダミーkeyが入っている)先頭要素の me_value に格納しておきます。

PEP 412: Key-Sharing Dictionary

次のインタラクティブセッションでは、2つの空の dict のメモリ使用量を表示しています。

>>> d = {}
>>> class A: pass
...
>>> a = A()
>>> ad = a.__dict__  # a の属性を格納している dict のインスタンス
>>> d
{}
>>> ad
{}
>>> type(d), type(ad)
(<class 'dict' at 0x109c735b0>, <class 'dict' at 0x109c735b0>)
>>> import sys
>>> sys.getsizeof(d)
288
>>> sys.getsizeof(ad)
96

両方共確かに dict の空のインスタンスなのですが、サイズは 288 バイトと 96 バイトと、3倍近くの差があります。なぜでしょうか?

ここで、説明を省略していた PyDictKeysObject の dk_refcnt と PyDictObject の ma_values が登場します。

dk_refcnt は参照カウントになっていて、A のインスタンス a を作った際、 a の属性を管理する dict インスタンスを作った後、その PyDictKeysObject の dk_refcnt をインクリメントして、クラス A にポインタをもたせます。

その後、クラスAのインスタンスを作る際は、そのインスタンス用の dict を作るときに PyDictKeysObject を作るのではなく、クラスAが持っているオブジェクトを参照し、参照カウントをインクリメントします。このように、同じクラスの複数のインスタンス間で、 PyDictKeysObject は共有されます。

ハッシュテーブルを共有しているので、 me_value に各 dict が持つはずの値を格納することができません。 PyDictObject の ma_values に、 dk_size と同じ大きさの PyObject* の配列を持たせて、 dk_entries[i].me_value の代わりに ma_values[i] に値を格納します。

dk_entries は各要素がポインタ3つ分の大きさを持っている一方で、 ma_values はポインタ1つ分で済むので、これでかなりのサイズを削減できます。

また、 dk_usable の初期値が (dk_size*2)/3 ではなく (dk_size*2+1)/3 になっていたのにも秘密があります。

通常の dict では dk_size の最小値が 8 なのですが、 key sharing dict では dk_size が 4 になっているのです。 (4*2)/3 は 2 なのに対して、 (4*2+1)/3 は3になるので、この最小の key sharing dict は3つの要素を格納することができるのです。

この結果、属性が3つ以下のインスタンスは 64bit 環境では 96 バイトの dict で属性を管理することができるのです。

この key sharing dict は、 Python 3.4 で導入されました。 (ちなみに 3.4 ではバグでサブクラスで有効にならなかったのが、 3.4.1 で解消されました)

この素敵な新機能が、 dict をハックしていた僕を、単純に実装を複雑にしたり考えないといけないケースを増やすというだけでなく、かなり重い意味で苦しめることになります。

その話は次回の記事で解説します。


@methane


songofacandy at 17:01
この記事のURLComments(0)TrackBack(0)Python 
2016年06月03日

pixiv private isucon 2016 攻略 (5/5)

はてなブックマークに登録

攻略記事一覧:

ボトルネック探し

前回は一番重かったトップページにページキャッシュを導入して劇的に高速化したものの、CPU以外がボトルネックになって大した高速化はできませんでした。 こういう場合は dstat が役に立つことが多いです。

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw
  2   0  98   0   0   0| 596k  271k|   0     0 |   0     0 | 606   755
  1   0 100   0   0   0|   0     0 | 192B 1190B|   0     0 | 119   177
  0   0 100   0   0   0|   0     0 |  66B  350B|   0     0 | 103   158
  1   0  98   1   0   0| 512k    0 | 537B  783B|   0     0 | 962  1035
 48   7  38   3   0   5|  16M  728k|4590k   60M|   0     0 |  24k   20k
 44   7  36   5   0   8|  11M  376k|6568k   71M|   0     0 |  34k   26k
 44  11  35   4   0   7|  18M  312k|6190k   71M|   0     0 |  33k   27k
 48   8  33   3   0   8|  14M  272k|7784k   71M|   0     0 |  31k   24k
 41   7  42   4   0   6|  17M  352k|8097k   72M|   0     0 |  31k   23k
 44   9  38   4   1   5|  14M  256k|8019k   71M|   0     0 |  33k   25k
 44  10  35   3   0   8|  10M  448k|7705k   71M|   0     0 |  32k   25k
 36   9  46   3   0   6|  14M  224k|7196k   71M|   0     0 |  32k   22k
 38  10  39   6   0   7|  16M   18M|7812k   71M|   0     0 |  31k   22k
 47   9  28  11   0   4|  20M   47M|6683k   72M|   0     0 |  29k   19k
 45   7  39   3   0   6|  10M  696k|6113k   71M|   0     0 |  33k   24k
 42   7  39   4   0   8|  12M  672k|3825k   71M|   0     0 |  33k   24k
 51   8  31   3   0   6|  13M  512k|6750k   71M|   0     0 |  31k   22k
 44   9  39   2   0   5|5496k  648k|8045k   71M|   0     0 |  32k   24k
 53   9  28   3   0   6|  20M  544k|5832k   71M|   0     0 |  29k   20k
 41   7  42   3   0   7|  14M  616k|7459k   71M|   0     0 |  35k   24k
 48   9  31   4   0   8|  17M  608k|5869k   71M|   0     0 |  30k   23k
 38  11  40   3   0   8|  14M  752k|8956k   71M|   0     0 |  32k   24k
 44  11  36   4   0   5|  13M  576k|7181k   71M|   0     0 |  33k   25k
 47   7  35   7   0   5|  14M   62M|5753k   65M|   0     0 |  30k   22k
...

net の send が 71M で張り付いてるのが目につきますね。アプリサーバーは c4.large なのでこんなもんでしょう。

ですが、 pixiv さんの Blog 記事 のスクリーンショットを見ると、多くのチームが 40k 点を超えていて、トップチームは180k点に到達しています。こっちは40k点の手前で帯域の壁にぶつかってるのに、変だぞ? (Twitter で pixiv の @catatsuy さんに、ポータルのスコアとコマンドラインによるベンチマーカーのスコアが同一であることを確認しました。)

さて、2つ目の記事で、次のように言っていましたね。

帯域は /image/ が支配的。帯域ネックになるようだったら、画像は再圧縮しにくいので、ヘッダーを適切に設定すればクライアントに "304 Not Modified" を返せるようになって大きなブレークスルーがあるかもしれない。

試しにクライアントのキャッシュ実装に影響を与えそうなヘッダーを追加してみましょう。 "nginx 静的ファイル キャッシュ" でググってそれっぽいのを探します

  upstream app {
    server 127.0.0.1:8080;
    keepalive 64;
  }

server {
  listen 80;

  client_max_body_size 10m;
  root /home/isucon/private_isu/webapp/public/;

  location / {
    try_files $uri @app;
  }
  location ~* \.(?:ico|css|js|gif|jpe?g|png)$ {
    try_files $uri @app;
    expires max;
    add_header Pragma public;
    add_header Cache-Control "public, must-revalidate, proxy-revalidate";
    etag off;
  }
  location @app {
    proxy_set_header Host $host;
    proxy_set_header X-Real-IP $remote_addr;
    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_pass http://app;
  }
}

計測してみます。

スコア:

{"pass":true,"score":182435,"success":174747,"fail":0,"messages":[]}

pixiv 社内 isucon のトップと同じくらいのスコアがでました。(これはプロファイルを取ったりいろいろしながらのスコアなので、仕上げしたらもう少し伸びるはずです)

top, dstat:

Tasks:  81 total,   3 running,  78 sleeping,   0 stopped,   0 zombie
%Cpu(s): 80.7 us, 11.5 sy,  0.0 ni,  3.0 id,  0.5 wa,  0.0 hi,  4.2 si,  0.0 st
KiB Mem:   1022972 total,   954144 used,    68828 free,    25432 buffers
KiB Swap:        0 total,        0 used,        0 free.   557948 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 1397 isucon    20   0  377096  97572   8880 S 100.5  9.5   0:27.35 app.dc4a3eaa
  731 mysql     20   0 1059292 183956  10552 S  65.9 18.0   2:26.08 mysqld
 1396 www-data  20   0   92088   5304   3144 R  18.6  0.5   0:04.99 nginx
 1069 isucon    20   0   33140  10476   2636 S   5.7  1.0   0:12.10 tmux
  308 memcache  20   0  334624   9744   2228 S   0.7  1.0   0:01.38 memcached
  110 root      20   0       0      0      0 S   0.3  0.0   0:00.08 jbd2/xvda2-8
 1034 root      20   0       0      0      0 S   0.3  0.0   0:02.89 kworker/1:0
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
  0   0 100   0   0   0|   0     0 |   0     0 |   0     0 |  45    76 
 21   5  71   2   0   1|  11M    0 |1987k   12M|   0     0 |8731  9184 
 73  15   5   2   0   5|  17M  904k|4574k   25M|   0     0 |  19k   20k
 78  13   3   1   0   6|  20M  272k|3815k   18M|   0     0 |  15k   17k
 80   9   6   2   0   4|  25M  272k|7221k   20M|   0     0 |  16k   17k
 81  11   4   1   0   4|  18M  272k|5953k   20M|   0     0 |  15k   16k
 81  10   4   0   0   5|  24M  256k|5363k   24M|   0     0 |  15k   17k
 76  13   6   2   0   4|  20M  272k|8293k   18M|   0     0 |  16k   17k
 82  11   2   1   0   5|  15M  552k|2665k   18M|   0     0 |  16k   16k
 80  14   3   1   0   4|  14M  408k|2870k   15M|   0     0 |  15k   16k
 79  12   5   1   0   4|  16M  360k|5475k   19M|   0     0 |  17k   18k
 79  11   5   2   0   3|  16M   65M|5456k   21M|   0     0 |  15k   16k
 77  12   6   1   0   4|  19M  760k|6763k   23M|   0     0 |  19k   20k
 79  12   4   2   0   4|  23M  592k|6824k   19M|   0     0 |  16k   17k
 79  12   5   2   0   3|  11M  632k|5994k   20M|   0     0 |  16k   18k
 82  11   3   1   0   4|  11M  680k|3447k   16M|   0     0 |  15k   17k
 83  11   2   0   0   4|  13M  792k|5076k   18M|   0     0 |  16k   18k
...

CPUを使い切るようになったのが判ります。

access.log 集計:

Request by count
117444 GET /image/*
7987 GET /
6394 GET /js/jquery-2.2.0.js
6394 GET /css/style.css
6394 GET /js/jquery.timeago.ja.js
6394 GET /favicon.ico
6394 GET /js/jquery.timeago.js
6394 GET /js/main.js
4028 POST /login
1459 GET /login
1176 GET /posts/*
959 POST /register
958 GET /admin/banned
873 GET /@user
731 GET /logout
609 POST /
330 GET /posts?max_created_at=
268 POST /comment
1 GET /initialize

Request by total time
98.996 0.299987878788 GET /posts?max_created_at=
84.66 0.0105997245524 GET /
84.077 0.0963081328751 GET /@user
52.172 0.0129523336643 POST /login
39.666 0.0337295918367 GET /posts/*
33.621 0.0552068965517 POST /
19.801 0.0738843283582 POST /comment
17.144 0.0117505140507 GET /login
...

Request by out bytes
894159053 7613 GET /image/*
185613643 23239 GET /
16456443 18850 GET /@user
11202870 33948 GET /posts?max_created_at=
4098331 3484 GET /posts/*
...

image の転送量が大幅に減ったことが確認できます。また、集計せずに access.log を見ると、狙い通り 304 を返せていることが判ります。

(余談) 壁の超え方

2つ目の記事で 304 Not Modified を返せることを予想していたのは、エスパーでもなんでもありません。一昨年 (2014年) の決勝であったんです。その時はこの壁を超えられず悔しい思いをしました。

その時、壁を超えたチームが2チームありました。準優勝チームは静的ファイルを返すための nginx の設定のテンプレ(いわゆる「秘伝のタレ」)を使ったらいきなりスコアが上がったけど何が起こったのか設定した本人にも分からなかった、そして優勝チームは順優勝チームのスコアを見て「必ず壁を超える方法があるはずだ」と試行錯誤した結果壁を超えたと記憶しています。(興味がある方は当時の blog 記事を探してみてください)

「秘伝のタレ」が偶然ハマる、という壁の超え方は準備の賜物です。 個人的にはチューニングするときはパラメーターを1つ1ついじって効果確認したいところですが、それだと時間がもったいないし、ベンチマーカーの挙動についての予想が当てられないと壁が超えられないので、やはり「秘伝のタレ」は強力な武器になります。

一方、ベンチマーカーの動作を予想し試行錯誤するやり方は、問題作成側の心理を読む ISUCON 力、可能性のある試行錯誤をするための引き出し(今回でいえば HTTP ヘッダーとキャッシュに関する知識)、精神力などが求められます。 過去に決勝で優勝したチームはどれもこの能力が特に優れていたチームだと思います。難しいですが優勝を目指して勉強と鍛錬をしましょう。

雑巾絞り

CPUネックになったことですし、CPUプロファイルを見てみましょう。

(pprof) top30 -cum
7.63s of 29.87s total (25.54%)
Dropped 601 nodes (cum <= 0.15s)
Showing top 30 nodes out of 296 (cum >= 4.36s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     28.68s 96.02%  runtime.goexit
         0     0%     0%     24.58s 82.29%  net/http.(*conn).serve
         0     0%     0%     23.35s 78.17%  net/http.(*ServeMux).ServeHTTP
         0     0%     0%     23.35s 78.17%  net/http.serverHandler.ServeHTTP
         0     0%     0%     23.32s 78.07%  github.com/zenazn/goji/web.(*Mux).ServeHTTP
         0     0%     0%     23.30s 78.00%  github.com/zenazn/goji/web.(*cStack).ServeHTTP
         0     0%     0%     23.30s 78.00%  github.com/zenazn/goji/web/middleware.RequestID.func1
         0     0%     0%     23.30s 78.00%  net/http.HandlerFunc.ServeHTTP
         0     0%     0%     23.25s 77.84%  github.com/zenazn/goji/web/middleware.Logger.func1
         0     0%     0%     22.71s 76.03%  github.com/zenazn/goji/web.(*mStack).newStack.func1
     0.01s 0.033% 0.033%     22.71s 76.03%  github.com/zenazn/goji/web.(*router).route
         0     0% 0.033%     22.71s 76.03%  github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
         0     0% 0.033%     22.71s 76.03%  github.com/zenazn/goji/web/middleware.Recoverer.func1
     0.01s 0.033% 0.067%     18.11s 60.63%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0% 0.067%     12.85s 43.02%  main.getPosts
         0     0% 0.067%     12.46s 41.71%  github.com/jmoiron/sqlx.(*DB).Select
         0     0% 0.067%     12.46s 41.71%  github.com/jmoiron/sqlx.Select
     0.07s  0.23%   0.3%     11.69s 39.14%  github.com/jmoiron/sqlx.scanAll
     1.72s  5.76%  6.06%      9.78s 32.74%  runtime.mallocgc
     0.16s  0.54%  6.60%      8.62s 28.86%  runtime.systemstack
     5.02s 16.81% 23.40%      7.29s 24.41%  runtime.scanobject
     0.15s   0.5% 23.90%      5.91s 19.79%  runtime.newobject
         0     0% 23.90%      5.33s 17.84%  runtime.gcAssistAlloc
         0     0% 23.90%      5.33s 17.84%  runtime.gcAssistAlloc.func1
     0.04s  0.13% 24.04%      5.33s 17.84%  runtime.gcDrainN
     0.04s  0.13% 24.17%      5.22s 17.48%  database/sql.(*Rows).Next
     0.03s   0.1% 24.27%      5.04s 16.87%  github.com/go-sql-driver/mysql.(*textRows).Next
     0.34s  1.14% 25.41%      5.01s 16.77%  github.com/go-sql-driver/mysql.(*textRows).readRow
         0     0% 25.41%      4.55s 15.23%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
     0.04s  0.13% 25.54%      4.36s 14.60%  main.makePosts


(pprof) list getPosts
Total: 29.87s
ROUTINE ======================== main.getPosts in /home/isucon/private_isu/webapp/golang/app.go
         0     12.85s (flat, cum) 43.02% of Total
         .          .    593:           fmt.Println(terr)
         .          .    594:           return
         .          .    595:   }
         .          .    596:
         .          .    597:   results := []Post{}
         .     11.19s    598:   rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= ? ORDER BY `created_at` DESC", t.Format(ISO8601_FORMAT
))
         .          .    599:   if rerr != nil {
         .          .    600:           fmt.Println(rerr)
         .          .    601:           return
         .          .    602:   }
         .          .    603:
         .      1.03s    604:   posts, merr := makePosts(results, getCSRFToken(r), false)
         .          .    605:   if merr != nil {
         .          .    606:           fmt.Println(merr)
         .          .    607:           return
         .          .    608:   }
         .          .    609:
         .          .    610:   if len(posts) == 0 {
         .          .    611:           w.WriteHeader(http.StatusNotFound)
         .          .    612:           return
         .          .    613:   }
         .          .    614:
         .          .    615:   fmap := template.FuncMap{
         .          .    616:           "imageURL": imageURL,
         .          .    617:   }
         .          .    618:
         .          .    619:   template.Must(template.New("posts.html").Funcs(fmap).ParseFiles(
         .       10ms    620:           getTemplPath("posts.html"),
         .          .    621:           getTemplPath("post.html"),
         .      620ms    622:   )).Execute(w, posts)
         .          .    623:}
         .          .    624:
         .          .    625:func getPostsID(c web.C, w http.ResponseWriter, r *http.Request) {
         .          .    626:   pid, err := strconv.Atoi(c.URLParams["id"])
         .          .    627:   if err != nil {

(pprof) list makePosts
Total: 29.87s
ROUTINE ======================== main.makePosts in /home/isucon/private_isu/webapp/golang/app.go
      40ms      4.36s (flat, cum) 14.60% of Total
         .          .    188:}
         .          .    189:
         .          .    190:func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
         .          .    191:   var posts []Post
         .          .    192:
         .       20ms    193:   for _, p := range results {
         .      720ms    194:           err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
         .          .    195:           if err != nil {
         .          .    196:                   return nil, err
         .          .    197:           }
         .          .    198:
         .          .    199:           query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
         .          .    200:           if !allComments {
         .          .    201:                   query += " LIMIT 3"
         .          .    202:           }
         .          .    203:           var comments []Comment
         .      920ms    204:           cerr := db.Select(&comments, query, p.ID)
         .          .    205:           if cerr != nil {
         .          .    206:                   return nil, cerr
         .          .    207:           }
         .          .    208:
         .          .    209:           for i := 0; i < len(comments); i++ {
      20ms      1.89s    210:                   uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
         .          .    211:                   if uerr != nil {
         .          .    212:                           return nil, uerr
         .          .    213:                   }
         .          .    214:           }
         .          .    215:
         .          .    216:           // reverse
         .          .    217:           for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
         .          .    218:                   comments[i], comments[j] = comments[j], comments[i]
         .          .    219:           }
         .          .    220:
         .          .    221:           p.Comments = comments
         .          .    222:
      20ms      780ms    223:           perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
         .          .    224:           if perr != nil {
         .          .    225:                   return nil, perr
         .          .    226:           }
         .          .    227:
         .          .    228:           p.CSRFToken = CSRFToken
         .          .    229:
         .          .    230:           if p.User.DelFlg == 0 {
         .       30ms    231:                   posts = append(posts, p)
         .          .    232:           }
         .          .    233:           if len(posts) >= postsPerPage {
         .          .    234:                   break
         .          .    235:           }
         .          .    236:   }

getPosts が重いのは、前に getIndex が重いのを直した時と同じく、 LIMIT すれば良さそうですね。

makePosts もクエリを投げすぎているので、 Post の取得とその User の取得は INNER JOIN で一気にする、コメント一覧はメモリ上にキャッシュしてしまうことにします。 あとテンプレートのコンパイルも事前にするようにしていきます。 Go アプリ側で出力しているログも tmux や ssh の CPU を食ってるのでそろそろ止めてしまいましょう。 (nginx のログを止めるのは一番最後です)

diff --git a/app.go b/app.go
index f246ad6..eca8413 100644
--- a/app.go
+++ b/app.go
@@ -187,54 +184,78 @@ func getFlash(w http.ResponseWriter, r *http.Request, key string) string {
 	}
 }
 
-func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
-	var posts []Post
+var (
+	commentM     sync.Mutex
+	commentStore map[int][]Comment = make(map[int][]Comment)
+)
 
-	for _, p := range results {
-		err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
+func getCommentsLocked(postID int) []Comment {
+	if cs, ok := commentStore[postID]; ok {
+		return cs
+	}
+
+	var cs []Comment
+	query := ("SELECT comments.id, comments.comment, comments.created_at, users.id, users.account_name " +
+		" FROM `comments` INNER JOIN users ON comments.user_id = users.id " +
+		" WHERE `post_id` = ? ORDER BY comments.`created_at`")
+
+	rows, err := db.Query(query, postID)
+	if err != nil {
+		log.Println(err)
+		return cs
+	}
+	for rows.Next() {
+		var c Comment
+		err := rows.Scan(&c.ID, &c.Comment, &c.CreatedAt, &c.User.ID, &c.User.AccountName)
 		if err != nil {
-			return nil, err
+			log.Println(err)
+			continue
 		}
+		cs = append(cs, c)
+	}
+	rows.Close()
 
-		query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
-		if !allComments {
-			query += " LIMIT 3"
-		}
-		var comments []Comment
-		cerr := db.Select(&comments, query, p.ID)
-		if cerr != nil {
-			return nil, cerr
-		}
+	commentStore[postID] = cs
+	return cs
+}
 
-		for i := 0; i < len(comments); i++ {
-			uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
-			if uerr != nil {
-				return nil, uerr
-			}
-		}
+func getComments(postID int) []Comment {
+	commentM.Lock()
+	defer commentM.Unlock()
+	return getCommentsLocked(postID)
+}
 
-		// reverse
-		for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
-			comments[i], comments[j] = comments[j], comments[i]
-		}
+func appendComent(c Comment) {
+	commentM.Lock()
+	cs := getCommentsLocked(c.PostID)
+	commentStore[c.PostID] = append(cs, c)
+	commentM.Unlock()
+}
+
+func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
+	var posts []Post
 
+	for _, p := range results {
+		comments := getComments(p.ID)
+		if !allComments && len(comments) > 3 {
+			comments = comments[len(comments)-3:]
+		}
 		p.Comments = comments
+		p.CSRFToken = CSRFToken
 
 		perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
 		if perr != nil {
 			return nil, perr
 		}
 
-		p.CSRFToken = CSRFToken
-
-		if p.User.DelFlg == 0 {
-			posts = append(posts, p)
+		if p.User.DelFlg != 0 {
+			continue
 		}
+		posts = append(posts, p)
 		if len(posts) >= postsPerPage {
 			break
 		}
 	}
-
 	return posts, nil
 }
 
@@ -411,8 +432,9 @@ func getLogout(w http.ResponseWriter, r *http.Request) {
 }
 
 var (
-	indexTemplate *template.Template
-	postsTemplate *template.Template
+	indexTemplate       *template.Template
+	postsTemplate       *template.Template
+	accountNameTempalte *template.Template
 
 	indexPostsM         sync.Mutex
 	indexPostsT         time.Time
@@ -434,6 +456,13 @@ func init() {
 		getTemplPath("posts.html"),
 		getTemplPath("post.html"),
 	))
+
+	accountNameTempalte = template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
+		getTemplPath("layout.html"),
+		getTemplPath("user.html"),
+		getTemplPath("posts.html"),
+		getTemplPath("post.html"),
+	))
 }
 
 func renderIndexPosts() {
@@ -506,7 +535,6 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
 	}
 
 	results := []Post{}
-
 	rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = ? ORDER BY `created_at` DESC", user.ID)
 	if rerr != nil {
 		fmt.Println(rerr)
@@ -527,12 +555,10 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
 	}
 
 	postIDs := []int{}
-	perr := db.Select(&postIDs, "SELECT `id` FROM `posts` WHERE `user_id` = ?", user.ID)
-	if perr != nil {
-		fmt.Println(perr)
-		return
+	for _, r := range results {
+		postIDs = append(postIDs, r.ID)
 	}
-	postCount := len(postIDs)
+	postCount := len(results)
 
 	commentedCount := 0
 	if postCount > 0 {
@@ -557,16 +583,7 @@ func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
 
 	me := getSessionUser(r)
 
-	fmap := template.FuncMap{
-		"imageURL": imageURL,
-	}
-
-	template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
-		getTemplPath("layout.html"),
-		getTemplPath("user.html"),
-		getTemplPath("posts.html"),
-		getTemplPath("post.html"),
-	)).Execute(w, struct {
+	accountNameTempalte.Execute(w, struct {
 		Posts          []Post
 		User           User
 		PostCount      int
@@ -595,7 +612,7 @@ func getPosts(w http.ResponseWriter, r *http.Request) {
 	}
 
 	results := []Post{}
-	rerr := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= ? ORDER BY `created_at` DESC", t.Format(ISO8601_FORMAT))
+	rerr := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 AND posts.`created_at` <= ? ORDER BY `created_at` DESC LIMIT 20", t.Format(ISO8601_FORMAT))
 	if rerr != nil {
 		fmt.Println(rerr)
 		return
@@ -806,9 +823,24 @@ func postComment(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?)"
-	db.Exec(query, postID, me.ID, r.FormValue("comment"))
-
+	now := time.Now()
+	commentStr := r.FormValue("comment")
+	query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`, `created_at`) VALUES (?,?,?,?)"
+	res, err := db.Exec(query, postID, me.ID, commentStr, now)
+	if err != nil {
+		log.Println(err)
+		return
+	}
+	lid, _ := res.LastInsertId()
+	c := Comment{
+		ID:        int(lid),
+		PostID:    postID,
+		UserID:    me.ID,
+		Comment:   commentStr,
+		CreatedAt: now,
+		User:      me,
+	}
+	appendComent(c)
 	renderIndexPosts()
 	http.Redirect(w, r, fmt.Sprintf("/posts/%d", postID), http.StatusFound)
 }
@@ -921,6 +953,7 @@ func main() {
 
 	go http.ListenAndServe(":3000", nil)
 
+	goji.DefaultMux = web.New()
 	goji.Get("/initialize", getInitialize)
 	goji.Get("/login", getLogin)
 	goji.Post("/login", postLogin)

計測

スコア:

{"pass":true,"score":271542,"success":256436,"fail":0,"messages":[]}

pixiv 社内 isucon の優勝チームのスコアを超えることができたと思います。

top:

ks:  82 total,   4 running,  78 sleeping,   0 stopped,   0 zombie
%Cpu(s): 57.1 us, 13.8 sy,  0.0 ni, 16.5 id,  5.1 wa,  0.0 hi,  7.3 si,  0.2 st
KiB Mem:   1022972 total,   926504 used,    96468 free,    27152 buffers
KiB Swap:        0 total,        0 used,        0 free.   432620 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                                                                 1494 isucon    20   0  544796 191292   8940 S  81.5 18.7   0:29.06 app.7f063c1
  731 mysql     20   0 1125024 182444  10552 S  44.9 17.8   3:04.05 mysqld
 1524 www-data  20   0   92056   5276   3140 R  27.6  0.5   0:09.65 nginx
  308 memcache  20   0  336672  11756   2228 S   1.7  1.1   0:02.25 memcached
   31 root      20   0       0      0      0 S   0.7  0.0   0:00.40 kswapd0
   89 root       0 -20       0      0      0 S   0.3  0.0   0:00.73 kworker/0:1H
    1 root      20   0   28636   4736   3100 S   0.0  0.5   0:01.31 systemd

ちょっと idle が出てきたかな。

dstat:

----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
  0   0 100   0   0   0|   0     0 |   0     0 |   0     0 |  82   283 
 11   3  82   2   0   2|  12M    0 |1684k   15M|   0     0 |7607  5952 
 55  13  17   9   0   7|  49M  864k|  11M   44M|   0     0 |  27k   20k
 58  15  14   8   0   6|  48M  416k|  13M   43M|   0     0 |  28k   20k
 48  14  21  12   0   5|  43M   63M|  12M   40M|   0     0 |  25k   19k
 55  17  14   7   0   7|  48M  528k|  14M   42M|   0     0 |  25k   18k
 55  12  19   8   0   6|  45M  488k|  12M   42M|   0     0 |  27k   20k
 52  17  16   6   0   8|  35M  592k|  14M   38M|   0     0 |  27k   19k
 50  12  19  14   0   6|  34M   59M|  11M   38M|   0     0 |  25k   17k
 56  12  18   6   0   7|  42M  720k|  11M   45M|   0     0 |  28k   20k
 51  15  18   9   0   8|  45M  704k|  14M   39M|   0     0 |  26k   19k
 52  17  17   7   0   7|  39M 3936k|  14M   45M|   0     0 |  27k   19k
 47  17  18  13   0   5|  41M   56M|  12M   39M|   0     0 |  24k   17k
 53  13  19   9   0   6|  45M  848k|  13M   41M|   0     0 |  27k   20k
 57  15  16   6   0   6|  38M  776k|  13M   42M|   0     0 |  27k   19k
 53  14  20   9   0   4|  28M   58M|  11M   29M|   0     0 |  24k   16k
 53  13  19   6   0   8|  44M  672k|  13M   38M|   0     0 |  26k   18k
 57  13  16   9   0   6|  46M  872k|  10M   38M|   0     0 |  25k   18k
 53  12  22   7   0   6|  44M  776k|  12M   41M|   0     0 |  28k   20k
 54  16  16   8   0   6|  33M   57M|9049k   33M|   0     0 |  24k   18k
 51  16  21   5   0   7|  32M  888k|  12M   38M|   0     0 |  27k   19k
 54  13  19   7   0   7|  49M 2264k|  11M   46M|   0     0 |  26k   18k
 54  14  19   6   0   7|  36M  680k|  12M   42M|   0     0 |  28k   19k
 48  16  19  10   0   7|  33M   52M|  14M   31M|   0     0 |  23k   16k
 55  15  15   7   0   7|  42M  720k|  12M   34M|   0     0 |  26k   20k
 59  14  17   5   0   6|  33M  744k|  12M   35M|   0     0 |  25k   18k
 47  15  25   7   0   6|  34M  736k|9604k   43M|   0     0 |  28k   19k
 47  11  27   8   0   6|  31M   51M|  12M   39M|   0     0 |  25k   17k
 54  18  17   5   0   7|  34M  816k|  12M   33M|   0     0 |  27k   20k
 55  16  16   6   0   6|  35M  888k|  14M   34M|   0     0 |  27k   19k
 57  13  18   6   0   6|  34M  720k|  11M   37M|   0     0 |  27k   19k
 52  12  18  12   0   6|  36M   53M|  11M   34M|   0     0 |  23k   17k
 62  12  15   4   0   7|  26M  720k|9309k   29M|   0     0 |  25k   19k
 46  20  19   5   0   9|  30M  560k|  16M   35M|   0     0 |  28k   20k
 59  12  20   5   0   5|  23M  544k|  10M   36M|   0     0 |  25k   17k
 53  13  21   8   0   5|  25M   47M|  11M   31M|   0     0 |  23k   16k
 54  14  18   6   0   9|  38M  584k|  14M   35M|   0     0 |  27k   21k
...

帯域は半分強使っていますね。大きい js があるので、 `nginx の gzip_static モジュールを使うなどでもう少し帯域を開けられると思います。

pprof:

(pprof) top30 -cum
6.95s of 22.25s total (31.24%)
Dropped 621 nodes (cum <= 0.11s)
Showing top 30 nodes out of 321 (cum >= 2.44s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     20.30s 91.24%  runtime.goexit
     0.02s  0.09%  0.09%     17.03s 76.54%  net/http.(*conn).serve
         0     0%  0.09%     14.60s 65.62%  net/http.(*ServeMux).ServeHTTP
         0     0%  0.09%     14.60s 65.62%  net/http.serverHandler.ServeHTTP
         0     0%  0.09%     14.58s 65.53%  github.com/zenazn/goji/web.(*Mux).ServeHTTP
         0     0%  0.09%     14.57s 65.48%  github.com/zenazn/goji/web.(*cStack).ServeHTTP
         0     0%  0.09%     14.57s 65.48%  github.com/zenazn/goji/web.(*mStack).newStack.func1
         0     0%  0.09%     14.57s 65.48%  github.com/zenazn/goji/web.(*router).route
         0     0%  0.09%     14.57s 65.48%  net/http.HandlerFunc.ServeHTTP
         0     0%  0.09%     10.03s 45.08%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
     0.01s 0.045%  0.13%      6.12s 27.51%  html/template.(*Template).Execute
         0     0%  0.13%      5.58s 25.08%  text/template.(*Template).Execute
     0.12s  0.54%  0.67%      5.57s 25.03%  text/template.(*state).walk
     0.01s 0.045%  0.72%      5.20s 23.37%  text/template.(*state).walkTemplate
     0.04s  0.18%   0.9%      4.68s 21.03%  text/template.(*state).walkRange
     0.01s 0.045%  0.94%      4.65s 20.90%  text/template.(*state).walkRange.func1
     0.97s  4.36%  5.30%      4.60s 20.67%  runtime.mallocgc
         0     0%  5.30%      4.46s 20.04%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
     0.23s  1.03%  6.34%      4.38s 19.69%  runtime.systemstack
     0.04s  0.18%  6.52%      4.07s 18.29%  text/template.(*state).evalPipeline
     0.08s  0.36%  6.88%      4.03s 18.11%  text/template.(*state).evalCommand
     2.54s 11.42% 18.29%      3.71s 16.67%  runtime.scanobject
     0.10s  0.45% 18.74%      3.09s 13.89%  text/template.(*state).evalCall
     0.03s  0.13% 18.88%      3.07s 13.80%  text/template.(*state).evalFunction
         0     0% 18.88%      2.99s 13.44%  main.getAccountName
     2.48s 11.15% 30.02%      2.70s 12.13%  syscall.Syscall
         0     0% 30.02%      2.62s 11.78%  main.getPosts
     0.01s 0.045% 30.07%      2.56s 11.51%  reflect.Value.Call
     0.26s  1.17% 31.24%      2.52s 11.33%  reflect.Value.call
         0     0% 31.24%      2.44s 10.97%  github.com/jmoiron/sqlx.(*DB).Get

テンプレートの実行とが重いのと、あとGCが重いですね。

テンプレートが重いのは、ページキャッシュだとトップページ以外はどれくらいキャッシュヒット率が見込めるかわかりません。 valyala/quicktemplate などの、リフレクションを多用しない高速なテンプレートエンジンに乗り換えるほうが早いかもしれません。

GCの方は、クエリ実行回数をさらに削っていけば、一時オブジェクトがを削減するのが有効そう。どこでアロケートが多発しているのかを確認したい場合は pprof -alloc_objects を使ってみてください。

まとめ

スコア: 4745 (初期状態) -> 39743 (前回) -> 182435 (Not Modified) -> 271542 (最終版)

壁を超えた効果で、いままで伸び悩んでいたスコアが一気にジャンプしました。

攻略記はここまでにしますが、できればさらにチューニングを続けてみてください。練習で実際に手を動かしていないことは、本番ではほぼ確実にできません。 私の場合は、次のようなチューニングで500k点を超えましたが、これでもまだ帯域を使い切っていないし nginx よりも app と MySQL が使用するCPUの方が大きいのでさらに上を狙えるはずです。

  • gzip_static を使う (スコアは上がりませんでしたが、帯域に余裕を作りました)
  • テンプレートが重い posts の部分で valyala/quicktemplate を使ってみる
  • ユーザーをオンメモリキャッシュし、強引なJOINをやめる
  • セッションストアを memcached からオンメモリに切り替える
  • nginx と app の間を unix domain socket に切り替える
  • nginx が重くなってきていたので worker_processes を 2 にする
  • 更新系のリクエストであえて time.Sleep() で待たせて、スコアへの影響が大きいシナリオの処理にリソースを向ける
  • アクセスログを切る (最初は静的ファイルだけ、最後は全部のアクセスログを消す)

ここまでのコミットログは methane/pixiv-private-isucon-2016 に置いてあります。 ですが、できるだけ自力で 500k 点超えを目指してみてください。

最後に、ISUCON の練習にとても良い題材を提供して頂いた pixiv さんに感謝します。


@methane


songofacandy at 18:53
この記事のURLComments(0)TrackBack(0)ISUCON | golang
2016年06月02日

pixiv private isucon 2016 攻略 (4/5)

はてなブックマークに登録

攻略記事一覧:

ここから、いよいよ ISUCON らしくなってきますよ。

現状確認

access.log の集計はこんな感じです。

Request by count
12317 GET /image/*
2797 GET /
1983 POST /login
1218 GET /posts/*
1029 GET /js/jquery-2.2.0.js
1029 GET /favicon.ico
1029 GET /js/jquery.timeago.js
1028 GET /css/style.css
1028 GET /js/jquery.timeago.ja.js
1028 GET /js/main.js
930 GET /@user
655 POST /register
654 GET /admin/banned
579 POST /comment
579 POST /
112 GET /login
83 GET /posts?max_created_at=
56 GET /logout
1 GET /initialize

Request by total time
72.877 0.0260554165177 GET /
34.018 0.0365784946237 GET /@user
18.444 0.22221686747 GET /posts?max_created_at=
15.705 0.0271243523316 POST /
12.566 0.0103169129721 GET /posts/*
8.439 0.000685150604855 GET /image/*
5.644 0.00284619263742 POST /login
1.825 0.00278625954198 POST /register
1.661 0.00286873920553 POST /comment
1.648 0.00251987767584 GET /admin/banned
0.475 0.00424107142857 GET /login
0.45 0.00803571428571 GET /logout
0.026 0.026 GET /initialize

top はこんな感じ

Tasks:  73 total,   1 running,  72 sleeping,   0 stopped,   0 zombie
%Cpu(s): 55.4 us, 10.8 sy,  0.0 ni, 23.5 id,  3.1 wa,  0.0 hi,  6.7 si,  0.5 st
KiB Mem:   1022972 total,   617428 used,   405544 free,    18260 buffers
KiB Swap:        0 total,        0 used,        0 free.   314552 cached Mem
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 1122 isucon    20   0  403944  68064   8328 S  76.3  6.7   0:16.87 app.f9aa6c7
  731 mysql     20   0  993756 159744  10756 S  62.6 15.6   0:15.46 mysqld
 1033 www-data  20   0   92024   5136   3056 S   7.0  0.5   0:01.63 nginx
 1069 isucon    20   0   28796   6136   2636 S   2.7  0.6   0:00.80 tmux
  308 memcache  20   0  330528   6060   2228 S   0.7  0.6   0:00.14 memcached

そろそろリクエスト数が増えてきたのと、まだ少し idle が残っているので、念の為ベンチマーク直後の netstat を確認しておきます。

$ netstat -tn
...
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63462         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:64494         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63477         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63563         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63877         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:64234         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63565         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:64008         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:63594         TIME_WAIT  
tcp6       0      0 127.0.0.1:8080          127.0.0.1:64065         TIME_WAIT  

$ netstat -tn | grep -c TIME_WAIT
1981

まだ詰まるほどじゃないけど一応 /etc/nginx/sites-enabled/isucon.conf で upstream の keepalive を 64 に増やしておきます。

ページキャッシュ

プロファイルを見てみます。

(pprof) top30 -cum
5.66s of 23.80s total (23.78%)
Dropped 584 nodes (cum <= 0.12s)
Showing top 30 nodes out of 326 (cum >= 3.55s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     22.30s 93.70%  runtime.goexit
         0     0%     0%     19.44s 81.68%  net/http.(*conn).serve
     0.01s 0.042% 0.042%     18.79s 78.95%  net/http.serverHandler.ServeHTTP
         0     0% 0.042%     18.78s 78.91%  net/http.(*ServeMux).ServeHTTP
         0     0% 0.042%     18.76s 78.82%  github.com/zenazn/goji/web.(*Mux).ServeHTTP
         0     0% 0.042%     18.72s 78.66%  github.com/zenazn/goji/web.(*cStack).ServeHTTP
         0     0% 0.042%     18.72s 78.66%  github.com/zenazn/goji/web/middleware.RequestID.func1
         0     0% 0.042%     18.72s 78.66%  net/http.HandlerFunc.ServeHTTP
     0.01s 0.042% 0.084%     18.69s 78.53%  github.com/zenazn/goji/web/middleware.Logger.func1
         0     0% 0.084%     18.27s 76.76%  github.com/zenazn/goji/web/middleware.Recoverer.func1
         0     0% 0.084%     18.21s 76.51%  github.com/zenazn/goji/web.(*mStack).newStack.func1
         0     0% 0.084%     18.21s 76.51%  github.com/zenazn/goji/web.(*router).route
         0     0% 0.084%     18.21s 76.51%  github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
     0.01s 0.042%  0.13%     14.43s 60.63%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0%  0.13%     12.63s 53.07%  main.getIndex
     0.07s  0.29%  0.42%      9.88s 41.51%  main.makePosts
     0.01s 0.042%  0.46%      6.89s 28.95%  github.com/jmoiron/sqlx.(*DB).Get
     0.01s 0.042%   0.5%      6.88s 28.91%  github.com/jmoiron/sqlx.Get
     0.03s  0.13%  0.63%      6.80s 28.57%  database/sql.(*DB).Query
     0.02s 0.084%  0.71%      6.77s 28.45%  database/sql.(*DB).query
     0.03s  0.13%  0.84%      6.43s 27.02%  database/sql.(*DB).queryConn
     0.06s  0.25%  1.09%      6.02s 25.29%  github.com/go-sql-driver/mysql.(*mysqlConn).Query
     0.02s 0.084%  1.18%      4.65s 19.54%  github.com/jmoiron/sqlx.(*DB).QueryRowx
     4.06s 17.06% 18.24%      4.38s 18.40%  syscall.Syscall
     1.17s  4.92% 23.15%      4.08s 17.14%  runtime.mallocgc
         0     0% 23.15%      3.83s 16.09%  github.com/jmoiron/sqlx.(*DB).Select
     0.01s 0.042% 23.19%      3.83s 16.09%  github.com/jmoiron/sqlx.Select
         0     0% 23.19%      3.72s 15.63%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
     0.12s   0.5% 23.70%      3.58s 15.04%  runtime.systemstack
     0.02s 0.084% 23.78%      3.55s 14.92%  syscall.Write

(pprof) list getIndex
Total: 23.80s
ROUTINE ======================== main.getIndex in /home/isucon/private_isu/webapp/golang/app.go
         0     12.63s (flat, cum) 53.07% of Total
         .          .    413:
         .          .    414:   http.Redirect(w, r, "/", http.StatusFound)
         .          .    415:}
         .          .    416:
         .          .    417:func getIndex(w http.ResponseWriter, r *http.Request) {
         .      330ms    418:   me := getSessionUser(r)
         .          .    419:
         .          .    420:   results := []Post{}
         .          .    421:
         .      600ms    422:   err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
         .          .    423:   if err != nil {
         .          .    424:           fmt.Println(err)
         .          .    425:           return
         .          .    426:   }
         .          .    427:
         .      8.43s    428:   posts, merr := makePosts(results, getCSRFToken(r), false)
         .          .    429:   if merr != nil {
         .          .    430:           fmt.Println(merr)
         .          .    431:           return
         .          .    432:   }
         .          .    433:
         .          .    434:   fmap := template.FuncMap{
         .          .    435:           "imageURL": imageURL,
         .          .    436:   }
         .          .    437:
         .       40ms    438:   template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
         .       10ms    439:           getTemplPath("layout.html"),
         .       10ms    440:           getTemplPath("index.html"),
         .          .    441:           getTemplPath("posts.html"),
         .          .    442:           getTemplPath("post.html"),
         .      1.20s    443:   )).Execute(w, struct {
         .          .    444:           Posts     []Post
         .          .    445:           Me        User
         .          .    446:           CSRFToken string
         .          .    447:           Flash     string
         .      2.01s    448:   }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
         .          .    449:}
         .          .    450:
         .          .    451:func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
         .          .    452:   user := User{}
         .          .    453:   uerr := db.Get(&user, "SELECT * FROM `users` WHERE `account_name` = ? AND `del_flg` = 0", c.URLParams["accountName"])

テンプレートに渡すための []Post を用意する makePosts 関数が一番重いものの、最初に Post 一覧を取得する select が 600ms, テンプレートのコンパイルと実行を足して 3.2sec ありますね。 テンプレートのコンパイルは起動時に一度やればいい処理なので 1.2sec は無駄です。 また、トップページに表示される内容はユーザーにかかわらず一定なので、レンダリング結果をまるごとページキャッシュできれば、 makePosts の 8.4sec とテンプレートのレンダリングの 2sec の合わせて 10sec をほぼ消し去ることができます。

ページキャッシュが実現できそうかテンプレートの中身を確認してみると、ユーザーごとに異なる内容は、 (1) ヘッダー部分, (2) 全フォームにある csrf token, でした。レンダリングが重いのはポスト一覧の部分でしょうから、ヘッダーはページキャッシュの対象外にして、ポスト一覧部分だけをキャッシュすれば (1) は問題ありません。問題は (2) ですが、レンダリング時に固定のキーワードを入れてレンダリングしておき、ユーザーに返すときに本当の csrf token に文字列置換することにします。

ページキャッシュを作るタイミングですが、 getIndex() が呼ばれた時にするよりも、トップページに何か変更があったとき (画像が投稿された、コメントされた、ユーザーが削除されたなど) にレンダリングするほうが効率的です。 さらに、性能が上がってくるとトップページに変更があるリクエストが並列で来る可能性があるので、レンダリングを Mutex で排他したうえで、 Mutex を待ってる goroutine が同時に複数存在した場合はそのうちの1つだけがレンダリングする方式を採用しました。 この方式は GoCon 2016 Spring で zero time cache パターンとして紹介したもので、全ての POST リクエストがレンダリングを待ってからレスポンスを返すので、キャッシュによる更新が反映されるまでの遅延が存在しません。

diff --git a/app.go b/app.go
index b5a8fac..f246ad6 100644
--- a/app.go
+++ b/app.go
@@ -1,6 +1,7 @@
 package main
 
 import (
+	"bytes"
 	crand "crypto/rand"
 	"crypto/sha512"
 	"encoding/hex"
@@ -109,6 +110,8 @@ func dbInitialize() {
 	for _, sql := range sqls {
 		db.Exec(sql)
 	}
+
+	renderIndexPosts()
 }
 
 func tryLogin(accountName, password string) *User {
@@ -414,38 +410,85 @@ func getLogout(w http.ResponseWriter, r *http.Request) {
 	http.Redirect(w, r, "/", http.StatusFound)
 }
 
-func getIndex(w http.ResponseWriter, r *http.Request) {
-	me := getSessionUser(r)
+var (
+	indexTemplate *template.Template
+	postsTemplate *template.Template
 
-	results := []Post{}
+	indexPostsM         sync.Mutex
+	indexPostsT         time.Time
+	indexPostsRenderedM sync.RWMutex
+	indexPostsRendered  []byte
+)
+
+func init() {
+	fmap := template.FuncMap{
+		"imageURL": imageURL,
+	}
 
+	indexTemplate = template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
+		getTemplPath("layout.html"),
+		getTemplPath("index.html"),
+	))
+
+	postsTemplate = template.Must(template.New("posts.html").Funcs(fmap).ParseFiles(
+		getTemplPath("posts.html"),
+		getTemplPath("post.html"),
+	))
+}
+
+func renderIndexPosts() {
+	now := time.Now()
+	indexPostsM.Lock()
+	defer indexPostsM.Unlock()
+	if indexPostsT.After(now) {
+		return
+	}
+	now = time.Now()
+
+	results := []Post{}
 	err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
 	if err != nil {
-		fmt.Println(err)
+		log.Println(err)
 		return
 	}
 
-	posts, merr := makePosts(results, getCSRFToken(r), false)
+	posts, merr := makePosts(results, "[[[CSRFTOKEN]]]", false)
 	if merr != nil {
-		fmt.Println(merr)
+		log.Println(merr)
 		return
 	}
 
-	fmap := template.FuncMap{
-		"imageURL": imageURL,
+	var b bytes.Buffer
+	if err := postsTemplate.Execute(&b, posts); err != nil {
+		log.Println(err)
+		return
 	}
 
-	template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
-		getTemplPath("layout.html"),
-		getTemplPath("index.html"),
-		getTemplPath("posts.html"),
-		getTemplPath("post.html"),
-	)).Execute(w, struct {
-		Posts     []Post
-		Me        User
-		CSRFToken string
-		Flash     string
-	}{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
+	indexPostsT = now
+	indexPostsRenderedM.Lock()
+	indexPostsRendered = b.Bytes()
+	indexPostsRenderedM.Unlock()
+}
+
+func getIndexPosts(csrf string) template.HTML {
+	indexPostsRenderedM.RLock()
+	t := bytes.Replace(indexPostsRendered, []byte("[[[CSRFTOKEN]]]"), []byte(csrf), -1)
+	indexPostsRenderedM.RUnlock()
+	return template.HTML(string(t))
+}
+
+func getIndex(w http.ResponseWriter, r *http.Request) {
+	me := getSessionUser(r)
+	csrf := getCSRFToken(r)
+	posts := getIndexPosts(csrf)
+
+	indexTemplate.Execute(w,
+		map[string]interface{}{
+			"Me":        me,
+			"CSRFToken": csrf,
+			"Flash":     getFlash(w, r, "notice"),
+			"Posts":     posts},
+	)
 }
 
 func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
@@ -708,8 +751,9 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
 	}
 	tf.Close()
 	copyImage(int(pid), tf.Name(), mime)
+
+	renderIndexPosts()
 	http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound)
-	return
 }
 
 func getImage(c web.C, w http.ResponseWriter, r *http.Request) {
@@ -765,6 +809,7 @@ func postComment(w http.ResponseWriter, r *http.Request) {
 	query := "INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?)"
 	db.Exec(query, postID, me.ID, r.FormValue("comment"))
 
+	renderIndexPosts()
 	http.Redirect(w, r, fmt.Sprintf("/posts/%d", postID), http.StatusFound)
 }
 
@@ -821,6 +866,7 @@ func postAdminBanned(w http.ResponseWriter, r *http.Request) {
 		db.Exec(query, 1, id)
 	}
 
+	renderIndexPosts()
 	http.Redirect(w, r, "/admin/banned", http.StatusFound)
 }
 
@@ -864,6 +910,15 @@ func main() {
 	db.SetMaxIdleConns(8)
 	defer db.Close()
 
+	for {
+		if db.Ping() == nil {
+			break
+		}
+		log.Println("waiting db...")
+	}
+
+	renderIndexPosts()
+
 	go http.ListenAndServe(":3000", nil)
 
 	goji.Get("/initialize", getInitialize)
diff --git a/templates/index.html b/templates/index.html
index 22ff9c2..8c2b639 100644
--- a/templates/index.html
+++ b/templates/index.html
@@ -19,7 +19,7 @@
   </form>
 </div>
 
-{{ template "posts.html" .Posts }}
+{{ .Posts }}
 
 <div id="isu-post-more">
   <button id="isu-post-more-btn">もっと見る</button>

計測

スコア:

{"pass":true,"score":39743,"success":32254,"fail":0,"messages":[]}

top:

Tasks:  77 total,   1 running,  76 sleeping,   0 stopped,   0 zombie
%Cpu(s): 44.7 us,  8.3 sy,  0.0 ni, 35.3 id,  5.1 wa,  0.0 hi,  6.0 si,  0.5 st
KiB Mem:   1022972 total,   961900 used,    61072 free,    23704 buffers
KiB Swap:        0 total,        0 used,        0 free.   604328 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 1337 isucon    20   0  207476  68192   8880 S  63.6  6.7   0:13.73 app.dc4a3eaa
  731 mysql     20   0 1059292 181996  10552 S  45.6 17.8   1:49.68 mysqld
 1033 www-data  20   0   92008   5092   3056 S   8.0  0.5   0:11.70 nginx
 1069 isucon    20   0   32140   9332   2636 S   4.0  0.9   0:07.71 tmux
    3 root      20   0       0      0      0 S   0.3  0.0   0:15.56 ksoftirqd/0
   13 root      20   0       0      0      0 S   0.3  0.0   0:29.07 ksoftirqd/1
   43 root      20   0       0      0      0 S   0.3  0.0   0:00.15 kworker/u30:1
  308 memcache  20   0  332576   7896   2228 S   0.3  0.8   0:00.89 memcached
  968 isucon    20   0   80656   3496   2656 S   0.3  0.3   0:00.28 sshd

CPU がだいぶ遊んできましたね。どこか別のところにあるボトルネックを見つけないといけません。

myprofiler:

  34 SELECT * FROM `users` WHERE `id` = N
  30 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
  23 SELECT * FROM `posts` WHERE `id` = N
  19 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC
  11 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N
  10 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
   8 SELECT `id` FROM `posts` WHERE `user_id` = N
   2 INSERT INTO `users` (`account_name`, `passhash`) VALUES (S,S)
   1 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC
   1 SELECT COUNT(*) AS count FROM `comments` WHERE `post_id` IN (...N)

user を PK で取得する部分が重いみたいです。

access.log:

Request by count
12394 GET /image/*
4149 GET /
2791 POST /login
1395 GET /posts/*
1207 POST /register
1207 GET /admin/banned
1049 GET /@user
1021 GET /js/jquery-2.2.0.js
1021 GET /css/style.css
1021 GET /js/jquery.timeago.ja.js
1021 GET /favicon.ico
1021 GET /js/jquery.timeago.js
1021 GET /js/main.js
704 POST /comment
698 POST /
120 GET /login
77 GET /posts?max_created_at=
61 GET /logout
1 GET /initialize

Request by total time
30.646 0.0292144899905 GET /@user
24.051 0.0344570200573 POST /
14.411 0.187155844156 GET /posts?max_created_at=
12.099 0.00867311827957 GET /posts/*
11.879 0.0168735795455 POST /comment
9.296 0.00224053988913 GET /
6.612 0.00236904335364 POST /login
3.355 0.00277961888981 POST /register
2.882 0.00023253187026 GET /image/*
2.21 0.00183098591549 GET /admin/banned
0.448 0.00373333333333 GET /login
0.443 0.00726229508197 GET /logout
0.038 0.038 GET /initialize

Request by out bytes
3847419944 310426 GET /image/*
264074503 258643 GET /js/jquery-2.2.0.js
99628388 24012 GET /
...

GET / が 2.2msec まで速くなりました。まだ速く出来る余地はあるけど、先に GET /@user などの高速化が先でしょうね。

まとめ

スコア: 4745 (初期状態) -> 32771 (前回) -> 39743 (トップページのページキャッシュ)

ボトルネックがCPU以外に移っているので、スコアが期待したほど伸びませんでした。次回はそのボトルネックを調査・解決します。

ページキャッシュに利用した zero time cache パターンは Go だから簡単に実現できるものなので、 prefork 型のアプリサーバーを使う他の言語ではちょっと難しいです。 (node.js なら、2コアマシンならシングルプロセスで頑張れるかも知れません)

他の言語では、普通に getIndex でページキャッシュしてベンチが完走するようにキャッシュの生存期間を調整するとか、バックグラウンドで動くデーモンが定期的にページキャッシュを生成するようにしてベンチが通るようにその生成間隔を調整するといったやり方がISUCONでは一般的だと思います。

しかし、今回の pixiv private isucon ではルールに POST が返ってからその内容が別の GET リクエストに反映されるまでの猶予が明記されていないので、調整のために複数回ベンチを走らせる必要があるかもしれません。 (Go 推し)


@methane


songofacandy at 17:51
この記事のURLComments(0)TrackBack(0)ISUCON | golang
2016年06月01日

pixiv private isucon 2016 攻略 (3/5)

はてなブックマークに登録

攻略記事一覧:

現状確認

access.log をもう一度見直しましょう。

Request by total time
74.113 0.0307140489018 GET /
70.007 0.00532696697611 GET /image/*
43.428 0.0575205298013 GET /@user
24.058 0.283035294118 GET /posts?max_created_at=
23.976 0.0522352941176 POST /
12.767 0.012987792472 GET /posts/*
6.642 0.00390476190476 POST /login
...

CPU を一番使っているのはトップページですが、レスポンスタイムに占める時間で言えば /image/* がほとんど並びました。 そろそろ /image/* をリバースプロキシするのは止めないといけません。

Go を使う場合は nginx を使うのをやめるのも候補になるのですが、静的ファイル配信は nginx に任せたほうがてっとり早いので、 nginx を外さない方針で行きましょう。

nginx の設定

僕も ISUCON 前以外は nginx の設定に詳しくないので、とりあえずこんな感じで設定しました。

  root /home/isucon/private_isu/webapp/public/;

  location / {
    try_files $uri @app;
  }
  location @app {
    proxy_set_header Host $host;
    proxy_set_header X-Real-IP $remote_addr;
    proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
    proxy_pass http://app;
  }

public ディレクトリは css とか js も入ってるので、その中に mkdir image しておき、 try_files ディレクティブでファイルが有ればそれを返す、なければリバースプロキシの設定を書いた @app location を使う設定にしています。

アプリ側は、 /image/* にアクセスがあったときに画像を返すついでにファイルに書き出すのと、画像がアップロードされたときにファイルに書いてDBには書かないように修正します。DBに書かないのは Disk IO 負荷低減のためです。

--- a/app.go
+++ b/app.go
@@ -78,6 +78,29 @@ func init() {
        store = gsm.NewMemcacheStore(memcacheClient, "isucogram_", []byte("sendagaya"))
 }

+func writeImage(id int, mime string, data []byte) {
+       var ext string
+       switch mime {
+       case "image/jpeg":
+               ext = ".jpg"
+       case "image/png":
+               ext = ".png"
+       case "image/gif":
+               ext = ".gif"
+       default:
+               fmt.Println("Failed to write file: ", id, mime)
+               return
+       }
+
+       fn := fmt.Sprintf("../public/image/%d%s", id, ext)
+       f, err := os.OpenFile(fn, os.O_WRONLY|os.O_CREATE, 0666)
+       if err != nil {
+               panic(err)
+       }
+       f.Write(data)
+       f.Close()
+}
+
 func dbInitialize() {
        sqls := []string{
                "DELETE FROM users WHERE id > 1000",
@@ -652,7 +675,7 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
                query,
                me.ID,
                mime,
-               filedata,
+               []byte(""),
                r.FormValue("body"),
        )
        if eerr != nil {
@@ -665,7 +688,7 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
                fmt.Println(lerr.Error())
                return
        }
-
+       writeImage(int(pid), mime, filedata)
        http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound)
        return
 }
@@ -695,6 +718,7 @@ func getImage(c web.C, w http.ResponseWriter, r *http.Request) {
                if err != nil {
                        fmt.Println(err.Error())
                }
+               writeImage(pid, post.Mime, post.Imgdata)
                return
        }

メモリが足りない!!

ここで問題にぶつかりました。メモリが足りなくてベンチが完走しません。 静的ファイル配信を nginx に任せることでメモリ使用量が減らせると思っていたのに!

多分、性能が向上したためにメモリアロケートのペースが早くなって問題が顕在化したのでしょう。プロファイラーで、ベンチマーク中 (メモリ使用量が増えてきたけどメモリ不足で落ちるよりは前) のメモリ使用量を調査してみます。

$ go tool pprof -inuse_space app.e27b8a http://localhost:3000/debug/pprof/heap
Fetching profile from http://localhost:3000/debug/pprof/heap
Saved profile in /home/isucon/pprof/pprof.app.e27b8a.localhost:3000.inuse_objects.inuse_space.002.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top40 -cum
319.72MB of 338.26MB total (94.52%)
Dropped 338 nodes (cum <= 1.69MB)
Showing top 40 nodes out of 52 (cum >= 8.34MB)
      flat  flat%   sum%        cum   cum%
         0     0%     0%   337.76MB 99.85%  runtime.goexit
         0     0%     0%   336.72MB 99.54%  net/http.(*conn).serve
         0     0%     0%   322.22MB 95.26%  github.com/zenazn/goji/web.(*mStack).newStack.func1
         0     0%     0%   322.22MB 95.26%  github.com/zenazn/goji/web.(*router).route
         0     0%     0%   322.22MB 95.26%  github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
         0     0%     0%   322.22MB 95.26%  github.com/zenazn/goji/web/middleware.Logger.func1
         0     0%     0%   322.22MB 95.26%  github.com/zenazn/goji/web/middleware.Recoverer.func1
         0     0%     0%   322.22MB 95.26%  github.com/zenazn/goji/web/middleware.RequestID.func1
         0     0%     0%   322.22MB 95.26%  net/http.HandlerFunc.ServeHTTP
         0     0%     0%   321.72MB 95.11%  github.com/zenazn/goji/web.(*Mux).ServeHTTP
         0     0%     0%   321.72MB 95.11%  github.com/zenazn/goji/web.(*cStack).ServeHTTP
         0     0%     0%   321.72MB 95.11%  net/http.(*ServeMux).ServeHTTP
         0     0%     0%   321.72MB 95.11%  net/http.serverHandler.ServeHTTP
         0     0%     0%   309.80MB 91.59%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0%     0%   301.29MB 89.07%  net/http.(*Request).FormValue
         0     0%     0%   301.29MB 89.07%  net/http.(*Request).ParseMultipartForm
         0     0%     0%   299.29MB 88.48%  main.postIndex
    0.50MB  0.15%  0.15%   298.79MB 88.33%  mime/multipart.(*Reader).ReadForm
         0     0%  0.15%   298.29MB 88.18%  bytes.(*Buffer).ReadFrom
  298.29MB 88.18% 88.33%   298.29MB 88.18%  bytes.makeSlice
         0     0% 88.33%   298.29MB 88.18%  io.Copy
         0     0% 88.33%   298.29MB 88.18%  io.CopyN
         0     0% 88.33%   298.29MB 88.18%  io.copyBuffer
         0     0% 88.33%       15MB  4.44%  net/http.(*conn).readRequest
       1MB   0.3% 88.63%       15MB  4.44%  net/http.readRequest
         0     0% 88.63%    12.42MB  3.67%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
   10.50MB  3.11% 91.73%       11MB  3.25%  net/textproto.(*Reader).ReadMIMEHeader
         0     0% 91.73%    10.50MB  3.10%  github.com/bradleypeabody/gorilla-sessions-memcache.(*MemcacheStore).Get
         0     0% 91.73%    10.50MB  3.10%  main.getSession
         0     0% 91.73%     9.42MB  2.78%  database/sql.(*Rows).Next
    9.42MB  2.78% 94.52%     9.42MB  2.78%  github.com/go-sql-driver/mysql.(*buffer).fill
         0     0% 94.52%     9.42MB  2.78%  github.com/go-sql-driver/mysql.(*buffer).readNext
         0     0% 94.52%     9.42MB  2.78%  github.com/go-sql-driver/mysql.(*mysqlConn).readPacket
         0     0% 94.52%     9.42MB  2.78%  github.com/go-sql-driver/mysql.(*textRows).Next
         0     0% 94.52%     9.42MB  2.78%  github.com/go-sql-driver/mysql.(*textRows).readRow
         0     0% 94.52%     8.34MB  2.47%  github.com/jmoiron/sqlx.(*DB).Get
         0     0% 94.52%     8.34MB  2.47%  github.com/jmoiron/sqlx.(*Row).Scan
         0     0% 94.52%     8.34MB  2.47%  github.com/jmoiron/sqlx.(*Row).scanAny
         0     0% 94.52%     8.34MB  2.47%  github.com/jmoiron/sqlx.Get
         0     0% 94.52%     8.34MB  2.47%  main.getImage
(pprof) list ReadForm
Total: 338.26MB
ROUTINE ======================== mime/multipart.(*Reader).ReadForm in /home/isucon/.local/go/src/mime/multipart/formdata.go
  512.02kB   298.79MB (flat, cum) 88.33% of Total
         .          .     19:// ReadForm parses an entire multipart message whose parts have
         .          .     20:// a Content-Disposition of "form-data".
         .          .     21:// It stores up to maxMemory bytes of the file parts in memory
         .          .     22:// and the remainder on disk in temporary files.
         .          .     23:func (r *Reader) ReadForm(maxMemory int64) (f *Form, err error) {
  512.02kB   512.02kB     24:   form := &Form{make(map[string][]string), make(map[string][]*FileHeader)}
         .          .     25:   defer func() {
         .          .     26:           if err != nil {
         .          .     27:                   form.RemoveAll()
         .          .     28:           }
         .          .     29:   }()
         .          .     30:
         .          .     31:   maxValueBytes := int64(10 << 20) // 10 MB is a lot of text.
         .          .     32:   for {
         .          .     33:           p, err := r.NextPart()
         .          .     34:           if err == io.EOF {
         .          .     35:                   break
         .          .     36:           }
         .          .     37:           if err != nil {
         .          .     38:                   return nil, err
         .          .     39:           }
         .          .     40:
         .          .     41:           name := p.FormName()
         .          .     42:           if name == "" {
         .          .     43:                   continue
         .          .     44:           }
         .          .     45:           filename := p.FileName()
         .          .     46:
         .          .     47:           var b bytes.Buffer
         .          .     48:
         .          .     49:           if filename == "" {
         .          .     50:                   // value, store as string in memory
         .          .     51:                   n, err := io.CopyN(&b, p, maxValueBytes)
         .          .     52:                   if err != nil && err != io.EOF {
         .          .     53:                           return nil, err
         .          .     54:                   }
         .          .     55:                   maxValueBytes -= n
         .          .     56:                   if maxValueBytes == 0 {
         .          .     57:                           return nil, errors.New("multipart: message too large")
         .          .     58:                   }
         .          .     59:                   form.Value[name] = append(form.Value[name], b.String())
         .          .     60:                   continue
         .          .     61:           }
         .          .     62:
         .          .     63:           // file, store in memory or on disk
         .          .     64:           fh := &FileHeader{
         .          .     65:                   Filename: filename,
         .          .     66:                   Header:   p.Header,
         .          .     67:           }
         .   298.29MB     68:           n, err := io.CopyN(&b, p, maxMemory+1)
         .          .     69:           if err != nil && err != io.EOF {
         .          .     70:                   return nil, err
         .          .     71:           }
         .          .     72:           if n > maxMemory {
         .          .     73:                   // too big, write to disk and flush buffer
(pprof) list postIndex
Total: 338.26MB
ROUTINE ======================== main.postIndex in /home/isucon/private_isu/webapp/golang/app.go
         0   299.29MB (flat, cum) 88.48% of Total
         .          .    612:           Me   User
         .          .    613:   }{p, me})
         .          .    614:}
         .          .    615:
         .          .    616:func postIndex(w http.ResponseWriter, r *http.Request) {
         .   512.17kB    617:   me := getSessionUser(r)
         .          .    618:   if !isLogin(me) {
         .          .    619:           http.Redirect(w, r, "/login", http.StatusFound)
         .          .    620:           return
         .          .    621:   }
         .          .    622:
         .   298.79MB    623:   if r.FormValue("csrf_token") != getCSRFToken(r) {
         .          .    624:           w.WriteHeader(StatusUnprocessableEntity)
         .          .    625:           return
         .          .    626:   }

メモリーを使ってる箇所はわかりましたが、どう見てもリークではないです。

ファイルアップロードの効率化

ググったり、multipart の ReadForm 周辺のソースコードを読んで、原因を調べ、対策を考えます。

原因:

  • postIndex で最初に Request.FormValue を呼んだときにフォームを解析する処理が実行されていて、そこでアップロードされたファイルを読み込んでいる。
  • アップロードされたファイルは、ある程度 (デフォルト32MB) までは bytes.Buffer に読み込まれ、それを超える場合はテンポラリファイルに書き出される。
  • bytes.Buffer は小さいサイズからどんどんリアロケートして拡大していくので、短時間に大量のアロケートが発生する。アプリの性能が上がるのに連動してファイルのアップロードの頻度が増え、アロケートのペースが速すぎてGCが追いつかなくなったようだ。

対策:

  • multipart を解析するときに明示的に ParseMultipartForm を呼び出し、32MBよりももっと早めにテンポラリファイルを使うようにする。
  • 並列にファイルアップロードの解析が走らないように Mutex で保護する。
--- a/app.go
+++ b/app.go
@@ -17,6 +17,7 @@ import (
        "regexp"
        "strconv"
        "strings"
+       "sync"
        "time"

        "github.com/bradfitz/gomemcache/memcache"
@@ -613,6 +614,8 @@ func getPostsID(c web.C, w http.ResponseWriter, r *http.Request) {
        }{p, me})
 }

+var uploadM sync.Mutex
+
 func postIndex(w http.ResponseWriter, r *http.Request) {
        me := getSessionUser(r)
        if !isLogin(me) {
@@ -620,6 +623,9 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
                return
        }

+       uploadM.Lock()
+       defer uploadM.Unlock()
+       r.ParseMultipartForm(1 << 10)
        if r.FormValue("csrf_token") != getCSRFToken(r) {
                w.WriteHeader(StatusUnprocessableEntity)
                return

これでもまだ足りませんでした。なので、一旦メモリに置いてからファイルに書き出すのを止め、一時ファイルにコピーして、それを image/ ディレクトリ配下にリネームするように改修しました。

--- a/app.go
+++ b/app.go
@@ -80,26 +80,21 @@ func init() {
 }

 func writeImage(id int, mime string, data []byte) {
-       var ext string
-       switch mime {
-       case "image/jpeg":
-               ext = ".jpg"
-       case "image/png":
-               ext = ".png"
-       case "image/gif":
-               ext = ".gif"
-       default:
-               fmt.Println("Failed to write file: ", id, mime)
-               return
+       fn := imagePath(id, mime)
+       err := ioutil.WriteFile(fn, data, 0666)
+       if err != nil {
+               log.Println("failed to write file; path=%q, err=%v", fn, err)
        }
+}

-       fn := fmt.Sprintf("../public/image/%d%s", id, ext)
-       f, err := os.OpenFile(fn, os.O_WRONLY|os.O_CREATE, 0666)
-       if err != nil {
-               panic(err)
+func copyImage(id int, src, mime string) {
+       dst := imagePath(id, mime)
+       if err := os.Chmod(src, 0666); err != nil {
+               log.Println("failed to chmod: path=%v, %v", src, err)
+       }
+       if err := os.Rename(src, dst); err != nil {
+               log.Println("failed to rename; src=%q, dst=%q; %v", src, dst, err)
        }
-       f.Write(data)
-       f.Close()
 }

 func dbInitialize() {
@@ -260,6 +255,19 @@ func imageURL(p Post) string {
        return "/image/" + strconv.Itoa(p.ID) + ext
 }

+func imagePath(id int, mime string) string {
+       var ext string
+       switch mime {
+       case "image/jpeg":
+               ext = ".jpg"
+       case "image/png":
+               ext = ".png"
+       case "image/gif":
+               ext = ".gif"
+       }
+       return fmt.Sprintf("../public/image/%d%s", id, ext)
+}
+
 func isLogin(u User) bool {
        return u.ID != 0
 }
@@ -662,16 +670,20 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
                }
        }

-       filedata, rerr := ioutil.ReadAll(file)
-       if rerr != nil {
-               fmt.Println(rerr.Error())
+       tf, err := ioutil.TempFile("../upload", "img-")
+       if err != nil {
+               log.Panicf("failed to create image: %v", err)
        }
-
-       if len(filedata) > UploadLimit {
+       written, err := io.CopyN(tf, file, UploadLimit+1)
+       if err != nil && err != io.EOF {
+               log.Panicf("failed to write to temporary file: %v", err)
+       }
+       if written > UploadLimit {
+               os.Remove(tf.Name())
+               tf.Close()
                session := getSession(r)
                session.Values["notice"] = "ファイルサイズが大きすぎます"
                session.Save(r, w)
-
                http.Redirect(w, r, "/", http.StatusFound)
                return
        }
@@ -694,7 +706,8 @@ func postIndex(w http.ResponseWriter, r *http.Request) {
                fmt.Println(lerr.Error())
                return
        }
-       writeImage(int(pid), mime, filedata)
+       tf.Close()
+       copyImage(int(pid), tf.Name(), mime)
        http.Redirect(w, r, "/posts/"+strconv.FormatInt(pid, 10), http.StatusFound)
        return
 }

これでメモリ不足は落ち着き、とりあえず静的ファイルと投稿画像を nginx から返す設定でベンチが完走しました。

{"pass":true,"score":32771,"success":27352,"fail":0,"messages":[]}

本当は、 http.Request の Form 解析によって作られる一時ファイルからアプリケーションの一時ファイルへのコピーが無駄なので、 Request の Form 系のAPIを使わず直接 Body を解析するともっと効率が良くなります。(難しそうに聞こえるかもしれませんが、ほぼ Request.ParseMultipartFormのコピペで行けるはずです)

ただし、この時点でメモリ不足は収まったので、これ以上はディスク書き込みがネックになってどうしようもなくなるまで置いておいて、本来やりたかったチューニングにもどりましょう。

まとめ

スコア: 4745 (初期状態) -> 30076 (前回) -> 32771 (nginxで画像配信)

思っていたより性能向上が少ないです。これは次回に持ち越しです。

今回はファイルアップロードによるメモリ不足に悩まされましたが、(2010年代も後半になって)1GBメモリのマシンで、すごい大量にアップロードされる画像を裁くのは ISUCON だとありがちです。ちゃんと効率のいいファイルアップロードのやり方を調べておきましょう。

また、自分が使う予定の言語でメモリ不足を調査する方法も調べておきましょう。(例えば Python なら標準ライブラリの tracemalloc が使えると思います。)


@methane


songofacandy at 15:52
この記事のURLComments(0)TrackBack(0)ISUCON | golang
2016年05月31日

pixiv private isucon 2016 攻略 (2/5)

はてなブックマークに登録

攻略記事一覧:

アプリを読む

ソースコードを読みながらだいたいの構成を把握していきます。

  • フレームワークは goji を使っている。 goji のサイトを見ると同じ名前で新しいフレームワークを作り直したみたいだけど、これは古い方を使ってるみたいです。
  • セッションは Gorilla のライブラリに memcached store を組み合わせている
  • テンプレートをレンダリングのたびにコンパイルしてるのが重そう。
  • コメントのユーザーをいちいちユーザーテーブルから引っ張ってるのも JOIN かキャッシュが効きそう。
  • 画像データを MySQL に突っ込んでるのは、ファイルに出す必要がありそう。(ファイルなら数十KBずつ読んでは返せるけれど、DBだと簡単な方法だと一度に全体をメモリに読んでしまうので、並列にアクセスが来たときにメモリが足りなくなります。)

読んでいると改善したいポイントがたくさん出てくるものの、いきなりあちこち改造しだすとバグったときに困ります。はじめは基礎的な設定とボトルネックに絞ったチューニングです。

最初にDBのコネクションプール設定できてないので設定しておきましょう。2コアなんでそんなにたくさんコネクションあっても仕方ないハズ。とりあえずちょい多めの8にしておきます。

+    db.SetMaxOpenConns(8)
+    db.SetMaxIdleConns(8)
     defer db.Close()

アクセスログを読む

事前に用意しておいたアクセスログ集計ツール(自作してもいいですし、過去のいろいろな方のISUCONの記事を探してみれば良いツールが紹介されているはずです)を、アクセスログやアプリのURLルーティングの設定を参考にカスタマイズしましょう。

僕の場合は自作スクリプトで、次のような集計をしました。

Request by count
8028 GET /image/*
644 GET /
551 GET /js/jquery-2.2.0.js
551 GET /css/style.css
551 GET /js/jquery.timeago.ja.js
551 GET /favicon.ico
551 GET /js/jquery.timeago.js
551 GET /js/main.js
450 POST /login
299 GET /posts/*
235 GET /@user
130 POST /
98 GET /login
90 POST /comment
79 POST /register
78 GET /admin/banned
56 GET /posts?max_created_at=
50 GET /logout
1 GET /initialize

Request by total time (total avg [sec])
198.379 0.308041925466 GET /
168.858 0.021033632287 GET /image/*
47.605 0.202574468085 GET /@user
34.491 0.0766466666667 POST /login
30.444 0.543642857143 GET /posts?max_created_at=
15.095 0.0504849498328 GET /posts/*
7.068 0.0894683544304 POST /register
6.7 0.0515384615385 POST /
6.51 0.0118148820327 GET /favicon.ico
6.483 0.0117658802178 GET /js/jquery-2.2.0.js
5.784 0.010497277677 GET /js/jquery.timeago.js
5.213 0.0094609800363 GET /js/jquery.timeago.ja.js
5.095 0.00924682395644 GET /css/style.css
4.997 0.00906896551724 GET /js/main.js
2.478 0.0275333333333 POST /comment
2.257 0.0230306122449 GET /login
1.314 0.0168461538462 GET /admin/banned
1.131 0.02262 GET /logout
0.061 0.061 GET /initialize

Request by out bytes (total avg)
2485959550 309661 GET /image/*
142499069 258619 GET /js/jquery-2.2.0.js
12206011 18953 GET /
4287247 18243 GET /@user
4105501 7451 GET /js/jquery.timeago.js
1912146 34145 GET /posts?max_created_at=
1108574 3707 GET /posts/*
980229 1779 GET /css/style.css
487635 885 GET /js/main.js
357048 648 GET /js/jquery.timeago.ja.js
195356 434 POST /login
177772 1814 GET /login
149872 272 GET /favicon.ico
34286 434 POST /register
23530 181 POST /
22200 444 GET /logout
16833 187 POST /comment
13104 168 GET /admin/banned
161 161 GET /initialize

これで考えるのは、主に次の2点です。

  • トップページと /image/ に掛かる時間が一番重い。特にトップページを最初にチューニングするのが良さそう。
  • 帯域は /image/ が支配的。帯域ネックになるようだったら、画像は再圧縮しにくいので、ヘッダーを適切に設定すればクライアントに "304 Not Modified" を返せるようになって大きなブレークスルーがあるかもしれない。

pprof

とりあえず app の CPU が重いので、CPUプロファイルから始めましょう。 pprof の基本的な使い方は、以前に Blog を書いたのでそれを参照してください。

diff --git a/app.go b/app.go
index 861ff03..eb52f47 100644
--- a/app.go
+++ b/app.go
@@ -9,6 +9,7 @@ import (
        "io/ioutil"
        "log"
        "net/http"
+       _ "net/http/pprof"
        "net/url"
        "os"
        "os/exec"
@@ -826,6 +827,8 @@ func main() {
+
+        db.SetMaxOpenConns(8)
+        db.SetMaxIdleConns(8)
        defer db.Close()

+       go http.ListenAndServe(":3000", nil)
+
        goji.Get("/initialize", getInitialize)
        goji.Get("/login", getLogin)
        goji.Post("/login", postLogin)
$ go tool pprof app http://localhost:3000/debug/pprof/profile
Fetching profile from http://localhost:3000/debug/pprof/profile
Please wait... (30s)
Saved profile in /home/isucon/pprof/pprof.localhost:3000.samples.cpu.001.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) top 10
14440ms of 29650ms total (48.70%)
Dropped 546 nodes (cum <= 148.25ms)
Showing top 10 nodes out of 214 (cum >= 7370ms)
      flat  flat%   sum%        cum   cum%
    2270ms  7.66%  7.66%     8650ms 29.17%  runtime.mallocgc
    2220ms  7.49% 15.14%     2220ms  7.49%  runtime.memclr
    2150ms  7.25% 22.39%     2840ms  9.58%  runtime.scanobject
    1930ms  6.51% 28.90%     2060ms  6.95%  syscall.Syscall
    1280ms  4.32% 33.22%     1280ms  4.32%  runtime.heapBitsSetType
    1240ms  4.18% 37.40%     1270ms  4.28%  runtime.(*mspan).sweep.func1
    1000ms  3.37% 40.78%     1000ms  3.37%  runtime.memmove
     930ms  3.14% 43.91%     5070ms 17.10%  database/sql.convertAssign
     750ms  2.53% 46.44%     2240ms  7.55%  time.parse
     670ms  2.26% 48.70%     7370ms 24.86%  github.com/go-sql-driver/mysql.(*textRows).readRow

メモリ管理が重いですね。あと MySQL から受け取った結果をパースしてる部分が重い。

メモリ管理が重い場合、メモリのアロケートしてる部分を見つけて潰していく方法もありますが、もっと高いレイヤーでのアプリのチューニングの方が先です。この場合 -cum オプションを使ってトップダウンにプロファイルを見ます。

(pprof) top -cum 40
10.25s of 29.65s total (34.57%)
Dropped 546 nodes (cum <= 0.15s)
Showing top 40 nodes out of 214 (cum >= 2.22s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     28.99s 97.77%  runtime.goexit
         0     0%     0%     25.69s 86.64%  net/http.(*conn).serve
         0     0%     0%     25.40s 85.67%  net/http.(*ServeMux).ServeHTTP
...
         0     0%     0%     25.08s 84.59%  github.com/zenazn/goji/web/middleware.Recoverer.func1
         0     0%     0%     22.42s 75.62%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0%     0%     20.61s 69.51%  main.getIndex
         0     0%     0%     20.26s 68.33%  github.com/jmoiron/sqlx.(*DB).Select
         0     0%     0%     20.26s 68.33%  github.com/jmoiron/sqlx.Select
...

上位にいるリクエストハンドラーは getIndex だけです。ここに集中しましょう。

ソースコードの行単位のプロファイルを見るにはデバッグ情報が必要なので、 pprof 起動時にアプリのバイナリを指定しておく必要があります。 バイナリを指定し忘れて URL だけでプロファイルを取ってしまった場合も、起動したときの "Saved profile in ..." に表示されているパスにプロファイル結果が保存されているので、再度プロファイリングしなくても go tool pprof app <プロファイル結果のパス> で大丈夫です。

isucon:~/private_isu/webapp/golang$ go tool pprof app  /home/isucon/pprof/pprof.localhost:3000.samples.cpu.001.pb.gz
Entering interactive mode (type "help" for commands)
(pprof) list main.getIndex
Total: 29.65s
ROUTINE ======================== main.getIndex in /home/isucon/private_isu/webapp/golang/app.go
         0     20.61s (flat, cum) 69.51% of Total
         .          .    388:
         .          .    389:   http.Redirect(w, r, "/", http.StatusFound)
         .          .    390:}
         .          .    391:
         .          .    392:func getIndex(w http.ResponseWriter, r *http.Request) {
         .      120ms    393:   me := getSessionUser(r)
         .          .    394:
         .          .    395:   results := []Post{}
         .          .    396:
         .     18.39s    397:   err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC")
         .          .    398:   if err != nil {
         .          .    399:           fmt.Println(err)
         .          .    400:           return
         .          .    401:   }
         .          .    402:
         .      1.34s    403:   posts, merr := makePosts(results, getCSRFToken(r), false)
         .          .    404:   if merr != nil {
         .          .    405:           fmt.Println(merr)
         .          .    406:           return
         .          .    407:   }
         .          .    408:
         .          .    409:   fmap := template.FuncMap{
         .          .    410:           "imageURL": imageURL,
         .          .    411:   }
         .          .    412:
         .          .    413:   template.Must(template.New("layout.html").Funcs(fmap).ParseFiles(
         .          .    414:           getTemplPath("layout.html"),
         .          .    415:           getTemplPath("index.html"),
         .          .    416:           getTemplPath("posts.html"),
         .          .    417:           getTemplPath("post.html"),
         .       70ms    418:   )).Execute(w, struct {
         .          .    419:           Posts     []Post
         .          .    420:           Me        User
         .          .    421:           CSRFToken string
         .          .    422:           Flash     string
         .      690ms    423:   }{posts, me, getCSRFToken(r), getFlash(w, r, "notice")})
         .          .    424:}
         .          .    425:
         .          .    426:func getAccountName(c web.C, w http.ResponseWriter, r *http.Request) {
         .          .    427:   user := User{}
         .          .    428:   uerr := db.Get(&user, "SELECT * FROM `users` WHERE `account_name` = ? AND `del_flg` = 0", c.URLParams["accountName"])

前回の記事の最後で myprofiler で見つけた、 posts からの LIMIT なしクエリが重い問題ですね。MySQL 側だけでなく、その大量の結果を全件取得してパースしてる app 側でも一番重くなっているようです。

このクエリの結果を利用している makePosts() の中を見てみると、ループの終端にこんな if 文があります。

        if len(posts) >= postsPerPage {
            break
        }

この手前に continue 文もないので、このまま postsPerPage で LIMIT しましょう。 (注: これが確認不足で後でハマります)

diff --git a/app.go b/app.go
index eb52f47..3dd9804 100644
--- a/app.go
+++ b/app.go
@@ -394,7 +394,7 @@ func getIndex(w http.ResponseWriter, r *http.Request) {

        results := []Post{}

-       err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC")
+       err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 20")
        if err != nil {
                fmt.Println(err)
                return

さて、計測です。本当は計測とプロファイルは別にした方がいいですが、時間が勿体無いのでプロファイルしながら計測です。

スコア:

{"pass":true,"score":12848,"success":22272,"fail":1201,"messages":["1ページに表示される画像の数が足りません (GET /)","リダイレクト先URLが正しくありません: expected '^/$', got '/login' (GET /login)"]}

あらら。エラーがでてきました。アプリのログを見ると、

fork/exec /bin/bash: cannot allocate memory

メモリが足りなくて fork に失敗してました。

top:

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
11931 isucon    20   0  406248 183372   9052 S  74.8 17.9   0:19.55 app
  720 mysql     20   0 1226416 215076  10404 S  65.5 21.0   3:24.11 mysqld

CPU 使用率は app と mysql がだいたい一緒ですね。足しても200にだいぶ届かないので、CPU以外の部分がネックにりはじめていそうです。

myprofiler:

  17 SELECT * FROM `posts` WHERE `id` = N
  12 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
   4 SELECT * FROM `users` WHERE `id` = N
   3 SELECT * FROM `users` WHERE `id` = ?

posts から id 指定で1レコード取得が重くなりました。 N+1 かな?

外部プロセス呼び出しをやめる

fork に失敗するのは、多分(スワップがないせいで?)オーバーコミットがオフになっていて、fork した瞬間に app と同じだけのメモリを持ってるもう1プロセスを作れないからだと思います。

CPU使用率が2コアなのに200%に全然届かないのも fork のせい (Go のランタイムの都合上 fork するためには全 goroutine を一旦止めないといけなくて待ち時間が発生する) かもしれないので、メモリ使用量削減のために画像ファイルをDBから切り出すよりも外部プロセス呼び出しをやめる方を優先しましょう。

外部プロセスを読んでるところを見ると、 openssl dgst -sha512 コマンドで sha512 ダイジェストを計算しているようです。 Go で sha512 を計算する方法を調べて、同じ出力をするプログラムを書いてみます。

$ cat t.go < app.go
package main

import (
        "crypto/sha512"
        "fmt"
        "io/ioutil"
        "os"
)

func main() {
        data, _ := ioutil.ReadAll(os.Stdin)
        fmt.Printf("%x\n", sha512.Sum512(data))
}
isucon@ip-10-0-1-202:~/private_isu/webapp/golang$ go run t.go < t.go
b252b55576a4f4e321d5761b6dc980b8ee41fd9767765c785861a73b736f6a59aa7f40f7ba0d92c508dea32a20bc800e0198056c3dc8b33d5ac445f27b163d17
isucon@ip-10-0-1-202:~/private_isu/webapp/golang$ openssl dgst -sha512 < t.go
(stdin)= b252b55576a4f4e321d5761b6dc980b8ee41fd9767765c785861a73b736f6a59aa7f40f7ba0d92c508dea32a20bc800e0198056c3dc8b33d5ac445f27b163d17

これを参考に app.go を書き換えます。

@@ -125,14 +125,7 @@ func escapeshellarg(arg string) string {
 }

 func digest(src string) string {
-       // opensslのバージョンによっては (stdin)= というのがつくので取る
-       out, err := exec.Command("/bin/bash", "-c", `printf "%s" `+escapeshellarg(src)+` | openssl dgst -sha512 | sed 's/^.*= //'`).Output()
-       if err != nil {
-               fmt.Println(err)
-               return ""
-       }
-
-       return strings.TrimSuffix(string(out), "\n")
+       return fmt.Sprintf("%x", sha512.Sum512([]byte(src)))
 }

さて、プロファイル&計測です。アプリのログには fork エラーが消えました。

スコア:

{"pass":true,"score":26755,"success":24050,"fail":119,"messages":["1ページに表示される画像の数が足りません (GET /)"]}

うーん、まだエラー出てますね。これは LIMIT 足したのがマズいかな?

top:

Tasks:  84 total,   1 running,  83 sleeping,   0 stopped,   0 zombie
%Cpu(s): 54.2 us, 20.7 sy,  0.0 ni, 15.0 id,  1.4 wa,  0.0 hi,  8.3 si,  0.4 st
KiB Mem:   1022972 total,   958404 used,    64568 free,    18292 buffers
KiB Swap:        0 total,        0 used,        0 free.   425600 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  720 mysql     20   0 1357488 210336   4476 S  78.6 20.6   5:19.05 mysqld
  763 isucon    20   0  619612 198632   9120 S  70.2 19.4   0:13.54 app
 2904 www-data  20   0   92028   4088   1928 S  11.3  0.4   0:29.40 nginx
 2572 isucon    20   0   34344  11148   2160 S   7.3  1.1   0:28.48 tmux

idle が 15% まで下がってます。狙い通り。 あと、 tmux が 7% まで来ました。 Goji のログがリッチすぎるので、最後には切らないといけませんね。

myprofiler:

##  2016-05-25 20:18:44.06 +0900
  13 SELECT * FROM `posts` WHERE `id` = N
   9 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
   9 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
   6 SELECT * FROM `users` WHERE `id` = ?
   6 SELECT `id` FROM `posts` WHERE `user_id` = N
   4 SELECT * FROM `users` WHERE `id` = N
   4 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?
   2 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N
   2 SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC LIMIT N
   2 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC

バグ修正

makePosts() を見直してみると、投稿したユーザーが論理削除されていたら配列への追加をしないようなコードになっていました。 (Go だと early return (continue) イディオムを使うことが多いのでこの部分を見逃していました)

        if p.User.DelFlg == 0 {
            posts = append(posts, p)
        }

SELECT の段階で強引に JOIN してこの論理削除のフィルタリングを実行してしまいます。

@@ -394,7 +387,7 @@ func getIndex(w http.ResponseWriter, r *http.Request) {
 
        results := []Post{}
 
-       err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC LIMIT 20")
+       err := db.Select(&results, "SELECT posts.`id`, `user_id`, `body`, `mime`, posts.`created_at` FROM `posts` INNER JOIN `users` ON posts.user_id=users.id WHERE users.del_flg = 0 ORDER BY `created_at` DESC LIMIT 20")
        if err != nil {
                fmt.Println(err)
                return

スコア:

{"pass":true,"score":27399,"success":23615,"fail":0,"messages":[]}

今度はちゃんと通りました。

top:

Tasks:  83 total,   4 running,  79 sleeping,   0 stopped,   0 zombie
%Cpu(s): 53.9 us, 23.6 sy,  0.0 ni,  9.8 id,  4.2 wa,  0.0 hi,  8.2 si,  0.2 st
KiB Mem:   1022972 total,   948340 used,    74632 free,    12604 buffers
KiB Swap:        0 total,        0 used,        0 free.   486056 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  720 mysql     20   0 1359224 209144   4576 S  85.9 20.4   6:06.96 mysqld
  910 isucon    20   0  487224 139892   8884 S  67.9 13.7   0:09.58 app
 2904 www-data  20   0   91852   2828    844 R  10.7  0.3   0:35.40 nginx
 2572 isucon    20   0   34472  10100    928 S   6.7  1.0   0:33.64 tmux

ちょっと mysql が重いですね。

myprofiler:

  15 SELECT * FROM `posts` WHERE `id` = N
   7 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
   6 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
   5 SELECT * FROM `users` WHERE `id` = ?
   5 INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (?,?,?)
   5 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N
   5 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC
   4 INSERT INTO `posts` (`user_id`, `mime`, `imgdata`, `body`) VALUES (?,?,?,?)
   4 INSERT INTO `users` (`account_name`, `passhash`) VALUES (?,?)
   3 SELECT * FROM `users` WHERE `id` = N

JOIN を足したけど、それでもまだ post を id で引くのが重いみたいです。

pprof top40 -cum:

...
         0     0%  0.38%     13.88s 76.18%  github.com/zenazn/goji/web/middleware.AutomaticOptions.func1
     0.01s 0.055%  0.44%      8.85s 48.57%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0%  0.44%      6.11s 33.53%  main.getIndex
     0.02s  0.11%  0.55%      4.92s 27.00%  github.com/jmoiron/sqlx.(*DB).Get
     0.01s 0.055%   0.6%      4.90s 26.89%  github.com/jmoiron/sqlx.Get
         0     0%   0.6%      4.78s 26.23%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
     0.02s  0.11%  0.71%      4.65s 25.52%  main.makePosts
     3.82s 20.97% 21.68%      4.06s 22.28%  syscall.Syscall
...

pprof list makePosts:

ROUTINE ======================== main.makePosts in /home/isucon/private_isu/webapp/golang/app.go
      20ms      4.65s (flat, cum) 25.52% of Total
         .          .    173:}
         .          .    174:
         .          .    175:func makePosts(results []Post, CSRFToken string, allComments bool) ([]Post, error) {
         .          .    176:   var posts []Post
         .          .    177:
      10ms       10ms    178:   for _, p := range results {
         .      1.05s    179:           err := db.Get(&p.CommentCount, "SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = ?", p.ID)
         .          .    180:           if err != nil {
         .          .    181:                   return nil, err
         .          .    182:           }
         .          .    183:
         .          .    184:           query := "SELECT * FROM `comments` WHERE `post_id` = ? ORDER BY `created_at` DESC"
         .          .    185:           if !allComments {
         .       20ms    186:                   query += " LIMIT 3"
         .          .    187:           }
         .          .    188:           var comments []Comment
         .      1.38s    189:           cerr := db.Select(&comments, query, p.ID)
         .          .    190:           if cerr != nil {
         .          .    191:                   return nil, cerr
         .          .    192:           }
         .          .    193:
         .          .    194:           for i := 0; i < len(comments); i++ {
         .      770ms    195:                   uerr := db.Get(&comments[i].User, "SELECT * FROM `users` WHERE `id` = ?", comments[i].UserID)
         .          .    196:                   if uerr != nil {
         .          .    197:                           return nil, uerr
         .          .    198:                   }
         .          .    199:           }
         .          .    200:
         .          .    201:           // reverse
         .          .    202:           for i, j := 0, len(comments)-1; i < j; i, j = i+1, j-1 {
         .          .    203:                   comments[i], comments[j] = comments[j], comments[i]
         .          .    204:           }
         .          .    205:
      10ms       10ms    206:           p.Comments = comments
         .          .    207:
         .      1.35s    208:           perr := db.Get(&p.User, "SELECT * FROM `users` WHERE `id` = ?", p.UserID)
         .          .    209:           if perr != nil {
         .          .    210:                   return nil, perr
         .          .    211:           }
         .          .    212:
         .          .    213:           p.CSRFToken = CSRFToken
         .          .    214:
         .          .    215:           if p.User.DelFlg == 0 {
         .       60ms    216:                   posts = append(posts, p)
         .          .    217:           }
         .          .    218:           if len(posts) >= postsPerPage {
         .          .    219:                   break
         .          .    220:           }
         .          .    221:   }

時間のかかってるクエリがコメント取得を除いて1レコード取得するだけのクエリなので、簡単なクエリを大量に投げてるのが問題で重いのでしょう。

プレースホルダがあるクエリは、デフォルトでは prepared statement を使い捨てにしている (prepare, execute, close の3コマンド) ので、明示的に prepared statement を再利用するコードを書くか、 prepared statement を使わないようにするのがいいです。 最高性能を目指すなら再利用の方がいいですが、改修が簡単なのは prepared statement を使わない方です。 dsn に interpolateParams=true を足すだけ! (僕が実装した機能です。 参考)

diff:

@@ -805,7 +805,7 @@ func main() {
        }

        dsn := fmt.Sprintf(
-               "%s:%s@tcp(%s:%s)/%s?charset=utf8mb4&parseTime=true&loc=Local",
+               "%s:%s@tcp(%s:%s)/%s?charset=utf8mb4&parseTime=true&loc=Local&interpolateParams=true",
                user,
                password,
                host,

スコア:

{"pass":true,"score":30076,"success":25687,"fail":0,"messages":[]}

30k 点に到達。

top:

Tasks:  83 total,   5 running,  78 sleeping,   0 stopped,   0 zombie
%Cpu(s): 63.1 us, 17.4 sy,  0.0 ni,  8.5 id,  3.4 wa,  0.0 hi,  7.4 si,  0.2 st
KiB Mem:   1022972 total,   960140 used,    62832 free,    13192 buffers
KiB Swap:        0 total,        0 used,        0 free.   472760 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  720 mysql     20   0 1359224 209132   4128 S  79.7 20.4   6:56.71 mysqld
 1010 isucon    20   0  514368 157192   8888 S  66.8 15.4   0:08.93 app
 2904 www-data  20   0   91876   2824    844 R  11.3  0.3   0:41.86 nginx
 1015 isucon    20   0   21176  18648   3444 R   8.3  1.8   0:01.31 myprofiler
 2572 isucon    20   0   34920  10472    916 S   7.3  1.0   0:38.28 tmux

myprofiler:

  18 SELECT * FROM `posts` WHERE `id` = N
  11 INSERT INTO `posts` (`user_id`, `mime`, `imgdata`, `body`) VALUES (N,S,_binaryS,S)
   9 SELECT * FROM `users` WHERE `id` = N
   7 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
   6 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = N ORDER BY `created_at` DESC
   5 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
   4 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N
   2 INSERT INTO `users` (`account_name`, `passhash`) VALUES (S,S)
   1 SELECT * FROM `users` WHERE `account_name` = S AND `del_flg` = N
   1 INSERT INTO `comments` (`post_id`, `user_id`, `comment`) VALUES (N,N,S)

pprof:

(pprof) top40 -cum
4.23s of 18.58s total (22.77%)
Dropped 583 nodes (cum <= 0.09s)
Showing top 40 nodes out of 317 (cum >= 2.07s)
      flat  flat%   sum%        cum   cum%
         0     0%     0%     17.10s 92.03%  runtime.goexit
...
         0     0%  0.22%      8.84s 47.58%  github.com/zenazn/goji/web.netHTTPHandlerFuncWrap.ServeHTTPC
         0     0%  0.22%      5.66s 30.46%  main.getIndex
         0     0%  0.22%      4.90s 26.37%  github.com/zenazn/goji/web.handlerFuncWrap.ServeHTTPC
         0     0%  0.22%      4.04s 21.74%  github.com/jmoiron/sqlx.(*DB).Get
     0.04s  0.22%  0.43%      4.04s 21.74%  github.com/jmoiron/sqlx.Get
         0     0%  0.43%      3.73s 20.08%  html/template.(*Template).Execute
     0.03s  0.16%  0.59%      3.50s 18.84%  main.makePosts
         0     0%  0.59%      3.32s 17.87%  github.com/jmoiron/sqlx.(*DB).Select
         0     0%  0.59%      3.32s 17.87%  github.com/jmoiron/sqlx.Select
     0.93s  5.01%  5.60%      3.23s 17.38%  runtime.mallocgc
         0     0%  5.60%      3.12s 16.79%  text/template.(*Template).Execute
     0.08s  0.43%  6.03%      3.12s 16.79%  text/template.(*state).walk
     0.01s 0.054%  6.08%      3.07s 16.52%  text/template.(*state).walkTemplate
         0     0%  6.08%      3.02s 16.25%  text/template.(*state).walkRange
         0     0%  6.08%      3.02s 16.25%  text/template.(*state).walkRange.func1
     0.13s   0.7%  6.78%      2.96s 15.93%  runtime.systemstack

そろそろテンプレートの重さが上位に見え始めましたが、まだDBの方が重い。

まとめ

スコア: 4745 (初期状態) -> 14208 (前回) -> 30076 (今回)

さて、そろそろプロファイルで重いところを潰すチューニングは、乾いた雑巾絞りに近づいてきました。 次回はもっとドラスティックなチューニングに移っていきたいと思います。

今回は pprof や myprofiler を使ったチューニングの紹介の意図があったのでちょっとやりすぎてしまいました。 実際にはもっと早めに大改造を必要とするようなチューニングを考えて実行しないと、後半に時間が足りなくてジリ貧になってしまうので気をつけましょう。


@methane


songofacandy at 11:10
この記事のURLComments(0)TrackBack(0)ISUCON | golang
2016年05月30日

pixiv private isucon 2016 攻略 (1/5)

はてなブックマークに登録

攻略記事一覧:

pixiv さんが社内で開催したプライベート ISUCON の AMI を公開してくれたので、手順を残しながら攻略していきます。

この記事の対象読者は途中で何をすればいいかわからなくなってしまう ISUCON 初心者です。 Go を利用して攻略していきますが、他の言語で参加する場合でも考え方などは参考になると思います。

最低限の初期設定

ssh の公開鍵を入れたり、エディターや git などのツール類をインストール・設定します。

このあたりは事前に自分用のチートシートやスクリプトを作って、手早くできるようにしておきましょう。

マシン調査

スペック

とりあえず CPU とメモリくらいはちゃんと把握しておきましょう。

$ grep processor /proc/cpuinfo
processor       : 0
processor       : 1

$ free -m
             total       used       free     shared    buffers     cached
Mem:           998        906         92         12         25        335
-/+ buffers/cache:        545        453
Swap:            0          0          0

CPUは2コアですね。メモリはトータル1GBでスワップなし。要注意です。

ps aux

何が動いているか確認します。 メールサーバーとか、AppArmor のような、競技に明らかに不要そうなデーモンは、ベンチマークスコアを安定させるためとメモリの節約のために落としておいたほうが良いです。

今回は特に何もする必要はありませんでした。

アプリの仕様把握

初期状態に復元する手順を確認してから、実際にアプリをブラウザからさわってみましょう。

初期状態への復元は、 tar でアーカイブしてローカルに持ってきておいたり、 mysqldump を取ったりしておくと良いです。 ただし今回の場合はAMIからやり直せるので、 /initialize というパスで初期化されると言うことだけアプリのコードで確認し、バックアップは手抜きしました。 ISUCON 本番では初期状態を復元するのに必要なデータをオペミスで失うと即死する恐れがあるので注意しましょう。

ブラウザのデバッグ機能でどういう通信をしているのか見たり、アプリのコードのURLルーティング部分を中心に軽く目を通したり、 mysqldump --no-data isuconp で取得したスキーマを参考に、ざっくりと全体像を把握していきます。

nginx の基礎設定

アクセスログを事前に用意しておいたフォーマットに変更して、 upstream への keepalive を付ける。 コア数少ないので worker_processes を 1 にして、 keepalive の効率を上げる。

静的ファイルを nginx から返す設定は、アプリの動作を把握してからでも遅くない。 Go 以外を使う人は、完全に静的なファイルが分かった段階ですぐに、Go を使う人はある程度チューニングが進んで nginx を外すかどうかを判断するタイミングで nginx から返すようにしよう。

/etc/nginx/nginx.conf:

    worker_processes 1;
    ...
        ##
        # Logging Settings
        ##
        log_format  isucon '$time_local $msec\t$status\treqtime:$request_time\t'
                           'in:$request_length\tout:$bytes_sent\trequest:$request\t'
                           'acceptencoding:$http_accept_encoding\treferer:$http_referer\t'
                           'ua:$http_user_agent';
        access_log /var/log/nginx/access.log isucon;

/etc/nginx/sites-enabled/isucon.conf:

  upstream app {
    server 127.0.0.1:8080;
    keepalive 32;
  }

  server {
    listen 80;
  
    client_max_body_size 10m;
    root /home/isucon/private_isu/webapp/public/;
  
    location / {
      proxy_set_header Host $host;
      proxy_set_header X-Real-IP $remote_addr;
      proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
      proxy_pass http://app;
    }
  }

あと、今回は Go を使うので ruby と php のサービスも止めてしまいます。 Go のサービスは開発中はコマンドラインで起動したいのでここでは設定しません。

$ sudo systemctl stop isu-ruby
$ sudo systemctl disable isu-ruby
$ sudo systemctl stop php7.0-fpm
$ sudo systemctl disable php7.0-fpm

MySQL の基礎設定

/etc/mysql/my.cnf を見てみます。ほぼディストリのデフォルトで使っているようなので、メモリ使用量削減とIO待ち削減のために次の設定だけ追加しておきます。

innodb_flush_method = O_DIRECT
innodb_flush_log_at_trx_commit = 2

重いクエリを手早く見つけるためのツールを用意する。僕の場合は myprofiler を使う。

$ wget https://github.com/KLab/myprofiler/releases/download/0.1/myprofiler.linux_amd64.tar.gz
$ tar xf myprofiler.linux_amd64.tar.gz
$ sudo mv myprofiler /usr/local/bin/

myprofiler の使い方は、 myprofiler -user=root です。クエリが減ってきたら myprofiler -user=root -interval=0.2 くらいにサンプリング間隔を短くすると良いでしょう。それ以外のオプションは myprofiler -h で確認してください。

ベンチマークの実行とざっくり状況把握

スコア:

{"pass":true,"score":4745,"success":4408,"fail":0,"messages":[]}

top:

Tasks:  81 total,   1 running,  80 sleeping,   0 stopped,   0 zombie
%Cpu(s): 94.1 us,  4.2 sy,  0.0 ni,  0.3 id,  0.0 wa,  0.0 hi,  1.3 si,  0.0 st
KiB Mem:   1022972 total,   701036 used,   321936 free,    21396 buffers
KiB Swap:        0 total,        0 used,        0 free.   346564 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  720 mysql     20   0 1087768 140276  10724 S 142.8 13.7   0:52.09 mysqld
 2908 isucon    20   0  582876 124364   8800 S  46.6 12.2   0:12.98 app
 2904 www-data  20   0   91680   4800   2988 S   1.7  0.5   0:00.61 nginx

MySQL が app の3倍CPU食ってるのがわかります。

myprofiler:

 198 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
 124 SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N
  11 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC
   9 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC
   5 SELECT * FROM `posts` WHERE `id` = N
   4 SELECT COUNT(*) AS count FROM `comments` WHERE `post_id` IN (...N)
   2 SELECT * FROM `users` WHERE `id` = ?
   2 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC
   1 SELECT * FROM users WHERE account_name = S AND del_flg = N
   1 SELECT COUNT(*) AS count FROM `comments` WHERE `user_id` = N

comments の SELECT と COUNT が遅い事がわかる。その次に posts の select。

一番最初のチューニング: インデックス

上位3件のクエリについて、インデックスが有るか確認して、なければ張っておく。

mysql> show create table comments\G
*************************** 1. row ***************************
       Table: comments
Create Table: CREATE TABLE `comments` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `post_id` int(11) NOT NULL,
  `user_id` int(11) NOT NULL,
  `comment` text NOT NULL,
  `created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=100049 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)

mysql> show create table posts\G
*************************** 1. row ***************************
       Table: posts
Create Table: CREATE TABLE `posts` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `user_id` int(11) NOT NULL,
  `mime` varchar(64) NOT NULL,
  `imgdata` mediumblob NOT NULL,
  `body` text NOT NULL,
  `created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=10056 DEFAULT CHARSET=utf8mb4
1 row in set (0.00 sec)

comments.post_idposts.created_at にインデックスがない。重いクエリ上位3つがこれ。

mysql> create index post_id on comments (post_id);
Query OK, 0 rows affected (0.19 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> create index created_at on posts (created_at);
Query OK, 0 rows affected (0.03 sec)
Records: 0  Duplicates: 0  Warnings: 0

とりあえずこれでもう一度計測しておきます。

top:

top - 18:13:32 up  2:13,  1 user,  load average: 2.01, 0.84, 0.52
Tasks:  79 total,   1 running,  78 sleeping,   0 stopped,   0 zombie
%Cpu(s): 74.0 us, 19.3 sy,  0.0 ni,  3.2 id,  0.2 wa,  0.0 hi,  3.4 si,  0.0 st
KiB Mem:   1022972 total,   944288 used,    78684 free,    23344 buffers
KiB Swap:        0 total,        0 used,        0 free.   462656 cached Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 2908 isucon    20   0  640148 174444   8800 S 109.7 17.1   0:44.93 app
  720 mysql     20   0 1093212 212252  10740 S  58.5 20.7   1:56.57 mysqld

app が mysql の 2倍になり、クエリがネックじゃなくなったのがわかります。

スコア:

{"pass":true,"score":14208,"success":13157,"fail":0,"messages":[]}

myprofiler:

  36 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC
  15 SELECT COUNT(*) AS count FROM `comments` WHERE `user_id` = N
   5 SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
   4 SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= S ORDER BY `created_at` DESC

上位2件を見ると

  • posts からの SELECT に LIMIT が無い
  • comments.user_id にインデックスがない

LIMIT がないのはアプリ側で修正が必要なのと、ボトルネックがアプリに移ってるので、アプリ改修に移る。

comments.user_id はついでにインデックス張っておく。(1番重いクエリじゃないのでベンチは省略)

mysql> create index user_id on comments (user_id);
Query OK, 0 rows affected (0.14 sec)
Records: 0  Duplicates: 0  Warnings: 0

まとめ

スコア: 4745 (初期状態) -> 14208 (インデックスチューニング)

systemd のコマンドとか nginx の設定とか MySQL の設定ファイルを見るとかインデックス張るとかいろいろ慣れて、ここまではスムーズにできるようになりましょう。

感覚値ですが、一人でやってる場合はここまでを2時間以内には終わらせられるようにしましょう。1時間を切れればスゴイです。


@methane


songofacandy at 11:09
この記事のURLComments(0)TrackBack(0)ISUCON | golang
2016年04月20日

ラズパイで作るネットワークエミュレータ(後編)

はてなブックマークに登録

前編で紹介したネットワークエミュレータ「PackDrop」のプロトタイプですが、雑に作ったわりに評判が良く予想外に需要が出てきてしまったので、ちゃんと業務での利用に耐えられる「量産型」を製作しました。

前回の記事がややウケで気を良くしています。@pandax381です。

機能追加

プロトタイプを作成してから暫くのあいだ試験運用してみたのですが、実際に使った方々からいつくか要望を受けました。

  • パケットをバーストロスさせるためのスイッチが欲しい
    一定時間、連続的にパケットが消失するバーストロスを再現するときに「パケロスのボリュームを100%まで回してまた戻す」という作業が面倒なので、専用のスイッチを設けて欲しい。

  • 稼働状況がわかるようにLEDをつけて欲しい
    試験用のパラメータを設定したまま元に戻すのを忘れてしまい「あれ、なんか今日ネット遅くね?」という事案が多発したので、遅延・パケロスが設定されている場合には一目でわかるようにLEDで警告して欲しい。

  • 特定のVLANだけを対象にしたい
    タグVLANを利用している場合に、特定のVLAN-IDのパケットだけをネットワークエミュレーションの対象にし、それ以外のパケットは素通しさせたい。

作り始めた時にはそこまで考えが及んでいなかったので、やっぱり他の人に触ってもらうのって大事ですね。どれもそんなに手間を掛けずに対応できそうなので、量産型の製作に先立って要望された機能を追加してみます。

工作パート

追加工作で必要なパーツは以下の通りです。例によってどれも秋月で調達できるものですが、スライドスイッチはマルツの方が種類が豊富だったのでそちらで購入しました。また、プロトタイプでラズパイ本体にマウントしたブレッドボードにはもうスペースがないので、量産型の製作までは同じブレッドボードをもう1つ後付けしてしのぐことにします。

000

相変わらず回路図が書けないクソザコなので配線図的なものを載せておきます。こういった図がちゃちゃっと作れてしまう「fritzing」めっちゃ便利ですね。LEDとスライドスイッチを、それぞれGPIOの17番と22番に接続します。LEDには330Ωの抵抗を噛ませてあります。スライドスイッチはオンの時にGPIOとGNDがショートするように配置します。

001

コード修正

制御プログラム packdrop.c のコードを修正します。まず、プログラムの冒頭でGPIOの初期化処理を追加します。wiringPiSetupGpio() を呼び出した後、pinMode() でGPIOピンの入出力モードを設定します。LEDが繋がるピンは出力(OUTPUT)に、スライドスイッチが繋がるピンは入力(INPUT)に設定します。加えて、スライドスイッチの繋がるピンは pullUpDnControl() でプルアップ(PUD_UP)に設定します。

ラズパイはプルアップ抵抗とプルダウン抵抗を内蔵していて、各 GPIO ピンに対してプルアップ/プルダウンをソフトウェア制御できます。今回のように入力ピンを扱う際には、そのピンをプルアップして使えば抵抗を減らせて回路がシンプルになります(と何処かに書いてあったのでそうしてみました)。

プルアップの設定をした入力ピンは、何もつながっていなければ「1(HIGH)」になり、回路が繋がると(電流はそちらに流れるため)「0(LOW)」になります。今回のスライドスイッチの繋ぎ方だと「オン=0」「オフ=1」になりますが、とっても紛らわしいので「SW_ON」として値を定義して使うようにしています。

メインループの中で、digitalRead() を呼び出してスライドスイッチの状態を読み取り、オンであれば burst_mode() を呼び出します。burst_mode() でやっていることは、パケロスを100%に設定してLCDの表示を切り替えてLEDを点灯させているだけです。LEDを点灯させるには digitalWrite() で「1」を書き込めば良く「0」を書き込めば消灯します。その後は digitalRead() でスイッチの状態を読み続けて、オフの状態になったらメインループに戻って通常動作に復帰するようになっています。

通常動作での変更点は、遅延またはパケロスが設定されている場合にはLEDを点灯させるようにしただけです。

/*
 * packdrop.c
 */
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <wiringPi.h>
#include <wiringPiSPI.h>
#include <mcp3002.h>

#define APP_NAME     "PackDrop"
#define APP_VERSION  "v1.0"

#define SPI_CHANNEL  (0)
#define PINBASE      (100)
#define VOLUME_DELAY (PINBASE)
#define VOLUME_LOSS  (PINBASE+1)
#define SW_ON        (0)
#define PIN_LED      (17)
#define PIN_SW       (22)

char **devices;
int devnum;

static void
tc_set (const char *dev, int delay, int loss) {
    char cmd[128];

    snprintf(cmd, sizeof(cmd), "tc qdisc change dev %s root netem delay %dms loss %d%%", dev, delay, loss);
    system(cmd);
}

static void
tc_init (const char *dev) {
    char cmd[128];

    snprintf(cmd, sizeof(cmd), "tc qdisc del dev %s root >/dev/null 2>&1", dev);
    system(cmd);
    snprintf(cmd, sizeof(cmd), "tc qdisc add dev %s root netem delay 0ms loss 0%%", dev);
    system(cmd);
}

static void
lcd_write_core (const char *upper, const char *lower) {
    char cmd[128];

    system("i2cset -y 1 0x3e 0 0x80 b");
    snprintf(cmd, sizeof(cmd), "i2cset -y 1 0x3e 0x40 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x i",
        upper[0], upper[1], upper[2], upper[3], upper[4], upper[5], upper[6], upper[7]);
    system(cmd);

    system("i2cset -y 1 0x3e 0 0xc0 b");
    snprintf(cmd, sizeof(cmd), "i2cset -y 1 0x3e 0x40 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x i",
        lower[0], lower[1], lower[2], lower[3], lower[4], lower[5], lower[6], lower[7]);
    system(cmd);
}

static void
lcd_write (int delay, int loss) {
    char upper[9], lower[9];

    snprintf(upper, sizeof(upper), "  %3d ms", delay);
    snprintf(lower, sizeof(lower), "  %3d %%", loss);
    lcd_write_core(upper, lower);
}

static void
lcd_init (void) {
    char name[9], ver[9];

    system("i2cset -y 1 0x3e 0 0x38 0x39 0x14 0x78 0x5f 0x6a i");
    system("i2cset -y 1 0x3e 0 0x0c 0x01 i");
    system("i2cset -y 1 0x3e 0 0x06 i");
    snprintf(name, sizeof(name), "%8s", APP_NAME);
    snprintf(ver, sizeof(ver), "%8s", APP_VERSION);
    lcd_write_core(name, ver);
}

static void
burst_mode (void) {
    int n, v;

    for (n = 0; n < devnum; n++) {
        tc_set(devices[n], 0, 100);
    }
    lcd_write_core(" burst  ", "   mode ");
    digitalWrite(PIN_LED, 1);
    while (1) {
        v  = digitalRead(PIN_SW);
        if (v != SW_ON) {
            break;
        }
        sleep(1);
    }
}

int
main (int argc, char *argv[]){
    int n, v, b, d, l;
    int delay = 0, loss = 0;

    lcd_init();
    if (wiringPiSetupGpio() == -1) {
        printf("wiringPiSetupGpio: failed\n");
        return -1;
    }
    pinMode(PIN_LED, OUTPUT);
    pinMode(PIN_SW, INPUT);
    pullUpDnControl(PIN_SW, PUD_UP);
    if (mcp3002Setup(PINBASE, SPI_CHANNEL) < 0) {
        printf("mpc3002Setup: failed\n");
        return -1;
    }
    devices = argv + 1;
    devnum  = argc - 1;
    for (n = 0; n < devnum; n++) {
        tc_init(devices[n]);
    }
    while (1) {
        v = digitalRead(PIN_SW);
        b = (v == SW_ON) ? 1 : 0;
        if (b) {
            burst_mode();
        }
        v = analogRead(VOLUME_DELAY);
        d = ++v / 2;
        v = analogRead(VOLUME_LOSS);
        l = ((float)++v / 1024) * 100;
        if (d != delay || l != loss || b) {
            delay = d;
            loss  = l;
            for (n = 0; n < devnum; n++) {
                tc_set(devices[n], delay, loss);
            }
            lcd_write(delay, loss);
            digitalWrite(PIN_LED, (delay || loss) ? 1 : 0);
        }
        sleep(1);
    }
    return 0;
}

以前と同じように -lwiringPi オプションをつけてコンパイルし、バイナリを生成しておきます。

# gcc -W -Wall -o packdrop packdrop.c -lwiringPi

自動起動のための設定

ethtool が必要になるので、事前に apt でインストールしておきます。

# apt-get install ethtool

毎回、手動でブリッジを作成しなくて済むように /etc/network/interfaces ファイルにブリッジの記述します。念のため、NICのオフロード機能やブリッジのマルチキャストスヌーピング機能を無効にする設定も記述しています。

auto lo
iface lo inet loopback

auto eth0
iface eth0 inet static
    address 0.0.0.0
    up ethtool -K $IFACE tso off ufo off gso off gro off lro off 2>/dev/null

auto eth1
iface eth1 inet static
    address 0.0.0.0
    up ethtool -K $IFACE tso off ufo off gso off gro off lro off 2>/dev/null

auto br0
iface br0 inet static
    address 0.0.0.0
    bridge_ports eth0 eth1
    bridge_maxwait 0
    up ethtool -K $IFACE tso off ufo off gso off gro off lro off 2>/dev/null
    up echo 0 > /sys/devices/virtual/net/$IFACE/bridge/multicast_snooping

PackDropにはIPアドレスは割り当てないので、dhcpクライアントが自動で起動しないようにします。

# systemctl disable dhcpcd.service
# systemctl disable avahi-daemon.service

続いて、/etc/rc.local に packdrop コマンドを自動起動するための処理を記述します。少し手間を掛けて、sysfs経由でブリッジに登録されているインタフェースの一覧を取得し、packdrop コマンドの引数として渡すようにしています。これにより、interfaces ファイル側でブリッジに登録するインタフェースを変更した場合に、その変更が自動的に反映されるようになります。また、ブリッジそのものやインタフェースが見つからない場合には、LCDにエラーメッセージを表示するようにしています。

#!/bin/bash -e

packdrop=/root/bin/packdrop
br=br0

function getbrif() {
    echo `ls -A "/sys/devices/virtual/net/$1/brif/" 2> /dev/null`
}

ifaces=`getbrif $br`
if [ -n "$ifaces" ]; then
    $packdrop $ifaces >/dev/null 2>&1 &
else
    i2cset -y 1 0x3e 0 0x38 0x39 0x14 0x78 0x5f 0x6a i
    i2cset -y 1 0x3e 0 0x0c 0x01 i
    i2cset -y 1 0x3e 0 0x06 i
    i2cset -y 1 0x3e 0 0x80 b
    i2cset -y 1 0x3e 0x40 0x45 0x72 0x72 0x6f 0x72 0x20 0x20 0x20 i
    i2cset -y 1 0x3e 0 0xc0 b
    i2cset -y 1 0x3e 0x40 0x20 0x45 0x42 0x52 0x4e 0x46 0x4e 0x44 i
fi

exit 0

動作確認

自動起動の設定を済ませたら、PackDropを再起動させて動作確認をします。

まず、ボリュームの値がゼロで、スライドスイッチもオフの状態です。この状態では遅延もパケロスも発生しないのでLEDは点灯していません。

002

遅延またはパケロスのボリュームを回すとLEDが点灯し、両方の値をゼロに戻せば消灯します。

003

スライドスイッチをオンにすると、LCDの表示が「Burst Mode」に変わりLEDも点灯します。このモードではボリュームの値に関係なく、全てのパケットが捨てられて一切の通信ができなくなります。スライドスイッチをオフにすると通常のモードへ戻り、ボリュームの値に従って動作します。

004

VLAN対応について

PackDropを通過するパケットの中から特定の VLAN ID のパケットのみを制御したい場合には、/etc/network/interfaces ファイルの内容を以下のように変更することで対応できます。ここでは、例として eth0 と eth1 に対して ID「100」の VLAN インタフェースを定義し、それを br0 に登録しています。ただ、この状態だと VLAN ID が 100 以外のパケットが破棄されてしまうので、新たなブリッジ「br1」を定義し、そこへ eth0 と eth1 を登録します。/etc/rc.local の処理で、packdrop には br0 に登録されているインタフェースのみが渡されるようにしたので、br1 に登録されているインタフェースは対象外、つまりパケットがそのまま素通しされることになります。

auto lo
iface lo inet loopback

auto eth0
iface eth0 inet static
    address 0.0.0.0
    up ethtool -K $IFACE tso off ufo off gso off gro off lro off 2>/dev/null

auto eth0.100
iface eth0.100 inet static
    address 0.0.0.0
    up ethtool -K $IFACE tso off ufo off gso off gro off lro off 2>/dev/null

auto eth1
iface eth1 inet static
    address 0.0.0.0
    up ethtool -K $IFACE tso off ufo off gso off gro off lro off 2>/dev/null

auto eth1.100
iface eth1.100 inet static
    address 0.0.0.0
    up ethtool -K $IFACE tso off ufo off gso off gro off lro off 2>/dev/null

auto br0
iface br0 inet static
    address 0.0.0.0
    bridge_ports eth0.100 eth1.100
    bridge_maxwait 0
    up ethtool -K $IFACE tso off ufo off gso off gro off lro off 2>/dev/null
    up echo 0 > /sys/devices/virtual/net/$IFACE/bridge/multicast_snooping
    
auto br1
iface br1 inet static
    address 0.0.0.0
    bridge_ports eth0 eth1
    bridge_maxwait 0
    up ethtool -K $IFACE tso off ufo off gso off gro off lro off 2>/dev/null
    up echo 0 > /sys/devices/virtual/net/$IFACE/bridge/multicast_snooping

PackDropとVLANスイッチをうまく組み合わせることで、PackDropにイーサネットポートを増設しない構成も作れます。

例えば、以下のような設定をしたVLANスイッチの port1 にPackDropを接続して、port3 と port4 のあいだで遅延とパケロスを挿入する、といったことができます。

(余談ですが NETGEAR のこのVLANスイッチ、コンパクトで使いやすいし激安なので1つ持っておくといいですよ)

011

上記の構成で動作させる場合、interfaces ファイルの内容は以下のようになります。

auto lo
iface lo inet loopback

auto eth0
iface eth0 inet static
    address 0.0.0.0
    up ethtool -K $IFACE tso off ufo off gso off gro off lro off 2>/dev/null

auto eth0.100
iface eth0.100 inet static
    address 0.0.0.0
    up ethtool -K $IFACE tso off ufo off gso off gro off lro off 2>/dev/null

auto eth0.200
iface eth0.200 inet static
    address 0.0.0.0
    up ethtool -K $IFACE tso off ufo off gso off gro off lro off 2>/dev/null

auto br0
iface br0 inet static
    address 0.0.0.0
    bridge_ports eth0.100 eth0.200
    bridge_maxwait 0
    up ethtool -K $IFACE tso off ufo off gso off gro off lro off 2>/dev/null
    up echo 0 > /sys/devices/virtual/net/$IFACE/bridge/multicast_snooping

量産型の製作

前置きが長くなってしまいましたが、ようやく量産型の製作に取り掛かります。プロトタイプの最大の欠点は、なんと言っても物理的にものすごく脆弱なことです。ブレッドボードにジャンプワイヤを生やしているだけなので、ちょっと指を引っ掛けただけでも断線の危険性がありますし、輸送したらバラバラになっているかもしれません...

ここでも同僚から「プリント基板設計しよう」「P版ドットコム」「中国に発注すれば安いよ」などと煽られましたが、ラズパイ本体にぴったりサイズのユニバーサル基板が各社から発売されているらしいので、それを使って量産型を作ることにしました。

部品一覧

今回はサンハヤト製のラズパイ用ユニバーサル基板を使うことにしました。こちら、表記は「B+用」となっていますがラズパイ2はB+と同じ形状なので全く問題なく使えます。あとは、プロトタイプで使っていたボリューム(可変抵抗)は、そのまま基板に実装できないタイプだったので、基板に実装できるタイプのものを改めて調達しました。

005

また、Eleduinoのケース付属のネジ(20mm)だと長さが足りなくてユニバーサル基板を固定できませんでした。このユニバーサル基板を固定するには少なくとも25mmのネジが必要です。通販で手ごろに入手できるところがなかったので、秋葉原にあるネジ専門店「西川電子部品」へ買いに行ってきました。付属ネジはM2.5ですが、M2.6で大丈夫です。

  • M2.6 25mm ネジ x 4
  • M2.6 ナット x 8
  • M2.6 ワッシャー x 12
006

製作

いままでブレッドボードで作っていたものをユニバーサル基板へ実装し直します。部品点数も少ないので、少し考えて配置すれば問題なく配線できると思います。配置と配線経路が決まったら、後はひたすら半田付けするだけです。

以下、僕の作例です。半田付けの初心者すぎてスズメッキ線の存在とか知らなくてブレッドボード用のジャンプワイヤだけで作ってあります。あと、このユニバーサル基板はスルーホールになっていて、パーツを間違って半田付けしてしまうと取り外すのにものすごく苦労します。何度も失敗してパーツを壊したり悲しい思いをしたので、それを教訓にしてパーツ部分にはICソケットとピンソケットを取り付けるようにしました。あと、左上に三本生えているピンヘッダはシリアル接続(UART)用です。

007

裏面はこんな感じです。電子工作に慣れている方ならもっとシンプルで見栄えのいいものが作れると思いますが「初心者が作るとこんな感じのものが出来上がるのか」と生温かい目で見てもらえると有難いです。。

008

ソケットにパーツを取り付けたら完成です。プロトタイプと比べてだいぶスッキリしましたね!

009

動作確認

量産型のユニバーサル基板をラズパイに取り付けて動作確認します。まず、プロトタイプに取り付けていたブレッドボードやボリュームを取り外して、ネジを25mmのものに交換します。ブレッドボードの両面テープは強力ですが、ゆっくりは剥がせばキレイに剥がれます。ユニバーサル基板を取り付ける前に、一旦ナットでケースを固定します。この際、スペーサーとしてワッシャーを3枚ずつ噛ませると丁度よくなります。

012

量産型のユニバーサル基板をピンヘッダに差し込みながら取り付けてナットで固定します。USBイーサネットアダプタは、プロトタイプの時と同じように側面に両面テープで固定しておきます。最後に電源を入れて、全ての機能が正常に動作することを確認します。

010

ファイルシステムの保護(電プチ対策)

こういったネットワーク機器は、シャットダウン処理などせず、なにも考えずに電源を切れたほうが使いやすいです(というより、そうでないと使いづらいです)。Raspbianは、素の状態だとSDカード上のファイルシステムを読み書き可能な状態でマウントしています。これで何が問題になるかというと、SDカード上のファイルシステムに常時書き込みが発生していると、SDカードの寿命を早めてしまう可能性があります。最近はどうかわかりませんが、一昔前だと何ヶ月かで壊れてしまうようなことが普通にありました。また、書き込み中に電源が落ちてファイルシステムを破壊してしまうことも考えられます。そういったことを防ぐために、SDカード上ファイルシステムを保護してあげる必要があります。ファイルシステムを保護するために fsprotect や overlayroot などのツールもありますが、ここでは initramfs と overlayfs を用いて自前でファイルシステムの保護を行います。

initramfs の作成

まず、busybox を使って initramfs の種を作成します。

# apt-get install busybox-static
# mkdir -p initramfs/{bin,dev,lib,proc,sys}
# /bin/busybox --install -s initramfs/bin
# cp /bin/busybox initramfs/bin

initramfs 内で必要になるカーネルモジュールをコピーします。最後のdepmodを実行し忘れるとカーネルがモジュールを認識できないので注意してください。

# mkdir -p initramfs/lib/modules/`uname -r`
# cp /lib/modules/`uname -r`/modules.{builtin,order} initramfs/lib/modules/`uname -r`
# mkdir -p initramfs/lib/modules/`uname -r`/kernel/fs/overlayfs
# cp -a /lib/modules/`uname -r`/kernel/fs/overlayfs/overlay.ko initramfs/lib/modules/`uname -r`/kernel/fs/overlayfs
# depmod -a --basedir initramfs

initramfs では /init スクリプトが自動実行されるので、initramfs ディレクトリ直下に、init という名前のシェルスクリプトを作成します。/dev/mmcblk0p2 を lower に、tmpfs を upper に指定して overlayfs をマウントしています。これだけで、SDカードのパーティションを Read Only でマウントしつつ、ルートファイルシステムは Read Write なシステムが構築できます。更にシステム起動後に発生したファイルシステム上の変更は電源断で消えてなくなるので、こういった装置にピッタリです。

また、コンフィグ投入の仕組みとして、FATパーティション(/dev/mmcblk0p1)に interfaces.txt という名前のファイルを置いておくと、それを /etc/network/interfaces にコピーしてから起動するようにしています。VLANの設定をしたくなった場合には、この仕組みを利用してPackDropの動作を変更できます。

#!/bin/sh

export PATH=/bin
export TZ=JST-9

mount -t devtmpfs devtmpfs /dev
mount -t proc proc /proc
mount -t sysfs sysfs /sys

echo "4 4 1 7" > /proc/sys/kernel/printk

modprobe overlay

mkdir /overlay /sysroot
mkdir /overlay/ro /overlay/rw
mount -t ext4 -o ro /dev/mmcblk0p2 /overlay/ro
mount -t tmpfs -o size=512M tmpfs /overlay/rw
mkdir /overlay/rw/root /overlay/rw/work
mount -t overlay -o lowerdir=/overlay/ro,upperdir=/overlay/rw/root,workdir=/overlay/rw/work overlay /sysroot
mount -t vfat -o ro /dev/mmcblk0p1 /sysroot/boot
mkdir /sysroot/overlay
mkdir /sysroot/overlay/ro /sysroot/overlay/rw
mount --move /overlay/ro /sysroot/overlay/ro
mount --move /overlay/rw /sysroot/overlay/rw

echo -n > /sysroot/etc/fstab
cp -f /sysroot/boot/interfaces.txt /sysroot/etc/network/interfaces 2>/dev/null

umount /sys
umount /proc
umount /dev

exec switch_root -c /dev/console /sysroot /sbin/init

作成したスクリプトに実行権限を付与します。

# chmod +x initramfs/init

initrafms ディレクトリの中身を cpio でアーカイブしてイメージファイルを作成します。initramfs のイメージファイルは、ブートローダが読み込める場所に配置する必要があるので /boot に出力します。

# cd initramfs
# find . | cpio -o -H newc | gzip -c > /boot/initramfs.img

ラズパイ本体の設定

作成した initramfs をロードしてブートするために、/boot/config.txt に以下の行を追記します。

initramfs initramfs.img

スワップファイルも無効にしておきます。

# dphys-swapfile swapoff
# dphys-swapfile uninstall
# update-rc.d dphys-swapfile disable

動作確認

上記の設定が済んだ状態で再起動させると、ファイルシステムが保護された状態で起動してきます。SDカードのパーティションは Read Only でマウントされているため、動作中に突然電源を切られてしまっても大丈夫です。

起動時のログを載せておきますので、うまくいかない場合には照らし合わせてみてください。 https://gist.github.com/pandax381/06508bd5e226f5aefd4997bba093cfde

また、以前の状態でファイルシステムを保護しない状態に戻したくなった場合には、以下のようにして /boot/config.txt に記述した initramfs の行をコメントアウトして再起動するだけで元どおりになります。

# mount -o rw,remount /boot
# sed -ie "s/^initramfs/#initramfs/" /boot/config.txt
# reboot

おわりに

電子工作初心者がラズパイで遊んでみたというだけの記事になってしまったような気がしなくもないですが、楽しかったです。そして、ソフトだけじゃなくハードもある程度できると幅が広がるなぁと当たり前のことを改めて実感しました。とりあえず、半田付けは初心者から少しだけレベルアップしたので、引き続き電子工作を楽しみながらハードにも強くなれるよう励みます。

あと、実際に社内で稼働しているバージョンはもう少し進化していて、ファームウェアの更新をしやすくするために rootfs の中身を squashfs でイメージ化したものをFATパーティションに置いて、それを使うようにしていたりします。このあたりのネタも面白いので、また個別に記事を書こうと思います。


klab_gijutsu2 at 19:02
この記事のURLComments(0)TrackBack(0)
2016年04月06日

ラズパイで作るネットワークエミュレータ(前編)

はてなブックマークに登録

ネットワークが絡んだ通信プログラムを開発していると、テストのために遅延やパケロスを意図的に発生させたくなることがあります。いまどきは IDE にネットワークエミュレーション機能が組み込まれていたり、仮想環境で容易に再現できたりもしますが、箱物のネットワークエミュレータがあるとネットワークの構成を気にせずカンタンに設置できるのですごく便利だったりします。世の中にはそういった製品が沢山あるので安価なものを買ってもいいのですが、新たにラズパイが届いたばかりだったので、これを使って超小型のネットワークエミュレータを自作してみました。前編と後編の二回に分けて紹介します。

最近、社内で「ラズパイおじさん」と呼ばれるようになりました。@pandax381 です。

001

ラズパイ + Linux = ネットワークエミュレータ

「ネットワークエミュレータを自作」と言うとなんだか凄そうな感じがしますが、実はものすごく簡単につくれます。なぜなら、ネットワークエミュレータに必要な機能を Linux が全て備えているからです。Linux をインストールしたラズパイがあれば、数万円の価格帯の製品と同等のことができます(というより、この価格帯の製品は単に Linux の機能を利用しただけのものが多いです)。

動作イメージ

作成したネットワークエミュレータは、ブリッジ(中継機)として動作するタイプのものです。ネットワーク機器同士の間に接続し、通過するパケットに対して遅延やパケロスを発生させます。

002

また、イーサネットポートを備えていないラップトップやスマートフォンの場合には、ネットワークシミュレータを「アクセスポイント〜スイッチ間」に設置することで、そのアクセスポイントに接続している端末の通信パケットに対して制御を加えることができます。例えば、Wi-Fi につないだままモバイルネットワークと同等の品質で通信するといったことができるようになります。

003

イーサネットポートが足りない問題

ブリッジとして動作させると言ったものの、ラズパイに搭載されているイーサネットポートは1つだけなので、物理的にポートが足りなくてネットワークをブリッジできません(個人的には2ポートのモデルがあるとすごく幸せなんですけど、一般的にはあまり需要ないんですかねぇ...)。

これはもう足りないなら増やすしかないので、ちょっと格好悪いですがUSBイーサネットアダプタを接続してポートを増設します。ラズパイに内臓されているイーサネットポートは100Mなので、増設するイーサネットアダプタも100Mで十分です。無駄にギガビットのアダプタを接続しても、ブリッジした際にもう片方の性能に引っ張られるので意味がないです。個人的には Logitec LAN-TXU2C あたりが安価で入手性もいいのでオススメです。Raspbian にはこのアダプタが使っているチップのドライバ(asix.ko)が入っているので、USBポートに接続するだけで認識します。

004

なお、USBイーサネットアダプタはそれなりに電力を消費するため、調子に乗って何個も接続するとラズパイ本体が電力不足で不安定になって落ちたりするので自重しましょう。

VLANスイッチと組み合わせるとイーサネットポートを増設しなくても済むようになりますが、それは後編で紹介します。

ブリッジを作ってパケットを通過させる

まず、ブリッジを作成してラズパイの持つ2つのイーサネットポート間でパケットが通過できるようにします。

005

ブリッジを作成するには、bridge-utils がインストールされている必要があります。Raspbian のイメージならインストールされているはずですが、なければ apt でインストールします。

# apt-get install bridge-utils

ブリッジの作成や操作は brctl コマンドで行います。brctl addbr でブリッジ を作成し、brctl addif でブリッジにインタフェースを追加します。ここでは、br0 という名前で新しくブリッジを作成し、そこに eth0 と eth1 を追加します。

# brctl addbr br0
# brctl addif br0 eth0 eth1

作成したブリッジは brctl show で確認できます。

# brctl show
bridge name     bridge id               STP enabled     interfaces
br0             8000.3495db294586       no              eth0
                                                        eth1

仕上げに、ip コマンドでインタフェースとブリッジを起動させれば、このラズパイは2ポートのハブのように振る舞いはじめます。試しに、PCとスイッチの間にこのラズパイを接続しても、PCは何事もなくこれまでと同じように通信できるはずです。

# ip link set eth0 up
# ip link set eth1 up
# ip link set br0 up

遅延とパケロスを発生させる

ブリッジを作成してパケットがラズパイを通過できるようになったので、次は通過するパケットに対して遅延やパケロスを発生させる設定をします。

Linux カーネルにはトラフィックコントロールやネットワークエミュレーションの機能が備わっていて、Raspbian を含めたほとんどのディストリビューションで有効になっています。

iproute2 に含まれる tc コマンドを使って、送信トラフィックに対して以下の制御を加えることができます。

  • 帯域制限
  • 帯域保証
  • 遅延
  • パケットロス
  • ビットエラー
  • 重複
  • 順序入れ替え

ネットワークエミュレータを名乗るからには全ての機能を取り入れたいところですが、今回は取り急ぎ必要だった 遅延パケロス のみを扱います。

tc コマンドを使いこなすと高度なトラフィック制御ができるようになりますが、Linux のトラフィックコントロールの概念はなかなかに複雑で、tc のコマンド体系もそれに習って難解です。ここでは決まった使い方しか示しませんが、tc コマンドやトラフィックコントロールの詳細について興味がある方には、GREEさんのエンジニアブログに掲載されている「よくわかるLinux帯域制限」という記事が秀逸でオススメです。

tc コマンドは複雑ですが、遅延とパケロスを設定するだけなら簡単です。例えば、eth0 に対して遅延とパケットロスを設定するには以下のコマンドを実行するだけです。これで、eth0 から「出て行く」パケットに対して 100ms の遅延が加わり、5% の確率でパケットロスが発生します。

# tc qdisc add dev eth0 root netem delay 100ms loss 5%

なお、新しく設定を追加する時は tc qdisc add ですが、設定済みの値を変更する際は tc qdisc change です。値が設定されていないのに change を指定したり、設定済みなのに add を指定するとエラーになります。

# tc qdisc change dev eth0 root netem delay 200ms loss 10%

設定した値は tc qdisc del で消せます。消去した後の再設定は tc qdisc add です。

# tc qdisc del dev eth0 root

ここでは、遅延やパケロスを固定的に発生させる方法を示していますが、遅延時間やパケロス発生頻度を一定の範囲内で分散させたりすることもできます。

UIについて考える

このように、Linux の標準的な機能を組み合わせることで、ラズパイを超小型のネットワークシミュレータに仕立て上げることができます。ただし、この状態だとめちゃくちゃ使いにくいです。遅延やパケロスの値を変えるのに、その都度シリアル経由でログインして tc コマンドを実行するとかありえないです。自分が手元で使うにしても、もう少し気の利いた UI が欲しいと思ってしまいます。

ネットワーク機器なので、シリアルでCLIを提供するというのも個人的にはアリですが、他の人に勧めようとした際に「USBシリアル変換ケーブルとか持ってないよ」と言われてしまう可能性が高いので微妙です。無難に Web で GUI を提供するのが現実的だと思いますが、メンテナンス用のイーサネットポートがないのでIPアドレスを割り当てる先がなく、これも微妙です。

どうにも決めかねていたので、たまたま通りがかった同僚に相談してみたところ「直感的なやつ」「アナログな感じで」「つまみでぐりぐり設定したい」「液晶もつけよう」「アキバ行こう」などと煽られました。

「まぁラズパイを使ってるんだから電子工作でアナログな UI を作るのも面白いなぁ〜」と思いはじめ、悪乗りしてネタにマジレスすることにしました。

UI(物理)を試作

パーツ一覧

まず、ラズパイ本体とケース、外付けのUSBイーサネットアダプタです。前回はRSコンポーネンツ製の純正ケースを買ったのですが、Eleduino のアクリルケースがお洒落だったのでこちらを選んでみました。ヒートシンクの効果は不明ですがカッコいいので付けてます。

006

続いて、UI用の工作パーツです。全て秋月で調達できます。コンセプトの「ぐりぐりして設定する」を実現するために、ボリューム(可変抵抗)を使います。なお、ラズパイはアナログ入力を備えていないので、SPI接続のADコンバータを使ってボリュームの値を読み取ります。設定した値を表示するために、I2C接続のキャラクタLCDも用意します。

007

UI用の工作パーツだけなら千円程度で揃います。

組み立て

回路図とか書けないクソザコなので、配線図的な何かを載せておきます。

007

設定した値を表示させるためのキャラクタLCDです。8文字×2行なので表示できる情報量は少ないですが、ものすごく小さいです。ピッチが狭いので変換基盤への半田付けが少し大変ですが、電子工作初心者で半田付けに不慣れな僕でもなんとかできたので大丈夫です。ちなみに、弊社では、その辺に FLUKE のオシロスコープが転がっていたりするのですが、なぜか半田ごてが備品として存在しておらず「これは由々しき問題だ」ということで、新たに温調式の半田ごてが備品に仲間入りすることなりました。

008

ボリュームは、GND(左)OUT(中)VCC(右)に接続するので、ジャンプワイヤを半田づけしておきます。

011

あとは、ブレッドボードとボリュームを両面テープでラズパイの上に固定して、ひたすら配線します。ブレッドボード付属の両面テープはかなり強力なので慎重に...貼ってしまうと剥がすのが大変です。ボリュームはクッション入りの両面テープで貼るとグラつかずに固定できます。

012

ちょっとジャンプワイヤがごちゃごちゃしていますが、まぁプロトタイプなのでこれでいいでしょう。ついでにUSBイーサネットアダプタも両面テープで側面に貼ってしまいます。なんだかそれっぽいガジェットに見えるようになってきましたね!

I2C接続のLCDが認識できない問題

秋月で調達したI2C接続のLCD「AE-AQM0802」が認識できないという問題に遭遇しました。ピッチ変換基盤への半田付けをミスったのかと思い、完成品を買ってきても認識してくれませんでした。少し調べてみたところ、同じようにラズパイで認識されないと報告している方がいました(逆にちゃんと動作したという方もいました)。

電子工作初心者のため、あまり良くわかってないのですが、どうも「I2C で使う GPIO ピンはラズパイ本体側に固定的にプルアップ抵抗が実装されていて、その抵抗値が小さすぎるためにうまく認識できない」ということのようです。解決策っぽいものの中で一番確実で分かりやすかったのが「ラズパイ本体側のプルアップ抵抗を取り除く」でした。ちょっと荒技な気もしますが、えいやでやってみたら見事に動いてくれました。

ラズパイ本体側のプルアップ抵抗とは、GPIOピンのすぐそばに表面実装されている R23 / R24 のチップ抵抗です。そのまま半田ごてを当ててもなかなか取れないので、半田を盛ってから吸い取り線で一緒に吸ってしまうとキレイに取れます。

010

ピッチ変換キットには10KΩのプルアップ抵抗が実装されていてるので、これをショートさせて有効にします。

009

その後、さらに調べてみたところ、ストロベリーリナックス製の LCD「SB0802GN」が、秋月のものとほぼ同じ仕様(形状もコントローラも同じ)で、これなら問題なく認識されるようです。ラズパイ本体に手を加えたくない場合には、代わりにこちらの LCD を使うのがいいかもしれません。

コードを書く

ラズパイの設定変更

ADコンバータとLCDの接続に、それぞれ SPI と I2C を使うので、これらを有効にするための設定をします。

/boot/config.txt に以下の内容を追記します。

dtparam=i2c_arm=on
dtparam=spi=on

/etc/modules に以下の内容を追記します。

i2c-bcm2708
i2c-dev
spi_bcm2835

再起動後に lsmod を実行して指定したモジュールがロードされていれば大丈夫です。

# lsmod
Module                  Size  Used by
sch_netem               8032  0 
bridge                 93064  0 
ipv6                  339514  17 bridge
stp                     1479  1 bridge
llc                     3600  2 stp,bridge
i2c_dev                 6047  0 
asix                   19981  0 
libphy                 24139  1 asix
i2c_bcm2708             5014  0 
spi_bcm2835             7248  0 
uio_pdrv_genirq         2966  0 
uio                     8235  1 uio_pdrv_genirq

必要なツールとライブラリのインストール

制御プログラムをC言語で書きますが、超絶便利なライブラリ「Wiring Pi」を使います。Wiring Pi は、ラズパイの GPIO を制御するためのライブラリで SPI や I2C にも対応しています。今回はADコンバータからボリュームの値を読み出す処理で Wiring Pi を使います。LCDの制御に関しては手抜きをして i2c-tools に頼ります。

  • i2c-tools
  • libi2c-dev
  • Wiring Pi

i2c-tools と libi2c-dev を apt でインストールします。Wiring Pi は git のリポジトリを clone してビルド&インストールします。

# apt-get install i2c-tools libi2c-dev
# git clone git://git.drogon.net/wiringPi
# cd wiringPi
# ./build

制御プログラム

アナログUIの制御プログラムです。一秒おきにADコンバータからボリュームの値を読み取り、前回の値から変改していたら tc コマンドの実行とLCDへの描画を行います。ほとんどの処理を system() 経由で外部コマンドに丸投げしていたり、エラー処理が手抜きだったり、かなり雑に作っていますがプロトタイプなのでご愛嬌。

/*
 * packdrop.c
 */
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <wiringPi.h>
#include <wiringPiSPI.h>
#include <mcp3002.h>

#define APP_NAME     "PackDrop"
#define APP_VERSION  "v0.4"

#define SPI_CHANNEL  (0)
#define PINBASE      (100)
#define VOLUME_DELAY (PINBASE)
#define VOLUME_LOSS  (PINBASE+1)

char **devices;
int devnum;

static void
tc_set (const char *dev, int delay, int loss) {
    char cmd[128];

    snprintf(cmd, sizeof(cmd), "tc qdisc change dev %s root netem delay %dms loss %d%%", dev, delay, loss);
    system(cmd);
}

static void
tc_init (const char *dev) {
    char cmd[128];

    snprintf(cmd, sizeof(cmd), "tc qdisc del dev %s root >/dev/null 2>&1", dev);
    system(cmd);
    snprintf(cmd, sizeof(cmd), "tc qdisc add dev %s root netem delay 0ms loss 0%%", dev);
    system(cmd);
}

static void
lcd_write_core (const char *upper, const char *lower) {
    char cmd[128];

    system("i2cset -y 1 0x3e 0 0x80 b");
    snprintf(cmd, sizeof(cmd), "i2cset -y 1 0x3e 0x40 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x i",
        upper[0], upper[1], upper[2], upper[3], upper[4], upper[5], upper[6], upper[7]);
    system(cmd);

    system("i2cset -y 1 0x3e 0 0xc0 b");
    snprintf(cmd, sizeof(cmd), "i2cset -y 1 0x3e 0x40 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x i",
        lower[0], lower[1], lower[2], lower[3], lower[4], lower[5], lower[6], lower[7]);
    system(cmd);
}

static void
lcd_write (int delay, int loss) {
    char upper[9], lower[9];

    snprintf(upper, sizeof(upper), "  %3d ms", delay);
    snprintf(lower, sizeof(lower), "  %3d %%", loss);
    lcd_write_core(upper, lower);
}

static void
lcd_init (void) {
    char name[9], ver[9];

    system("i2cset -y 1 0x3e 0 0x38 0x39 0x14 0x78 0x5f 0x6a i");
    system("i2cset -y 1 0x3e 0 0x0c 0x01 i");
    system("i2cset -y 1 0x3e 0 0x06 i");
    snprintf(name, sizeof(name), "%8s", APP_NAME);
    snprintf(ver, sizeof(ver), "%8s", APP_VERSION);
    lcd_write_core(name, ver);
}

int
main (int argc, char *argv[]){
    int n, v, d, l;
    int delay = 0, loss = 0;

    lcd_init();
    if (mcp3002Setup(PINBASE, SPI_CHANNEL) < 0) {
        printf("mpc3002Setup: failed\n");
        return -1;
    }
    devices = argv + 1;
    devnum  = argc - 1;
    for (n = 0; n < devnum; n++) {
        tc_init(devices[n]);
    }
    while (1) {
        v = analogRead(VOLUME_DELAY);
        d = ++v / 2;
        v = analogRead(VOLUME_LOSS);
        l = ((float)++v / 1024) * 100;
        if (d != delay || l != loss) {
            delay = d;
            loss  = l;
            for (n = 0; n < devnum; n++) {
                tc_set(devices[n], delay, loss);
            }
            lcd_write(delay, loss);
        }
        sleep(1);
    }
    return 0;
}

Wiring Pi のライブラリを使っているので、-lwiringPi を指定してコンパイルします。

# gcc -W -Wall -o packdrop packdrop.c -lwiringPi

動かしてみる

実際に制御プログラムを動かして、ちゃんと遅延とパケロスが発生するのかを確認します。

まず、事前にブリッジを作成しておきます。

# brctl addbr br0
# brctl addif br0 eth0 eth1
# ip link set eth0 up
# ip link set eth1 up
# ip link set br0 up

続けて、制御プログラムの packdrop を起動します。packdrop の引数には、ブリッジに追加したインタフェースを指定します。

# ./packdrop eth0 eth1

実際に動作させている動画です。

動画を見ると一目瞭然ですが、青いボリュームを回すと「遅延」が増加し、ピンクのボリュームを回すと「パケロス」が増加します。遅延もパケロスも「上りと下りの両方に適用」されるため、ping の RTT には設定した遅延の2倍の時間が加算され、パケロスが 10% の場合には 0.9 x 0.9 = 0.81(81%)の確率で応答パケットが届きます。

余談

このネットワークエミュレータには「PackDrop」という名前を付けたのですが、なぜか社内では「パケ落ちくん」という愛称で呼ばれています。

次回予告

半分ネタで雑に作ったネットワークエミュレータですが、実際に案件でデバッグに使ってみてもらったところ、わりと評判が良く、各所から「それ欲しい」という要望が出てきました。

ラズパイの在庫は豊富にあるので何台でも作れるのですが、指を引っ掛けたら配線が抜けてしまうんじゃないかとか、両面テープで固定しているだけなのでボリュームが取れてしまうんじゃないかとか、ちょっと物理的に脆弱すぎるという問題が...

他にも、ちゃんと起動スクリプトを作ったり電プチに対応したり、アプライアンス的に使えるようにした方が使い勝手が良さそうだったりします。そんな訳で、後編ではもう少し真面目に作った「量産型」を紹介します。

013

klab_gijutsu2 at 16:29
この記事のURLComments(0)TrackBack(0)network 
2016年04月01日

Thundering herd 対策の本命、 EPOLLEXCLUSIVE を試してみた

はてなブックマークに登録

epoll を使った prefork 型アプリケーションサーバーにおける Thundering herd 対策の決定版として注目されていた EPOLLEXCLUSIVE が、 3/13 にリリースされた Linux 4.5 で導入されました。

昨年 SO_REUSEPORT というソケットオプションが登場して、 Thundering herd 対策として話題になったものの、ワーカーごとに listen キューが作られるため graceful restart するときに listen キューに入ってるリクエストを取りこぼす可能性があり利用するのが難しい状況でした。

参考: epoll の thundering herd 問題について解説しているサイト

一方、 EPOLLEXCLUSIVE は、 listen キューは一本のまま、その listen キューを待っている複数プロセスの epoll_wait() を全部起こすのではなく、1つ以上(1つとは限らない)だけ起こすという機能です。 graceful shutdown 中は epoll_wait() をしていないはずなので、 listen キューに来たリクエストは他のワーカープロセスの epoll_wait() に通知され、取りこぼしがありません。

http://man7.org/linux/man-pages/man2/epoll_ctl.2.html

       EPOLLEXCLUSIVE (since Linux 4.5)
              Sets an exclusive wakeup mode for the epoll file descriptor
              that is being attached to the target file descriptor, fd.
              When a wakeup event occurs and multiple epoll file descriptors
              are attached to the same target file using EPOLLEXCLUSIVE, one
              or more of the epoll file descriptors will receive an event
              with epoll_wait(2).  The default in this scenario (when
              EPOLLEXCLUSIVE is not set) is for all epoll file descriptors
              to receive an event.  EPOLLEXCLUSIVE is thus useful for
              avoiding thundering herd problems in certain scenarios.

使い方は、 EPOLL_CTL_ADD するときに、 events で EPOLLIN などと bitwise OR で組み合わせて利用します。

struct epoll_event ev = {EPOLLIN | EPOLLEXCLUSIVE, NULL};
epoll_ctl(epfd, EPOLL_CTL_ADD, listenfd, &ev);

環境準備

Ubuntu 16.04 LTS xenial xerus や Amazon Linux 2016.03 といった最新(あるいはもうすぐリリースされる)のディストリビューションでも、採用しているのは Linux 4.4 なので、そのままでは試すことができません。 (Fedora 24 は Linux 4.5 らしいですが、普段使わないので除外しました)

そこで、 Ubuntu 15.10 を元に、 https://wiki.ubuntu.com/KernelTeam/GitKernelBuild にある手順に従い Linux 4.5 をソースからビルドして再起動することにしました。 書いてある手順通りで問題ないのですが、私の場合 Ubuntu 15.10 の公式 AMI のデフォルトディスクサイズ (8GB) で容量が足らずに一度ビルドに失敗して32GBに拡張したので、同じくAWSを使われる方は注意してください。

カーネルのインストールが終わって再起動したら、Linux 4.5 カーネルを利用していることを確認します。 また、 <sys/epoll.h> にはまだ EPOLLEXCLUSIVE が定義されていないので、定数の値を確認しておきます。

$ uname -a
Linux ip-10-0-1-221 4.5.0-custom #1 SMP Thu Mar 31 07:35:29 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

~/linux-4.5/include$ ag EPOLLEXC
uapi/linux/eventpoll.h
30:#define EPOLLEXCLUSIVE (1 << 28)

EPOLLEXCLUSIVE を使った場合にどれくらい性能に影響がでるか、簡単なベンチマークをしたいので、 TIME_WAIT で詰まる問題を回避するおまじないをしておきます。

$ echo 'net.ipv4.tcp_tw_reuse = 1' | sudo tee -a /etc/sysctl.conf
$ sudo sysctl -p
net.ipv4.tcp_tw_reuse = 1

meinheld

meinheld は奥一穂さんの picoev を利用した Python アプリケーション用の HTTP サーバーです。

listen ソケット以外に、ワーカー間で共有しつつ epoll を利用する fd はないので、 EPOLL_CTL_ADD しているところで無条件に EPOLLEXCLUSIVE してしまいます。

diff --git a/meinheld/server/picoev_epoll.c b/meinheld/server/picoev_epoll.c
index 06e1dbb..773cf3c 100644
--- a/meinheld/server/picoev_epoll.c
+++ b/meinheld/server/picoev_epoll.c
@@ -115,6 +115,7 @@ int picoev_update_events_internal(picoev_loop* _loop, int fd, int events)
     SET(EPOLL_CTL_MOD, 0);
     if (epoll_ret != 0) {
       assert(errno == ENOENT);
+      ev.events |= (1 << 28);  // EPOLLEXCLUSIVE (from linux 4.5)
       SET(EPOLL_CTL_ADD, 1);
     }
   }
@@ -124,7 +125,12 @@ int picoev_update_events_internal(picoev_loop* _loop, int fd, int events)
   if ((events & PICOEV_READWRITE) == 0) {
     SET(EPOLL_CTL_DEL, 1);
   } else {
-    SET(target->events == 0 ? EPOLL_CTL_ADD : EPOLL_CTL_MOD, 1);
+    if (target->events == 0) {
+      ev.events |= (1 << 28);  // EPOLLEXCLUSIVE (from linux 4.5)
+      SET(EPOLL_CTL_ADD, 1);
+    } else {
+      SET(EPOLL_CTL_MOD, 1);
+    }
   }

 #endif

試験に使っていたのは AWS の c4.xlarge で、4コアなので、8ワーカー起動し、 "hello, world" を返すだけのアプリに ab で4並列で負荷をかけてみました。 (wrk ではなく ab を使ったのは、今回は keep-alive しない試験だったからです。)

結果は、改造前がだいたい 15k req/sec で、 改造後がだいたい 20k req/sec を超えるくらいでした。

uWSGI

Python だけでなくいろんな言語に対応している uWSGI というサーバーでも試してみました。 epoll に追加する関数が read と write で別れているので、accept で利用する read 側にだけ EPOLLEXCLUSIVE を追加します。

diff --git a/core/event.c b/core/event.c
index 36751a6..32a1934 100644
--- a/core/event.c
+++ b/core/event.c
@@ -514,7 +514,7 @@ int event_queue_add_fd_read(int eq, int fd) {
        struct epoll_event ee;

        memset(&ee, 0, sizeof(struct epoll_event));
-       ee.events = EPOLLIN;
+       ee.events = EPOLLIN | (1 << 28);
        ee.data.fd = fd;

        if (epoll_ctl(eq, EPOLL_CTL_ADD, fd, &ee)) {

こちらもだいたい meinheld と同じような数値 (15k req/sec -> 20+k req/sec) で性能向上を確認できました。

また、1並列で ab を実行したときの accept の回数を、 strace で確認してみました。

ubuntu:~/app$ strace -f ~/.local/bin/uwsgi --master --workers=8 --http-socket :8080 --wsgi hello 2>trace.log
ubuntu:~$ ab -c1 -n1000 http://localhost:8080/  # 別セッションから
ubuntu:~/app$ grep -c '] accept4' trace.log  # 改造前
6884
ubuntu:~/app$ grep -c '] accept4' trace.log   # 改造後
1557

改造前は 6884 回ですが、これは 8 プロセスのうち accept に成功した 1 プロセスが、レスポンスを返してから epoll し直している間に、他のプロセスが次のリクエストを accept しているから、7000回弱になっているのでしょう。

一方改造後は 1557 回になっていて、リクエストの回数の約 1.5 倍になっています。 man に書いてあるとおり、必ずしも1つのイベントに対して1つの epoll だけが起こされるわけではなく、複数の epoll が起こされる場合があるのだと思います。

雑感

meinheld を strace していて気づいたのですが、 thundering herd 問題が起きている状況で multi accept (1度 epoll が起きたときに、 accept を1度だけでなく、エラーが出るまで複数回実行する) をすると、「起こされたのにすることがない」状況が発生しやすくなります。

keep-alive に対応しないシンプルなアプリケーション・サーバーなら、レスポンスを返したあと次にすることがなので、「自分(レスポンスを返したばかりのプロセス)が寝るか、他人(起こされたばかり)が寝るか」の違いでしかありません。自分で実行したほうが、コンテキストスイッチを待たずに処理を始められるので、ベンチマークスコアは上がると思います。 一方、 keep-alive に対応していたり、 nginx のようにいろんな処理を行う場合は、 multi accept を無効化した方が綺麗にコネクションを分散させることができて良いかもしれません。

あと、今回はかなり雑な感じに EPOLLEXCLUSIVE 対応したのですが、古いディストリビューションを使いつつもカーネルをアップグレードすることはよくあるので、 #ifdef EPOLLEXCLUSIVE せずに、今回のような強引な方法で対応するのは意外と現実的な気がします。 実際、 xenial の標準のカーネル (Linux 4.4) で EPOLLEXCLUSIVE を有効にしても、 epoll_ctl がエラーを返すこともなく普通に動作しました。


@methane


songofacandy at 15:58
この記事のURLComments(0)TrackBack(0)kernel | network
このブログについて
DSASとは、KLab が構築し運用しているコンテンツサービス用のLinuxベースのインフラです。現在7ヶ所のデータセンタにて構築し、運用していますが、我々はDSASをより使いやすく、より安全に、そしてより省力で運用できることを目指して、日々改良に勤しんでいます。
このブログでは、そんな DSAS で使っている技術の紹介や、実験してみた結果の報告、トラブルに巻き込まれた時の経験談など、広く深く、色々な話題を織りまぜて紹介していきたいと思います。
KLabについて
KLab株式会社は、信頼性の高いクラウドサービス、ソフトウェアパッケージ、自社で企画・開発したソーシャルアプリやデジタルコンテンツを提供しています。
Blog内検索
最新コメント
最新トラックバック
Archives
Syndicate this site