Strace: примеры использования.
Strace. Наверное нет того человека, который бы не слышал про strace. Если кто не слышал, то strace — это утилита, отслеживающая системные вызовы, которые представляют собой механизм трансляции, обеспечивающий интерфейс между процессом и операционной системой (ядром). Эти вызовы могут быть перехвачены и прочитаны. Это позволяет лучше понять, что процесс пытается сделать в заданное время. Перехватывая эти вызовы, мы можем добиться лучшего понимания поведения процессов, особенно если что-то идет не так. Функциональность операционной системы, позволяющая отслеживать системные вызовы, называется ptrace. Strace вызывает ptrace и читает данные о поведении процесса, возвращая отчет. Детали можно прочитать в вики или официальном man. Лично для меня strace это как последняя инстанция. Когда уже все логи просмотрены, все debug и verbose ключи включены, а причина проблем так и не обнаружена, яВ интернетах полно вводных статей, где описываются примеры запуска strace. Я же в этой статье покажу проблемы и их решение с помощью strace.
Для тех кто не знаком с strace вкратце несоклько слов... strace позволяет подключиться к уже запущеной программе или запустить другую программу в режиме трассировки. В таком режиме мы сможем получить информацию о том какие системные вызовы выполняются запущенной программой. Полученные данные позволяют наглядно разобраться с тем что происходит внутри программы.
Первый случай. Не запускается виртуальная машина KVM с включенной настройкой vhost=on для сетевых интерфейсов. Если опустить этот параметр, виртуальная машина успешно запускается.
Итак для начала я отсек все лишние параметры и оставил только обязательные опции и параметры создания сетевого интерфейса. Это нужно чтобы не увеличивать и без того объемный вывод strace:
# qemu-system-x86_64 -m 4096 -netdev tap,ifname=tap90,id=tap90,vhost=on -device virtio-net-pci,netdev=tap90,mac=08:77:D1:00:90:90
qemu-system-x86_64: -netdev tap,ifname=tap90,id=tap90,vhost=on: vhost-net requested but could not be initialized
qemu-system-x86_64: -netdev tap,ifname=tap90,id=tap90,vhost=on: Device 'tap' could not be initialized
Красным отмечены ошибки, итак запускаем виртуальную машину с strace и анализируем вывод. Я намерено опускаю большую часть вывода и показываю только ту часть по которой можно определить причину проблемы.
# strace -f qemu-system-x86_64 -m 4096 -netdev tap,ifname=tap90,id=tap90,vhost=on -device virtio-net-pci,netdev=tap90,mac=08:77:D1:00:90:90
...
open("/dev/vhost-net", O_RDWR) = -1 ENOMEM (Cannot allocate memory)
write(2, "qemu-system-x86_64:", 19qemu-system-x86_64:) = 19
write(2, " -netdev", 8 -netdev) = 8
write(2, " tap,ifname=tap90,id=tap90"..., 65 tap,ifname=tap90,id=tap90,vhost=on) = 65
write(2, ": ", 2: ) = 2
write(2, "vhost-net requested but could no"..., 48vhost-net requested but could not be initialized) = 48
write(2, "\n", 1 ) = 1
write(2, "qemu-system-x86_64:", 19qemu-system-x86_64:) = 19
write(2, " -netdev", 8 -netdev) = 8
write(2, " tap,ifname=tap90,id=tap90"..., 65 tap,ifname=tap90,id=tap90,vhost=on) = 65
write(2, ": ", 2: ) = 2
write(2, "Device 'tap' could not be initia"..., 37Device 'tap' could not be initialized) = 37
write(2, "\n", 1 ) = 1
Как видно вызов open() завершается с ошибкой при попытке открытия устройства /dev/vhost-net. После чего, печатаются сообщения об ошибках которые наблюдались при простом запуске виртуальной машины.
В качестве workaround пришлось сбросить page cache и buffers через выполнение "echo 3 > /proc/sys/vm/drop_caches", после чего виртуальная машина успешно запустилась. Потом часть машин перенесли на другие хосты, но это уже другая история.
Второй случай. И снова виртуальная машина и забегая вперед скажу что здесь снова вопрос памяти. Опытным путем стало понятно что виртуальная машина не запускается с большим значением выделяемой памяти. В данном случае -m 10240. Если указывать меньшие значения, то машина запускается. При этом свободной памяти на сервере больше 10GB. И снова расчехляем strace. В примере ниже я опускаю весь список параметров запуска виртуальной машины и часть ненужного вывода strace.
# strace -f qemu-system-x86_64 -m 10240 ...
open(process_vm_readv: Bad address 0x7eff1ccf40b8, O_RDONLY) = 25
fstat(25, process_vm_readv: Bad address {...}) = 0
mmap(NULL, 26244, PROT_READ, MAP_SHARED, 25, 0) = 0x7eff1e74c000
close(25) = 0
futex(0x7eff1cf31900, FUTEX_WAKE_PRIVATE, 2147483647) = 0
mprotect(0x7eff0c021000, 24576, PROT_READ|PROT_WRITE) = -1 ENOMEM (Cannot allocate memory)
mmap(NULL, 134217728, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7efc72bfd000
munmap(0x7efc72bfd000, 20983808) = 0
munmap(0x7efc78000000, 46125056) = 0
mprotect(0x7efc74000000, 163840, PROT_READ|PROT_WRITE) = -1 ENOMEM (Cannot allocate memory)
munmap(0x7efc74000000, 67108864) = 0
mmap(NULL, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = -1 ENOMEM (Cannot allocate memory)
mprotect(0x7eff0c021000, 24576, PROT_READ|PROT_WRITE) = -1 ENOMEM (Cannot allocate memory)
mmap(NULL, 134217728, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7efc72bfd000
munmap(0x7efc72bfd000, 20983808) = 0
munmap(0x7efc78000000, 46125056) = 0
mprotect(0x7efc74000000, 163840, PROT_READ|PROT_WRITE) = -1 ENOMEM (Cannot allocate memory)
munmap(0x7efc74000000, 67108864) = 0
write(2, process_vm_readv: Bad address 0x7eff0c00e000, 77 (process:10928): GLib-ERROR **: gmem.c:230: failed to allocate 131072 bytes) = 77
--- SIGTRAP {si_signo=SIGTRAP, si_code=SI_KERNEL, si_value=
int=487903808, ptr=0x7eff1d14d240}} ---
<... syscall_16 resumed> ) = ? <unavailable>
+++ killed by SIGTRAP +++
Trace/breakpoint trap
Ищем и находим что ограничивает нас sysctl ключ vm.overcommit_memory со значением 2. Меняем на 0 и машина успешно запускается.
Третий случай. Здесь есть некоторый процесс который работает какое-то время, затем неожиданно начинает расходовать ресурсы CPU. Load average поднимается с 0.5 до 1,5 (в системе, а это виртуальная машина всего 2 виртуальных процессора). Latency увеличивается, и отзывчивость сервиса падает. При перезапуске процесса ситуация повторяется. Время прошедшее с момента запуска и перед сбоем всегда разное. Итак, подключаем strace к процессу в момент когда процесс начинает вести себя неправильно. И тут же видим много сообщений типа:
ppoll([{fd=10, events=POLLIN|POLLPRI}], 1, {0, 90000000}, NULL, 8) = 1 ([{fd=10, revents=POLLIN}], left {0, 90000000})
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
epoll_wait(10, {{EPOLLIN, {u32=57661216, u64=57661216}}}, 4096, 0) = 1
rt_sigprocmask(SIG_SETMASK, ~[SEGV VTALRM RTMIN RT_1], NULL, 8) = 0
accept(15, 0x7ffff8f46af0, [16]) = -1 EMFILE (Too many open files)
Системный вызов accept() завершается с ошибкой "EMFILE (Too many open files)". Смотрим лимиты процесса в /proc/$pid/limits и проверяем количество открытых файлов с помощью lsof.
# grep files /proc/12345/limits
Max open files 1024 1024 files
# lsof -nPp 12345 |wc -l
1086
Лимит открытых файлов 1024, и текущее количество открытых процессом файлов, чуть превышает значение лимита. Тут все ясно, сначала увеличиваем значение лимита с помощью prlimit, и затем закрепляем лимиты на совсем через правку /etc/security/limits.conf.
Четвертый случай. Здесь следует сделать небольшое отступление. Здесь мы рассматриваем связку pgBouncer - PostgreSQL. Приложение работает с базой данных через pgBouncer, т.е. подключается к нему, pgBouncer выдает коннект к базе из пула, приложение делает свои дела, отключается, а коннект возвращается в пул и находится до тех пор пока не будет выдано следующему клиенту.
Итак проблема, в логе приложения начали появляться сообщения о том что транзакции в базе данных не могут выполнить обновление/удаление/вставку данных, т.к. транзакция находится в READ ONLY режиме.
В процессе поиска, была выдвинуто несколько гипотез, одна из них впоследствии оказалась правильной. Клиент, подключаясь к пулеру устанавливает транзакцию в READ ONLY режим. Отключившись эта настройка прилипает к серверному коннекту и живет с ним пока pgBouncer принудительно не завершит этот коннект. Если указать server_reset_query = DISCARD ALL в настройках pgBouncer, то при отключении все session-based настройки будут сброшены. Таким образом кто-то выставлял READ ONLY сессию, она сохранялась и затем этот коннект доставался другим клиентам. Вобщем DISCARD ALL и было решением, однако хотелось найти виновника. Поиски были продолжительными и подозрения легли на приложение, однако разработчики уверяли что проверили все места в коде и не выявили проблемных мест...
Достаем strace, подключаемся в pgBouncer и ждем.
Ловим по ключевому слову READ ONLY. А вывод сохраняем в отдельный лог. Так как после обнаружения придется еще покопаться в нем.
Итак прошло какое-то время и вот оно. Обратите внимание на выделенную 10.
recvfrom(10, "Q\0\0\0:SET SESSION CHARACTERISTICS AS TRANSACTION READ ONLY;\0", 2048, 0, NULL, NULL) = 59
sendto(11, "Q\0\0\0:SET SESSION CHARACTERISTICS AS TRANSACTION READ ONLY;\0", 59, 0, NULL, 0) = 59
sendto(10, "C\0\0\0\10SET\0Z\0\0\0\5T", 15, 0, NULL, 0) = 15
Ждем еще некоторое время (ловим другие запросы этого же клиента, последующие системные вызовы recvfrom() с дескриптором 10 покажут нам запросы клиента), выключаем strace и открываем наш лог.
Здесь самое важное номера дескрипторов, они отмечены красным (тот самый номер 10). Нужно найти кто открыл эти дескрипторы которое предшествовали пойманному сообщению, немного grep и вот оно. Системный вызов accept() открывает тот самый дескриптор с номером 10.
accept(8, {sa_family=AF_INET, sin_port=htons(58952), sin_addr=inet_addr("192.168.10.1")}, [16]) = 10
getpeername(10, {sa_family=AF_INET, sin_port=htons(58952), sin_addr=inet_addr("192.168.10.1")}, [16]) = 0
getsockname(10, {sa_family=AF_INET, sin_port=htons(6432), sin_addr=inet_addr("192.168.10.10")}, [16]) = 0
В беседе с разработчиками выяснилось что адрес 192.168.10.1 принадлежит VPN-серверу, через который подключались разработчики. После проведения воспитательных бесед и принятия организационных мер проблема больше не проявлялась.
Вот такие дела.
На главную "Virtualizing Linux"
Комментариев нет:
Отправить комментарий