В прошлый раз мы рассмотрели базовый функционал и принцип работы утилиты strace. Сегодня уделим внимание конкретному ее флагу '-c', который позволяет поверхностно оценить производительность через пулл полезной информации про каждый системный вызов, выполненный для целевого процесса.
Давайте на простом примере посмотрим, что же можно выцепить из приложения, если прогнать его через "strace -c":
#include <unistd.h>
#include <fcntl.h>
#include <string.h>
int main()
{
int fd = open("input.txt", O_WRONLY);
char* buffer = "Why am I doing this?";
while(1) {
write(fd, buffer, strlen(buffer));
}
close(fd);
return 0;
}
Этот код просто занимается тем, что постоянно пишет в файл один и тот же буфер с данными.... Да, супер полезная работа, но нам для примера подойдет. Как думаете, к чему это приведет? Правильно, к потреблению CPU в 100%!
Не всегда у пользователя есть возможность и желание копаться в исходниках программы. Для начала хочется базово продебажить софт и проверить, лежит ли проблема на поверхности: в этом нам поможет команда "strace -c", через которую мы поймем, на что тратятся ресурсы системы.
Для того, чтобы получить статистику, нужно просто запустить утилиту с указанными параметрами, выждать необходимое количество времени и прервать выполнение через "ctrl-c":
$ strace -c ./prog
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ------
99.74 0.245607 8 28230 write
0.06 0.000145 24 6 mmap
0.05 0.000111 27 4 mprotect
0.03 0.000073 24 3 openat
0.01 0.000033 16 2 close
.....
Вывод дает нам следующую информацию про каждый системный вызов:
1) time - процент процессорного времени, затраченного на выполнение вызовов (от общего времени);
2) seconds - фактическое процессорное время, затраченное на выполнение вызовов;
3) usecs/call - усредненное количество микросекунд, затраченных на выполнение 1 вызова;
4) calls - количество обращений к вызову;
5) errors - количество вызовов, вернувших ошибку;
6) syscall - название системного вызова;
В результате мы пониманием, что что-то не так: почти все время уходит на выполнение одной и той же операции, причем количество этих операций аномальное...
Дополнительно хочется акцентировать внимание на том, что не все системное процессорное время уходит только на выполнение вызовов. По этой причине временные показатели команды time могут отличаться от того, что покажет strace, так как последний учитывает исключительно то время, которое затрачено ядром на обработку вызовов для целевого процесса:
$ strace -c ./prog
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----
99.95 1.188828 8 140343 write
0.01 0.000157 26 6 mmap
....
------ ----------- ----------- --------- ---------
100.00 1.189413 8 140375 1 total
$ time ./prog
real 0m7.520s
user 0m1.048s
sys 0m6.274s