Один из аспектов моей работы как индивидуального сотрудника Atlassian - устранение ошибок в производственной среде. Это может быть сложной и приятной формой решения проблем. Недавно я помог понять и исправить периодически возникающую проблему с Jira Cloud. Это была интересная история не только из-за основной причины, которую мы наконец обнаружили, но и потому, что она показала мне несколько интересных аспектов этого процесса:

  • Проблемы, с которыми мы сталкиваемся, меняются в зависимости от масштаба, и по мере роста нам необходимо находить и исправлять новые проблемы.
  • Решение проблем может быть очень итеративным процессом, когда вопросы, ответы на которые приводят к новым вопросам, являются неотъемлемой частью процесса.
  • Иногда наши вопросы не приводят к хорошему ответу, и мы заходим в тупик. Это не решает и не устраняет проблему, но заставляет нас подвергать сомнению наши предположения и исследовать различные части системы.

Небольшая справочная информация о вероятности

Предположим, я подбрасываю честную монету - вероятность того, что вы увидите голову, составляет 1 из 2. Если я подброшу дважды, какова вероятность выпадения двух орлов? Это 1 из 4 (= 2 x 2). Три головы из трех подбрасываний? 1 из 8 (= 2 х 2 х 2). Тридцать голов после тридцати бросков подряд? 1 из 1 073 741 824 - примерно один на миллиард. Это кажется маловероятным, правда?

Однако что, если я сделаю это примерно 10 раз в миллисекунду? То есть примерно 10 000 раз в секунду. Получается примерно 10 000 x 60 x 60 x 24 = 864 000 000 раз в день. В этом случае вы ожидаете, что все тридцать бросков выпадут орлом примерно в 80% дней, или примерно 5 или 6 раз в неделю.

Другими словами, события, которые кажутся редкими однажды, не являются редкостью в достаточно больших масштабах.

При чем здесь Jira?

Как упоминалось во введении, эта история касается периодически возникающей проблемы с Jira Cloud. Это происходило примерно раз в неделю, плюс-минус. Достаточно редко, чтобы показаться странным, но достаточно повторяющимся, чтобы потребовать расследования.

Симптомы были очень странными. Началось с переполнения стека. Как только один из узлов в кластере Jira испытал это переполнение стека, этот узел получил их в огромных объемах - например, почти 14000 в минуту. Единственный выход - убить узел. В стеке, когда мы его получили, был повторяющийся раздел, который выглядел как

Здесь я сжал имена пакетов, первый и последний кадры взяты из классов в com.atlassian пакете, а все остальные кадры взяты из открытого исходного кода или кода JDK: sun.reflect, java.lang, org.springframework и org.eclipse.gemini. Единственный код Atlassian - это первый и последний фреймы, и даже тогда они на самом деле являются прокси-серверами, созданными CGLIB - детали реализации пересечения границ OSGi между компонентами (называемыми пакетами) монолита Jira. Если вы проверите код для UserBeanFactory.buildUserBeans, он не вызывает себя, и поэтому у нас не было объяснения очевидной рекурсии выше.

Эти прокси OSGi используются для соединения загрузчиков классов между пакетами. Когда один пакет хочет вызвать метод (в данном случае UserBeanFactory.buildUserBeans) в другом пакете, он вызывает метод на прокси-сервере. Этот прокси-сервер находит нужную службу OSGi в другом пакете и перенаправляет вызов с небольшим добавлением специального соуса загрузчика классов.

Или, по крайней мере, это то, что он должен делать. В этом случае на самом деле он обнаруживает себя и вызывает себя, что приводит к бесконечной регрессии и переполнению стека. Конечно, он не воспроизводился, когда я запускал Jira локально, даже когда я запускал его вместе с запущенными промежуточными службами и с URL-адресами запросов, которые имитировали те, которые были замечены в производственном журнале. Когда бы я ни пытался, он правильно находил нужную базовую службу OSGi.

После небольшой отладки удачного пути по коду у меня появилась теория, что симптомы могут возникнуть, если правильная служба была удалена, в зависимости от того, как код обрабатывал резервные копии, когда правильная служба отсутствовала. OSGi - это динамическая система, которая позволяет регистрировать и отменять регистрацию сервисов во время выполнения, что, в свою очередь, позволяет обновлять код во время выполнения. Таким образом мы обновляем пакеты в наших серверных продуктах, обеспечивая обновления среды выполнения для серверных плагинов. В облаке мы не обновляем пакеты во время выполнения, а повторно развертываем монолит для обновления кода. Таким образом, эта отмена регистрации пакета никогда не должна происходить в Jira Cloud, но, возможно, наследие нашего сервера повторно появилось в результате какой-то ошибки?

Итак, мы добавили логирование

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

OSGi ServiceEvent detected: type 4 service [com.atlassian.jira.rest.v2.factory.UserBeanFactory]

type 4 - это событие UNREGISTERING в соответствии с константами в org.osgi.framework.ServiceEvent. Однако мы не знали, почему это было вызвано - я не включил стек. Сотрудник вмешался, чтобы добавить запись для трассировки стека для этого случая. После немного большего ожидания мы были вознаграждены:

OSGi ServiceEvent detected: type UNREGISTERING service [com.atlassian.jira.rest.api.permission.PermissionSchemeBeansFactory]

Интересно, что в этом случае переполнения стека не произошло, и сервис уже не тот, который мы видели раньше. Однако это была отмена регистрации, и в ней был стек, который привел меня к имеющемуся у нас пути кода, который реализует компоненты с ограниченным объемом запросов. Он выполняет итерацию по коллекции destructionCallbacks, чтобы уничтожить компоненты области видимости запроса в конце запроса. Теперь ни UserBeanFactory, ни PermissionSchemeBeansFactory не имеют области действия запроса, так почему они уничтожаются?

Поэтому мы снова добавили ведение журнала, на этот раз для регистрации вызовов пути кода, ответственного за регистрацию обратных вызовов, которые были задействованы в приведенном выше стеке, то есть кода, добавляющего записи в коллекцию destructionCallbacks. Я рассудил, что каким-то образом в эту коллекцию попадают неправильные бобы, и это их пометит. Мы сразу увидели в журналах регистрацию известного bean-компонента с ограниченным объемом запроса, имеющего дело с контекстом URI, поэтому я был уверен, что ведение журнала правильно помечает регистрации.

В конце концов, мы снова увидели неожиданное UNREGISTERING событие. Взволнованный, я вернулся, чтобы узнать, как ему удалось попасть в destructionCallbacks, и вытащил пробел. Нет регистрации. Правильно - мы никогда не регистрировали bean-компонент для уничтожения, но все же у нас была трассировка стека, вызывающая логику уничтожения.

Это было довольно удивительно.

Итак, мы посмотрели еще раз

В этот момент я знал, что происходит что-то очень странное. В журнале для добавления обратного вызова регистрировались только ожидаемые вызовы, а логика уничтожения отменяла регистрацию неожиданных bean-компонентов. Как такое могло произойти? Это побудило меня снова изучить первоначальный стек разрушения - очень внимательно. Каким-то образом, рассудил я, это могло быть вызвано неправильным бобом. Что-то где-то должно было ошибочно принять уничтожение bean-компонента с областью действия запроса за уничтожение служб OSGi.

Кадр за кадром я шел по коду, помня о том, что что-то, должно быть, перекрещивает провода. Наконец, я нашел то, что искал, в Spring Scanner - расширении Spring, которое мы используем, чтобы упростить написание плагинов Atlassian с использованием аннотаций. Рассматриваемый код был:

Здесь exporters - это Hashtable<Integer, OsgiServiceFactoryBean> - он отображает bean-компоненты (через их identityHashCode - подробнее об этом чуть позже) фабрике служб, которая их создала.

Этот код в Spring Scanner вызывается из реализации Spring DestructionAwareBeanPostProcessor, в частности ее postProcessBeforeDestruction. Это работает так: каждый Spring BeanFactory получает уведомление о том, что компонент собирается быть уничтожен. Это позволяет фабрике принять меры в случае необходимости. Spring Scanner использует это для удаления служб OSGi при удалении подключаемых модулей на сервере.

Так что такое identityHashCode? Он возвращает тот же результат, что и реализация Object hashCode для предоставленного объекта. Почему, черт возьми, этот код использует это?

Немного истории

Чтобы понять identityHashCode, нам понадобится немного истории. Насколько я понимаю, в начале своего развития Java работала только на 32-битных машинах. Он не использовал копирующий сборщик мусора, поэтому объекты занимали один и тот же адрес в памяти на протяжении всей своей жизни. В этом мире есть хорошая дешевая реализация hashCode - вы возвращаете указатель на объект как 32-битное целое число.

Это отличный hashCode. Он стабилен - не меняется за время жизни объекта. Он также уникален для всего срока службы Object. У разных объектов разные хэш-коды. Обратите внимание, что этого не происходит с большинством хэш-кодов - обычно они теряют информацию. Однако в этом особенном мире этого не происходит. Это означало, что вы могли использовать hashCode для запоминания Object идентичности без сохранения объекта. Это дает очень удобный способ отслеживать объекты, которые вы видели, без риска осложнений при сборке мусора. В мире, где раньше не было слабых ссылок, это было очень полезно. Фактически настолько полезен, что System.identityHashCode позволяет вам получить это значение, даже если класс объекта предоставляет свою собственную hashCode реализацию.

Однако с тех пор многое изменилось. Теперь у нас есть копирующие сборщики мусора, поэтому на самом деле вам нужно сохранить хэш-код на объекте, чтобы он был стабильным. У нас есть лучшие решения (слабые ссылки) для проблем со сборкой мусора. Однако, что наиболее важно в этой истории, мы перешли на 64-битные JVM. Когда это было сделано, API для identityHashCode не изменился. 64-битная JVM может создавать более 2 ^ 32 объектов. Еще больше. Это означает, что identityHashCode больше не может быть уникальным, как бы вы это ни реализовали.

Когда я это узнал, это называлось принцип голубятни. Если у вас больше N голубей, и вам нужно поместить их в N голубятней, то как минимум два голубя окажутся в одной голубятне. Если у нас есть более 2³² объектов и мы пытаемся уместить их в 2³² хэш-кода, то по крайней мере два объекта получат один и тот же хэш-код.

Кстати, если вы углубитесь в источник JVM, я понимаю, что на самом деле используется только 31 бит, но основная проблема та же.

Так что же на самом деле происходит?

Для многих запросов к Jira мы создаем bean-компонент с ограниченным объемом запроса для обработки контекста URI. Это bean-компонент, который я обнаружил, когда добавил последнюю партию логов. Каждый завершающийся запрос уничтожает этот bean-компонент. Когда это происходит, мы сообщаем Spring Scanner, что компонент уничтожается. Spring Scanner проверяет, является ли он одним из его bean-компонентов OSGi , сравнивая identityHashCode. Если он совпадает, он уничтожает службу OSGi.

Но подождите - каковы шансы на это? Вам нужно то, что фактически является случайным Integer (хешем bean-компонента с ограниченным объемом запроса), чтобы соответствовать таковому для службы OSGi. Случайно выстраиваются два 32-битных целых числа? Это все равно что подбросить 32 монеты подряд и увидеть все решки. Это шанс четыре миллиарда к одному (против).

Jira обрабатывает множество запросов. Я быстро просмотрел журналы наших производственных кластеров Jira в нашем индексе журналов Splunk и обнаружил около 10 миллионов событий в 15-минутном окне по умолчанию. Или 40 миллионов запросов в час. Или почти миллиард запросов в день. Наш шанс один из четырех миллиардов должен происходить примерно раз в четыре дня.

Я упоминал, что ошибка возникает примерно раз в неделю?

Хорошо - итак, цифры здесь немного неточные. На самом деле сервисов OSGi очень много - тысячи. Запросов много, но не каждый запрос создает bean-компонент с заданной областью действия. Тем не менее, у лотов есть, и поэтому порядок величины проверяется.

Последним доказательством, конечно же, было устранение первопричины. Коллега исправил Spring Scanner, мы развернули его в облаке Jira, и симптомы исчезли. Мы также связали основную причину (неправильная отмена регистрации сервисов OSGi) с другими периодически возникающими трудными для отслеживания ошибками, и они также были исправлены.

Кстати, такой код есть не только в Atlassian. Это также в текущем коде Spring:

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

Какие выводы?

Как обсуждалось выше, эта история повела меня по интересному пути открытий и решения проблем. Я думаю, что из этой истории можно кое-что узнать, в том числе некоторые общие наблюдения о природе решения проблем в большой и сложной программной системе:

Вывод 1

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

Вывод 2

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

Вывод 3

Тупики - это тоже информация. Я был очень удивлен, когда последняя вырубка вернулась с пустыми руками. Я был почти уверен, что мы на правильном пути, и я действительно ожидал увидеть, как какой-нибудь странный случай случайно запросит определение не того. Однако это просто означало вернуться назад и заново изучить то, что вы знаете.

Первоначально опубликовано на https://blog.developer.atlassian.com 4 сентября 2019 г.