サーバ＊のクラウドストレージ(Backblaze B2)へのバックアップに使っているソフト duplicacyが時々エラーを出していた。※ 調べたら4年近く試行錯誤していたが、最後の対処をしてから半年くらい起こっていないので、ようやく直った感じだ。
＊デスクトップでも使っている。
※随分前に書いた気がするものの、探しても出て来ないので、対策しつつ様子を見ていたのかも知れない。
(耳や臭いの問題と同様に)原因が はっきり分からないのだが、バックアップ中のメモリ不足かディスクアクセス過多、あるいはその両方ではないかと推測している。: 通常は問題ないが、(サーバのハード(仮想マシン)は貧弱なので)他に大量にメモリを使うか頻繁にディスクアクセスをするプロセスが一緒に動いていると、問題が起こるようだ。
現象
- クラウドストレージのprune(古い変更履歴の削除)処理時に、いくつかのチャンク(ブロック)が ないというエラーが出る。
- エラーメッセージの例(発生し始めた頃のもの, 一部改変した)
2019-07-17 03:41:18.960 ERROR CHUNK_DELETE Failed to fossilize
the chunk fdXXXXXX: URL request 'https://YYYY.backblazeb2.com/b2api/v1/b2_hide_file' returned 400 File not present: chunks/fd/XXXXXX
-
- そのチャンクを含むリビジョン(履歴)を削除するかexhaustive prune処理を実行すると、エラーは出なくなる。
- 問題のリビジョンのバックアップ時にはエラーは出ていない。
謎と検討
妙なのは、デスクトップとサーバで同じようにバックアップしているのに、サーバだけでエラーが起こることだ。しかも、サーバ(VPS)のハードが交換された あとから起こるようになった。 ← 実は その前から起こっていた。(記録のために残す)
そのことから、(OSは同様なので、)サーバとデスクトップのハード(リソースや性能)の違いが関係している可能性がある。
対処
半年くらい前(2022/11)に以下のように対処したら、問題が起こらなくなった。
- duplicacyのバックアップ処理のパラメタを調整し、使用メモリ量を減らすようにした。
- オプションに -max-in-memory-entries 51200 を指定した。
- → 使用メモリ量が200MB前後になった。 (無指定時は600MB以上になる場合があった。: 下を参照)
- 値を減らすと使用メモリ量は減るが、比例は しない(下限がある?)ようで、10240と かなり小さくしても200MBは使うようだ。
- オプションに -max-in-memory-entries 51200 を指定した。
- バックアップ処理と、メモリを大量に使用してディスクアクセスが頻繁なclamscan(ウイルススキャンソフト)が同時に動かないようにした。
- どちらもcrontabで定期的に起動している(周期や時刻は異なるが、どちらも実行時間が長いので同時に動く可能性がある)ので、起動前に片方が実行中の場合はスキップし、次回まで延期するようにした(片方が終わるまで延々と延期する)。
- 今気付いたが、微妙なタイミング(例: たまたま2つが同時に起動時刻になった場合)で同時に起動してしまう場合があるかも知れない。 ← プログラム(スレッドやプロセス)でないので、開始時刻(分)を違えておけば大丈夫そうだ。
- こちらは上より先に実施したが、問題が全く起こらなくなる訳ではなかったようだ。
- どちらもcrontabで定期的に起動している(周期や時刻は異なるが、どちらも実行時間が長いので同時に動く可能性がある)ので、起動前に片方が実行中の場合はスキップし、次回まで延期するようにした(片方が終わるまで延々と延期する)。
分かった切っ掛け
対処方法が分かった(問題が起こらないようにできた)切っ掛けは、ある時のduplicacyの更新内容に「使用メモリ量の削減」というものがあったことだ。※ もしかすると、他の方がメモリ不足でのトラブルを報告したのかと思った。
※僕はそれまで、duplicacyがメモリを大量に使用する可能性があるとは全く意識していなかった。想像だが、duplicacyの重複排除処理(重複ブロック(チャンク)の検索?)でメモリを使うのではないか。
なお、更新されたduplicacyのストレージ(スナップショット/リビジョン)は新しいフォーマットになって使用メモリ量が少なくなるというので、全部のスナップショットが入れ替わるまで(変更履歴の保存期間が過ぎるまで)使用メモリ量の変化を見ていたが、余り減らなかった。最初(duplicacyを更新した直後)が一番減った気がする。
それで、duplicacyと一緒にclamscanが動く時にメモリ不足になって、エラーの原因になるのではないかと推測した。ただ、OSのログにはメモリ不足関連のエラーは出ていないので、正確には、実メモリ(RAM)が不足して仮想記憶(ディスク)が使用されて(スワップ)、処理が遅くなってエラーの原因が発生するのではないだろうか。
duplicacyのエラーメッセージから考えて、原因はバックアップ時にチャンクがクラウドストレージに保存されないことがある(ただ、その時にエラーは出ない)というものだろうから、実メモリが不足してスワップが起こると処理が遅くなって、チャンクのクラウドストレージへの送信が失敗するのではないかと推測している。
処理が遅くなって送信が失敗することがあるとは思えないが、例えば通信のタイムアウトやリトライ処理のタイムアウトなどであろうか。前者とすれば、送信するチャンクのデータをメモリにバッファリングせず、ディスクから読み出しながら送っていて、たまに遅くなると送れないことがある? : いずれにしても、duplicacyの処理のロバスト性が今一つなのかも知れない。
そう言えば、以前duplicacyのフォーラムを調べたら、僕と同様に「チャンクがない」というエラーが出る方が問い合わせていたが、結局「再現せず」や本質的でない回答のあとは放置されて、解決していなかった。
そしてその方は怒っていた気がする。: その方のKopiaのフォーラムへの投稿からduplicacyに戻って、上の問題を知った覚えがある。
そこで、試しにduplicacyのバックアップ時の使用メモリ量の表示をさせてみたら※、600MB以上消費する場合があることが分かった。普通は それくらいは問題ないのだが、サーバのメモリ量は1GBと少ないので＊、他のソフトも大量に使用するとスワップが起こりそうだ。なお、prune時は使用メモリ量は小さく、100MB以下だった。
※メモリ量削減と一緒に そういう機能が追加された。
＊以前、たまにメモリ不足の問題が起こっていたため、仮想記憶(スワップ)を有効にしていた。その問題が何だったか思い出せないが、やっぱりduplicacyだったのかも知れない。
メモリ不足の他には、duplicacyもclamscanもディスクアクセスが頻繁なために処理が遅くなって、上と同様にチャンクのクラウドストレージへの送信が失敗する可能性も考えられる。更に、メモリ不足と頻繁なディスクアクセスが一緒になると、余計処理が遅くなって更にひどいことになりそうだ。
ちなみに、過去1年のサーバの稼働状況を調べたところ、duplicacyの使用メモリ量を制限した頃からスワップ頻度(ページ/s, 下の左のグラフ: 中央辺りから制限した)が減ったようだ。ディスクI/O頻度(回数/s, 同右)に関しては変化は少なく、逆に少し増えた感じだ(ただし、なぜか今年4月以降は小さくなっている)。ディスクを複数プロセスで同時に使うと、効率が低下して全体的な性能が低下するためだろうか。
-
- 過去1年のサーバのスワップ頻度の履歴 (Munin)
-
- 同、ディスクI/O頻度の履歴
グラフから、duplicacyのメモリ使用量が大きくてスワップが多かったことは確かそうだ。
※なお、同じ期間のメモリの状態(memory usage)、ディスク動作率(utilization)、ディスクの遅延(latency)、NWの通信速度、システム負荷(load average)に目立った変化は なかったので、グラフは省略した。
考察
いずれにしても、送信失敗時にエラーが出るはず・べきだが出ないのはduplicacyの問題(異常時の処理が甘い)か、これらが原因ではないかの どちらかだろう。
今後問題が再発すれば後者だし、逆に、duplicacyの使用メモリ量の制限を止め、常にclamscanと一緒に動かして問題が起これば、僕の推測が正しいことが分かる。が、面倒だし ほとんど無意味(僕が作ったものでないし、サポートが やる気ない: おそらく「環境の問題」で終わり)なのでやる気は しない。
もしduplicacyの問題だとしたら、「バックアップしたつもりなのに(エラーになっていないのに)、できてなかった」という、結構ひどいものだ。が、起こるのは限られた環境のようだし、駄目になるのは一部のファイルだけなので、致命的とまでは言えなさそうだ。でも、これは遊びのソフトじゃないので、重大な信頼性の欠陥だと思う。
補足すると、特定の環境・状況で処理が失敗するのは仕方ない(すべての環境・状況で使えるものは作れない)が、使った時に失敗したことが分からないのが問題だ。
そう言えば、作者は こういうエラーメッセージ関係の重要性を軽視しているようで、以前、「エラーメッセージ(か終了コード)が誤解する・分かりにくいから変更して欲しい」という要求を拒否していた。
これは単なる表示・見た目の問題ではない。ちゃんと作る(起こり得る すべての失敗を想定・想像する)のは大変だが、製品には必要だ。
試行錯誤
対処方法が分かるまでに以下を試したが、ほとんど効果がなかった。若干良くなるように見えたが、問題は起こった。
- バックアップ時の送信スレッド数を減らす。: デフォルト: 4個 → 1個 (-threads 1)
- バックアップ時の送信速度を下げる。: 約250kB/s (-limit-rate 250)など
- B2のメンテナンス時間帯(毎週1回)のバックアップを避ける。
これより、問題の原因はduplicacy単体ではない可能性が高いことが推察される。 ← 上も動作環境(NWやB2)が関係していることを推測して行ったので、これは言えない。 (22:11)
余談
何度か この件をduplicacyに問い合わせようと思ったが、ハードが関係していそうだし、上述のようにサポートが余り親切・適切でなさそうで解決する見込みがないので、止めていた。そして、もし僕の推測した原因が正しかったら、問い合わせても全く解決せず、(いつものように)ただイライラするだけだっただろう。
duplicacyは通常時は問題なく動作しているのだが、上に書いたように異常対応やロバスト性が心許ない気がしているし、サポートの態度にも問題がある。あと、バックアップの対象・除外設定と動作が複雑で頭が狂ってしまう。
そこで、以前書いたKopiaなど新しいバックアップソフトを検討したいが なかなか面倒だし、そっちが良い保証もない。他に やることが溜まっているので、検討するとしても来年と考えている。
PS. 書く前は手短かに終わらせようと思って居たが、長くなったし熱くなった(ムカついた)。調べたら長年苦労して来たし、作者がテキトーなのを思い出したせいだ。それにしても、国内・国外関係なく、いい加減なソフト屋が多い。ハードも同様だ(以前も同じことを書いた)。
