Strace

В течение минуты думал над заголовком, так ничего и не придумал…
Strace. Наверное нет того человека, который бы не слышал про strace. Лично для меня strace это как последняя инстанция. Когда уже все логи просмотрены, все debug и verbose ключи включены, а причина проблем так и не обнаружена, я достаю из широких штанин запускаю strace. Есть одно но, 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 

И снова уже известный Cannot allocate memory, но уже в mprotect(). Ищем и находим что ограничивает нас 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 выдает коннект к базе из пула, приложение делает свои дела, отключается, а коннект возвращается в пул и находится до тех пор пока не будет выдано следующему клиенту.
Итак проблема, в логе приложения и в логе postgres’а начали появляться сообщения о том что транзакции в базе данных не могут выполнить обновление/удаление/вставку данных, т.к. транзакция находится в READ ONLY режиме.
В процессе поиска, была выдвинуто несколько гипотез, одна из них впоследствии оказалась правильной. Клиент, подключаясь к пулеру устанавливает сессию в READ ONLY режим. После отключения клиента, эта настройка прилипает к серверному коннекту и живет с ним пока pgBouncer принудительно не завершит этот коннект. Если указать server_reset_query = DISCARD ALL в настройках pgBouncer, то при отключении все session-based настройки будут сброшены. Таким образом кто-то выставлял READ ONLY сессию, она сохранялась и затем этот коннект доставался другим клиентам. Вобщем DISCARD ALL было временным решением, пока искали виновника. Поиски были продолжительными и подозрения легли на приложение, однако разработчики уверяли что проверили все места в коде и не выявили проблемных мест…
Достаем strace, подключаемся в pgBouncer и ждем.
Ловим по ключевому слову READ ONLY. А вывод сохраняем в отдельный лог. Так как после обнаружения придется еще покопаться в нем.
Итак прошло какое-то время и вот оно:

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 

Ждем еще некоторое время (ловим другие запросы этого же клиента), выключаем strace и открываем наш лог.
Здесь самое важное номера дескрипторов, в частности дескриптор с номером 10 (обратите внимание на recvfrom(10). Нужно найти кто открыл эти дескрипторы которое предшествовали пойманному сообщению, немного grep и вот оно. Системный вызов accept() ( accept(…) = 10) открывает тот самый дескриптор с номером 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-серверу, через который подключались разработчики. После проведения воспитательных бесед и принятия организационных мер проблема больше не проявлялась.

Вот такие дела. Всем спасибо за внимание.