Диагностика высокой загрузки процессора в Docker для Mac

Question

Как диагностировать причину Docker в MacOS, в частности com.docker.hyperkit, используя 100% ЦП?

Статистика Docker

Статистика Docker показывает, что все запущенные контейнеры имеют низкий ЦП, память, чистый ввод-вывод и блочный ввод-вывод.

iosnoop

iosnoop показывает, что com.docker.hyperkit выполняет около 50 операций записи в секунду, что составляет 500 КБ в секунду в файл Docker.qcow2. Согласно Что такое Docker.qcow2? , Docker.qcow2 - это разреженный файл, который является постоянным хранилищем для всех контейнеров Docker.

В моем случае файл не такой уж разреженный. Физический размер соответствует логическому размеру.

dtrace (dtruss)

dtruss sudo dtruss -p $DOCKER_PID показывает большое число psynch_cvsignal и psynch_cvwait вызовы.

psynch_cvsignal(0x7F9946002408, 0x4EA701004EA70200, 0x4EA70100)          = 257 0
psynch_mutexdrop(0x7F9946002318, 0x5554700, 0x5554700)           = 0 0
psynch_mutexwait(0x7F9946002318, 0x5554702, 0x5554600)           = 89474819 0
psynch_cvsignal(0x10BF7B470, 0x4C8095004C809600, 0x4C809300)             = 257 0
psynch_cvwait(0x10BF7B470, 0x4C8095014C809600, 0x4C809300)               = 0 0
psynch_cvwait(0x10BF7B470, 0x4C8096014C809700, 0x4C809600)               = -1 Err#316
psynch_cvsignal(0x7F9946002408, 0x4EA702004EA70300, 0x4EA70200)          = 257 0
psynch_cvwait(0x7F9946002408, 0x4EA702014EA70300, 0x4EA70200)            = 0 0
psynch_cvsignal(0x10BF7B470, 0x4C8097004C809800, 0x4C809600)             = 257 0
psynch_cvwait(0x10BF7B470, 0x4C8097014C809800, 0x4C809600)               = 0 0
psynch_cvwait(0x10BF7B470, 0x4C8098014C809900, 0x4C809800)               = -1 Err#316

Обновление: top на хосте Docker

С https://stackoverflow.com/a/58293240/30900:

docker run -it --rm --pid host busybox top

Загрузка ЦП на встроенном хосте Docker~ 3%Загрузка процессора на моем MacBook составила ~ 100%. Таким образом, встроенный хост докера не вызывает скачок загрузки процессора.

Обновление: запуск сценариев dtrace наиболее распространенных трассировок стека

Трассировки стека из сценариев dtrace в ответе ниже: https://stackoverflow.com/a/58293035/30900.

Эти трассировки стека ядра выглядят безобидными.

              AppleIntelLpssGspi`AppleIntelLpssGspi::regRead(unsigned int)+0x1f
              AppleIntelLpssGspi`AppleIntelLpssGspi::transferMmioDuplexMulti(void*, void*, unsigned long long, unsigned int)+0x91
              AppleIntelLpssSpiController`AppleIntelLpssSpiController::transferDataMmioDuplexMulti(void*, void*, unsigned int, unsigned int)+0xb2
              AppleIntelLpssSpiController`AppleIntelLpssSpiController::_transferDataSubr(AppleInfoLpssSpiControllerTransferDataRequest*)+0x5bc
              AppleIntelLpssSpiController`AppleIntelLpssSpiController::_transferData(AppleInfoLpssSpiControllerTransferDataRequest*)+0x24f
              kernel`IOCommandGate::runAction(int (*)(OSObject*, void*, void*, void*, void*), void*, void*, void*, void*)+0x138
              AppleIntelLpssSpiController`AppleIntelLpssSpiDevice::transferData(IOMemoryDescriptor*, void*, unsigned long long, unsigned long long, IOMemoryDescriptor*, void*, unsigned long long, unsigned long long, unsigned int, AppleIntelSPICompletion*)+0x151
              AppleHSSPISupport`AppleHSSPIController::transferData(IOMemoryDescriptor*, void*, unsigned long long, unsigned long long, IOMemoryDescriptor*, void*, unsigned long long, unsigned long long, unsigned int, AppleIntelSPICompletion*)+0xcc
              AppleHSSPISupport`AppleHSSPIController::doSPITransfer(bool, AppleHSSPITransferRetryReason*)+0x97
              AppleHSSPISupport`AppleHSSPIController::InterruptOccurred(IOInterruptEventSource*, int)+0xf8
              kernel`IOInterruptEventSource::checkForWork()+0x13c
              kernel`IOWorkLoop::runEventSources()+0x1e2
              kernel`IOWorkLoop::threadMain()+0x2c
              kernel`call_continuation+0x2e
               53

              kernel`waitq_wakeup64_thread+0xa7
              pthread`__psynch_cvsignal+0x495
              pthread`_psynch_cvsignal+0x28
              kernel`psynch_cvsignal+0x38
              kernel`unix_syscall64+0x27d
              kernel`hndl_unix_scall64+0x16
               60

              kernel`hndl_mdep_scall64+0x4
              113

              kernel`ml_set_interrupts_enabled+0x19
              524

              kernel`ml_set_interrupts_enabled+0x19
              kernel`hndl_mdep_scall64+0x10
             5890

              kernel`machine_idle+0x2f8
              kernel`call_continuation+0x2e
            43395

Очевидно, что наиболее распространенные трассировки стека в пространстве пользователя в течение 17 секунднеявный com.docker.hyperkit. За 17 секунд 1365 стековых трассировок, в которых com.docker.hyperkit создали потоки, в среднем до 80 потоков в секунду.

              com.docker.hyperkit`0x000000010cbd20db+0x19f9
              com.docker.hyperkit`0x000000010cbdb98c+0x157
              com.docker.hyperkit`0x000000010cbf6c2d+0x4bd
              libsystem_pthread.dylib`_pthread_body+0x7e
              libsystem_pthread.dylib`_pthread_start+0x42
              libsystem_pthread.dylib`thread_start+0xd
               19

              Hypervisor`hv_vmx_vcpu_read_vmcs+0x1
              com.docker.hyperkit`0x000000010cbd4c4f+0x2a
              com.docker.hyperkit`0x000000010cbd20db+0x174a
              com.docker.hyperkit`0x000000010cbdb98c+0x157
              com.docker.hyperkit`0x000000010cbf6c2d+0x4bd
              libsystem_pthread.dylib`_pthread_body+0x7e
              libsystem_pthread.dylib`_pthread_start+0x42
              libsystem_pthread.dylib`thread_start+0xd
               22

              Hypervisor`hv_vmx_vcpu_read_vmcs
              com.docker.hyperkit`0x000000010cbdb98c+0x157
              com.docker.hyperkit`0x000000010cbf6c2d+0x4bd
              libsystem_pthread.dylib`_pthread_body+0x7e
              libsystem_pthread.dylib`_pthread_start+0x42
              libsystem_pthread.dylib`thread_start+0xd
               34

              com.docker.hyperkit`0x000000010cbd878d+0x36
              com.docker.hyperkit`0x000000010cbd20db+0x42f
              com.docker.hyperkit`0x000000010cbdb98c+0x157
              com.docker.hyperkit`0x000000010cbf6c2d+0x4bd
              libsystem_pthread.dylib`_pthread_body+0x7e
              libsystem_pthread.dylib`_pthread_start+0x42
              libsystem_pthread.dylib`thread_start+0xd
               47

              Hypervisor`hv_vcpu_run+0xd
              com.docker.hyperkit`0x000000010cbd20db+0x6b6
              com.docker.hyperkit`0x000000010cbdb98c+0x157
              com.docker.hyperkit`0x000000010cbf6c2d+0x4bd
              libsystem_pthread.dylib`_pthread_body+0x7e
              libsystem_pthread.dylib`_pthread_start+0x42
              libsystem_pthread.dylib`thread_start+0xd
              135

Связанные проблемы

Github - docker / for-mac: com.docker.hyperkit 100% использование процессора снова вернулось # 3499 . Один комментарий предлагает добавить кеширование тома, описанное здесь: https://www.docker.com/blog/user-guided-caching-in-docker-for-mac/. Я попробовал это и получил небольшое ~ 10% снижение загрузки процессора.

Answer 1

Я подозреваю, что проблема связана с IO. В томах MacOS это включает osxfs, где вы можете выполнить некоторые настройки производительности. В основном, если вы можете принять меньшее количество проверок согласованности, вы можете установить режим громкости на delegated для повышения производительности. Для получения более подробной информации см. Документы: https://docs.docker.com/docker-for-mac/osxfs-caching/. Однако, если ваше изображение содержит большое количество небольших файлов, производительность может снизиться, особенно если у вас также есть много слоев изображения.

Вы также можете попробоватьследующая команда для отладки любых проблем процесса во встроенной виртуальной машине, которую использует Docker:

docker run -it --rm --pid host busybox top

(Для выхода используйте <ctrl>-c)

---

Чтобы отследить, является ли это IO,Вы также можете попробовать следующее:

$ docker run -it --rm --pid host alpine /bin/sh
$ apk add sysstat
$ pidstat -d 5 12

Он будет работать внутри альпийского контейнера, работающего в пространстве имен VM pid, показывая любой ввод-вывод, происходящий из любого процесса, независимо от того, находится ли этот процесс внутри контейнера. Статистика каждые 5 секунд в течение одной минуты (12 раз), а затем она даст вам среднюю таблицу за процесс. Затем вы можете <ctrl>-d уничтожить альпийский контейнер.

---

Из комментариев и правок эти статистические данные могут проверить. 4-ядерный MBP имеет 8 потоков, поэтому полная загрузка ЦП должна составлять 800%, если MacOS сообщает то же самое, что и другие системы на основе Unix. Внутри виртуальной машины более 100% нагрузки показано в верхней команде для среднего значения за последнюю минуту (хотя и меньше 5-ти и 15-ти средних), что примерно соответствует показателю процесса гиперкита на хосте. Мгновенное использование превышает 12% сверху, а не 3%, так как вам нужно добавить системные и пользовательские проценты. И числа ввода-вывода, показанные в pidstat, примерно совпадают с тем, что вы видите записанным в образе qcow2.

---

Если движок докера перебивает (например, перезапускает контейнеры или выполняет много проверок работоспособности), тогда вы можетеотладить это, наблюдая за выводом:

docker events

Answer 2

Это небольшой сценарий dTrace, который я использую, чтобы найти, где ядро ​​проводит свое время (оно из Solaris и восходит к ранним временам Solaris 10):

#!/usr/sbin/dtrace -s

profile:::profile-1001hz
/arg0/
{
    @[ stack() ] = count();
}

Это просто примеры ядрастек отслеживает и подсчитывает каждое, с чем встречается в агрегации @hot.

Запустите его от имени root:

... # ./kernelhotspots.d > /tmp/kernel_hot_spots.txt

Дайте ему поработать приличное количество времени, пока у вас есть процессорпроблемы, затем нажмите CTRL-C, чтобы сломать скрипт. Он будет испускать все найденные им следы стека ядра, самый распространенный последний. Если вам нужно больше (или меньше) стековых фреймов по умолчанию с

    @[ stack( 15 ) ] = count();

Это покажет стековый фрейм с глубиной 15 вызовов.

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

Этот скрипт будет делать то же самое для трассировки стека пользовательского пространства:

#!/usr/sbin/dtrace -s

profile:::profile-1001hz
/arg1/
{
    @[ ustack() ] = count();
}

Запустите его аналогично:

... # ./userspacehotspots.d > /tmp/userspace_hot_spots.txt

ustack() немного медленнее - чтобы выдавать реальные имена функций, dTrace нужно проделать гораздо больше работы, чтобы получить их из адресных пространств соответствующих процессов.

Отключение защиты целостности системы может помочь вам улучшить трассировку стека.

Подробнее см. Основы действия DTrace .