Назад | Перейти на главную страницу

Понимание вывода strace для определения низкой производительности приложения

У меня есть серверное приложение, которое принимает соединения от клиентского приложения и работает почти непрерывно. Проблема в том, что после того, как этот серверный процесс работал в течение нескольких часов, его производительность снижается (как это происходит в клиентском приложении) до такой степени, что становится практически непригодным для использования. Перезапуск серверного процесса восстанавливает нормальную производительность в течение следующих нескольких часов. Я пытаюсь определить причину этого.

Я бегал strace на процесс, как когда он работает хорошо, так и когда он замедляется. Есть некоторые различия, но я не уверен, как интерпретировать результаты и помогает ли это определить причину. Основные моменты:

Выполнение той же операции в клиентском приложении (которое включало загрузку фрагмента данных из серверного процесса) занимает 61 с, когда «медленно», и 14 с, если «быстро».
Файл журнала для «быстрого» запуска значительно больше (22818 строк) по сравнению с 8052 строками для «медленного».
Пропускная способность сервера (например, загрузка файла из apache, копирование файла с помощью SCP) идентична, поэтому я думаю, что я устранил внешние сетевые условия.

Типичные шаблоны журналов для медленный бегать:

11:56:28.216594 recv(23, "\0", 1, MSG_PEEK) = 1
11:56:28.216660 recv(24, "\0", 1, MSG_PEEK) = 1
11:56:28.217808 recv(23, "\0", 1, MSG_PEEK) = 1
11:56:28.217894 recv(23, "\3", 1, MSG_PEEK) = 1
11:56:28.217982 recv(23, "\2", 1, MSG_PEEK) = 1
11:56:28.218084 recv(23, 0xbf973c8b, 1, MSG_PEEK) = -1 EAGAIN (Resource temporarily unavailable)
11:56:28.218272 recv(24, "\0", 1, MSG_PEEK) = 1
11:56:28.218358 recv(24, "\323", 1, MSG_PEEK) = 1
11:56:28.218446 recv(24, "\2", 1, MSG_PEEK) = 1
11:56:28.218544 recv(24, 0xbf973c8b, 1, MSG_PEEK) = -1 EAGAIN (Resource temporarily unavailable)
11:56:28.455550 --- SIGIO {si_signo=SIGIO, si_code=SI_KERNEL} ---
11:56:28.455653 recv(23, "\0", 1, MSG_PEEK) = 1
11:56:28.455716 recv(23, "\0", 1, MSG_PEEK) = 1
11:56:28.455800 recv(23, "\3", 1, MSG_PEEK) = 1
11:56:28.455888 recv(23, "\2", 1, MSG_PEEK) = 1
11:56:28.455987 recv(23, 0xbf973c8b, 1, MSG_PEEK) = -1 EAGAIN (Resource temporarily unavailable)
11:56:28.456467 --- SIGIO {si_signo=SIGIO, si_code=SI_KERNEL} ---
11:56:28.456570 recv(24, "\0", 1, MSG_PEEK) = 1
11:56:28.456632 recv(24, "\0", 1, MSG_PEEK) = 1
11:56:28.456716 recv(24, "\323", 1, MSG_PEEK) = 1
11:56:28.456805 recv(24, "\2", 1, MSG_PEEK) = 1
11:56:28.456904 recv(24, 0xbf973c8b, 1, MSG_PEEK) = -1 EAGAIN (Resource temporarily unavailable)
11:56:28.695455 --- SIGIO {si_signo=SIGIO, si_code=SI_KERNEL} ---
11:56:28.695553 recv(24, "\0", 1, MSG_PEEK) = 1
11:56:28.695614 recv(24, "\0", 1, MSG_PEEK) = 1
11:56:28.695700 recv(24, "\323", 1, MSG_PEEK) = 1
11:56:28.695788 recv(24, "\2", 1, MSG_PEEK) = 1

Типичные шаблоны журналов для быстро бегать:

11:59:01.462652 recv(20, "\0", 1, MSG_PEEK) = 1
11:59:01.462732 recv(20, "\351", 1, MSG_PEEK) = 1
11:59:01.462831 recv(20, "\2", 1, MSG_PEEK) = 1
11:59:01.462967 recv(20, 0xbfcc0c2b, 1, MSG_PEEK) = -1 EAGAIN (Resource temporarily unavailable)
11:59:01.463102 --- SIGIO {si_signo=SIGIO, si_code=SI_KERNEL} ---
11:59:01.463191 recv(15, "\0", 1, MSG_PEEK) = 1
11:59:01.463437 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.463646 recv(15, "\0", 1, MSG_PEEK) = 1
11:59:01.463728 recv(15, "\36", 1, MSG_PEEK) = 1
11:59:01.463827 recv(15, "\5", 1, MSG_PEEK) = 1
11:59:01.463932 recv(15, 0xbfcc0c2b, 1, MSG_PEEK) = -1 EAGAIN (Resource temporarily unavailable)
11:59:01.464436 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.465435 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.466435 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.467436 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.468436 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.468687 --- SIGIO {si_signo=SIGIO, si_code=SI_KERNEL} ---
11:59:01.468816 recv(21, "\0", 1, MSG_PEEK) = 1
11:59:01.469437 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.469578 recv(21, "\0", 1, MSG_PEEK) = 1
11:59:01.469656 recv(21, "\240", 1, MSG_PEEK) = 1
11:59:01.469756 recv(21, "\2", 1, MSG_PEEK) = 1
11:59:01.469861 recv(21, 0xbfcc0c2b, 1, MSG_PEEK) = -1 EAGAIN (Resource temporarily unavailable)
11:59:01.470017 --- SIGIO {si_signo=SIGIO, si_code=SI_KERNEL} ---
11:59:01.470103 recv(22, "\0", 1, MSG_PEEK) = 1
11:59:01.470438 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.470543 recv(22, "\0", 1, MSG_PEEK) = 1
11:59:01.470621 recv(22, "3", 1, MSG_PEEK) = 1
11:59:01.470700 recv(22, "\5", 1, MSG_PEEK) = 1

Обратите внимание, что разница в размерах файлов, похоже, полностью состоит из таких строк:

11:59:01.504417 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.505417 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.506416 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.507417 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.508417 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.509416 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.510417 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.511415 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.512417 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.513417 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---
11:59:01.514417 --- SIGALRM {si_signo=SIGALRM, si_code=SI_KERNEL, si_value={int=13003728, ptr=0xc66bd0}} ---

а иногда таких записей подряд идут сотни перед любыми другими типами записей.

Единственное, что я смог заметить, это то, что метка времени в «медленном» журнале, кажется, имеет гораздо больший «промежуток» после получения EAGAIN ответ, например:

11:56:28.218446 recv(24, "\2", 1, MSG_PEEK) = 1
11:56:28.218544 recv(24, 0xbf973c8b, 1, MSG_PEEK) = -1 EAGAIN (Resource temporarily unavailable)
11:56:28.455550 --- SIGIO {si_signo=SIGIO, si_code=SI_KERNEL} ---
11:56:28.455653 recv(23, "\0", 1, MSG_PEEK) = 1
11:56:28.455716 recv(23, "\0", 1, MSG_PEEK) = 1

с промежутком 237006 мкс после EAGAIN вход. Обратите внимание, что это не всегда так, но я не вижу ничего подобного в быстрой трассировке.

Есть идеи, где дальше искать, что может быть причиной этого? Я пробовал посмотреть различные варианты конфигурации сети в разделе /proc/sys/net, и хотя существует огромное количество информации о том, что каждый из них делает, я не смог найти ничего, что помогло бы определить, является ли какой-либо из этих ограничений вызывая проблема для конкретного процесса.