Холмс, 993 вызова исчезли, и лучше не становится. Три ловушки Rust IPC в Tauri 2

Дорогой Шерлок, вы знаете мою слабость к заметкам, задачам и конспектам ваших дедуктивных выкладок. Держу я всё это в приложении, которое сам и пишу: десктоп на Rust Tauri 2 поверх обычной папки на диске.

Новое дело выглядело скромно. Сорок с небольшим записей: несколько заметок, пара таблиц, остальное — ссылки на внешние документы. Решил все перетянуть из одной ветки дерева в другую, ошибся с папкой, нажал undo. И я увидел, как время остановилось. Это было не «подвисло на секунду», а именно вязкое перемещение документов из папки в папку и обратно.

Разберусь сам, подумал я. Делов на один вечер.

Счётчик повесил на границу между интерфейсом и Rust — то окошко, через которое webview передаёт вызовы в бэкенд. Перетащил те же 46 элементов…

1203 вызова

26 вызовов на каждую перетащенную строку. Для сравнения, Холмс: открытие всего воркспейса целиком — со сканированием дерева, метаданными, превью и построением поискового индекса — стоит 1293. А за перенос 46 строк мышью + undo заплатил почти столько же, сколько за запуск с нуля!

Полезной работы в этой тысяче было 46 вызовов, по одному на элемент. Остальные 1111 казались чем-то другим.

По итогу пришлось разбираться три дня и трижды чинить не то. Виновата всё время была одна и та же вещь, просто в разных обличьях: работа, которой не видно и на первый взгляд и на второй…

Как все замерялось

Счётчиков в коде не было — ни числа вызовов, ни отметок времени. Логи ситуацию не проясняли. Пришлось написать свой счетчик.

Дев-обёртка над invoke считает вызовы по имени команды и складывает их время. Сценарий называем сами, чтобы отличать разные замеры в дальнейшем:

__hiveIpc.reset();
__hiveIpc.startScenario("dnd-46");
// … тащим мышью …
__hiveIpc.endScenario();
__hiveIpc.printGlobal();

Сразу оговорюсь, Холмс, чтобы меня не поймали на этом позже: замеры сделаны в дев-сборке. Число вызовов от типа сборки не зависит, а вот время каждого завышено. Дальше я опираюсь на счётчик и на соотношения, а не на абсолютные миллисекунды.

Дело первое: перенос, который дороже запуска

Первый анализ показал - в дампе 1027 вызовов из 1203 читали список задач хотя задачи и не переносились! У каждой папки в дереве может быть свой список дел, на строке рисуется бейдж с их числом. При переносе файлов задачи не меняются вообще — их там и быть не должно.

Сам по себе перенос - ложный след. После дропа документов код вызывал общий рефреш воркспейса, тот шёл в полную перезагрузку, и пересобирал индекс задач по всему дереву — по одному вызову на узел. Вот он и попался! В дампе рядом лежали улики, которые не оставляют сомнений: сканирование дерева, миграция названий заметок, чтение истории отмен, конфига и стилей. Всё то, что делается при первом запуске.

Каждый драгндроп открывал воркспейс заново. Я перевешивал картину и после этого проводил полную инвентаризацию квартиры.

Заодно отметьте мелкую деталь, Холмс, она пригодится далее: при каждом перемещении сущности приложение перечитывает и перезаписывает файл со связями.

Первым желанием было выкинуть рефреш всего дерева. К счастью, я сначала посмотрел, кто на него опирается. Выяснилось, что рефреш — не мусор, а контракт: на нём висело перечитывание истории undo-redo с диска перед записью нового шага, без которого ломалась отмена конвертации документов в папку (это отдельная функциональность), и сброс правил группировки, на который сознательно рассчитывали обработчики сортировки и переноса.

Оказалось уволить дворника было нельзя: он между делом единственный поливал цветы и забирал почту.

Пришлось сначала распределить обязанности — вынести два явных действия, «перечитать историю undo» и «перечитать конфиг стилей дерева», — и только потом облегчать общий путь. Итог: полный рефреш с дропа ушёл. Чтений задач — ноль. Следующий замер того же Dnd вместе с Ctrl+Z дал 297 вызовов вместо 1203!! — важно понимать что это не чистый дроп, а дроп + отмена. Это будет важно для третьего дела.

Дело второе: 993 вызова исчезли, а результат?

Новое дело: это уже не DnD, а открытие папки дерева целиком - на глаз заметно как легкий глитч, не тормоза, но неприятно. Но раз уж начал измерять то идем до конца. Два прогона открытия одной и той же папки — до починки и сразу после. И кто виновник? Опять вмешивается чтение задач: 993 вызова из 1293. Свернул обход в пакетный вызов и сделал индекс ленивым — считаем только то, что человек раскрыл. В итоге счётчик показал 288 IPC вместо начального 1293 - минус 78 процентов. Довольный я пошёл заваривать чай.

Новые замеры. Правда была жесткой. Открытие не ускорилось: количество вызовов упало на 78%, а суммарное время возросло.

Черт возьми, но как, Холмс?

Вы, конечно, уже догадались, что я смотрел не туда. Лично я смотрел на число вызовов. А вы на что-то другое? Копаемся в куче вызовов и находим очень подозрительных сэров: “метаданные”, которые отвечают за теги, бейджи, время создания и тд для каждого документа. Из общей работы (всех IPC) выделяем замеры “чтения метаданных” для тех же двух прогонов открытия — до и после уменьшения всех вызовов IPC на 78%. Получаем:

• было 164 вызова и 38 секунд суммарно,

• стало 190 вызовов и 109 секунд суммарно.

Средний вызов подорожал с 234 до 573 миллисекунд и их стало больше! Мало того, внезапно к сэрам примкнули IPC ребята из клуба “превью ссылок”: их было всего 16 - количество не изменилось, а время среднего выросло с 271 до 622 мсек.

Что происходит?

Здесь нужна оговорка, иначе меня справедливо поправят. Сумма времени всех вызовов — не время открытия: вызовы идут параллельно, и 109 секунд в сумме не значат, что папка открывается две минуты. Но произошло подорожание каждого отдельного вызова, и это ПОСЛЕ того как были убраны ненужные.

Это получается, что дополнительная работа сокращала время выполнения?? Холмс, глаза говорят - возможно Солнце крутится вокруг Земли. Причина таких чудес оказалась дьявольски простой.

Те 993 дешёвых IPC чтения по семь миллисекунд работали турникетом на входе — они растягивали поток запросов во времени.

Я убрал турникет, и все тяжёлые запросы приехали к двери одновременно борясь за желание пройти. Дверь стала открываться каждому в два с половиной раза медленнее. Cтройная, хоть и длинная, очередь крепких ребят и превратилась в давку с дракой.

Лечится это не батчем, а уменьшением запросов. Элемент в папке сначала смотрит в кэш и молчит при попадании, а уже промахи собираются в один пакетный вызов IPC. Сто девяносто отдельных чтений превратились в одно на 87 миллисекунд, это бинго!

И про методику: холодный замер — это сброс кэша или перезапуск приложения. Иначе вы меряете свой собственный прогретый кэш и радуетесь результату. Земля опять крутится вокруг Солнца.

Дело третье: батч, который батч только снаружи

Драгндроп работал, папки со сложными элементами (например, линками на внешние документы) открывались молниеносно. Осталось проверить отмену того самого переноса. Делается это элегантно по-британски Ctrl-Z (Undo). Шерлок, мне кажется, я слишком много гулял голодным на болотах. При отмене линки вальяжно возвращались на моих глазах буквально по одной — около 3х секунд.

Детальные замеры показали что Dnd + undo это 297 вызовов, из них 44 IPC именно undo. Срочно применяем технику оптимизации IPC и видим счетчик undo IPC: 28 вызовов вместо 44. Время отмены улучшилось: 2136 миллисекунд, из них 1836 — диск. Уже лучше, но все еще не достаточно.

Под подозрение сразу попал рояль в кустах - один пакетный вызов внутри работал 1334 миллисекунд, а это уже Rust, это серьезно.

Вот и та “мелкая” лакированная деталь из первого дела. Снаружи это был один вызов и не вызывал подозрения (тк мы меряли количества IPC), а внутри Rust шёл по каждой ссылке и на каждую перечитывал и перезаписывал файл со связями — дважды. Сорок с лишним ссылок примерно и дают те самые полторы секунды.

Я сложил 44 письма в один конверт, курьер съездил один раз, а на почте конверт вскрыли и понесли письма по одному, каждый раз заполняя адрес заново.

Настоящая починка была не на границе IPC, а в глубинах бекенда: одно чтение и одна запись метаданных на пару узлов, пакетное обновление связей и ключей учёта времени и так далее. Это была очень безликая и тягостная работа, которую, впрочем, нужно было обязательно сделать.

Что имеем по факту:

Батч на границе не обещает ничего про то, что происходит за ней. Один вызов может внутри быть тем же N+1, только теперь его не видно в счётчике.

Что из этого следует

Была и четвёртая мелочь, для полноты. Превью читались через границу в base64: файл читается в Rust, кодируется в строку, едет в webview, декодируется обратно — 41 вызов на открытие.

Для PDF на десять мегабайт дорого не число вызовов, а память и кодирование; это как пересылать фотографию, диктуя её по телефону цифрами. Переход на прямой доступ к файлу убрал их все, а время подготовки превью упало с восьми секунд до примерно 240 миллисекунд.

Мой изначальный метод, Холмс, был плох ровно одним: я считал улики вместо того, чтобы их взвешивать. Что я вынес:

1. Счётчик ставится до оптимизаций, иначе чините не то — виновник почти наверняка окажется не тем, кого вы подозревали.

2. Число вызовов и время смотрите раздельно: самый частый и самый дорогой — обычно разные вызовы.

3. Падение числа вызовов может ухудшить тайминги, если вы сняли троттлинг с того, что осталось.

4. Батч на границе процессов не равен батчу на диске — проверяйте, что внутри команды не тот же цикл.

5. N+1 ищите в индексах и фоновых пересборках, а не в видимом UI.

6. Прежде чем резать общий рефреш, выясните, какие побочные эффекты на нём висят: это часто контракт, а не мусор.

7. Холодный замер — только после сброса кэша или перезапуска.

Нераскрытое дело

Одну улику я так и не объяснил. После всех починок новым лидером стала проверка «существует ли файл»: 143 вызова на один перенос с отменой и 47 на раскрытие папки с пятьюдесятью заметками. Часть понятна — галерея и сверка ссылок спрашивают про каждую строку, — но откуда именно 143 на одну операцию, я не понимаю до конца. Рядом ждут своего часа опрос фокуса каждые полсекунды вместо событий и построение поискового индекса на 600–1000 миллисекунд.

Холмс, если у вас есть версия — она нужна мне в комментариях. Заодно интересно, ловил ли кто-нибудь ещё это расхождение: вызовов стало меньше, а тайминги хуже.

Приложение, на котором всё это мерилось: https://github.com/getintessika/intessika