プログラムの事とか

お約束ですが「掲載内容は私個人の見解です」

トラブルシューティングゲーム

今回は実際に実務行った調査の流れをざっくりと書いてみようとおもいます

実務なので詳細は書けませんが(関係者にこのブログを捕捉される恐れもあるし)、私はこんな感じで原因を探したよというメモ的なやつ(今回の調査で新しい知識も得たので)

このブログが誰かの助けになったらさいわいです

構成

サーバー+クライアントの2台構成で、サーバーには常時起動のサービスが複数とWebアプリ(IIS)

サーバーにはそれ以外に他社製の何かも入っている模様

サーバーOSもハードも不明(OSはたぶんServer 2016、ハードは小さい奴らしい)

クライアントPCは今回関係ないので割愛

第一報

サーバーが応答しない

常駐アプリを作っている人でこんな報告が来た時に「私は悪くない」といえる人が世の中に何人いるでしょうか?

テスト環境でいくらヒートランしてもしょせんテスト環境だからね、実環境では何が起こるかわからないよね

続報

  • サーバーへのPINGも失敗

ということでサーバーがOSごと落ちているっぽいです

  • 数日前にも同様の現象があったらしい

再現性があるのはいいことですね (白目

再現させるよ

実環境ではいろいろなことができないので(納品したものだし)何とかテスト環境で再現させます

といっても私はソフト担当なのでハードの調達とか再現テストとかは全部ほかの人任せ。さっさと再現させてよ~的なスタンスです

可能な限り実環境と同じ条件で動かしたらめでたく再現してくれました。これで調査がはかどるね

まぁ再現しなかったら「気のせいじゃね?」で終わらせるんですが

まずはログを見よう

こんなこともあろうかと私のアプリはちゃんとログを吐いているので収集してもらいます (当たり前)

OSが逝っているのでWindowsのイベントビューアーのログも収集してもらいます

ログを見た

自分で出しているログではネットワーク系のエラーが大量に (redisとかHttpClientとか)。例外の内容はリソース不足

イベントビューアーのシステムログではIISのリサイクルがリソース不足で失敗、がたくさんでて徐々にいろんなのがリソース不足で失敗して最後におなくなりになってました

リソース不足とは

メモリの空きがなくなったかハンドルの空きがなくなったか、どっちかですかね?

最近ハンドル不足って聞かないのでメモリ不足(メモリリーク)の線で調査します

再現する環境ができると数日に1回OSが亡くなるので情報収集もらくちんちんです

パフォーマンスモニタで収集してもらう

とりあえず空きメモリと作ったプロセスの使用メモリと.Net系のメモリのカウンタと、あとは再現させるのだるいのでそれっぽいものいろいろまとめて収集してもらいました

f:id:puni-o:20180511110604j:plain

どんどん減っているのが空きメモリです

右肩上がりなのはGCの回数たち。 空きメモリが少なくなったら必死にGCで空きを作ろうとしているけなげな様子がうかがえます (かわいいやつよ

ということで空きメモリが無くなってOSが止まってしまったことは間違いなさそうです

ところが我々の入れたアプリには空きメモリを食いつぶすほどのメモリを使っているものがいませんでした

スナップショット的な情報が欲しい

パフォーマンスモニタの結果を見ると線形的にメモリが食われているのがわかります

ということである程度動かした状態でシステムの情報を見れば原因が分かるかもしれません

とりあえずリソースモニターのメモリタブの情報をとってもらいました

使途不明メモリ??

全プロセスの使用メモリの合計と使用中メモリの合計が全然合いませんでした。なんだこれ?

ドライバーなんかがリークしてる???という疑惑が出てきたので

technet.microsoft.com

このアプリで情報収集してもらいました (私の環境では落ちて情報取れないんですが、収集したファイルは見ることができるので)

収集したファイルをRamMapで開いてProcessesタブを見てみると・・・

f:id:puni-o:20180511112353j:plain

プロセスがいっぱいあるよぉぉぉぉ~~~~~

上のスクショではcmd.exeがたくさんありますね。数万行cmd.exeが続きます。PIDも普段見ない桁になってますね。楽しいですね

cmd.exeのほかにはPING.exeやRoboCopy.exeなんかもたくさんありました

タスクマネージャーで見てもこんなにたくさんのプロセスはいないので (いたらさすがに気づくよね) いわゆるゾンビプロセスというやつらですね

このへんで担当者から聞いたのですが、batファイルで定期的にコピーやPINGを実行しているらしいです。上のゾンビたちはその残骸ですね。

ゾンビさがし

どうやらゾンビプロセスたちがメモリを食いつぶしていたようですね (一つは20kくらいですが塵も積もれば山となる)

今度はゾンビに関する情報収集です

Zombie Processes are Eating your Memoryrandomascii.wordpress.com

この中ではCreateProcessのハンドル閉じないとリークするよー的なことが書いてあったような無かったような・・

そこで紹介されている

github.com

このプログラムがゾンビを探してくれます。C#で簡潔に書かれているのでわかりやすいです

FindZombieHandles

85013 total zombie processes.
    170014 zombies held by (4)
        49164 zombies of \Device\HarddiskVolume4\Windows\SysWOW64\Robocopy.exe
        49164 zombies of \Device\HarddiskVolume4\Windows\SysWOW64\cmd.exe
        24582 zombies of \Device\HarddiskVolume4\Windows\System32\PING.EXE

わーい、たくさんみつかったよぅ~~

held by (4) はPID 4の人が持っているハンドルで、PID 4はsystemさんですよね・・・

試しに何か立ち上げて終了してみる

メモ帳立ち上げて終了を数十回繰り返すと

48 zombies of \Device\HarddiskVolume5\Windows\System32\notepad.exe

全部残ってる!!!!

あとは任せた

呼吸するだけで太るような状態のシステムで我々はいったい何ができるのだろうか?

ということであとはサポートにぶん投げて終了 (現象が発生するのは特定のハードだけだったので)

自分が原因でないトラブルは他人事っぽい感じで関われるからたのしいね (楽しくない