株式会社クリアコード > ククログ

ククログ

«全文検索エンジンgroongaを囲む夕べ 2: 「groonga村」と「mroongaのベンチマーク」用資料 最新 Ruby関連のコンテストっぽいものへの応募例»
タグ:

デバッグ力: よく知らないプログラムの直し方

クリアコードではMozilla製品やRuby関連の開発だけではなく、広くフリーソフトウェアのサポートもしています。もちろん、サポート対象のソフトウェアの多くは私達が開発したものではありません。しかし、それらのソフトウェアに問題があった場合は調査し、必要であれば修正しています。

このようなサポートが提供できるのは、もともと、私達がフリーソフトウェアを利用したり開発したりしているときに日常的に問題の調査・修正をしていたからです。ソフトウェアを利用していると、問題に遭遇することはよくあることです。そのソフトウェアがフリーソフトウェアの場合は、開発者に問題を報告し、可能ならパッチを添えます。このとき、そのソフトウェアの内容を完全に把握していることはほとんどありません。しかし、それでも修正することができます。

それはどうしてでしょうか?今まではどのようにやっているのかを自分達でもうまく説明できなかったのですが、最近、少し説明できるようになってきた気がするのでその方法を紹介します。題材はruby-trunk - Bug #5688: Solaris10 で spawn を繰り返すとメモリリークする - Ruby Issue Tracking Systemです。この問題はメモリリークなので、プログラムを動かし続けてもメモリ使用量が増えなくなれば解決ということになります。

基本的な流れ

まず、よく知らないプログラムをデバッグするときの流れを整理してみました。整理してみると、以下のような流れで作業をしていました。

  1. 問題を再現する小さなプログラムを作成する。
  2. 問題のソフトウェアを変更しながら原因となっている箇所を特定する。
  3. 問題を修正する。

問題を再現する小さなプログラムの作成

問題が発覚するときは問題のある処理と問題のない処理が混ざっていますが、この状態のままで修正作業に着手するのは現実的ではありません。例えば、問題が再現するまでに時間がかかる・問題を再現させることが面倒・調査対象の範囲が広くなってしまう、などといった理由で修正作業が大変になってしまいます。ですのでこのような時は、問題が再現する必要最低限の条件(再現条件、再現手順*1)をなるべく正確に特定しておく事が大事です。

また、再現条件はプログラムやスクリプト、自動テストなどのような形で、誰がやっても何度でも正確に問題を再現できるという状態にしておく事が望ましいです*2。今回はRubyそのものの問題の調査なので、自動化された再現手順として、問題を再現する小さなプログラムを作成する事にしました。

この時点では、あくまでもソフトウェアの外から見るという視点で問題をざっくりと切り分けていきます。今回の例の問題に遭遇したときは、同じような処理を実行するRubyスクリプトをいくつか動かしていたときでした。その中の一部のRubyスクリプトではメモリ使用量が増えていき、それ以外のRubyスクリプトではメモリ使用量が増えませんでした。そこで、それらの違いを抽出して、Redmineにある以下のような外部プロセスを実行するだけのRubyスクリプトを作成しました。

1
2
3
4
5
6
#!/usr/bin/env ruby
ARGV[0].to_i.times do |n|
  spawn("sleep", "5")
  sleep 0.2
  GC.start if n % 100 == 0
end

これでも問題が再現したため、原因はRubyのspawn内にあると考えることができます。このように、十分小さな再現プログラムを作成できたら次のステップに進みます。*3

問題のソフトウェアを変更して原因となっている箇所を特定

再現プログラムができたら、問題となっているソフトウェアについてあたりをつけることができます。今回の例では、ライブラリを使っているわけではないので、Ruby本体が怪しいと言えます。

再現プログラムでは、外から問題の原因を絞り込んでいましたが、このステップでは、中から絞り込んでいきます。今回の例では、forkの実体であるrb_fork_err()の中が絞り込み対象です。rb_fork_err()を簡略化すると以下のようになっています。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
rb_pid_t
rb_fork_err(...)
{
    rb_pid_t pid;

    for (; before_fork(), (pid = fork()) < 0; prefork()) {
        ...;
    }
    if (!pid) {
        ...; /* 子プロセス用の処理 */
    }
    after_fork();
    return pid;
}

このうち、「for (...) {...}」は「forkに失敗しても何回か試してみる」という処理なのでさらに簡略化して以下のように考えることができます。

1
2
3
4
5
6
7
8
9
10
11
12
13
rb_pid_t
rb_fork_err(...)
{
    rb_pid_t pid;

    before_fork();
    pid = fork();
    if (!pid) {
        ...; /* 子プロセス用の処理 */
    }
    after_fork();
    return pid;
}

ここで、どこが原因の切り分けポイントになるかを考えます。まず、上記の処理の中を大きく分けると以下のようになります。

  1. before_fork()
  2. fork()
  3. if (!pid) {...}
  4. after_fork()

このうち、「if (!pid) {...}」は子プロセス専用の処理なので今回は考えなくてもよいことがわかります。なぜなら、今回の再現プログラムでは親プロセスのメモリ使用量が増えることを問題視していて、子プロセスに関しては気にしていないからです。すると以下が問題の切り分けポイントになることがわかります。

  1. 何も実行しなかったらどうなるか。
  2. before_fork()のみ実行したらどうなるか。
  3. before_fork()fork()のみ実行したらどうなるか。

それぞれの結果で以下のようなことがわかります。

試すこと メモリリークした場合 メモリリークしなかった場合
何もせずにすぐにreturn rb_fork_err()の前に原因あり。(今回はこのケースはないはず。) before_fork()fork()after_fork()に原因あり。
before_fork()の後にすぐにreturn before_fork()の中に原因あり。 fork()after_fork()に原因あり。
fork()の後にすぐにreturn fork()の中に原因あり。(fork()はOSが提供しているので、今回はこのケースはないはず。) after_fork()に原因あり。

それぞれを試すコードは以下のようになります。

何もせずにreturn:

1
2
3
4
5
rb_pid_t
rb_fork_err(...)
{
    return -1;
}

before_fork()の後にすぐにreturn:

1
2
3
4
5
6
rb_pid_t
rb_fork_err(...)
{
    before_fork();
    return -1;
}

fork()の後にすぐにreturn:

1
2
3
4
5
6
7
8
9
10
11
12
rb_pid_t
rb_fork_err(...)
{
    rb_pid_t pid;

    before_fork();
    pid = fork();
    if (!pid) {
       _exit(EXIT_FAILURE); /* 子プロセスは気にしないのですぐ終了する。 */
    }
    return pid;
}

実際に試すと以下のことがわかりました。

試すこと メモリリークしたか
何もせずにすぐにreturn しない
before_fork()の後にすぐにreturn しない
fork()の後にすぐにreturn しない

よって、after_fork()の中に問題があることがわかります。

続いて、上記の手順と同様にafter_fork()の中を調べ、原因を絞り込んでいくことを繰り返すと、rb_thread_create_timer_thread()の中のpthread_attr_tに原因があることがわかります。ここで大事なことは「上記の手順と同様に…繰り返す」という部分です。少し原因を絞り込めたからといって、一足飛びに手順を飛ばして原因を見つけようとすると迷子になってしまいます。十分に絞り込めるまではコツコツと一歩ずつ確実に原因を絞り込んでいくことが重要です。さくさくとデバッグを進めていく様子だけを見ると、手順を飛ばして一気に問題を解決しているように見えるかもしれませんが、そんなことはありません。一歩ずつ確実に進めています。ただ、その一歩ずつがテキパキと手早く進んでいるだけなのです。

原因を十分に絞り込めたら問題を修正します。

問題の修正

今回の例では、原因を絞り込むとpthread_attr_tを使った場合のみメモリ使用量が増えることがわかりました。簡略化すると以下のように使用していました。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
static void
rb_thread_create_timer_thread(void)
{
    ...;
    if (!timer_thread_id) {
        pthread_attr_t attr;
        ...;
        pthread_attr_init(&attr);
        ...;
        err = pthread_create(&timer_thread_id, &attr, thread_timer, 0);
        ...;
    }
    ...;
}

同じソースコード内のpthread_attr_tの他の使用例を見ると、以下のようになっています。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
static int
native_thread_create(rb_thread_t *th)
{
    ...;
    else {
        pthread_attr_t attr;
        ...;
        CHECK_ERR(pthread_attr_init(&attr));
        ...;
        err = pthread_create(&th->thread_id, &attr, thread_start_func_1, th);
        ...;
        CHECK_ERR(pthread_attr_destroy(&attr));
        ...;
    }
    ...;
}

違いはpthread_attr_destroy()を呼んでいるかいないかです。pthread_attr_destroy()は名前からして必要のなくなったリソースを解放する関数にみえるので、rb_thread_create_timer_thread()pthread_attr_destroy()を呼び忘れていることが原因と考えてよさそうです。実際にpthread_attr_destroy()を追加して再現プログラムを実行するとメモリ使用量が増えなくなることが確認できました。これで修正できたと考えてよさそうです。ということで、パッチができあがることになります。

まとめ

Rubyでのメモリリークの問題を例にして、私達がやっている「よく知らないプログラムの直し方」を説明しました。今回のような直し方では「それぞれのコードがどうしてそのようなコードになっているのか」という点はほとんど考慮にいれていません。単純に「その処理を実行したら問題が再現するかどうか」だけで絞り込んでいます。そのため、プログラム全体を把握する必要がなくなり、よく知らないプログラムに対しても使える技術になっています。もちろん、この技術はよく知っているプログラムに対しても使えます。

おさらいすると、プログラムの直し方は以下のステップになります。

  1. 問題を再現する小さなプログラムを作成する。
  2. 問題のソフトウェアを変更しながら原因となっている箇所を特定する。
  3. 問題を修正する。

このうち、「問題を再現する小さなプログラムを作成する」ことはよく聞くのではないでしょうか。バクレポートを報告する文脈でも、「再現プログラムをつけてくれるとうれしい」というのはよく言われます。しかし、「問題のソフトウェアを変更しながら原因となっている箇所を特定する」についてはあまり言及されていないようです。今回は処理を実行するかどうかで判断する方法を使いましたが、print文を埋め込んだり、デバッガを使ったりすることもあります。これらは場合によって使い分けます。それらのやり方よりも大事なことは、「この結果で何がわかるか」を意識しながら一歩一歩着実に原因を絞り込んでいくことです。多くの場合、原因がわかったら修正することはそれほど難しいことではありません。

たとえよく知らないプログラムでも、問題を見つけたときはその問題を直す人が増えることを願っています。華麗に回避することもできるでしょうが、次に同じ道を進んできた人が同じ問題にぶつからずにすんだらステキではないでしょうか。

*1 Steps To Reproduce、略してSTRと言われる事もあります。

*2 言葉で再現条件を説明した場合、読み違いが原因で、人によっては問題を再現できないといった事が起こり得ます。また、デバッグ中に何度も再現試験を実施する際に、ヒューマンエラーで再現手順を間違えてしまうという事もあり得ます。

*3 この後にforkしてすぐにexitするだけでも問題が再現するところまで再現プログラムを小さくしていました。そのため、実際は、次のステップに進む前にspawnというよりもfork内に原因があるということまで絞り込めていました。

2011-12-06

«全文検索エンジンgroongaを囲む夕べ 2: 「groonga村」と「mroongaのベンチマーク」用資料 最新 Ruby関連のコンテストっぽいものへの応募例»
2008|05|06|07|08|09|10|11|12|
2009|01|02|03|04|05|06|07|08|09|10|11|12|
2010|01|02|03|04|05|06|07|08|09|10|11|12|
2011|01|02|03|04|05|06|07|08|09|10|11|12|
2012|01|02|03|04|05|06|07|08|09|10|11|12|
2013|01|02|03|04|05|06|07|08|09|10|11|12|
2014|01|02|03|04|05|06|07|08|09|10|11|12|
2015|01|02|03|04|05|06|07|08|09|10|11|12|
2016|01|02|03|04|05|06|07|08|09|10|11|12|
2017|01|02|03|04|05|06|07|08|09|10|11|12|
タグ: