Расширения Chrome иногда могут душить сами себя, попадая в бесконечные циклы. В статье я расскажу о том, как искал причины странного поведения pop-up окна нашего внутреннего расширения. Найдя их, я провёл ряд оптимизаций, а ещё создал чек-лист проверок, которые полезно выполнять перед публикацией нового расширения Chrome.

Привет, Хабр! Меня зовут Анатолий, я занимаюсь фронтендом в компании Циан.

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

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

попап: 76 мс
попап: 153 мс
попап: 1227 мс
попап: 89035 мс

Последнее - почти полторы минуты. И CPU при этом был почти свободен.

Как я уже упоминал, расширение у нас внутреннее: Manifest V3, React, antd - и 208 установок. Оно подменяет заголовки, помогает работать со стейджингом и A/B-экспериментами, показывает ленту аналитики. Попап не отладить через обычную консоль (она закрывается вместе с документом), поэтому он измеряет свой старт сам и отправляет сводку в service worker.

Внутренний таймер отнес 86 из 89 секунд к загрузке бандла и инициализации модулей. Туда я и пошёл в первую очередь.

Бандл не объяснял 89 секунд

popup.js весил 1,96 МБ: antd - 474 КБ, react-dom - 177 КБ, своего кода 57 КБ. Подозреваемый, казалось, был очевиден. Бандл большой - наверное, дело в этом.

Замеры моё предположение не подтвердили. Компиляция всего бандла заняла 18 мс - то есть на этой сборке она узким местом не была вообще. Заметное время занимала только инициализация модулей antd - около 280 мс в jsdom: лишняя треть секунды, но не 89 секунд! Инициализация точно никак не объясняла, почему к вечеру проблема исчезает.

Заодно проверил на практике народный совет: “Импортировать нужно не из индекс-файла antd, а из antd/es/…”:

import { Button } from 'antd'
//или
import Button from 'antd/es/button'

Оба варианта дали одинаковые 523 КБ. В нашей сборке процесс tree shaking уже сделал свою работу, и переписывать импорты было незачем. Подобные расхожие советы стоит проверять замером, а не применять, потому что вы это где-то слышали.

День ушёл, к причине я так и не приблизился.

Имя ключа в логе

Строить дальнейшие гипотезы мне помог не профайлер, а лог медленных операций.

Вокруг обращений к chrome.storage.local у нас есть обёртка, которая засекает время каждой операции и пишет предупреждение, если та заняла больше 150 мс. Когда таких операций нет, лог молчит. В первой версии он печатал только их общую длительность:

storage.set: 21800 мс

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

get giteaToolsCustomPatterns: 15289 мс
set giteaToolsFileStats:       6647 мс
set giteaToolsFileStates:      7941 мс
get giteaToolsCustomPatterns: 21947 мс

Все три ключа были частью одной нашей фичи, инструментов для страницы диффа в Gitea: счётчики файлов, состояния фильтров и пользовательские шаблоны. Деактивация сбрасывает их вместе с флагом включения giteaTools.

Двадцать секунд на один ключ! Поиск по префиксу привёл наше расследование к двум местам: функции деактивации и обработчику storage.onChanged, который её вызывал.

Цикл, который сам себя запускает

Обработчик и функция деактивации по отдельности выглядели нормально. Вместе они замыкались в цикл. Ниже упрощённый эквивалент на чистом chrome.storage: в проекте обработчик подписан через watch() из Plasmo, но на сам цикл это не влияет.

chrome.storage.onChanged.addListener((changes) => {
  if (changes.giteaTools?.newValue?.enabled === false) {
    deactivateGiteaTools();
  }
});

async function deactivateGiteaTools() {
  // снимаем подсветку, чистим состояние...
  await chrome.storage.local.set({ giteaTools: { enabled: false } });
}

Обработчик реагирует на выключение инструмента и вызывает деактивацию. Деактивация в конце записывает в тот же ключ enabled: false - то есть ровно то значение, которое там уже лежит!

Казалось бы, второй раз событие прийти не должно - значение-то не поменялось. Документация описывает onChanged одной строкой: «Fired when one or more items change». Прочитав её, легко сделать вывод, что повторная запись того же значения событие не вызовет. А наш обработчик изменял то состояние, на изменение которого сам был подписан, входя в петлю. Потому что нигде нет гарантий, что эквивалентная запись будет отфильтрована до вызова обработчика!

В нашей связке повторная запись приводила к новому событию - это наблюдаемый факт из лога. Разбираться, на чьей стороне так решили - Chrome или @plasmohq/storage, через который у нас проходят значения, - мы не стали: правильный обработчик выглядит одинаково в обоих случаях. Он сравнивает только переход состояния, и он не учитывает, было ли отфильтровано то же самое значение. Расчёт на уже предусмотренную фильтрацию - лишнее допущение о чужом коде, которое ничего не экономит.

Отсюда два правила.

Первое: обработчик проверяет переход состояния, а не текущее значение.

chrome.storage.onChanged.addListener((changes) => {
  const change = changes.giteaTools;
  if (!change) return;

  const wasEnabled = change.oldValue?.enabled === true;
  const isEnabled = change.newValue?.enabled === true;

  if (wasEnabled && !isEnabled) {
    deactivateGiteaTools();
  }
});

async function deactivateGiteaTools() {
  // побочные действия должны спокойно переживать повторный вызов
  await removeHighlightIfPresent();
  await clearRuntimeStateIfPresent();
}

Сравнивать нужно в том формате, который получает конкретный обработчик: watch() из Plasmo отдаёт уже разобранный объект, а на chrome.storage.onChanged приходит то, что физически лежит в хранилище. В нашем случае это строка.

Второе: из обработчика не пишите то, о чём событие уже сообщило. У нас запись всё же осталась - деактивация чистит несколько ключей одним setMany, и флаг записывается вместе с ними. Поэтому дополнительно понадобилась защита от повторного входа, которая сбрасывается при следующей активации. Если такой связки у вас нет, будет проще её и не создавать.

Почему ждал попап

Цикл крутился в service worker. Попап - отдельный документ, своя память, свой код. Почему он-то стоял?

У всех частей расширения общим оказалось само хранилище, не переменная. Все три части собираются одним Plasmo-билдом, но выполняются независимо:

chrome.storage - не объект в памяти, а асинхронное хранилище в процессе браузера. Чтения и записи из попапа, контент-скрипта и service worker уходят туда отдельными запросами. Поток фоновых операций как раз и задерживал запуск попапа. Такое взаимодействие с процессом браузера называют IPC - inter-process communication; подробности - в документации chrome.storage.

Отсюда же три симптома, которые сбивали с толку:

Последнее стало для меня правилом: если в Manifest V3 проблема «сама проходит», первым делом проверяю перезапуск service worker.

Тут же нашлось и объяснение для таймера, который отправил меня в бандл. В логе стояло бандлИИнитМс = 86769: почти всё время попап якобы провёл в загрузке бандла и module-init. Вот из чего складывается то же время на машине без этой проблемы:

Чтение хранилища здесь занимает 1 мс, и в период высокой нагрузки оно оставалось таким же: внутри своего кода попап почти не ждал операций хранилища. Пока расширение обрабатывало очередь операций, запуск кода попапа просто не начинался - а замер записал всё это ожидание в ближайшую фазу, которую умел различать.

То есть замер не врал. Он просто определил границу слишком грубо.

Та же ошибка ещё в трёх местах

Цикл ушёл, в логе остался ровно один setMany от деактивации. Но предупреждения о медленных операциях не исчезли. Разбор лога скриптом дал 106 медленных операций за сеанс:

Каждая операция возвращала правильный результат - ошибка была в их количестве. Фон восемнадцать раз за минуту читал один и тот же флаг и писал null поверх null, словно работал с локальным объектом, а не с асинхронным хранилищем, обращаться к которому каждый раз дорого.

Для этих проблем антирейтинг (после цикла у storage.onChanged) был таким:

Место второе - попап. Наш хук useCustomStorage(key, default) внутри вызывает useStorage из @plasmohq/storage, а тот делает ровно что обещает: один ключ - одно чтение и одна подписка. Удобно, пока ключей два-три; их оказалось 25. Публичный API хука мы не тронули - все 49 мест вызова остались, как были. Батчинг уехал внутрь: один экземпляр, один слушатель, одно чтение всех ключей, запрошенных за первый коммит React. Для связки подошёл useSyncExternalStore. Проблема была не в библиотеке, а в масштабе использования, и заметна она стала не у нас, а на чужой машине под нагрузкой. Чем меньше мощность машины и чем больше вкладок открыто, тем вероятнее проблема.

Место третье - загрузка деплоев. Функция loadDeployments спрашивает у внутреннего сервиса, какие версии микросервисов развёрнуты, и кэширует ответ с TTL в минуту. В замере эта функция давала 5,7 секунды по двум причинам. Отметка lastUpdated записывалась только после возврата обоих запросов. Пока ответ в полёте, TTL никого не останавливал, и каждый следующий вызов запускал ещё одну полную загрузку. А триггером был webNavigation.onBeforeNavigate, который срабатывает и на подкадрах: на странице их десятки, и каждый iframe запускал загрузку заново. Повторные вызовы стали ждать ответ первого, фильтр frameId === 0 отсёк подкадры - 5673 -> 179 мс.

Если снять с этих трёх случаев обёртку из chrome.storage, под ней окажутся давно известные вещи: N+1 запросов, запись без проверки на изменение, отсутствие склейки одновременных обращений и кэш, расходящийся с источником. Ничего экзотического. Просто chrome.storage выглядит как объект в памяти - вот и обращаются с ним как с объектом, хотя это база с очередью и задержками!

Помогли справиться с “тормозами” четыре меры: 

• батчить чтения,

• пропускать записи неизменившихся значений,

• кэшировать часто читаемое с одним слушателем onChanged на свежесть,

• не складывать в ключ лишнего.

Последняя мера сначала не сработала. Главным писателем после кэша стал set activeTabBrowser - ключ, куда фон кладёт текущую активную вкладку (благодаря этому  попап и сервисы знают, с чем работают). Самая долгая запись заняла почти 19 секунд. Кэш их не отсекал, потому что в ключ писали весь объект chrome.tabs.Tab. В нём лежит lastAccessed, который меняется на каждом событии, поэтому сравнение ни разу не посчитало значения одинаковыми. Оставили только id и url - единственное, что читали потребители, которым требовалась только активная вкладка.

У кэша есть и ловушка, которую мы пока не закрыли: он обновляется до подтверждения записи. Упавшая запись оставит в памяти значение, которого в хранилище нет. А поскольку не изменившиеся значения больше не пишутся, повторная попытка будет пропущена - и расхождение проживёт до перезапуска service worker.

Что показали контрольные замеры

После исправлений и оптимизаций я повторил замеры на своей машине - та же production-сборка, тот же сценарий:

И ни одного предупреждения о медленном хранилище за сеанс! На машине коллеги зависания попапа прекратились, всё работало штатно.

Прокомментирую саму цифру 89 035 мс: это пиковое значение, а не среднее. Ровно один замер на пике шторма. По тем же логам после первого этапа исправлений были быстрые открытия 127–252 мс и отдельные зависания на 16,8 и 63,1 секунды.

Побочный результат. При разборе бандлов нашёлся импорт из нашего же индекс-файла с UI-компонентами: он затягивал всю antd в контент-скрипт, который ни одного её компонента не использует. Прямой импорт нужного модуля уменьшил контент-скрипт с 1928 до 584 КБ, это минус 1,3 МБ в каждой открытой вкладке. К зависанию попапа это не относилось, поэтому подробности оставлю для отдельного материала.

Чек-лист перед публикацией расширения

Если хочется избежать аналогичных ошибок, перед публикацией я бы проверил следующее.

• Есть ли обработчики onChanged, которые сами пишут в storage? Сравнивают ли они старое состояние с новым?

• Безопасен ли повторный вызов операции?

• Пропускаются ли записи не изменившихся значений?

• Не попадает ли в ключ лишнее - поля, которые никто не читает, и поля, которые меняются сами?

• Батчатся ли чтения при старте интерфейса?

• Обновляется ли кэш только после успешной записи?

• Ждут ли повторные одинаковые запросы ответа первого?

• Отфильтрованы ли лишние события - frameId === 0 у навигации, changeInfo.status у tabs.onUpdated? (Фильтра событий у него нет: UpdateFilter существует только в Firefox.)

• Логируются ли медленные операции вместе с именем ключа - и включено ли это в production-сборке? Иначе о проблеме вы узнаете только со слов пользователя.

• Проверено ли всё это на production-сборке там, где проблема воспроизводится?

Что я вынес для себя

По отдельности обработчик и функция деактивации выглядели нормально. Ревью каждого из них ничего бы не дало: корень проблемы был в связи между ними, а такую связь не видно в диффе.

Обнаружить её помогли не профайлер или чтение кода, а одна строчка лога с именем ключа. Пока лог печатал только длительность, он давал понять, что “тормоза” есть, но не показывал, где они. Имя ключа помогло обнаружить проблемное место.

Удалось сформулировать правило, которое я теперь применяю первым: если CPU почти свободен, а интерфейс всё равно подвисает, то проблему создаёт не объём кода. Нужно искать, что этот код делает снова и снова, пока человек ждёт.