MAIN PAGE

strace [-p PID] [-e trace=…] [programm]

-p Указываем PID процесса, который будет смотреть strace
-r Время в милисекундах от старта программы
-tt Текущее время в милисекундах
-T процессорное время для каждого вызова
-v не сокращать аргументы для каждого из вызовов
-x вывод сообщений в hex

Все -e trace, позволяют выводить на экран, только интересующие нас процессы.

-e trace=set trace=open,close,read,write. The default is trace=all.
-e trace=file trace=open,stat,chmod,unlink,…
-e trace=process
-e trace=network
-e trace=signal

-s99999 Указывает размер строки которое может выводить strace

ищем в выводе

Весь вывод идет на ошибки, так что следует:

strace command 2>&1 | grep some

ищем подключения

grep --color "connect(\|inet"

ищем проблемы

grep "= \-1 " ./

permission denied

2>&1 | grep -i --color "\-1 EACCES"

Дети

Чтобы искать в порождаемых процессах:

strace -o straceFile -ff /etc/init.d/proftpd start
strace -o straceFile -s999 -tt -ff someCommand #в заранее подготовленной директории

А потом уже можно, к примеру

grep --colour -iRH open ./

Примеры из жизни

Смотрим какие файлы и в какой последовательности открывает php скрипт

strace  php index.php 2>&1 | grep --color open | grep --color php | grep 6$ | uniq

Выполнять PHP страницу после подключения к ней strace

if ($_GET['dobadebug'] == 'Y') { $pid = posix_getpid(); posix_kill($pid,19); }
if($_SERVER['REMOTE_ADDR'] == "149.255.117.166"){ $pid = posix_getpid(); posix_kill($pid,19); }

Метки для strace
if ($_GET['dobadebug'] == 'Y'){file_exists("TBG1");}
if ($_SERVER['REMOTE_ADDR'] == "149.255.117.166"){file_exists("TBG3");}

1

Условия:
Скрипт порождает 200 тредов и всеми из них коннектится и флудит на mysql в попытках вызвать нагрузку.
Первые 5 секунд скрипт работает корректно, но потом:

  $ strace /usr/bin/python3.2 ./workspace/MySQLDEB/TooManyConnect.py
  ...
  ... Много хорошего вывода
  ... Ошибка:
  ) = ? ERESTARTSYS (To be restarted)
  --- SIGWINCH (Window changed) @ 0 (0) ---
  futex(0x8d1a828, FUTEX_WAIT_PRIVATE, 0, NULL) = ? ERESTARTSYS (To be restarted)
  --- SIGWINCH (Window changed) @ 0 (0) ---
  futex(0x8d1a828, FUTEX_WAIT_PRIVATE, 0, NULL('5.1.61',) 2
  ) = ? ERESTARTSYS (To be restarted)
  --- SIGWINCH (Window changed) @ 0 (0) ---
  futex(0x8d1a828, FUTEX_WAIT_PRIVATE, 0, NULL) = ? ERESTARTSYS (To be restarted)
  --- SIGWINCH (Window changed) @ 0 (0) ---
  futex(0x8d1a828, FUTEX_WAIT_PRIVATE, 0, NULL('5.1.61',) 2

Идут активные попытки соединения:

# lsof -i | grep SYN_SENT | wc -l
197

Если закрыть приложение и сразу повторно открыть, то все застревает на:

futex(0x8300ba4, FUTEX_WAIT_PRIVATE, 399, {0, 4920980}) = 0
futex(0x8300b80, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x8300b80, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x8adb1a0, FUTEX_WAIT_PRIVATE, 0, NULL

- Локализуем проблему:
Запускаем первый скрипт и при получение ошибок запускаем второй на уже другой MySQL хост. В результате видно, что проблема явно на локальной машине.

Итог: Еще не известен

Count

soyuz-minor.ru 26319

Discussion

qwe, 2014/03/31 17:29

для просмотра открываемых файлов

strace -ff ./script.py 2>&1  | grep "^open" | grep -v "ENOENT"

Constantin Conovaloff, 2015/04/07 17:56

То что надо расшифровать

restart_syscall(<... resuming interrupted call ...>^C <unfinished ...>

epoll_wait(5, ^C <unfinished ...>    # <- тоже что и select, только более экономичное на большом количестве ожидающих сокетов
[pid 12606 (main_process)] <... epoll_wait resumed> {{EPOLLIN|EPOLLHUP, {u32=8, u64=19420167075266568}}}, 10, 1000) = 1

Constantin Conovaloff, 2015/06/11 13:30

получение -p pid через grep

lsof -i -Pn | grep 40105 | awk '{print $2}' ORS=' ' | sed 's/\([0-9]*\)/-p \1/g'

-p 27665 -p 27666 -p 27667 -p 27668 -p 27669 -p

You could leave a comment if you were logged in.