止まる,性能が出ない…システム開発に携わる人なら誰もがぶつかった経験のあるトラブルでしょう。特に,通常は問題がないのに,負荷が高くなったり,長時間連続稼働した時にだけ発生するトラブル,さらにどういった場合に発生するのかわからないトラブルはやっかいです。

 でも,原因を突き止める方法はあります。この連載では,そういったトラブルをタカハシくんとスズキさんの2人といっしょに解決していきましょう。

 タカハシくんは,IT企業の若手エンジニア。元気はあるのですが,おっちょこちょいなのが欠点です。LinuxでC言語やJavaを使った開発には少し自信が出てきましたが,トラブルがあるとなかなか原因がわからず,先輩のスズキさんに教えを請う毎日です。スズキさんはこの道ン十年,汎用機でのアプリケーション開発の経験もあるベテラン・エンジニアです。

 第1回目は,高負荷時にアプリケーションが異常終了するというトラブルです。トレーサやデバッガを用いて解析する方法を紹介します。

 それでは,タカハシくんとスズキさんにご登場いただきましょう。

タ: うーん,なんで落ちるんだ?ぶつぶつ...
ス: どうかしたの?
タ: あ,スズキさん。今度A社に納入予定のシステムのアプリケーションなんですが,時々異常終了するんですよ。
ス: あらあら。そりゃ困ったね。何かエラーメッセージは出ているの?
タ: いえ,出ていないですね。
ス: そうか,大変そうだね。あ,もう会議の時間だ。まぁ,もう少し自力で頑張ってみてよ。

そして数日が過ぎ...

ス: どう,例の問題は解決した?
タ: いえ,それがまだ...
ス: どこまで解析が進んでいるの?
タ: 負荷を高くすると,再現するということが分かった程度です。
オープンソースのアプリケーションなので,最新版もダウンロードして試してみたんですが,解決しませんでした。助けて下さいよ~。
ス: トレーサは使ってみた?
タ: いえ。何ですか,それ?
ス: プログラムがどの順番で何を実行しているかを追跡して表示するものだよ。
Linuxでは,システムコールを追跡するstraceと,ライブラリコールを追跡するltraceが有名だな。
とりあえずltraceを使って,どのライブラリコールで落ちているか,確認しよう。
タ: ltraceですね。どうやって使うんですか?
ス: 何か分からなければ,取りあえずmanしてみる!
タ: は,はい。(とmanで確認する)

リスト1●ltraceの使い方

ltrace [option ...] [command [arg ...]]             
                                                    
代表的なオプションとして,下記がある。              
 ・-f:       子プロセスの挙動もあわせてトレースする  
 ・-o fname: トレース結果をファイルに保存する      
 ・-S:       システムコールも表示する              
 ・-t:       タイムスタンプも表示する              
 ・-p PID:   実行中のプログラムをトレースする      

タ: 色々とオプションがあるみたいですけど,基本的には「ltrace コマンド名」で行けそうですね。それ!(と実行する)
で,負荷を高めに設定して,と...あっ落ちましたよ!

リスト2●トレース結果画面

$ ltrace mem_app                                    
 :(省略)                                          
5421 sleep(1)                                   = 0 
5421 malloc(10485760)                           = 0x927b3008
5421 printf("%u\tmsg-out: %d\n", 59, 10485760)  = 22
5421 sleep(1)                                   = 0 
5421 malloc(10485760)                           = NULL      
5421 --- SIGSEGV (Segmentation fault) ---           
5421 +++ killed by SIGSEGV +++                      

タ: 最後は,セグメンテーション違反()で終了しているのが分かりますね。
セグメンテーション違反とは: プログラムが許容範囲外のメモリーを使用した場合に発生する障害。そのような行儀の悪いプログラムは,OSによって強制終了させられる。
ス: その前方のライブラリコールに着目して,何か異常が起こっていないか確認してみよう。
タ: うーん,特に何かあるようには見えないんですけど...
ス: いや,良く見るとmallocが何度か呼ばれているけと,最後のmallocだけNULLを返しているよ。
タ: あ,本当だ。
ス: 高負荷の影響で,メモリー確保に失敗している可能性があるね。メモリー確保の失敗を考慮したプログラムかどうか,ソースコードを見て確認した方が良いね。
タ: はい,確認してみます。mallocを呼んでいる所を検索して,と...

リスト3●ソースコード抜粋

  #define SIZE		(10 * 1024 * 1024)        
  #define MAX_BUF_SIZE	(64 * 1024)               
  :(省略)                                         
	p = malloc(SIZE); ---(1)
	for (i = 0; i < SIZE; i++)                        
		p[i] = 'a';
  :(省略)                                         
	p = malloc(MAX_BUF_SIZE); ---(2)
	for (writes = 0; writes < MAX_BUF_SIZE; writes += cnt) { 
		cnt = read(f, buf, size);                 
		if (cnt == 0)                             
			return 1;                         
		else if (cnt < 0)                         
			return 0;                         
		memcpy(p + writes, buf, cnt);             
	}                                                 
  :(省略)                                         

タ: mallocをコールしている箇所が複数((1),(2))ありますね。うーん,どちらが問題の箇所なんだろう?
ス: 引き数の値や,前後の関数呼び出しなどを,トレース結果と比較して切り分けると良いよ。
タ: トレース結果だと,失敗しているmallocの引き数は約10Mバイトですね。それとマッチする箇所は... (1)の箇所ですね。
タ: mallocの戻り値をどう使っている?
ス: そのまま,データを書いていますね。
ス: メモリー負荷が高くなって,mallocがエラーでNULLを返した場合は...
タ: 0番地に書き込んでしまって,セグメンテーション違反になりますね!
なるほど,負荷が高い時に発生するという現象と,辻褄が合いますね。
エラー処理が抜けているのですね。
ス: 問題の原因が解明できたね。ところで,コアファイルは出力されてなかったの?
タ: すみません,コアファイルって何ですか?