Я минуту думал над названием, но ничего не придумал.
Стрейс.
Наверное, нет человека, который бы не слышал о стрейсе.
Если кто не слышал, strace — это утилита, отслеживающая системные вызовы, представляющие собой механизм трансляции, обеспечивающий интерфейс между процессом и операционной системой (ядром).
Эти вызовы можно перехватить и прочитать.
Это позволяет лучше понять, что процесс пытается сделать в данный момент времени.
Перехватывая эти вызовы, мы можем лучше понять поведение процесса, особенно когда что-то идет не так.
Функциональность операционной системы, позволяющая отслеживать системные вызовы, называется ptrace. Strace вызывает ptrace и считывает поведение процесса, возвращая отчет. Подробности можно прочитать в вики или официальный человек .
На самом деле, ну, мы, конечно, говорим о Linux. Другие ОС имеют свои аналоги.
Так что лично для меня strace — это последнее средство.
Когда все логи уже просмотрены, все клавиши debug и verbose включены, а причина проблем не найдена, я достаю ее из широких штанов и запускаю strace. Есть одно но, strace — это инструмент, который вовсе не панацея, который сразу все покажет и расскажет. Работа со strace требует определенных знаний, и чем шире и глубже эти знания, тем больше вероятность обнаружения проблемы.
В Интернете полно вводных статей, описывающих примеры запуска strace. В этой статье я покажу конкретные проблемы и их решение с помощью strace. Первый случай.
Виртуальная машина KVM не запускается, если этот параметр включен.
vhost = включено для сетевых интерфейсов.
Если вы опустите этот параметр, виртуальная машина запустится успешно.
Итак, для начала я отсек все ненужные параметры и оставил только необходимые опции и параметры для создания сетевого интерфейса.
Это необходимо для того, чтобы не увеличивать и без того объемный вывод 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 запрошен, но не может быть инициализирован qemu-system-x86_64: -netdev Tap,ifname=tap90,id=tap90,vhost=on: Устройство «tap» не может быть инициализировано Итак, мы запускаем виртуальную машину со strace и анализируем вывод. Я намеренно опускаю большую часть вывода и показываю только ту часть, которая может помочь определить причину проблемы.
Как видите, ошибка возникает при вызове открыть() при попытке открыть устройство /dev/vhost-net .# 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
После чего выводятся сообщения об ошибках, которые наблюдались при простом запуске виртуальной машины.
В качестве обходного пути мне пришлось сбросить кеш страниц и буферы во время выполнения.
эхо 3 > /proc/sys/vm/drop_caches, после чего виртуальная машина успешно запустилась.
Потом часть машин перевели на другие хосты, но это уже другая история.
Второй случай.
И снова виртуальная машина и забегая вперед скажу, что здесь снова вопрос памяти.
Опытным путём стало понятно, что виртуальная машина не запускается при большом значении выделенной памяти.
В этом случае -м 10240 .
Если вы укажете меньшие значения, машина запустится.
При этом свободной памяти на сервере более 10Гб.
И снова обнаруживаем 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
И снова уже известное Невозможно выделить память, но уже в mprotect() .
Ищем и находим то, что нас ограничивает ключ sysctl vm.overcommit_memory со значением 2. Измените на 0, и машина успешно запустится.
Третий случай.
Здесь есть какой-то процесс, который работает какое-то время, а затем внезапно начинает использовать ресурсы ЦП.
Средняя нагрузка возрастает с 0,5 до 1,5 (в системе всего 2 виртуальных процессора, то есть виртуальная машина).
Задержка увеличивается, скорость реагирования службы снижается.
При перезапуске процесса через некоторое время ситуация повторяется.
Время, прошедшее с момента запуска и до сбоя всегда разное.
Итак, мы подключаем 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)
Системный вызов принимать() завершается с ошибкой «EMFILE (слишком много открытых файлов)».
Мы рассматриваем пределы процесса в /proc/pid/limits и проверьте количество открытых файлов, используя лсоф .
# grep files /proc/12345/limits
Max open files 1024 1024 files
# lsof -nPp 12345 |wc -l
1086
Лимит открытых файлов составляет 1024, а текущее количество файлов, открытых процессом, немного превышает предельное значение.
Здесь все понятно, сначала с помощью прлимит увеличиваем предельное значение запущенного процесса, а затем полностью исправляем лимиты, редактируя /etc/security/limits.conf .
Четвертый случай .
Здесь следует сделать небольшое отступление.
Вот смотрим ссылку pgBouncer — PostgreSQL .
Приложение работает с базой данных через pgBouncer, т.е.
подключается к ней, pgBouncer выдает подключение к базе данных из пула, приложение делает свои дела, отключается, а соединение возвращается в пул и сохраняется до тех пор, пока не будет выдано следующему клиенту.
.
Итак проблема в том, что в журнале приложения и в журнале postgres стали появляться сообщения о том, что транзакции в базе данных не могут обновить/удалить/вставить данные, поскольку транзакция находится в режиме READ ONLY. В процессе поиска было выдвинуто несколько гипотез, одна из них впоследствии оказалась верной.
Клиент, подключаясь к пулеру, переводит сессию в режим ТОЛЬКО ЧТЕНИЕ.
После отключения клиента этот параметр привязывается к соединению с сервером и остается с ним до тех пор, пока pgBouncer принудительно не разорвет это соединение.
Если в настройках pgBouncer указать server_reset_query = DISCARD ALL, то при отключении все настройки на основе сеанса будут сброшены.
Таким образом, кто-то установил сессию в режим 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 (обратите внимание на получение из(10 ).
Нам нужно немного найти, кто открыл эти дескрипторы, предшествовавшие пойманному сообщению.
греп и вот оно.
Системный вызов принимать() ( принять(.
) = 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-серверу, через который подключались разработчики.
После проведения воспитательных бесед и принятия организационных мер проблема больше не проявлялась.
Вот и все.
Спасибо всем за внимание.
Теги: #Системное администрирование #Конфигурация Linux #strace
-
Управление Онлайн-Стратегией На Битрикс24
19 Oct, 24 -
Реальные Модульные Тесты
19 Oct, 24 -
Сказка О Векторах
19 Oct, 24 -
Понижение Версии Журнала
19 Oct, 24
