В течение минуты думал над заголовком, так ничего и не придумал…
Strace. Наверное нет того человека, который бы не слышал про strace. Если кто не слышал, то strace — это утилита, отслеживающая системные вызовы, которые представляют собой механизм трансляции, обеспечивающий интерфейс между процессом и операционной системой (ядром). Эти вызовы могут быть перехвачены и прочитаны. Это позволяет лучше понять, что процесс пытается сделать в заданное время. Перехватывая эти вызовы, мы можем добиться лучшего понимания поведения процессов, особенно если что-то идет не так. Функциональность операционной системы, позволяющая отслеживать системные вызовы, называется ptrace. Strace вызывает ptrace и читает данные о поведении процесса, возвращая отчет. Детали можно прочитать в вики или официальном man. Собственно вот, ну и речь конечно же о Linux. В других ОС свои аналоги.
Так вот, лично для меня 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 и анализируем вывод. Я намерено опускаю большую часть вывода и показываю только ту часть по которой можно определить причину проблемы.
Как видно ошибка возникает в вызове open() при попытке открытия устройства /dev/vhost-net. После чего, печатаются сообщения об ошибках которые наблюдались при простом запуске виртуальной машины.
В качестве workaround пришлось сбросить page cache и buffers через выполнение echo 3 > /proc/sys/vm/drop_caches, после чего виртуальная машина успешно запустилась. Потом часть машин перенесли на другие хосты, но это уже другая история.
Второй случай. И снова виртуальная машина и забегая вперед скажу что здесь снова вопрос памяти. Опытным путем стало понятно что виртуальная машина не запускается с большим значением выделяемой памяти. В данном случае -m 10240. Если указывать меньшие значения, то машина запускается. При этом свободной памяти на сервере больше 10GB. И снова расчехляем strace. В примере ниже я опускаю весь список параметров запуска виртуальной машины и часть ненужного вывода strace.
И снова уже известный Cannot allocate memory, но уже в mprotect(). Ищем и находим что ограничивает нас sysctl ключ vm.overcommit_memory со значением 2. Меняем на 0 и машина успешно запускается.
Третий случай. Здесь есть некоторый процесс который работает какое-то время, затем неожиданно начинает расходовать ресурсы CPU. Load average поднимается с 0.5 до 1,5 (в системе, а это виртуальная машина всего 2 виртуальных процессора). Latency увеличивается, отзывчивость сервиса падает. При перезапуске процесса, через какое-то время ситуация повторяется. Время прошедшее с момента запуска и перед сбоем всегда разное. Итак, подключаем strace к процессу в момент когда процесс начинает вести себя неправильно. И тут же видим много сообщений типа:
Системный вызов accept() завершается с ошибкой «EMFILE (Too many open files)». Смотрим лимиты процесса в /proc/pid/limits и проверяем количество открытых файлов с помощью lsof.
Лимит открытых файлов 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. А вывод сохраняем в отдельный лог. Так как после обнаружения придется еще покопаться в нем.
Итак прошло какое-то время и вот оно:
Ждем еще некоторое время (ловим другие запросы этого же клиента), выключаем strace и открываем наш лог.
Здесь самое важное номера дескрипторов, в частности дескриптор с номером 10 (обратите внимание на recvfrom(10). Нужно найти кто открыл эти дескрипторы которое предшествовали пойманному сообщению, немного grep и вот оно. Системный вызов accept() ( accept(...) = 10) открывает тот самый дескриптор с номером 10.
В беседе с разработчиками выяснилось что адрес 192.168.10.1 принадлежит VPN-серверу, через который подключались разработчики. После проведения воспитательных бесед и принятия организационных мер проблема больше не проявлялась.
Вот такие дела. Всем спасибо за внимание.
Strace. Наверное нет того человека, который бы не слышал про strace. Если кто не слышал, то strace — это утилита, отслеживающая системные вызовы, которые представляют собой механизм трансляции, обеспечивающий интерфейс между процессом и операционной системой (ядром). Эти вызовы могут быть перехвачены и прочитаны. Это позволяет лучше понять, что процесс пытается сделать в заданное время. Перехватывая эти вызовы, мы можем добиться лучшего понимания поведения процессов, особенно если что-то идет не так. Функциональность операционной системы, позволяющая отслеживать системные вызовы, называется ptrace. Strace вызывает ptrace и читает данные о поведении процесса, возвращая отчет. Детали можно прочитать в вики или официальном man. Собственно вот, ну и речь конечно же о Linux. В других ОС свои аналоги.
Так вот, лично для меня strace это как последняя инстанция. Когда уже все логи просмотрены, все debug и verbose ключи включены, а причина проблем так и не обнаружена, я
В интернетах полно вводных статей, где описываются примеры запуска 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-серверу, через который подключались разработчики. После проведения воспитательных бесед и принятия организационных мер проблема больше не проявлялась.
Вот такие дела. Всем спасибо за внимание.