はじめまして。
スパイダープラス CREの森川です。
24歳でIT業界に入り、出産を経てからは、システム保守やテクニカルサポートといった分野で経験を積んできました。そんな私の最近一番の難題は、仕事のトラブルシュートより難しい、思春期の子どもとのコミュニケーションです。
さて、私の所属するCREチームは、お客様が直面する技術的な課題を解決し、サービスの安定稼働を支えるミッションを元に日々活動しています。メンバーがそれぞれ異なる強みを持ってるため、一人では解決が困難な問題も、チームとして連携することで乗り越える場面が多々あります。このような『チームへ貢献する意識』がその先にいるお客様の課題を解決したいという、自然なモチベーションの源泉になっていると感じています。
1. プロローグ：最初の通報
CREチームが特に腕を試されるのが、「なんか遅いんです」「もう再現はしないのですが…」といった、再現性の低い漠然としたお問い合わせです。
こうした手がかりの少ない課題に対し、私たちはどのようにサーバーと向き合い、原因を紐解いていくのか。本記事では、その調査プロセスを具体的なコマンドと共にご紹介し、読者の皆さんと追体験していきたいと思います。
2. 調査編：Linuxコマンドでサーバーと対話する
ある日、お客様から下記のような至急対応のお問合せが入りました。
- 2025/01/01の13時40分頃に、特定のサーバーでログイン後、現場の全員が画面を開けなかった。(発生日時は仮です)
- 当時カスタマーサポートでも再現し、「ネットワークの変更が検出されました（曖昧）」ようなメッセージが出ていた。
- 2分後には解消されて、以降再現していない。
エラーメッセージの情報があるだけ良い方かもしれません。さっそく調査に入ります。
ステップ1：状況把握とログの初期調査
- サービス全体で同様の事象や類似の問い合わせが発生しているか？ → NO
- 社内で事象発生前後にサーバー設定変更やリリースを行ったか？ → NO
- サーバーログで該当時間にエラーは出ているか？ → YES（申告内容と一致）
grep -E '2025-01-01 13:4.*ネットワーク' [ERROR_LOG_FILENAME] | less
{
"datetime": "2025-01-01 13:40:56.034607+0900",
"level": "INFO",
"subdomain": "[SUBDOMAIN]",
"message": "ネットワークエラーが発生しました。",
"context": {
"ticket_id": "[TICKET_ID]",
"index": 2,
"progress_rate": 83.3
},
"extra": {
"user_id": "",
"access_id": "[ACCESS_ID]",
"process_id": 2973,
"file": "[FILE_PATH]/[FILE_NAME].php",
"line": 399,
"class": "[CLASS_NAME]",
"function": "[FUNCTION_NAME]"
}
}
- syslogでApacheが再起動していることを確認
grep 'Apache' syslog* | less Jan 01 13:40:54 [VM_HOSTNAME] systemd[1]: Stopping LSB: Apache2 web server... Jan 01 13:40:55 [VM_HOSTNAME] apache2[8001]: Stopping web server: apache2. Jan 01 13:40:55 [VM_HOSTNAME] systemd[1]: Starting LSB: Apache2 web server... Jan 01 13:40:56 [VM_HOSTNAME] apache2[8219]: Starting web server: apache2[Sun Jan 01 13:40:56.075203 2025] [so:warn] [pid 8242] AH01574: module rewrite_module is already loaded, skipping Jan 01 13:40:56 [VM_HOSTNAME] apache2[8219]: [Sun Jan 01 13:40:56.075549 2025] [so:warn] [pid 8242] AH01574: module headers_module is already loaded, skipping Jan 01 13:40:56 [VM_HOSTNAME] apache2[8219]: AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using [IP_ADDRESS]. Set the 'ServerName' directive globally to suppress this message Jan 01 13:40:57 [VM_HOSTNAME] apache2[8219]: . Jan 01 13:40:57 [VM_HOSTNAME] systemd[1]: Started LSB: Apache2 web server.
これまで確認できた状況は下記です。
- 特定サーバーのみで一時的に発生した事象である
- 社内ではリリースやサーバー設定変更などが行われた告知はない
- 事象が発生していた数分間でApacheが再起動した
- ネットワークエラーが発生している
ステップ2：リソース状況の確認と仮説立て
sarコマンドで、サーバーのリソース状況を確認していきます。
CPU使用率を見ると、お客様から申告のあった13:40頃までは%userが10〜30%台で推移しており、特に異常は見られません。しかし、13:42からCPU使用率が55%まで急上昇しています。これは、13:40のApache再起動後、溜まっていたリクエストを処理するために一時的に負荷が上がったものと推測でき、障害の直接原因ではなさそうです。
# CPU/負荷 sar -u -f [LOG_FILE_PATH]/saDD -s "13:00:00" -e "14:00:00" 13時00分01秒 CPU %user %nice %system %iowait %steal %idle 13時01分01秒 all 9.99 0.00 3.60 3.39 0.00 83.02 13時02分01秒 all 6.04 0.00 2.71 0.89 0.00 90.36 13時03分01秒 all 10.34 0.00 3.89 1.55 0.00 84.22 13時04分01秒 all 11.02 0.00 3.87 0.74 0.00 84.37 13時05分01秒 all 7.56 0.00 3.38 0.94 0.00 88.13 13時06分01秒 all 5.38 0.00 2.93 1.60 0.00 90.09 13時07分01秒 all 5.15 0.00 2.88 0.68 0.00 91.29 13時08分01秒 all 6.94 0.00 3.06 0.27 0.00 89.73 13時09分01秒 all 12.44 0.00 3.64 0.27 0.00 83.65 13時10分01秒 all 10.58 0.00 4.17 0.56 0.00 84.69 13時11分01秒 all 7.59 0.00 3.51 0.99 0.00 87.91 13時12分01秒 all 10.52 0.00 3.51 0.71 0.00 85.27 13時13分01秒 all 8.24 0.00 3.29 0.34 0.00 88.13 13時14分01秒 all 9.16 0.00 3.36 1.39 0.00 86.10 13時15分01秒 all 14.17 0.00 3.87 0.79 0.00 81.17 13時16分01秒 all 13.96 0.00 3.63 0.96 0.00 81.45 13時17分01秒 all 13.26 0.00 3.37 0.73 0.00 82.63 13時18分01秒 all 16.25 0.00 3.62 0.93 0.00 79.20 13時19分01秒 all 11.16 0.00 3.65 0.95 0.00 84.24 13時20分01秒 all 17.70 0.00 4.18 0.81 0.00 77.31 13時21分01秒 all 23.74 0.00 4.71 0.37 0.00 71.18 13時22分01秒 all 31.46 0.00 5.80 2.54 0.00 60.20 13時23分01秒 all 33.03 0.00 5.43 0.77 0.00 60.77 13時24分01秒 all 21.80 0.00 4.77 0.87 0.00 72.56 13時25分01秒 all 19.83 0.00 3.90 0.36 0.00 75.91 13時26分01秒 all 22.30 0.00 4.34 0.55 0.00 72.81 13時27分01秒 all 17.77 0.00 5.39 1.45 0.00 75.40 13時28分01秒 all 11.03 0.00 4.20 0.52 0.00 84.24 13時29分01秒 all 9.01 0.00 2.85 0.17 0.00 87.97 13時30分01秒 all 18.66 0.00 3.80 0.23 0.00 77.31 13時31分01秒 all 15.71 0.00 3.80 0.20 0.00 80.29 13時32分01秒 all 15.37 0.00 4.08 0.22 0.00 80.33 13時33分01秒 all 11.78 0.00 3.79 0.76 0.00 83.67 13時34分01秒 all 12.77 0.00 3.39 0.22 0.00 83.63 13時35分01秒 all 7.12 0.00 3.01 0.20 0.00 89.67 13時36分01秒 all 13.67 0.00 3.70 0.41 0.00 82.23 13時37分01秒 all 13.39 0.00 3.67 0.37 0.00 82.56 13時38分01秒 all 10.40 0.00 3.71 0.48 0.00 85.41 13時39分01秒 all 11.79 0.00 3.59 0.20 0.00 84.43 13時40分01秒 all 11.56 0.00 4.28 0.44 0.00 83.72 13時41分01秒 all 12.76 0.00 3.79 0.59 0.00 82.86 13時42分01秒 all 55.05 0.00 7.89 1.67 0.00 35.40 13時43分01秒 all 49.89 0.00 7.11 1.10 0.00 41.89 13時44分01秒 all 45.31 0.00 6.27 0.92 0.00 47.50 13時45分01秒 all 40.59 0.00 6.29 0.94 0.00 52.18 13時46分01秒 all 28.03 0.00 4.40 0.76 0.00 66.81 13時47分01秒 all 34.08 0.00 5.12 0.52 0.00 60.28 13時48分01秒 all 27.49 0.00 4.29 0.49 0.00 67.73 13時49分01秒 all 26.84 0.00 4.85 0.93 0.00 67.38 13時50分01秒 all 11.01 0.00 3.56 1.37 0.00 84.07 13時51分01秒 all 9.79 0.00 4.13 0.89 0.00 85.19 13時52分01秒 all 9.44 0.00 3.55 0.43 0.00 86.57 13時53分01秒 all 13.42 0.00 4.06 0.44 0.00 82.09 13時54分01秒 all 9.08 0.00 3.52 0.15 0.00 87.26 13時55分01秒 all 9.31 0.00 3.91 0.86 0.00 85.91 13時56分01秒 all 8.92 0.00 3.96 0.34 0.00 86.78 13時57分01秒 all 10.10 0.00 3.67 0.51 0.00 85.72 13時58分01秒 all 11.41 0.00 4.12 1.18 0.00 83.29 13時59分01秒 all 20.26 0.00 4.28 0.23 0.00 75.24 平均値: all 16.48 0.00 4.09 0.76 0.00 78.67
次にメモリ使用率（-r）を見ると、%memusedが常に95%前後と高く見えますが、これはLinuxが積極的にメモリをキャッシュ（kbcached）として利用しているためです。空きメモリ（kbmemfree）が極端に少ないわけではなく、スワップも発生していないため、メモリが逼迫していたとは考えにくい状況です。
# メモリ/スワップ/ページング sar -r -f [LOG_FILE_PATH]/saDD -s "13:00:00" -e "14:00:00" 13時00分01秒 kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit kbactive kbinact kbdirty 13時01分01秒 1431056 31587564 95.67 160576 18137192 7636180 21.84 11283852 8045580 292 13時02分01秒 1355940 31662680 95.89 160720 18163732 7732456 22.11 11319692 8061348 788 13時03分01秒 1069832 31948788 96.76 160864 18258808 7916424 22.64 11475128 8149772 576 13時04分01秒 997972 32020648 96.98 161020 18304260 7865520 22.49 11533064 8138148 452 13時05分01秒 739612 32279008 97.76 161156 18420120 8166364 23.35 11653076 8231452 1484 13時06分01秒 921432 32097188 97.21 161280 18342756 7873980 22.52 11567276 8145852 392 13時07分01秒 1031572 31987048 96.88 161380 18374860 7548000 21.58 11425768 8162912 200 13時08分01秒 952340 32066280 97.12 161536 18406152 7579896 21.67 11445428 8188376 324 13時09分01秒 329288 32689332 99.00 160560 17541676 9463668 27.06 13058876 7320332 568 13時10分01秒 2051588 30967032 93.79 160824 17389864 7825024 22.38 11538432 7142860 1256 13時11分01秒 1805916 31212704 94.53 160968 17485456 8049836 23.02 11707180 7173032 1364 13時12分01秒 1677532 31341088 94.92 161124 17610528 7973128 22.80 11813772 7172780 436 13時13分01秒 1628740 31389880 95.07 161288 17656612 7957700 22.75 11973208 7037580 648 13時14分01秒 1524616 31494004 95.38 161412 17653488 7971640 22.79 12180256 6893332 392 13時15分01秒 1285080 31733540 96.11 161560 17753712 8306224 23.75 12417720 6851648 536 13時16分01秒 1166112 31852508 96.47 161728 17861440 8184680 23.40 12421956 6946000 1756 13時17分01秒 1144808 31873812 96.53 161880 17865360 7919956 22.65 12420984 6944692 1216 13時18分01秒 1218172 31800448 96.31 162068 17956568 7687172 21.98 12268868 7000748 112 13時19分01秒 969680 32048940 97.06 162224 18033280 8067340 23.07 12408764 7057096 824 13時20分01秒 1000480 32018140 96.97 160652 17866244 8335588 23.84 12603244 6874416 9596 13時21分01秒 1042388 31976232 96.84 159336 17833016 8423376 24.09 12585432 6838724 3376 13時22分01秒 1036500 31982120 96.86 155488 17821164 8377824 23.96 12580284 6894516 1968 13時23分01秒 1003200 32015420 96.96 153592 17833124 8649380 24.73 12660892 6868856 1720 13時24分01秒 1166100 31852520 96.47 151680 17756812 8442960 24.14 12616860 6829500 728 13時25分01秒 1218492 31800128 96.31 151836 17844472 8316964 23.78 12464256 6896988 1012 13時26分01秒 947504 32071116 97.13 152004 17969480 8623384 24.66 12648408 6991448 4204 13時27分01秒 1325332 31693288 95.99 150092 18011076 8627884 24.67 12658344 6994720 1044 13時28分01秒 1496044 31522576 95.47 150236 18105860 8666052 24.78 12743524 7047208 564 13時29分01秒 1431636 31586984 95.66 150396 18140460 8838268 25.27 12798324 7075648 276 13時30分01秒 1320076 31698544 96.00 150300 18153236 9160388 26.19 12941568 7052516 2380 13時31分01秒 1018620 32000000 96.92 150480 18212804 9452868 27.03 13185180 7099936 428 13時32分01秒 1135288 31883332 96.56 150696 18274700 9507896 27.19 13089640 7134092 452 13時33分01秒 1954332 31064288 94.08 150848 17613756 9575488 27.38 12875880 6780284 576 13時34分01秒 1805148 31213472 94.53 151032 17671136 9718436 27.79 12958996 6815456 828 13時35分01秒 1786012 31232608 94.59 151180 17701128 9575256 27.38 12920492 6843008 1392 13時36分01秒 1706264 31312356 94.83 151396 17727160 9649272 27.59 12959620 6853420 3248 13時37分01秒 1642792 31375828 95.02 151572 17749988 9620976 27.51 12977504 6866620 528 13時38分01秒 1531584 31487036 95.36 151764 17771136 9857340 28.19 13057888 6874544 280 13時39分01秒 1966244 31052376 94.05 151712 17402756 9954056 28.46 12904340 6697436 292 13時40分01秒 1859200 31159420 94.37 152104 17444360 10032084 28.69 12952848 6720836 1616 13時41分01秒 2530204 30488416 92.34 154396 17442980 7953388 22.74 12278520 6753324 4280 13時42分01秒 2255808 30762812 93.17 154552 17699116 8496732 24.30 12273280 6932528 7628 13時43分01秒 2164728 30853892 93.44 154796 16397360 10210752 29.20 13422656 6260820 1704 13時44分01秒 3108524 29910096 90.59 154976 16277428 9524864 27.24 12608620 6181632 8008 13時45分01秒 3568892 29449728 89.19 155164 16547836 8540308 24.42 11973992 6317724 6672 13時46分01秒 1536208 31482412 95.35 155556 16507420 10545848 30.16 13949952 6343948 524 13時47分01秒 3308668 29709952 89.98 155752 16630860 8610304 24.62 12064472 6428360 1440 13時48分01秒 3223436 29795184 90.24 155900 16736768 8745672 25.01 12057980 6494452 2064 13時49分01秒 3442860 29575760 89.57 156056 16744128 8261200 23.62 11773376 6503824 384 13時50分01秒 3099288 29919332 90.61 156204 17123444 8045384 23.01 12276868 6306784 1484 13時51分01秒 3804912 29213708 88.48 156364 16405368 8093024 23.14 11572156 6286968 352 13時52分01秒 3690424 29328196 88.82 156500 16446536 8136216 23.27 11612512 6318120 432 13時53分01秒 3264040 29754580 90.11 156692 16481912 8502328 24.31 11975736 6334704 2028 13時54分01秒 3390360 29628260 89.73 156848 16506012 8400704 24.02 11808796 6350316 1092 13時55分01秒 3252304 29766316 90.15 157000 16593168 8431816 24.11 11829088 6428260 1864 13時56分01秒 3101792 29916828 90.61 157164 16674572 8452228 24.17 11901340 6470356 812 13時57分01秒 2959924 30058696 91.04 157344 16737692 8508872 24.33 11945616 6523816 1556 13時58分01秒 2776752 30241868 91.59 157476 16812064 8640376 24.71 12038504 6566388 356 13時59分01秒 2550676 30467944 92.28 157676 16873500 8833172 25.26 12189312 6601008 4368 平均値: 1859734 31158886 94.37 156423 17521320 8611256 24.62 12316095 6951136 1647
この結果から、「サーバーリソース枯渇が原因ではなさそうだ。Apache再起動が怪しい」という仮説を立て、Apache再起動の経緯を確認するためインフラ運用チームに連携しました。
ステップ3：発生経緯の解明と根本原因の追求
3-1. 関係部署との連携で事実確認
インフラ運用チームから、サーバー運用業者に再起動の有無を確認依頼し、下記の経緯が判明しました。
- 2025/01/01 13:30: 該当サーバーのポート監視がDownを検知
- 2025/01/01 13:40: Apacheが応答しないため、一次対応として手動で再起動を実施
3-2. 根本原因の深掘り
では、なぜApacheは応答しなかったのか？
ここからが調査の正念場です。まずは定石通り、Apacheのエラーログからフリーズ直前の時間帯（13:30〜13:40）を確認します。
grep -E '2025-01-01 13:3' [ERROR_LOG_FILENAME] | less
しかし、ログには有力な手がかりは残っていませんでした。調査は振り出しか…と諦めかけたその時、もう一度sarのデータに違和感がないか見直すことにしました。
すると、メモリ使用率（%memused）には現れない、ある兆候を見つけました。それがkbcommit（コミットチャージ）の急上昇です。
▼sar -rの再検証
# 抜粋：sar -r の kbcommit の変化 13時30分01秒 ... kbcommit 9160388 ... 13時31分01秒 ... kbcommit 9452868 ... ... 13時39分01秒 ... kbcommit 9954056 ... 13時40分01秒 ... kbcommit 10032084 ...
このように、障害発生直前の10分間でkbcommitが一貫して上昇していることが分かります。
kbcommitの上昇は「物理メモリはまだ空いているように見えても、OS内部では『将来使う予定のメモリ』の予約量がどんどん増え、メモリ空間全体が危険水域に近づいていた」ことを示唆しています。レストランで言えば、まだ席は空いているのに『予約席』の札がどんどん置かれていき、新しいお客さんを案内できなくなる状況に似ています。 このメモリプレッシャーが、Apacheのプロセスを不安定にし、一時的に応答不能（フリーズ）状態を引き起こした可能性が非常に高いと考えられます。
では、何がこの短時間でメモリ予約（kbcommit）を急増させたのでしょうか？
私たちは次に、この時間帯に実行されていたアプリケーションの処理内容に注目しました。調査の結果、Apache再起動の直前、まさに kbcommit が上昇していた時間帯に、特定のお客様が「ページ数が100枚を超える超高画質の図面登録処理」を行っていたことがアクセスログなどから判明しました。
この処理は、画像の処理やデータ登録のために一時的に大量のメモリを確保（予約）する特性があり、今回の kbcommit 上昇の直接的な原因であると特定しました。
3. 解決編：CREの真価
今回の調査により、「お客様からの『画面が開けない』という申告は、特定の重い処理（超高画質の図面登録）が実行されたことでサーバーのメモリ予約量（kbcommit）が急増し、メモリプレッシャーが高まった結果、Webサーバー（Apache）のプロセスが一時的に応答不能（フリーズ）となり、それを検知した運用業者がサービスを復旧させるために再起動したことで発生した」と結論づけました。
お客様へは、特定の処理が集中したことによる一時的なリソース逼迫が原因であったことを、調査結果と共にご報告し、納得いただくことができました。
私たちCREの役割は、こうした再現性の低い問題に対して技術的な裏付けをもって「何が起きたのか」を明らかにすることです。原因が分からないという状況は、お客様にとって一番の不安材料となります。私たちは、ログやサーバーのデータを元にした明確な事実を調査・報告することでその不安を取り除き、安心してサービスを使い続けていただくことを目指しています。
また、今回の調査過程と結論を詳細に記録し、チームの知識として蓄積します。これにより、未来に類似の事象が発生した際に、より迅速な解決に繋げることができるのです。
4. エピローグ：CREが見る未来
あの日お客様からいただいた「現場の全員が画面を開けなかった」という漠然とした不安の声。その正体は、サーバーの片隅に記録されていたsarのデータの中に隠されていました。
私たちの仕事は、このようにお客様が体験している事象と、サーバー内部で起きている技術的な事実とを結びつけ、システムの信頼を取り戻すことだと考えています。一本のログ、データに現れたわずかな兆候から原因を紐解いていく過程は、まるで探偵のようでもあり、この仕事の大きなやりがいの一つです。
仕事のトラブルシュートも、思春期の子供との対話も、一筋縄ではいかない問題と向き合う毎日です。しかし、一つひとつの事象に真摯に向き合い、チームの力を借りて解決していく先に、お客様の安心と信頼があると思うと、自然と力が湧いてきます。
最後までお読みいただき、ありがとうございました。この記事を通して、CREという仕事の面白さや奥深さが少しでも伝われば幸いです。
ところで、スパイダープラスでは仲間を募集しています。ちょっとでも興味が出てきた方はぜひお話しましょう！
