【障害記録】No.8:月次のデータ削除処理が48時間を超えて長時間走行


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

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

8 B アプリ 月次のデータ削除処理が48時間を超えて長時間走行 ★★★☆☆

 


 


 

発生日時 2014/03某日 解決日時 2015/03某日 発見者 お客さん 対応者 原因者 俺ではない!(笑)
障害の詳細内容 お客さん(の情報システム部の方)から、
「とあるバッチジョブが丸々2日間動き続けています」
という問い合わせがあった。
調べてみると確かに2日前から動き続けている。
この時点で吐き気を催す壮大な案件であるのは間違いないが、
強いて言うなら唯一救いだったのは
このバッチジョブが「不要になった昔のデータを削除する処理」だったことか。
つまり直接的な業務影響はなかったのである。
(お客さんの運用保守担当の方には余計な作業を発生させてしまったという意味では業務影響合ったのだが)
まあ業務影響が出るなら2日と待たずに表面化するはずだから
2日間誰も気にしなかった時点であんまり大事でもなかったのだが。

この件にはいろいろ面倒な背景がある(後述する)のだが、
単純に直接的な原因でいうと、
  1. 対象のテーブルはOracleパーティションを採用していて、パーティションKEYに「年月」を使っている
  2. 対象のテーブルは13か月保持
  3. 13か月前のデータは月次でパーティションTRUNCATEが走る(1)
  4. その翌月に当該パーティションを含むそれより前の年月に対するDELETEを行う(2)
  5. その翌月にもう一度調べて0件だったら手動でパーティションをDROPする
という流れを組んでいる。
で、平たく言うと
(1)がバグっていてTRUNCATEが空振りし、
(2)が本来の処理想定件数とは比べ物にならないほどのとてつもなく大量のデータを削除しようとして、
2日間(48時間)を超えるほど処理が長時間化した

というのが事の真相である。
つまり、48時間という処理時間は別にテーブルロック開放待ちとかそんなんではなく、
単純に「データ量が無茶苦茶多かったから」ということのようだ。
よってずーっと待ってればそのうち終わったのかもしれない。
ただ最初に冒頭の問合せを受けたときには
「やべえ!!」という感覚が何よりも先行しており、
「とにかく延々と動き続けてるこのアホをまずは殺さなくては!!」という考えしかなく、
取り急ぎ48時間処理中のDELETEのOracleセッションをKILL、
処理内容を全てROLLBACKさせて、その後原因調査に入った。
(ROLLBACK自体も2時間くらいかった記憶があるな…
まあ逆に言えば2時間で終わったんだから大して削除してなかったのかもしれないが)
対応内容・経緯等 設計した本人ではないので、どういう考え方があってのことかは知らないが、
このテーブルは少し癖のあるデータの持ち方をしていた。
このテーブルはパーティションキーとしてYYYYMMの年月文字列を採用していたが
YYYY年01月だけなぜかYYYY13の形でデータを保持していた。
要するにパーティションキーがYYYY02~YYYY13になっているわけだ。

「現在日付の13か月前」をYYYYMM形式で取得することは簡単なのだが、
当然ながら普通にやるとYYYY01~YYYY12までしか取得できない。
このため実質「1月」を指しているYYYY13のパーティションを、「13か月前」として算出することになる月、
つまりYYYY年2月の処理でおかしなことが起こる(「1月」を正しく特定できない)
実例を挙げると、
2014年2月の13か月前は2013年1月になるが、
2013年1月はテーブル上は「201213」のパーティションでデータ保持しているので、
「201301」で処理しようとすると空振って処理されない。
↑に挙げたデータ削除のバッチ構成
(1)パーティションをTRUNCATEして  
 ↓  
(2)その翌月に(1)のパーティションを含むそれより前の月をDELETE  
に基づくと、
(1)が2014年2月に動いて空ぶって、
(2)が2014年3月に動いて大量削除をしてしまい、
この問題を招いた。

実例に沿って整理みると…
2014年1月の処理⇒2014年2月の処理⇒2014年3月の処理
(1)TRUNCATE
年月結果
201213 1000万件くらい
201212 0件
201211 (超微量)

(2)DELETE
年月結果
201213 1000万件くらい
201212 0件
201211 0件
(1)TRUNCATE
年月結果
201302 1000万件くらい 201213 1000万件くらい
↑空振って消せてない
(本来ならここで
0件になっている想定)
201212 (超微量)

(2)DELETE
年月結果
201302 1000万件くらい 201213 1000万件くらい 201212 0件
↑この月は「201212以下」で
削除するので、
まだ被害は出ない
(1)TRUNCATE
年月結果
201302 0件 201213 1000万件くらい 201212 (超微量)

(2)DELETE
年月結果
201213 1000万件くらい
201213 1000万件くらい
201212 (超微量)
↑「201301以下」で削除するが
「201213」に想定外の件数が
残存しており、長時間走行。

この件を分かりづらくさせている要因として
(1)と(2)は同じタイミングで動くのに処理対象の年月が異なる (1)は「13か月前」しか対象としないのに対し、
(2)は実質「14か月以上前」を対象としている。
このため、(1)のバグが(2)によって直接的に露呈するまで1か月の間が空いてしまう。
(1)はYYYY13を消せないが、(2)はYYYY13を(意図せず)消せる (1)も(2)も、「1月」を指定する時は内部的に「YYYY01」になるが、
(1)は「"201301"のパーティションが見つからない(から空振りで終了)」
(2)は「"201301"以前と指定すると"201213"は対象に入る」
という点で違いが出る。
文字列の大小比較をしている以上、"201213"は"201301"より前と判定されるためだ。
どちらもYYYY13の存在を考慮できていない点では同じだろうが、
(2)は1月のデータが201301だろうと201213だろうと消せるので、
その意味では(2)のほうが優秀である。
というのが挙げられるだろう。(まあ同じことを別の視点で書いてるだけだが)

そして、(2)が長時間走行したという事実だけを捉えると、
一見すると(2)の実行計画が狂ったとか、そういうところに目が行きがちだが、
実際そうではなく(1)が正しく処理しなかったために起きている。

ここで一つ疑問に思うのは、
(2)から見れば前月の時点で削除済(TRUNCATE済)のはずのデータを
なんでわざわざまた翌月にDELETEするのかというところだが、
このテーブルが持つデータの特性上、
わずかながら「13か月以上前のデータがたまにポツっと発生する」ことがあり、
その「わずかに発生した過去データ」を削除するための処置として
(2)を用意した経緯があったようだ。
パーティションテーブルという仕様上、
そのパーティションに属するデータが発生すると、
最低でもそのパーティションのイニシャルサイズ分のテーブルスペースは確保してしまう。
「一度TRUNCATEしたあとに、すごい昔のデータが発生する」
ことで、せっかく空っぽにしたパーティションにまた余計なテーブルスペースを取られてしまい、
それがディスク容量の圧迫を起こして、運用上の課題になっていた。
これの対策として、(2)を用意した経緯があったようだ。
⇒ちなみにさっきから”ようだ”と言っているがこれには理由があり、
それは「あとがき」欄で後述する。

個人的には、YYYY13でデータを持っている方がなんかおかしい気がするが、
このテーブルにデータを取り込む処理と、
このテーブルを後続で集計に使っている処理等が、
諸々なぜかYYYY13前提で処理を進めているため、
その辺への影響を考えるとYYYY13でデータを持っていることを前提に
パーティションTRUNCATEをそれに対応させなければならなそうだと気付き、
少し気持ち悪いのだが(1)を修正するに至った。
この件の特性上1年たたないと問題が再発していないことを確認できないため、
結局確認完了まで1年がかりの案件になってしまった。
反省点・あとがき (2)のDELETEは、実は最初は存在しなかった。<br/ あとから追加されたのである。
そして(2)を作ったのは実は俺(達)ではなく、
というか(2)を作ったのがお客さんの情報システム部の方なのだが、
(それがまたこの件をややこしくさせている)
「一度消した後に昔のデータが発生する」という事情があることに対して、
それの対策として「翌月にもう一度DELETEする」という手法を取ったのが
個人的に正直2つの点でイケてない。
まず「翌月に」だが、
それをやるくらいなら
(1)を「13か月以前のパーティションを全てTRUNCATEする」ように改造すればいい。
そうすると、毎月同じタイミングで13か月以前のデータは全て綺麗さっぱり消えてなくなる。
いちいち対処を翌月にまわすからややこしくなる。
次に「DELETE」だが、
まあ↑とかぶるんだが、複数のパーティションを跨る可能性があり、
しかもTRUNCATEのやり方が確立されているにもかかわらず、
わざわざ時間のかかるDELETEを削除手段として選択する意味がない。

ただ、
  • 過去データ発生は、業務上せいぜい13~14か月以前くらいまで(つまり14か月経てばもう発生しないと見做していい)
  • テーブルに対する単純条件のDELETE文実行はシステム上汎用化された実装手段がある

というお客さんの社内での話し合いがあったうえで(2)を独自追加した経緯があったらしいので、
(1)がYYYY13を考慮漏れしている点を踏まえても決してお客さんを責められるものではない。
一つ言うなら
「相談してくれたら(1)直したのにな」
っていう思いがあるのは残念なところではある。
(1)がYYYY13を考慮漏れしている点を一旦無視すると(これが結構重要なところだ)
「13か月より昔の過去データが発生して無駄なテーブルスペースを食ってしまう」
っていう運用上の課題に対して、
「(1)の条件を、13か月”だけ”から13か月”以前”に変更できませんか」
っていう相談を俺たちSEにはせずに
「自分らで13か月より前を消すバッチ作ればいいか」
っていう方針になったのが残念だ、という意味である。
もしかしたら俺が知らないところでちょっとした相談レベルの話はあったかもしれないが、
この改修は恐らく仕様変更(=追加費用が発生する)なので、
「お金かかるならお願いしなくてもいいや、自分たちでやろう」ってことになったのかもしれない。
その辺は把握していないが、
少なからず「お客さんにそこまで信頼はされていない」というSEの実情が
この件の背景からなんとなく読み取れる。
これは(1)のバッチの処理条件の変更に焦点をあてた改修の話なので、
「YYYY13の考慮漏れ」はひとまず全然関係ない(だから上で「一旦無視」と書いた)
同じ意味で(2)をお客さんが作ることになった背景にもYYYY13の件は関係ない。
逆に言えば(1)も(2)もYYYY13の存在は考慮できていない。
しかしこの選択が結果的に(1)のYYYY13の考慮漏れを露呈し、
結局(1)を直す(しかも障害対応ということで無償)羽目になったのである。
みんなに不幸しか生まない選択になった。

事前に相談を受けて直すことになっていれば、
ひょっとしたらそのときにYYYY13の問題に気付いて
問題が起きる前にしれっと暗殺が出来たかもな、

というのも一つ心残りではあるが、
結果論なので後からはどうとでもいえる。
諸々残念な事態を生んだ案件だったと思っている。