63 ядра заблокированы семью инструкциями

Original author: Bruce Dawson
  • Translation
Кажется, у меня появилась привычка писать о мощных машинах, где множество ядер простаивают из-за неправильных блокировок. Так что… Да. Опять про это.

Эта история особенно впечатляет. В самом деле, как часто у вас один поток несколько секунд крутится в цикле из семи команд, удерживая блокировку, которая останавливает работу 63 других процессоров? Это просто восхитительно, в каком-то ужасном смысле.

Вопреки распространённому мнению, у меня на самом деле нет машины с 64 логическими процессорами, и я никогда не видел этой конкретной проблемы. Но с ней столкнулся мой друг, этот ботан зацепил меня он попросил о помощи, и я решил, что проблема достаточно интересная. Он выслал трассировку ETW с достаточным количеством информации, чтобы коллективный разум в твиттере быстро решил проблему.

Жалоба у друга была достаточно простая: он собирал билд с помощью ninja. Обычно ninja отлично справляется с ростом нагрузки, постоянно поддерживая n+2 процессов, чтобы избежать простоя. Но здесь использование CPU в первые 17 секунд сборки выглядело следующим образом:



Если очень внимательно присмотреться (шутка), то видна тонкая грань, где общая загрузка CPU за пару секунд падает со 100% до 0%. Всего за полсекунды загрузка снижается с 64 до двух или трёх потоков. Вот увеличенный фрагмент одного из таких падений — по горизонтальной оси отмечены секунды:



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

Для выяснения причины простоя идеально подходит таблица CPU Usage (Precise). Там хранятся логи всех переключений контекста, в том числе точные записи о каждом запуске потока, включая место и время ожидания.

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

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



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

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

Итак, я попробовал в программе другое расположение столбцов:

  • Switch-In Time (когда произошло переключение контекста)
  • Readying Process (кто освободил блокировку после ожидания)
  • New Process (кто начал работать)
  • Time Since Last (как долго ждал новый процесс)

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

Оказалось, что этого достаточно. Таблица ниже говорит сама за себя, если знать, как её читать. Первые несколько переключателей контекста не представляют интереса, потому что время ожидания нового процесса (Time Since Last) довольно мало, но на выделенной строке (#4) начинается интересное:



В этой строке говорится, что System (4) подготовил cl.ехе (3032), который ждал 3,368 секунды. В следующей строке говорится, что менее чем через 0,1 мс cl.ехе (3032) подготовил cl.exe (16232), который ждал 3,367 секунды. И так далее.

Несколько переключателей контекста, как в строке #7, не входят в цепочку ожидания, а просто отражают другую работу в системе, но в целом цепочка растягивается на много десятков элементов.

Это означает, что все эти процессы ожидают освобождения одной и той же блокировки. Когда процесс System (4) освобождает блокировку (после удержания в течение 3,368 секунд!) ожидающие процессы, в свою очередь, захватывают её, делают свою небольшую работу и передают блокировку дальше. В очереди ожидания около сотни процессов, что показывает степень влияния единственной блокировки.

Небольшое изучение Ready Thread Stacks показало, что большинство ожиданий идёт от KernelBase.dllWriteFile. Я попросил WPA отобразить вызывающие объекты этой функции, с группировкой. Там можно увидеть, что за 12 миллисекунд этого катарсиса 174 потока выходят из ожидания WriteFile, и они ждали в среднем 1,184 секунды:


174 потока ждут WriteFile, среднее время ожидания 1,184 секунды

Это удивительное отставание, и на самом деле даже не весь масштаб проблемы, потому что освобождения той же блокировки ожидают многие потоки из других функций, таких как KernelBase.dll!GetQueuedCompletionStatus.

Что делает System (4)


В этот момент я знал, что прогресс сборки остановился из-за того, что все процессы компилятора и другие ожидали WriteFile, поскольку System (4) удерживал блокировку. Ещё один столбец Ready Thread Id показал, что блокировку освободил поток 3276 в системном процессе.

Во время всех «подвисаний» сборки поток 3276 был загружен на 100%, поэтому ясно, что он выполнял некоторую работу на CPU, удерживая блокировку. Чтобы выяснить, куда тратится процессорное время, посмотрим график CPU Usage (Sampled) для потока 3276. Данные об использовании CPU оказались удивительно чёткими. Практически всё время занимает работа одной функции ntoskrnl.exe!RtlFindNextForwardRunClear (в колонке с цифрами указано количество образцов):


Стек вызовов ведёт к ntoskrnl.exe!RtlFindNextForwardRunClear

Просмотр стека потоков Readying Thread Id подтвердил, что NtfsCheckpointVolume освободил блокировку через 3,368 с:


Стек вызовов из NtfsCheckpointVolume в ExReleaseResourceLite

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

В этом случае очень быстро появился правильный ответ от Кейтлин Гэдд, наряду с множеством других замечательных предложений. Она отключила функцию восстановления системы — и внезапно сборка пошла в два-три раза быстрее!

Но подождите, дальше ещё лучше


Блокировка выполнения по всей системе в течение 3+ секунд довольно впечатляет, но ситуация впечатляет ещё сильнее, если в таблицу CPU Usage (Sampled) добавить столбец Address и отсортировать по нему. Он показывает, куда именно в RtlFindNextForwardRunClear попадают образцы — и 99% из них приходится на одну инструкцию!



Я взял у себя файлы ntoskrnl.exe и ntkrnlmp.pdb (той же версии, что у друга) и запустил dumpbin /disasm для просмотра интересующей функции в ассемблере. Первые цифры адресов отличаются, потому что код перемещается при загрузке, но последние четыре значения hex совпадают (они не изменяются после ASLR):

RtlFindNextForwardRunClear:
…
14006464F: 4C 3B C3      cmp r8,rbx
140064652: 73 0F         jae 0000000140064663
140064654: 41 39 28      cmp dword ptr [r8],ebp
140064657: 75 0A         jne 0000000140064663
140064659: 49 83 C0 04   add r8,4
14006465D: 41 83 C1 20   add r9d,20h
140064661: EB EC         jmp 000000014006464F
…

Мы видим, что инструкция на ...4657 входит в цикл из семи инструкций, которые встречаются и в других образцах. Справа указано количество таких образцов:

RtlFindNextForwardRunClear:
…
14006464F: 4C 3B C3      cmp r8,rbx                4
140064652: 73 0F         jae 0000000140064663      41
140064654: 41 39 28      cmp dword ptr [r8],ebp     
140064657: 75 0A         jne 0000000140064663      7498
140064659: 49 83 C0 04   add r8,4                  2
14006465D: 41 83 C1 20   add r9d,20h               1
140064661: EB EC         jmp 000000014006464F      1
…

В качестве упражнения для читателя оставим интерпретацию количества образцов на суперскалярном процессоре с внеочередным исполнением инструкций, хотя в этой статье можно найти некоторые хорошие идеи. В данном случае у нас 32-ядерный AMD Ryzen Threadripper 2990WX. Видимо, процессорная функция Micro-Up Fusion с выполнением пяти инструкций за раз на самом деле позволяет каждый цикл завершать на jne, поскольку инструкция после самой дорогой инструкции попадает в большинство прерываний выборки.

Так и получается, что машина с 64 логическими процессорами стопорится циклом из семи команд в системном процессе, удерживая жизненно важную блокировку NTFS, что исправляется путём отключения восстановления системы.

Coda


Непонятно, почему этот код плохо себя вёл на этой конкретной машине. Предполагаю, это как-то связано с распределением данных на почти пустом диске 2 ТБ. Когда восстановление системы включили обратно, проблема тоже вернулась, но уже не такая суровая. Может, есть некая патология для дисков с огромными фрагментами пустого пространства?

Другой фоловер в твиттере упомянул баг Volume Shadow Copy из Windows 7, который допускает выполнение за время O(n^2). Эту ошибку якобы исправили в Windows 8, но, возможно, она сохранилась в какой-то форме. Мои трассировки стека чётко показывают, что VspUpperFindNextForwardRunClearLimited (поиск используемого бита в этой 16-мегабайтной области) вызывает VspUpperFindNextForwardRunClear (ищет следующий используемый бит в любом месте, но не возвращает его, если тот находится за пределами указанной области). Конечно, это вызывает некое чувство дежавю. Как я недавно рассказывал, O(n^2) — слабое место плохо масштабируемых алгоритмов. Тут совпадают два фактора: такой код достаточно быстрый, чтобы попасть в продакшн, но достаточно медленный, чтобы этот продакшн уронить.

Были сообщения, что подобная проблема возникает при массированном удалении файлов, но у нас трассировка не показывает много удалений, так что проблема, видимо, не в этом.

В завершение продублирую общесистемный график загрузки CPU из начала статьи, но в этот раз с указанием использования CPU проблемным процессом System (зелёным цветом внизу). В такой картинке проблема совершенно очевидна. Системный процесс технически виден на верхнем графике, но на таком масштабе его легко упустить.



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

Запросы


Как обычно, это расследование я завершаю призывом лучше именовать потоки. У системного процесса десятки потоков, многие из которых имеют специальное назначение, и ни у одного нет названия. Самым загруженным системным потоком в этой трассировке был MiZeroPageThread. Я неоднократно погружался в его стек, и каждый раз вспоминал, что он не представляет интереса. Компилятор VC++ тоже не именует свои потоки. Чтобы проименовать потоки, не требуется много времени, и это реально полезно. Просто дайте названия. Это просто. Chromium даже включает в себя инструмент для перечисления названий потоков в процессе.

Если кто-то из команды NTFS в Microsoft хочет поговорить на эту тему, дайте знать, а я могу связать вас с автором оригинального отчёта и предоставить трассировку ETW.

Ссылки


Similar posts

AdBlock has stolen the banner, but banners are not teeth — they will be back

More
Ads

Comments 24

    +1
    А какая разница, блокировка удерживается семью командами или двумя тысячами?

    Почему упор именно на «семь»?
      +2

      Чем меньше элементов в цепочке действий, тем больше шанс, что они когда-то сойдутся в нехорошую последовательность…
      Да и забавна такая ситуация, как и писал автор, просто заинтересовало

        +4
        семью командами или двумя тысячами

        Рефакторить какой код предпочтете? Видимо тут с намеком что в такой мелкой функции порядок не навели.
        +10
        1. В упомянутом цикле не ожидание блокировки, а сканирование битовой карты.
        2. Качество кода, с точки зрения оптимизации производительности, в Windows (aka mustdie) местами уже давно никакое, даже в некоторых критичных местах. Почему — отдельный разговор. Но в качестве "пруфа" просто посмотрите на эти несчастные семь инструкций: на 64-битой супер-скалярной платформе поиск ведется тупым циклом с 32-битным сравнением (надо примерно так).
        3. В описанной ситуации добавляется еще какой-то системный/алгоритмический просчет или ошибка, ибо достаточно глупо (даже для Windows) каждый раз сканировать всё карту блоков с самого начала (хотя такое уже видели). Т.е. видимо какая-то ошибка в поддержке индекса/кэша, либо в его постоянной инвалидации. Но вникать нет никакого желания (в том числе читать треды по ссылкам) — гораздо проще и эффективнее на больших серверах использовать подходящую ОС, а не садиться на desktop-кактус ;)
          0
          Да, код на редкость кривой.
          Но если yleo намекает на использование AVX (AVX2), то оно не на всех новых процессорах есть (Celeron, Pentium).
          Майкл Ларабел (Michael Larabel) с Phoronix писал, что на 64 ядрах винда работает плохо, Linux — хорошо, FreeBSD — ещё лучше.
          Просто не используйте MS Windows на слишком многоядерных процессорах.
            0

            "Толсто намекаю" но не только на AVX/AVX2, а в том числе на SSE2 (пример), ибо доступно на всех 64-битных x86 и дает ~4-х кратное ускорение в сравнении с 7-ю инструкциями (насколько помню, код в примере быстрее "просто сканирования" в ~10 раз).

              +1

              Насчет "FreeBSD лучше Linux на multicore" — это давно устаревшая информация, очень давно. Кто-то даже может резонно спорить что это "совсем не правда и быть не может", но я просто помню что когда-то это было именно так.


              Но "эпоха" закончилось где-то перед Linux 2.6.32. Хотя еще можно найти бенчмарки, в которых какой-то софт быстрее работает во FreeBSD (как правило из-за того, что делает что-то не правильно в Linux и/или не использует splice/sendfile т.д.). Еще есть бенчмарки (сомнительные, если разобраться), в которых FreeBSD внезапно в 2 раза быстрее (а в Linux при этом забывают выключить THP, SELinux и т.п.).


              FreeBSD — хорошая система, но в Linux огромный объем превосходного кода. Тот случай, когда лучшее не враг хорошего, а просто превзошло его.

                0
                Да, код на редкость кривой.

                Я встречал «лыцалей», которые снисходительно говорили про «кривой код».

                Только, это «лыцалство» быстро заканчивалось, как только дело доходило до практики и вскрывался контекст такого «кривого кода», который «лыцаль» не стразу понял/увидел.
                  0

                  Ой да ладно винду хаить, помнится как там нарицательное о вставании линуксового я дра колом при дисковых рперациях… и всем подряд. Не говоря о работе линукс в условиях ограниченной памяти ;)


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

                    0
                    Не говоря о работе линукс в условиях ограниченной памяти
                    Это про то что если отрубить своп то при нехватке памяти линукс упадёт? Ну дак винда тоже упадёт в таких условиях.
                      0

                      Нет. Это про то, что если памяти начнёт не хватать, то Линукс начнёт дико виснуть и грузить ЖД на 100%. Из-за этого всякие андроиды много патчей специализированных тащят.

                        0

                        И даже если своп есть, он работает так, что все становится раком :)

                0

                Ну, винда она такая. Всегда виснет. А из за чего конкретно – это как звезды в небе сложились.

                  0
                  Я взял у себя файлы ntoskrnl.exe и ntkrnlmp.pdb (той же версии, что у друга) и запустил dumpbin /disasm для просмотра интересующей функции в ассемблере.

                  Кто-нибудь объясните, как это возможно при явном запрете на такие действия лиц.соглашением?
                  Может ли МС за подобный поиск багов отправить на известную скамью?
                    +2
                    Для чего тогда существует отладочная версия Windows?
                      0
                      Правильный ответ — зависит от страны.
                        +2
                        при явном запрете на такие действия лиц.соглашением
                        каждый раз когда читаю подобное так и подмывает спросить «в какой стране?». Законодательство то везде разное, например у себя в стране я могу дебажить, изучать и модифицировать ПО легально купленое сколько душе угодно, до тех пор пока не начну результаты работы распространять или продавать. Это закон страны который никакие лицензионные соглашения МС отменить не могут, как бы им этого не хотелось.
                          0
                          Подскадите, в какой стране вы живете?
                          Так, чисто из любопытства, для себя, вдруг поизучать что-нибудь захочу.
                            +2
                            Вам такое?
                            3. Лицо, правомерно владеющее экземпляром программы для ЭВМ, вправе без согласия правообладателя и без выплаты дополнительного вознаграждения декомпилировать или поручать декомпилирование программы для ЭВМ с тем, чтобы изучать кодирование и структуру этой программы при следующих условиях:
                            информация, необходимая для взаимодействия независимо разработанной данным лицом программы для ЭВМ с другими программами, недоступна из других источников;
                            информация, полученная в результате этого декомпилирования, может использоваться лишь для организации взаимодействия независимо разработанной данным лицом программы для ЭВМ с другими программами, а не для составления новой программы для ЭВМ, по своему виду существенно схожей с декомпилируемой программой для ЭВМ или для осуществления любого другого действия, нарушающего авторское право;
                            декомпилирование осуществляется в отношении только тех частей программы для ЭВМ, которые необходимы для организации такого взаимодействия.
                              0
                              На секунду представлю себя прокурором, которому взяток не надо, только дай кого-нибудь посадить.
                              Я бы давил на то, что в законе перечислены пункты, когда лицу позволена процедура декомпиляции, но среди них нет пункта публикации на каких-либо ресурсах.
                              Режим прокурора выключил.
                              Для себя оставил мнение, что «да, возможно, но адвокат потребуется подкованный».
                        0
                        Еще бы кто рассказал почему WMI запросы выполняются так… вдумчиво.
                          +1

                          Так погоняйте под ETW

                          –2
                          Все проще — это AMD. Таких глюков на них миллион.
                            +1

                            этот ботан зацепил меня


                            А тема ведь не раскрыта. И какое же эквивалентное сопротивление?

                            Only users with full accounts can post comments. Log in, please.