Apple

EKEventStoreChanged は自分自身の変更でも飛んでくる

  • macOS
  • Swift
  • EventKit
  • Vigilare
  • パフォーマンス

Vigilare の一覧で完了チェックを1回つけるだけで、EventKit のリマインダー全件フェッチが2回走っていました。保存処理を行うと、自分の変更に対しても EKEventStoreChanged が飛んできます。その通知を外部からの変更と同じ経路で受けてフルリロードしていたので、操作側の明示リフレッシュと合わせて2回になっていました。

通知には誰が変更したのかを示す情報がないので、操作中に届いた通知は捨て、操作の最後に必ずリストとリマインダーを読み直す形にしました。実機で全件フェッチは1回に減りましたが、操作の所要時間は変わっていません。

VigilareFloating Reminders for macOSKeep your Apple Reminders always on top with a floating window for macOS. Works in fullscreen apps, with quick actions, list filtering, and a built-in Markdown editor.

完了チェック1回で EventKit を3回読みに行っていた

Vigilare はタスクを保存する自前のデータベースを持たず、Apple の標準リマインダーと同じ EventKit のストアを直接読み書きしています。この構成は前の記事で扱いました。

ブログEventKitのcalendar(withIdentifier:)はcalendars(for:)と食い違うことがあるVigilareのMCPツールでlist_idを指定してもリマインダーが絞り込まれないことがある不具合を修正しました。原因はEventKitの2つのカレンダー取得APIが食い違う場合があり、片方だけがnilを返す状況でエラーなく「全カレンダー」へフォールバックしていたことです。

標準アプリや iPhone 側で加えた変更を拾うために、EventKit のストアをラップしている層が EKEventStoreChanged を購読しています。届いたら EKEventStore.reset() で内部キャッシュを捨て、アプリ内の変更通知に変換します。

一覧画面はそれを受けて再読込の要求を積み、150ms のデバウンスを挟んでから、リストの列挙とリマインダーの全件フェッチを両方やり直します。外部変更はいつ来るか分からないので、全部読み直す側に倒しています。

一方で、一覧の行に対する操作は一覧のビューモデルが担っています。完了、削除、期限の変更、リストの移動、複数選択の一括操作などです。どれも EventKit への書き込みが終わると、自分でリマインダーを読み直していました。

外部変更は通知経由、自分の操作は明示リフレッシュ、という分担です。この分担には穴があります。EKEventStoreChanged は外部プロセスの書き込みだけでなく、自分のストアで save を呼んだときにも飛びます。SDK の EKEventStore.h に、この定数の説明としてそう書いてあります。

Notification name sent out when the database is changed by either an external process, another event store in the same process, or by calling saveEvent: or removeEvent: on a store you are managing. When you receive this notification, you should consider all EKEvent instances you have to be invalid.

自分の書き込みでは、明示リフレッシュに加えて通知経由のリフレッシュまで走ってしまいます。通知経由で走るのは外部変更を想定したフルリロードなので、完了チェック1回で「明示リフレッシュのリマインダー全件フェッチ」「通知経由のリスト列挙」「通知経由のリマインダー全件フェッチ」の3回になります。

リマインダーの全件フェッチは軽くありません。別のタスクで計測したときは、リマインダーが約3,200件ある iCloud アカウントで1回あたり中央値 768ms でした。

ログを仕込んで実機で順番を測った

直す前に、本当にそうなっているかを実機で確かめました。知りたかったのは回数よりも順番です。通知が save() の後に届くのか、途中で届くのかで、取れる手が変わります。

OSLog に計測専用のサブシステム(com.example.echoprobe のような名前)を切り、一時的なログを仕込んでビルドしました。ログを入れたのは、リマインダーの全件フェッチとリストの列挙、save() の前後、通知オブザーバー、ビューモデル側の完了トグルと明示リフレッシュ、通知由来の再読込の積み込みと実行です。

一覧の完了チェックを1回クリックして、ログを取り出します。

log show --predicate 'subsystem == "com.example.echoprobe"'

Vigilare には MCP サーバーが内蔵されていますが、そちらから操作すると別プロセスからの書き込みになり、ヘッダーにある external process の方に当たってしまいます。今回見たいのは自分のプロセスの書き込みなので、GUI の操作で測りました。

修正前のビルドで、完了チェック1回分のログを整形したものがこれです。

#3  +13788ms 完了トグル 開始
#4  +13800ms save() 呼び出し
#5  +13815ms EKEventStoreChanged 受信
#6  +13817ms save() 復帰
#7  +13818ms 通知由来の再読込を積む
#8  +13884ms 明示リフレッシュ 開始
#9  +13884ms リマインダー全件フェッチ(1本目)
#10 +13972ms 通知由来の再読込 開始(デバウンス後)
#11 +13972ms リスト列挙
#12 +14107ms リマインダー全件フェッチ(2本目)
#13 +15041ms 完了トグル 終了

読み取れたことが4つあります。

通知は save() が戻る前に届いています。#5 のオブザーバー発火が、#6 の save() 復帰より 2ms 早いのです。後で述べるとおり、この順番だと取れる手はかなり限られます。

#7 で通知由来の再読込が積まれてから #10 で実行されるまで 154ms で、150ms のデバウンスどおりです。通知が連打されているわけではなく、設計どおり1回に畳まれたうえで、それでも明示リフレッシュと二重になっています。

EventKit を読みに行った回数は3回です。#9 が明示リフレッシュのリマインダー全件フェッチ、#11 と #12 が通知経由のリスト列挙とリマインダー全件フェッチで、全件フェッチだけ数えると2回です。

もうひとつ、通知由来のフェッチ #12 が、明示リフレッシュがまだ走っている最中に始まっています。完了トグルは明示リフレッシュの完了を待ってから #13 を出すので、#12 の時点でまだ終わっていないことが分かります。

リマインダーを読み直す処理が2本同時に走る区間が、特殊な操作ではなく完了チェック1回で毎回できていたということです。この重なりは別のタスクで「実害は未計測の理論上の競合」と評価して優先度を下げていたのですが、日常操作で常時起きていました。

修正後のビルドで同じ操作を測ったログ(後述)と並べると、通知が届く位置は同じで、違うのはそこから先だけです。

完了チェック1回分の時系列を修正前と修正後で並べた図。どちらも EKEventStoreChanged は save() が戻る 2ms 前に届く。修正前はその通知が外部変更と同じ経路に入り、明示リフレッシュがまだ走っている最中に2本目の全件フェッチが始まる。修正後はその通知が操作中なので捨てられ、操作後の再読込1本だけが走る

順番が分かったことで、既存のテストの前提が違っていたことも分かりました。この2回フェッチを現状値として固定していたテストは、完了トグルが終わった後に通知を流し込む書き方で、「通知は操作の後に来る」前提になっていました。実機では操作の途中に来ます。

通知からは自分の書き込みかどうか分からない

通知に「誰が変えたか」や「何が変わったか」が付いていれば、自分の書き込み分だけ無視すれば済みます。付いていません。

EKEventStore.h にあるのは上で引用した説明と定数の宣言だけで、EventKit のヘッダー全体を grep しても、変更元や変更されたオブジェクトを伝える userInfo のキーはひとつも宣言されていません。

Apple の EKEventStoreChangedNotification のドキュメントにも「Individual changes are not described」とあります。

通知の object はオブザーバーを登録したストア自身です。Vigilare は自分のストアを object に指定して購読していて、それでも他のプロセスからの変更が届くので、object を見ても、誰が変更したのかは分かりません。

区別は API の外、アプリ側でつけるしかありません。候補を3つ検討して、どれも採りませんでした。

明示リフレッシュをやめて通知経路に一本化する案は、フェッチが1回になる代わりに、操作後の画面反映がデバウンスの 150ms ぶん遅れます。行操作の反応をその分遅らせたくなかったので採りませんでした。

ストアをラップしている層で、アプリ内の変更通知を発行すること自体を止める案は、購読者が一覧だけではないので却下です。詳細画面のインスペクターも同じ通知を購読して、開いているリマインダーを最新の状態に更新しています。ストア側で止めると、そちらまで巻き込みます。

save() が戻ってから「次の1件は無視する」期間を設ける案は、計測結果を見た時点で消えました。通知は save() が戻る前に届いています。戻ってから期間を区切っても間に合いません。時間で区切る案も、その長さが当てずっぽうになるので採りません。

抑制するなら、購読側であるビューモデルがリフレッシュするかどうかを決める形にした方が、影響範囲を小さくできます。

操作中に届いた通知は捨て、操作の最後に必ず全部読み直す

採ったのは、誰が変更したのかを見分けない形です。

一覧のビューモデルには、操作中のリマインダー ID を入れておく集合がもともとありました。同じ行に対する操作が重ならないようにするためのものです。これを「空でなければ操作が進行中で、その操作は必ず読み直しで終わる」と読み替えました。

通知を受けて再読込を積む入口で、この集合が空でなければ通知を捨て、捨てたという事実だけをフラグに残します。概略はこうです。

func requestRefresh() {
  if !inFlightReminderIDs.isEmpty {
    discardedWhileInFlight = true
    return
  }
  // ここから先は従来どおり、デバウンスを挟んで読み直す
}

捨てた通知は、自分の書き込みが跳ね返ってきたものなのか、たまたま同じタイミングで来た外部変更なのか、判定しません。どちらであっても、操作の最後に走る読み直しが拾うようにしたからです。

そのために、十数箇所ある行操作のメソッドの終わりを1つの処理に統一し、中身をリマインダーだけでなくリストも含めた読み直しにしました。フラグを下ろすのは読み直しの開始前です。読み直しが始まる前に届いた通知は、その通知が指す変更も読み直しが拾うので、ここで下ろして差し支えありません。

読み直しが始まった後に届いた通知と、書き込みに失敗して読み直しまで辿り着かなかった操作は、操作を抜けるときに拾い直します。各メソッドが defer で直接集合を触っていたのをやめて、操作の終了処理に寄せました。集合が空になった時点でフラグが立っていれば、通常の経路で再読込を積み直します。

func finishOperation(_ ids: Set<String>) {
  inFlightReminderIDs.subtract(ids)
  guard inFlightReminderIDs.isEmpty, discardedWhileInFlight else { return }
  requestRefresh()
}

通知が届いてからの分岐と、操作の終了処理での拾い直しは、3つの処理をまたいだループになっています。

EKEventStoreChanged が届いたあとの分岐と、操作の終了処理での拾い直し。操作中でなければ従来どおり 150ms のデバウンスを挟んでリストとリマインダーを読み直し、操作中なら通知を捨てて、捨てた事実だけをフラグに残す。操作の側では、操作後の読み直しがフラグを下ろしてから読み直し、終了処理が ID を集合から外した時点でフラグが立っていれば再読込の要求に戻す。書き込みに失敗した操作は操作後の読み直しを通らずに終了処理へ進む

読み直しの範囲とフラグのリセット位置で2回作り直した

この形に落ち着くまでに、レビューで2回止まっています。

最初の版では、操作後の読み直しがリマインダーだけでした。行操作はリマインダーしか書き換えないので、リストまで読み直す理由がないように見えます。

テックリードのレビューで指摘されたのは、捨てた通知が外部のリスト作成やアーカイブによるものだった場合です。その通知はもう二度と来ないので、サイドバーのリスト一覧がずっと古いままになります。

誰が変更したのかを見分けないと決めた以上、操作後の読み直しは通知経由と同じ範囲を読み直すことになります。

リストの列挙は、以前のタスクで未完了件数の集計をやめてからカレンダーを並べるだけの処理になっていて、全件フェッチ1回を削って浮いた分に比べれば安く済みます。

2回目は、パフォーマンス観点のレビューで、フラグのリセット位置が問題になりました。最初は読み直しの await が終わった後でリセットしていました。

そうすると、自分の読み直しがフェッチしている最中に届いた通知は、集合が空ではないので捨てられ、その直後のリセットで捨てた事実ごと消えます。走り始めているフェッチが、その通知の指す変更を読めている保証はありません。

リマインダーの全件フェッチが中央値 768ms かかるアカウントでは、その 768ms のあいだに届いた外部変更を、まるごと取りこぼす形になっていました。リセットを読み直しの開始前に移し、開始後に届いた分は終了処理が拾う形に直しています。

テストはリフレッシュ回数を固定するテストに数本足しました。本命は、モックの save にゲートを仕込んで「通知が書き込みの最中に届く」順番を決定論的に再現し、全件フェッチが1回になることを見るものです。

ほかに、読み直しのフェッチ中に届いた通知が取りこぼされないこと、書き込みが失敗しても捨てた通知が拾い直されること、操作が進行中でなければ通知がそのまま反映されることも、それぞれ固定しています。2回フェッチを固定していた古いテストは、本命のテストで置き換えました。

本命のテストと取りこぼしのテストは、実際に該当ロジックを外して、その1本だけが落ちることを確かめています。

全件フェッチは1回に減り、所要時間は変わらなかった

同じログ入りのビルドで、修正後の完了チェック1回分を測り直しました。

#3  +4044ms 完了トグル 開始
#4  +4053ms save() 呼び出し
#5  +4065ms EKEventStoreChanged 受信
#6  +4067ms save() 復帰
#7  +4068ms 通知由来の再読込を積む(操作中: 1件)
#8  +4068ms 通知を捨てる
#9  +4124ms 操作後の読み直し 開始
#10 +4124ms リスト列挙
#11 +4136ms リマインダー全件フェッチ(1本だけ)
#12 +5308ms 完了トグル 終了

通知は相変わらず save() が戻る 2ms 前に届いていて、#8 で捨てられています。順番を測った節に載せた図の右側がこのログです。

指標(完了チェック1回あたり)BeforeAfter
リマインダー全件フェッチ2回1回
リスト列挙1回1回
通知由来の再読込1回0回
リマインダー読み直しの同時実行ありなし
操作の所要時間(開始から終了)1253ms1264ms

減ったのはリマインダー全件フェッチ1回分で、リマインダーが約3,200件あるアカウントなら、行操作1回ごとに 768ms 規模の EventKit の処理が裏で1本消える計算になります。

副産物として、修正前に見えていた「リマインダーの読み直しが2本同時に走る区間」もなくなりました。

操作の所要時間は変わっていません。1253ms が 1264ms で、誤差の範囲です。完了チェックの体感を決めているのは明示リフレッシュ側の読み直しで、それはもともと1回しか走っていなかったからです。

この変更で減ったのは EventKit にやらせる処理の総量であって、操作のレスポンスではありません。メニューバーに常駐して動き続けるアプリなので、裏で消える処理に意味はありますが、速くなったと書くのは正しくありません。

操作後の読み直しにリストを含めた副作用もあります。以前のリスト列挙は通知経路のデバウンスを挟んで走っていて、連続操作では複数の通知が1回の読み直しに畳まれていました。操作後の読み直しに移したことで、行操作ごとに独立したリスト列挙が走るようになります。

リスト一覧を書き込む処理は世代ガードの対象外だったので、別々の行を素早く連続操作したときに古い結果が新しい結果を上書きしうる状態になります。こちらはリマインダー側と同じ世代ガードを入れて塞いであります。

二重フェッチが残っている操作

抑制が効くのは、操作中の ID の集合に ID を入れる操作だけです。リマインダーの新規作成と複製は、書き込む前に ID が存在しないので集合に入らず、操作後の読み直しは走るものの、通知の方は捨てられません。

作成1回でフェッチが2回走るケースは残っています。この記事を書くためにコードを読み直して気づいたもので、実機では測っていません。

詳細画面の自動保存も対象外です。ノートを編集していると、手が止まるたびに自動保存が走り、そのたびに同じように自分の書き込みが通知になって返ってきますが、詳細画面は別のビューモデルで、この集合の仕組みに乗っていません。

効果を一番体感しやすいのはこのケースなので、そのうち手を入れようと思っています。