Strace

    В течение минуты думал над заголовком, так ничего и не придумал…
    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 и анализируем вывод. Я намерено опускаю большую часть вывода и показываю только ту часть по которой можно определить причину проблемы.
    # 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-серверу, через который подключались разработчики. После проведения воспитательных бесед и принятия организационных мер проблема больше не проявлялась.

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

    Similar posts

    Ads
    AdBlock has stolen the banner, but banners are not teeth — they will be back

    More

    Comments 33

      +1
      Я благодаря strace выяснил, почему в моём дебьяне по минуте открывался диалог сохранения файлов — висело изза сломаных прав на dbus
        0
        Хотелось бы узнать подробностей! :)
          0
          всё просто, я запускал диалог командой kdialog --getopenurl.
            0
            не успел дописать
            он зависал на минуту-две при открытии, точно так же висел и dolphin
            тогда я запустил strace kdialog --getopenurl. 2> out.log и после открытия диалога пролистал лог на наличие слова timeout
            висело, если я не ошибаюсь вот тут
            connect(14, {sa_family=AF_FILE, path="/var/run/dbus/system_bus_socket"}, 33) = 0
        +1
        Полезная статья. Утилитка тоже выручала когда пытался подружить пых с mssql через FreeTDS.

        К слову для MacOSX есть dtruss
          0
          Apple честно лицензировал всю технологию dtrace у сана уже достаточно давно.
          +31
          «Наверное нет того человека, который бы не слышал про strace»
          Наверное есть.
            +1
            добавил описание и пару ссылок.
              +1
              Присоединяюсь.
              Услышал впервые (не столь давно стал пользователем *nix систем, но поверхностно уже разбираюсь). Утилита очень интересная и предлагает, как понимаю, очень большой функционал отладки и нахождения проблем в работе приложений и системы.
              Спасибо автору =)
                0
                функционал-то как раз не очень большой )

                Просто выводит исполняемые системные вызовы программы и результат их работы.
                А вот что делать с этой информацией — вопрос опыта или умения пользоваться поисковиком. :)
            • UFO just landed and posted this here
                +2
                Я хотел около года назад написать похожую статью, но только не целиком про strace(ktrace/kdump под FreeBSD), а ещё про дополнительные полезные утилиты.

                От себя в копилку: иногда клиентские сайты очень надолго зависали, причём на конкретную величину (30 или около того секунд).

                Проблема была в том, что в коде у них содержалось обращение к внешнему серверу, который в этот момент лежал.

                Выглядело это как зависший read после открытия сетевого соединения.
                  0
                  Ну открывать удаленный url из процесса, который рендерит вам html-страницу — это вообще довольно плохой стиль. Для этого существуют асинхронные очереди / воркеры / WebSocket'ы
                    0
                    Привет битриксу, например :) Или создателям тем и плагинов для вордпресса.
                      0
                      Расскажите это PayPal'у, сообщающему вам номер совершённой транзакции, но требующий дополнительного обращения к себе, вместо отправки подписанного подтверждения post'ом, или OAuth провайдерам. WebSocket'ы то тут вообще при чём?
                      0
                      Для отладки PHP приложений лучше вооружиться профайлером.
                        0
                        Это-то конечно, но не думаю что хорошо включать профайлер на сервере хостинга для всех клиентов, верно?
                          0
                          depends что за профайлер [и когда включать, и какой сервер]. Я тут, вот, о Pinba слышал (только не хочу серверную часть на MySQL)
                        0
                        Для фри есть же православный dtrace, зачем кусать кактус?
                        +5
                        Было бы неплохо дать хотя бы краткое введение — что показывает strace. Если судить по подаче текста, так просто панацея получается, хотя это далеко не так. Это я к тому, что «для тех, кто знает» что такое strace тут мало нового, а для тех, кто не знает — мало понятного =)
                          0
                          Спасибо за статью, я сегодня тоже узнал про утилиту впервые.
                          Смотря вот на эти 2 строчки не понял как определить, что одна из них выдает ошибку:
                          open("/dev/vhost-net", O_RDWR) = -1 ENOMEM (Cannot allocate memory)
                          write(2, «qemu-system-x86_64:», 19qemu-system-x86_64:) = 19

                          Я привык даже визуально парсить логи на наличие слов типа ERROR. Тут что ошибку выдает? -1 или фраза «Cannot allocate memory»?
                            +1
                            ENOMEM errno enum жи
                              +4
                              = -1 — это возвращенное функцией open значение. Согласно документации результат < 0 — ошибка (смотреть надо в документацию на функцию).
                              ENOMEM — значение переменной errno.
                              Cannot allocate memory — текстовая расшифровка кода ошибки ENOMEM.

                              strace — это не отладчик, это трассировщик системных вызовов, по этому он ничего не знает ошибка это или так задумано, по этому не может написать ERROR или более заметное сообщение, но информацию о результате работы системных вызовов, в том числе и завершившихся ошибкой он выдает.
                              +3
                              А я в своё время с помощью strace разобрался как patch -p пользоваться. :(
                                +6
                                В своё время пытался понять, почему древняя Linux-версия rar не принимает ключ. strace позволил узнать, что rar ищет его где-то в /etc/rarreg.*, ~/rarreg.*, ~/.rarreg.*. Пытался размещать соответственно. А потом немного подумал и понял, что open(/etc/rarreg.*) не будет раскрывать звёздочку, и переименовал файл ключа из rarreg.key в rarreg.*. Это решило проблему.
                                  +1
                                  к вопросу о быдлокоде :)
                                  0
                                  Спасибо. Благодаря статье наконец взялся выяснить почему у меня xfrun4 5 секунд запускается. Оказалось тривиально:
                                  Скрытый текст
                                  sendmsg(6, {msg_name(0)=NULL, msg_iov(2)=[{"l\1\0\1\t\0\0\0\3\0\0\0\200\0\0\0\1\1o\0\23\0\0\0/org/xfc"..., 144}, {"\0\0\0\0\0\0\0\0\0", 9}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 15
                                  3
                                  poll([{fd=6, events=POLLIN}], 1, 5000)  = 0 (Timeout)
                                  



                                  И дальше сразу же нашёл баг. Не знаю сколько бы я ещё избегал использования xfrun4 без статьи… :)
                                    0
                                    Хочу предостеречь новичков.
                                    Если вы используете Unix (например, FreeBSD), а не Linux, то лучше пользоваться ktrace: последний ведёт отладку на уровне ядра системы и не использует системный вызов ptrace для подключения к процессу.
                                    Были случаи когда strace/truss валил программу при подключении или сам зависал (ведь используется переключение контекста на приложение).
                                    К сожалению, в Linux-системах нет аналога ktrace.

                                    Что касается статьи, а именно, части про PostgreSQL:
                                    НЕ делать DISCARD ALL в pgbouncer'е — как-то очень дико. Этот параметр должен быть включен всегда, ибо read only — не самое страшное что может сделать клиент в рамках сессии.
                                      +1
                                      О perf не слышали? Мощнейший инструмент.
                                      Скрытый текст
                                      $ sudo perf record -a -g ./src/stress --cpu 4 --io 2 --vm 2 --timeout 10s
                                      $ sudo perf report -g
                                      # ========
                                      # captured on: Fri Mar 14 04:12:21 2014
                                      # hostname : ######
                                      # os release : 3.12-1-amd64
                                      # perf version : 3.12.6
                                      # arch : x86_64
                                      # nrcpus online : 8
                                      # nrcpus avail : 8
                                      # cpudesc : #################
                                      # cpuid : ###########
                                      # total memory : #########
                                      # cmdline : /usr/bin/perf_3.12 record -a -g ./src/stress --cpu 4 --io 2 --vm 2 --timeout 10s 
                                      # event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, excl_usr = 0, excl_kern = 0, excl_host = 0, excl_guest = 1, precise_ip = 0, attr_mmap2 = 0, attr_mmap  = 1, attr_mmap_data = 0
                                      # HEADER_CPU_TOPOLOGY info available, use -I to display
                                      # HEADER_NUMA_TOPOLOGY info available, use -I to display
                                      # pmu mappings: cpu = 4, software = 1, tracepoint = 2, breakpoint = 5
                                      # ========
                                      #
                                      # Samples: 241K of event 'cycles'
                                      # Event count (approx.): 221562887737
                                      #
                                      # Overhead        Command       Shared Object                                         Symbol
                                      # ........  .............  ..................  .............................................
                                      #
                                          30.28%         stress  libc-2.18.so        [.] __random_r                               
                                                         |
                                                         --- __random_r
                                      
                                          19.70%         stress  libc-2.18.so        [.] __random                                 
                                                         |
                                                         --- __random
                                      
                                           8.41%         stress  stress              [.] hogcpu                                   
                                                         |
                                                         --- hogcpu
                                      
                                           5.94%         stress  [kernel.kallsyms]   [k] page_fault                               
                                                         |
                                                         --- page_fault
                                                             hogvm
                                      
                                           5.05%         stress  libc-2.18.so        [.] rand                                     
                                                         |
                                                         --- rand
                                      
                                           4.84%         stress  [kernel.kallsyms]   [k] clear_page_c_e                           
                                                         |
                                                         --- clear_page_c_e
                                                             hogvm
                                      
                                           4.23%         stress  stress              [.] hogvm                                    
                                                         |
                                                         --- hogvm
                                      
                                           2.74%         stress  stress              [.] rand@plt                                 
                                                         |
                                                         --- rand@plt
                                      
                                           1.90%         stress  [kernel.kallsyms]   [k] get_page_from_freelist                   
                                                         |
                                                         --- get_page_from_freelist
                                              ...
                                      

                                        0
                                        Честно говоря, вроде не слышал. :) Но понял, что во FreeBSD есть аналог — pmcstat из PmcTools.
                                        Но ведь это профайлеры, а не трассировщики системных вызовов.
                                          0
                                          вот как раз потихоньку колупаю perf, мне нравится, пока нашел для него применение в целях определения тех мест в которых проводит свое время процесс (и сколько времени проводит).
                                          0
                                          про DISCARD ALL. Не скажу точно где (толи pgsql-hackers, толи pgsql-performance), но проскакивало что DISCARD ALL добавляет вполне ощутимый оверхед. Померять руки не дотянулись, но тем дядькам я вобщем доверяю. Да и вроде как время кривых orm прошло уже)))
                                          0
                                          спасибо. Не знал про такое. Взял на вооружение.

                                          Only users with full accounts can post comments. Log in, please.