トラブルシューティングの極意―達人に訊く問題解決のヒント

第4回[サーバ・インフラ・ネットワーク編]サポート観点から見た―トラブル時の情報収集法

今回は、トラブルシューティングにおいて適切な情報収集の重要性を具体例から考えます。トラブルシューティングでは、誤った方向を向いて対応を実施しないためにも正しく問題を定義する必要があります。正しく問題を定義するためには、簡単に言えば「事象」という形のはっきりしないものを手にしているツールを利用し、⁠その形を明らかにすること」が必要となります。筆者の日常業務であるRHELのサポートに寄せられる実際の問い合わせを具体例に、どのような情報収集の方法が有用なのかということを紹介します。

トラシュー事例(初級編)
「XX月YY日にシステムが予期せぬ再起動をしました。原因調査をしてください」

上記のような問い合わせについて、みなさんだったらどのような仮説が考えられるでしょうか。筆者が簡単に推測できる内容でも次のような要素が考えられます。

  • ハードウェア
  • アプリケーション
  • ユーザによる操作
  • カーネルパニック

このような問い合わせ内容の場合、具体的に収集することが望ましい情報というのは、上記の要素だけでもさまざまな種類のログやコマンド結果が必要となります。また情報収集は事象が発生している最中の情報収集が最も有用ですが、今回のような事象ではそれは望めません。ですから事象発生後に確認できる情報からみていきます。

情報収集の初期段階では、メッセージ、ログは、必ず一度に網羅的に収集することを心がけてください。これは、時間が経過するにつれて消失する情報があることや、さまざまな情報を簡単に確認できることが調査を進めるうえで非常に有効であるためです。Red Hat Enterprise Linux(以下、RHEL)では、一度に幅広い情報を手軽に収集を行うことを実現するツールとしてsosreportがあります。

sosreportとは

sosreportは、RHELの基本的なコマンドの結果や、サービスのログを収集するツールです。sosパッケージにて提供されており、ツールそのものはPythonで記述され、収集する情報の種類ごとにスクリプトがわかれています。具体的なファイル構成については、rpm -ql sosを実行し、確認してみてください。

sosreportの構造

収集したsosreportは図1のようになっています。一般的に確認することが多いディレクトリについて紹介しています。この図から、sosreportがさまざまな情報を収集することがわかると思います。

図1 sosreportの構造(代表的なもの)
.
├── boot /boot 配下の設定ファイルを収めている
├── etc /etc 配下の設定ファイルを収めている
├── proc /proc ファイルシステム配下から収集した情報を収めている
├── root /root 配下の収集したファイルを収めている
├── sos_commands 各スクリプトで実行したコマンドの実行結果をスクリプトごとに収めている
│   ├── autofs
│   ├── bootloader
│   ├── crontab
├── sys /sys ファイルシステム配下から収集した情報を収めている
└── var /var/ 配下のログなどを収めている
     ├── crash kdumpで取得されたvmcoreのデフォルトの保存先で、vmcore-dmesg.txtを配置している
     └── log 収集した一般的なログを収めている

soreportを使って調査してみよう

取得したsosreportから、今回の事象について調査をしてみましょう。ここでは、カーネルパニックが発生したという仮説の検証を行います。以降の本稿で取り上げる実機の情報は、RHEL6.6のインストールメディアを用いて標準インストールを行い、kernelのみ2015年2月10日時点の最新へアップデートした環境において取得したものとなります。

まず、kdumpサービスが正常に起動している環境であるか確認します。サービスの自動起動設定は、sos_commands/startup/chkconfig_--listから確認できます。図2からkdumpサービスが自動起動する設定であることがわかります。

図2 chkconfigの確認結果
$ cat sos_commands/startup/chkconfig_--list ¦grep kdump
kdump           0:off 1:off 2:on 3:on 4:on 5:on 6:off

次に事象が発生した日時の直前のシステムログ(messages)から、kdumpサービスが正常に起動していることを確認します。

図3から、事象発生当時のシステムでは、kdumpサービスは正常に起動していたと考えられます。kdumpサービスによって今回の事象が発生していた場合には、vmcore(システム全体のメモリイメージ)が取得されていることが期待されます。vmcoreの出力先や、kdumpの挙動については、/etc/kdump.confにて設定します。

図3 kdumpサービスの起動ログ
Feb 11 11:08:12 localhost kdump: kexec: loaded kdump kernel
Feb 11 11:08:12 localhost kdump: started up

保存先を指定するpathオプションを確認すると図4から保存先は/var/crashに指定されていることがわかります。ほかのオプションについては「man 5 kdump.conf」を参照してみてください。

図4 /etc/kdump.confの設定内容
$ cat etc/kdump.conf ¦ grep -v ^# ¦ grep -v ^[[:space:]]*$
path /var/crash
core_collector makedumpfile -c --message-level 1 -d 31

vmcoreが保存されている場合には、その取得したホスト名と、取得日時でディレクトリが作成され、そこに、vmcoreならびにvmcoredmesg.txtというvmcoreに含まれているkernelのリングバッファを出力したものが保存されます。RHEL6.6に同梱されているsosパッケージは、/var/crash配下にvmcore-dmesg.txtがある場合には、それを収集するようにスクリプトが作られていますので、sosreport内の「var/crash/<hostname>-<取得日付>」配下のvmcoredmesg.txtの内容を確認します。vmcore-dmesg.txtはファイルの最後尾に、カーネルパニックが発生した際の内容を記録していますので、まずそちらを確認するようにしてください。今回のケースでは、リスト1のような内容が記録されています。

リスト1 vmcore-dmesg.txtの最後尾の内容
<0>Uhhuh. NMI received for unknown reason 30 on CPU 0.
<0>Do you have a strange power saving mode enabled?
<0>Kernel panic - not syncing: NMI: Not continuing
<4>Pid: 0, comm: swapper Not tainted 2.6.32-504.8.1.el6.x86_64 #1
<4>Call Trace:
<4> <NMI> [<ffffffff815292d6>] ? panic+0xa7/0x16f
<4> [<ffffffff8152dec9>] ? do_nmi+0x329/0x340
<4> [<ffffffff8152d620>] ? nmi+0x20/0x30
<4> [<ffffffff81040f8b>] ? native_safe_halt+0xb/0x10
<4> <<EOE>> [<ffffffff810167ad>] ? default_idle+0x4d/0xb0
<4> [<ffffffff81009fc6>] ? cpu_idle+0xb6/0x110
<4> [<ffffffff8151061a>] ? rest_init+0x7a/0x80
<4> [<ffffffff81c29f8f>] ? start_kernel+0x424/0x430
<4> [<ffffffff81c2933a>] ? x86_64_start_reservations+0x125/0x129
<4> [<ffffffff81c29453>] ? x86_64_start_kernel+0x115/0x124

この内容から、今回の予期せぬ再起動は、カーネルパニックによってkdumpサービスが動作したことによって発生したことがわかります。

今回は、情報収集の方法についてRHELに塔載されている網羅的な情報収集ツール、sosreportを利用し、そこから実際の事象についての有用な情報をさまざまな視点から確認できることを示しました。このように、1つのツールを利用することで、気軽にさまざまな視点の情報を確認できるというのはsosreportの大きなメリットです。みなさんもトラブルシューティングの初動にはぜひ、sosreportを取得してさまざまな視点から取得された情報から事象を観察してみてください。


ここからは一歩進んだ情報収集について、具体例から紹介していきたいと思います。

トラシュー事例(上級編①)
「過去のパフォーマンス問題について調査したい」

過去のパフォーマンス問題について調査したい場合には、前提条件として、事象発生前から継続してパフォーマンスデータを取得していることが必要となります。RHELではそのような用途に利用できる、sysstatパッケージを用意しています。

sysstatパッケージに含まれるsarは、広い範囲に渡るシステムの稼働情報を取得し記録します。sysstatサービスが起動している場合には、デフォルトで10分おきに取得しています。データは、/var/log/sa配下に保存され、1日が経過するごとにバイナリ(saXX)をテキスト(sarXX)に変換しています。

注意する点としては、バイナリデータはsarのバージョン間で互換性がないこと、また、sarは一定期間経過するとファイルがローテートしますので、sosreportを利用するなどして事象発生後、少なくとも1週間以内に取得することが推奨されます。図5は、sarに記録されているCPU使用率の例となります。

図5 sarの出力結果(CPU使用率)
Linux 2.6.32-504.8.1.el6.x86_64 (localhost.localdomain)    2015-02-09    _x86_64_    (1 CPU)

08:38:45 PM     LINUX RESTART

08:40:01 PM   CPU   %usr   %nice   %sys  %iowait  %steal   %irq  %soft  %guest   %idle
08:50:01 PM   all   0.52    0.00   0.09     2.54    0.01   0.00   0.00    0.00   96.84
08:50:01 PM     0   0.52    0.00   0.09     2.54    0.01   0.00   0.00    0.00   96.84
09:00:01 PM   all   0.02    0.00   0.08     0.50    0.01   0.00   0.00    0.00   99.40
09:00:01 PM     0   0.02    0.00   0.08     0.50    0.01   0.00   0.00    0.00   99.40
09:10:01 PM   all   0.23    0.00   0.31     1.09    0.03   0.00   0.00    0.00   98.33
09:10:01 PM     0   0.23    0.00   0.31     1.09    0.03   0.00   0.00    0.00   98.33
(...省略...)

このようにsarの情報から過去のシステムの稼動状況を確認することができます。今回紹介したCPU使用率以外にも、メモリ、スワップ、ディスク、ネットワーク、ロードアベレージなどの観点から調査できます。詳しくは、man1 sarを参照してください。

トラシュー事例(上級編②)
「システムがハングした」

このような状況のトラブルシューティングで有用となる情報は、その事象が発生している最中に取得されたvmcoreとなります。システムハングの場合、ログやシステムの稼働情報なども正常に取得できていないことが多く、事象が発生している状況で取得されたvmcore以外で調査できないためです。

vmcoreについては、前節で触れたkdumpサービスを利用します。注意する点としては、kdumpサービスを起動しただけでは、カーネルパニックには対処できますが、システムがハングしたという事象には対応できないことです。よってほかの方法でシステムがハングしている最中に意図的にカーネルパニックさせる必要があります。そのために、表1のカーネルパラメータを利用します。

表1 カーネルパニックさせるパラメータ
パラメータ内容
①kernel.softlockup_panicsoft lockupを検出した際にパニックさせる
②kernel.hung_task_panichung taskを検出した際にパニックさせる
③vm.panic_on_oomOut of Memoryを検出した際にパニックさせる
④kernel.sysrqSysrqファシリティの有効化
⑤kernel.unknown_nmi_panicハードウェアからのNMIを検出した際にパニックさせる
⑥kernel.panic_on_unrecovered_nmiハードウェアからのNMIを検出した際にパニックさせる
⑦kernel.panic_on_io_nmiハードウェアからのNMIを検出した際にパニックさせる

それぞれ(1:有効、0:無効)

①~③は、カーネル側で検出できるプロセスの状態から自動的にパニックさせるパラメータです。それぞれ次のような状態を示します。①のsoft lockupはプロセスがCPUを長時間占有している状態を指します。②のhung taskは、プロセスが長時間割り込み不可の待ち状態であることを指します。③のOut of Memoryはメモリ枯渇の状態を指します。

④については、Sysrqファシリティ(特殊なキーコンビネーション、⁠Alt][SYSREQ]+<command>)の有効化です。Sysrqファシリティを有効化している場合には、⁠Alt][SYSREQ][C]にてシステムをクラッシュさせることができます。

⑤~⑦はハードウェアによって、どのNMIを手動で発行できるかということは異なりますので、ハードウェアの実装に従って設定してください。

筆者のお勧めは、④と⑤~⑦の中から利用できるものを設定することです。理由は、任意のタイミングで手動でパニックさせられるためです。紹介したカーネルパラメータの設定は、/etc/sysctl.confで行います。

vmcoreの解析にはcrashユーティリティを利用しますが、誌面の関係上、参考文献の紹介に留めます。


本稿では、情報収集という観点からトラブルシューティングの際に利用できる手法を紹介してきました。ここで紹介したパッケージや設定を必須のものとして、よりよいシステム設計に役立てていただければと思います。

Software Design

本誌最新号をチェック!
Software Design 2022年9月号

2022年8月18日発売
B5判/192ページ
定価1,342円
(本体1,220円+税10%)

  • 第1特集
    MySQL アプリ開発者の必修5科目
    不意なトラブルに困らないためのRDB基礎知識
  • 第2特集
    「知りたい」⁠使いたい」⁠発信したい」をかなえる
    OSSソースコードリーディングのススメ
  • 特別企画
    企業のシステムを支えるOSとエコシステムの全貌
    [特別企画]Red Hat Enterprise Linux 9最新ガイド
  • 短期連載
    今さら聞けないSSH
    [前編]リモートログインとコマンドの実行
  • 短期連載
    MySQLで学ぶ文字コード
    [最終回]文字コードのハマりどころTips集
  • 短期連載
    新生「Ansible」徹底解説
    [4]Playbookの実行環境(基礎編)

おすすめ記事

記事・ニュース一覧