分析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.3sec，在用户空间使用U=0.01sec，并且有7+1692上下文开关。一个上下文开关大约需要2000 10sec * (7+1692) = 3.398msec 1，但是还有超过10秒的时间，我想知道这个程序现在正在做什么。有没有其他工具来调查程序一直在做什么？gprof只是告诉我(userspace)调用图的时间，gcov没有列出在每一行中花费的时间，而是只列出执行一次时间的频率。

1

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 )。如果被阻止，您可以检查堆栈跟踪和内核源代码，以找出原因。