Instanaで挑む！トラブルシュート事件簿　第1回　遅い、遅すぎる！POSシステムの遅延原因をInstanaで解決

# はじめに

こんにちは、Airitech株式会社の代表取締役をしている、山﨑政憲と申します。
これからInstanaが現場で活躍した事例をいくつか紹介していこうと思います。

# Instanaとは

InstanaはIBMが提供しているObserbavilityツールです。
私は起業した2017年からInstanaを性能改善やトラブルシューティングに活用しており、「早い」「美味い」「安い」と三拍子揃ったInstanaの便利さを日々、実感していますし、Instana好きが高じてIBM Championの認定も受けていましす。
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/76238/8dd06a80-9c0e-bead-57bf-fff3bc5357c1.png)


Airitechでは、X上でマンガも掲載しています。
こちらもご覧ください。
https://x.com/AiritechSupport/status/1765633493084893569
<link href="https://x.com/AiritechSupport/status/1765633493084893569">
<img width="400" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/76238/f3d27c44-a4b1-ede6-1fbf-5765d1bbec2b.png">
</link>

# 第一幕　事件発生
システムトラブルシュートを営んでいる当社に、1件の性能改善依頼が舞い込んできました。
全国津々浦々に展開している店舗で利用しているPOSシステムが、最近やたらと遅くなってしまって店舗の接客に支障をきたしているとのこと。

店舗から大量のクレームが寄せられているため急ぎの解決が必要であるが、開発ベンダの調査では原因が掴めず、POSパッケージのベンダも類似事例が無いとのことで暗礁に乗り上げているとのことでした。

システムトラブルでは往々にして、どこに原因があるか分からない、したがって誰が調べるべきか分からない、という状況に陥りがちです。
全体を俯瞰して調査の力点を絞り込むのも私たちのトラブルシュータの役割の一つです。
依頼を受けて、顧客との打合せを実施しました。

# 第二幕　聞き込み実施
さて、「遅い」というだけでは情報不足なので、まずはお客様に聞き込みを実施です。
・遅いのはいつもでしょうか？特定の時間でしょうか？
　「顧客が多く来店する時間の方が顕著に遅くなります。」
・いつから遅くなったのでしょうか？
　システム導入当初からです。3カ月くらい前からになります。
・システムの構成を教えてください。
　インフラはAWS上に構築しています。
　POSパッケージを中心に基幹システムとの連携などを作りこみました。
　データベースはPOSパッケージがMySQL、基幹システムがORACLEです。
　端末はiPadです。

POSパッケージはPHPで実装されているということで、非常に一般的なWebアプリケーションです。
これならInstanaも即座に効果を発揮しそうだということで、Instanaの適用を提案しました。

# 第三幕　Instanaを適用してみる
システムやトラブルの概要が分かったところで、Instanaを適用した結果、驚くべき遅延状況が明らかになりました。

普段は3秒程度で終わっている処理が、時間帯によっては100秒を超えています。
Instanaの表示するチャートを再現すると、以下のような感じです。
![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/76238/1fee8991-4359-5864-ddab-29b869339ea9.png)

一つの画面を描画するのに、2、3リクエストが必要だそうなので、合計で3、4分程度待たされている可能性もあります。
店舗を出る際に3分も待たされたら、お客様の怒りも相当なのは想像に難くありません。
しかも、遅延は顧客の退店が集中する時間に発生しています。
待たされている顧客のさらに後ろで待機している顧客もいる状況と思われます。
これは早く解決せねばということでさらに解析を行いました。
Instanaの記録したトレースを確認すると、特定の2つのSQLのみ、やたらに処理時間が変動していることが判明しました。
早い時には1秒もかかりませんが、遅い時には100秒と大きな変化をします。
図にすると以下のような感じです。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/76238/14847882-1995-f03e-e40a-7c446cab2c43.png)

SQLの内容を見ると、いずれも

SELECT ・・・ FOR UPDATE

となっています。
データを更新している非常にシンプルなSQLです。
なぜこれの処理時間が大幅に変動しているのか？
これが問題解決の鍵と思われました。

# 第四幕　原因判明
処理の流れをInstanaのトレース機能で確認すると、問題のSQLは全てリクエストの先頭で実行されていることが分かりました。
来店顧客、退店顧客が多くなると、このSQLは全国から大量に実行されることになります。

FOR UPDATEがついているため、このSQLが実行できるのはシステム全体で一人。
全国にまたがって待ち行列が出来ていたということになります。
しかも、そのリクエスト全体がトランザクションの範囲になるので、リクエストが終わるまで、他のユーザは必ず待たされるという仕組みでした。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/76238/9a60a755-f0ee-5948-8fb7-dedd1eba431b.png)

SQLの内容について、POSパッケージベンダに確認したところ、処理の一意性を示す番号を採番しているとのこと。
履歴の出力などで処理の一貫性を識別するために使用すると言う事でした。

# 第五幕　対策実施
答えが分かれば後は対策を立案して実施するだけです。
要は採番処理だけを他の処理と分離して、別のトランザクションで実施すれば良い。
全国での待ち行列は残りますが、待ち時間は一瞬になる。

こうすると採番の順序性は担保されなくなりますが、必須の要件では無いということで、今回はこのまま修正を実施していただきました。
効果はてき面、問題のSQLは常に1ミリ秒程度で終わるようになり、100秒かかっていた処理も2、3秒で終わるようになりました。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/76238/c68dbd2b-a726-faa0-33c8-cc63009a5f25.png)

目に見えてシステムが高速になったため、店舗スタッフも大喜び。
喜びの声が情シス部門にも伝わることとなりました。
情シス部門の方々の喜んだ顔を今でも覚えています。

# さいごに

いかがでしたでしょうか？
開発ベンダが長時間かけても原因が分からなかった性能トラブルに、Instanaが非常に効果的だったことが伝われば幸いです。
Instanaの使い方、効果に興味を持たれた方はIBMのSoftware Salonでも使い方や事例について解説しているので、ぜひ、ご覧になってみてください。

IBM Software Salon 第10回 (2024/9/19)
トラブル解決でヒーローになろう！障害事例にみるObservabilityツール活用の勘所
https://video.ibm.com/recorded/133995814
<link href="https://video.ibm.com/recorded/133995814">
<img width="400" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/76238/165aeb44-f50b-e035-7e36-fa84e56f1290.png">
</link>

また、Instanaユーザコミュニティも、定期的にイベントを行っています。
こちらもぜひ、ご覧ください。
https://instanautsjp.connpass.com/

それでは、今後もInstanaの便利な使い方や事例の紹介を行いますので、よろしくお願いいたします。