Анализ производительности readdir()

Question

Меня беспокоит, что linux занимает так много времени, чтобы перечислить все файлы для огромных каталогов, поэтому я создал небольшой тестовый скрипт, который рекурсивно перечисляет все файлы в каталоге:

#include <stdio.h>
#include <dirent.h>

int list(char *path) {
    int i = 0;

    DIR *dir = opendir(path);
    struct dirent *entry;
    char new_path[1024];

    while(entry = readdir(dir)) {
        if (entry->d_type == DT_DIR) {
            if (entry->d_name[0] == '.')
                continue;

            strcpy(new_path, path);
            strcat(new_path, "/");
            strcat(new_path, entry->d_name);
            i += list(new_path);
        }
        else
            i++;
    }
    closedir(dir);

    return i;
}

int main() {
    char *path = "/home";
    printf("%i\n", list(path));
    return 0;

При компиляции с gcc -O3, программа работает около 15 секунд (я запускал программу несколько раз, и она примерно постоянна, поэтому кэш fs здесь не должен играть никакой роли):

$ /usr/bin/time -f "%CC %DD %EE %FF %II %KK %MM %OO %PP %RR %SS %UU %WW %XX %ZZ %cc %ee %kk %pp %rr %ss %tt %ww %xx" ./a.out
./a.outC 0D 0:14.39E 0F 0I 0K 548M 0O 2%P 178R 0.30S 0.01U 0W 0X 4096Z 7c 14.39e 0k 0p 0r 0s 0t 1692w 0x

Таким образом, он тратит около S=0,3 сек в пространстве ядра и U=0,01 сек в пространстве пользователя и имеет 7+1692 переключения контекста. Переключение контекста занимает около 2000 нсек * (7+1692) = 3,398 мсек [1] ​​Однако осталось больше 10 ссек, и я хотел бы узнать, что программа делает в это время. Существуют ли другие инструменты для изучения того, что программа делает все время? gprof просто сообщает мне время для графа вызовов (userspace), а gcov перечисляет не время, проведенное в каждой строке, а только частоту выполнения времени...

[1] http://blog.tsunanet.net/2010/11/how-long-does-it-take-to-make-context.html

Answer 1

oprofile является достойным профилировщиком выборки, который может профилировать как пользовательский, так и код режима ядра.

Однако, согласно вашим цифрам, примерно 14,5 секунд времени уходит на сон, что не очень хорошо регистрируется oprofile, Возможно, что может быть более полезным ftrace в сочетании с чтением кода ядра. ftrace обеспечивает точки трассировки в ядре, которые могут регистрировать сообщения и отслеживать трассировку, когда они происходят. Событие, которое может показаться наиболее полезным для определения того, почему ваш процесс спит, будет sched_switch событие. Я бы порекомендовал вам включить стеки режима ядра и sched_switch В этом случае установите достаточно большой буфер для захвата всего времени жизни вашего процесса, затем запустите ваш процесс и сразу же прекратите трассировку. Изучив трассировку, вы сможете видеть каждый раз, когда ваш процесс перешел в спящий режим, был ли он запущен или не запущен, отметка времени с высоким разрешением и стек вызовов, указывающий, что перевело его в режим ожидания.

ftrace контролируется через debugfs, В моей системе это установлено в /sys/kernel/debug, но ваш может быть другим. Вот пример того, что я хотел бы сделать, чтобы захватить эту информацию:

# Enable stack traces
echo "1" > /sys/kernel/debug/tracing/options/stacktrace
# Enable the sched_switch event
echo "1" > /sys/kernel/debug/tracing/events/sched/sched_switch/enable
# Make sure tracing is enabled
echo "1" > /sys/kernel/debug/tracing/tracing_on
# Run the program and disable tracing as quickly as possible
./your_program; echo "0" > /sys/kernel/debug/tracing/tracing_on
# Examine the trace
vi /sys/kernel/debug/tracing/trace

В результате вы получите строки, которые выглядят так:

# tracer: nop
#
# entries-in-buffer/entries-written: 22248/3703779   #P:1
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
          <idle>-0     [000] d..3  2113.437500: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:0 next_pid=878 next_prio=120
          <idle>-0     [000] d..3  2113.437531: <stack trace>
 => __schedule
 => schedule
 => schedule_preempt_disabled
 => cpu_startup_entry
 => rest_init
 => start_kernel
     kworker/0:0-878   [000] d..3  2113.437836: sched_switch: prev_comm=kworker/0:0 prev_pid=878 prev_prio=120 prev_state=S ==> next_comm=your_program next_pid=898 next_prio=120
     kworker/0:0-878   [000] d..3  2113.437866: <stack trace>
 => __schedule
 => schedule
 => worker_thread
 => kthread
 => ret_from_fork

Линии, о которых вы позаботитесь, будут, когда ваша программа появится в виде prev_comm задача, означающая, что планировщик переключается с вашей программы на запуск чего-то другого. prev_state будет указывать, что ваша программа все еще работоспособна (R) или был заблокирован (S, U или другое письмо, см. источник ftrace). Если он заблокирован, вы можете проверить трассировку стека и исходный код ядра, чтобы выяснить, почему.