【障害記録】No.7：アップロード処理のレスポンス改善対応

IT

自分が体験したシステム障害を紹介してトラウマを抉り返す自虐コーナー
※特定避けるため一部脚色・変更しているが、大体ほぼ実体験。

障害No障害分類No
（自分用）発生分類
アプリ/データ/ミドル/ハード案件名個人的ヤバイ度
（５段階評価）

6 B アプリ アップロード処理のレスポンス改善対応 ★★☆☆☆

 

 

 

発生日時 2010年某日 解決日時 2013年某日 発見者 お客さん 対応者 俺 原因者 強いて言えば
俺ということに
なるのかな(´・ω・`)
障害の詳細内容 画面からファイルをアップロードして、トランザクションにデータを書き込む処理がある。
一言でいえばそれだけである。
しかしアップロード完了するまでがまあ遅い。
アップロードするファイルの内容にもよるのだが、
遅い場合は10分以上も応答が返ってこない。
アップロードしてからタバコ２本吸って戻ってきてもまだ処理中だったときがある（実体験）。
ただ、遅いってだけでデータがバグってるわけではないので、
なんとか耐えて運用を続けてもらっていた。
（↑に書いた通り、アップロード指示してあとは放置していればそのうち終わっているので）

これについてはリリース直後からずーーーーーーーーーーーーーーーーっと言われ続けていたことだが
使い勝手が悪くなるものの他の業務継続困難系の案件に比べて
こういう「運用回避でなんとなかる系（回避してないが）」の案件は優先度を低くしがちで、
結局３年以上も塩漬け状態になってしまっていた。
2013年頃、最早仕様変更案件も諸々底を尽きて（要するに費用がなくなった）、
「そろそろなんとかするか」と重い腰をあげて対処に向かった。
若干マスクするが、
本件対応前に平均140秒かかっていた処理が、本件対応後に平均45秒まで改善した。
普通に考えると画面処理としては45秒でも大分遅い方だが、
顧客と合意したレスポンス改善度合いにおいて「50%改善」が謳われていたので
見事クリアしたということで（むしろ合意指標からするとかなりいい記録）、無事クローズと相成った。
対応内容・経緯等 はっきり言うとこの件が「遅い」と指摘されたとき、
どこに時間がかかっているのかを真剣に調べてはいなかった。
そんなことに時間を割ける余裕がなかったのである。
本腰をいれて対処にあたると心に決めた後、真剣になって（笑）ログを見てみたところ、
処理時間の多くは「過去実施したアップロード履歴との突合せチェック」にかかっていた。
これが処理全体の約70%。
全体で140秒ならこのチェックだけで98秒である。
重すぎる。

いろいろ処理を深堀してみると、このアップロード処理は、
（１）アップロードファイル内容を全件ワークテーブルに格納する  
　┃  
（２）ワークテーブルを上から１件ずつ取得し、１件ごとに「属性」「桁数」等チェックする  
　┃  
（３）ワークテーブルを上から１件ずつ取得し、１件ごとに「過去履歴との突合せチェック」を実施する  
　┃  
（４）ワークテーブルの件数をサマリし、ユーザ別の「上限件数」を超えているかチェックする  
　┃  
（５）ワークテーブル内容をトランザクション側に反映（ＵＰＤ・ＩＮＳ）する
という流れになっていて、
（２）と（３）で２回、同じ数だけループが走っていた。
つまりアップロードファイルが100件なら（２）で100回、（３）で100回ループしているのである。
もっと言うと（１）もご丁寧にアップロードファイル１行ずつを処理するループになっていたので
（１）（２）（３）で合計3回アップロードファイルの中身を総なめすることになっている。
アホだ。

といいつつ（１）（２）にはそこまで時間がかかっていなく、
（３）に無茶苦茶時間がかかっていた。
この（３）が、上述した「過去実施したアップロードとの突合せチェック」である。
このチェックにあたって、「ワークテーブル」と「トランザクション」を突き合わせて（結合して）いるのだが、
ワークテーブル自体は対した件数ではない（最大でも1000件（※これには少し罠があった。後述する））のだが
突合せる側の「トランザクション」は定期削除していたものの1億件を超える件数を保持しており
1件1件は大したことないものの、それがループされるとその分だけ処理時間がかさみ、
結果的に全体の処理時間を大幅に圧迫していたようだった。
そもそも（１）終了時点でワークテーブルに全件データが入ってるのだから、
（２）も（３）も極論ＳＱＬ一発でチェック可能なはずだ。
少なくとも１件１件処理する必要はまったくあるまい。
ちなみに（３）をＳＱＬ一発にしたらテスト環境ですら70秒⇒30秒くらいに改善された。（hintとかは付けたが）
もうこれでいいんじゃん、と思っていたところ、お客さんから意外な話が出た。

改善の中間報告として上記の状況を共有しに打合せしたところ、
俺「（３）に70%くらい時間を要しています。  
　　ただ、これは正直作りが悪いので直しました。  
　　そしたら70秒が30秒になりました！(`・ω・´)ｼｬｷｰﾝ」  

客「え！？

　　（３）なんていらないよｗｗ

　　なんでそんなチェックやってるのｗｗｗ

　　ウケるｗｗｗｗｗ

　　バルスｗｗｗｗｗｗｗｗｗ」




俺「(´・ω・`)」


ちょっと誇張しているがまあこんな感じである。
「なんで」ってそりゃチェックしろってオメーが昔いったからだろーがよ！！
とは言わなかったけどマジでそういう設計記録は残っている。
俺が設計担当したからよく覚えてるんだなこれが。。
（そういう意味で↑の「原因者」は「強いて言うなら俺」と書いた）

まあ３年も経つといろいろ考え方も変わってくるというか、
おっそ～い状態で３年運用してしまうと、
一括で重いのをダラダラ処理するよりは、
小分けでチョコチョコ処理するように変わっていったので、
その分ローカルでのチェック運用がはっきりまわっていたのだろう…
真相はよく知らないがなんとなく話していたかんじそんなチェック運用やツールの存在を感じた。
（もしそうならそれはゴメンね、おれたちのせいだね。）

長くなったが、上記のような経緯を辿り、結果的に、
（３）のつくりを改善するというよりは
（３）自体をなくすというダイナミックな改修に対応方針が変わり、
これにより（３）そのものが消えてなくなって、
（３）にかかっていた70%分が消滅して晴れてレスポンスが改善されたわけである。
反省点・あとがき 結果的にこの処理は（３）をなくすことで解決したが、
実は（３）が遅い原因と思われる要因にお客さんには言っていないものが一つある。（ここで懺悔する）

この処理ではアップロードデータを一度ワークテーブルに格納するわけだが、
ワークテーブル自体は一つなので、
「5分前にアップロードしたやつ」「1時間前にアップロードしたやつ」が残っている。
（削除は1日1回、夜間に行われる）
ので、（２）や（３）のチェックにあたっては、
「そのときアップロードしたやつ」を特定してあげる必要がある。
このため、ワークテーブル自体のKEYに、
タイムスタンプ（ミリ秒まで）を文字列にした項目を使っていた。
このタイムスタンプは（１）を開始する前に取得し、以後の処理内で使いまわす。
なのだが、（２）ではちゃんと使っていたが、（３）では全く使っていなかった。
条件として全く使おうとしていない。
これにより（３）でチェックする範囲が
「そのときアップロードしたやつ」から「その日にアップロードしたやつ」全体になっていて、
無駄に多くのデータをチェックしていたことになるのだ。

これの理由はわからない。
多分理由なんてなく単純に実装漏れなんだろうと思っている。
といいつつお客さんには言えないので黙っていたし、
結局この（３）自体消滅したからもうどうでもいいのだが。
冒頭で「アップロードしてからタバコ２本吸って帰ってきてもまだ処理中だった」というのも、
正確には追跡していないが多分これが原因で、
テストのために何度も何度もアップロードを繰り返していた分、
ワークテーブルにデータが蓄積されまくって、
実質無条件チェックの（３）がどんどん遅くなっていった、ということだろうと予想している。
まあ今となっちゃどうでもいいんだけどねホントにね。

はっきり言うともともとのつくりがよくない案件だと思うが、
こうして真面目に向き合ってみないとその辺を明らかにできないものだ。
まあ結果オーライということで良しとする。。