为什么这个 `__xstat64` 在性能上要花这么多钱？

Question

我有一个解析时间戳的 C++ 程序。

#include <iostream>
#include <fstream>
#include <cstdint>
#include <type_traits>
#include <string>
#include <cstddef>
#include <cstring>
#include <sstream>
#include <cstdio>
#include <ctime>


void one(){
    std::ifstream fin;
    fin.open("log2.txt");
    unsigned long long x = 0;
    while (!fin.eof()) {
        std::string line;
        std::getline(fin, line);
        int year;
        int month;
        int day;
        int hour;
        int minute;
        int second;
        int milli_second;
        int timezone_hour;
        int timezone_min;

        std::sscanf(line.data(), "[%d/%d/%d %d:%d:%d.%d %d:%d]", &year, &month, &day, &hour, &minute, &second, &milli_second,
            &timezone_hour, &timezone_min);

        std::tm time {};
        time.tm_year = year - 1900;
        time.tm_mon = month - 1;
        time.tm_mday = day;
        time.tm_hour = hour;
        time.tm_min = minute;
        time.tm_sec = second;

        time_t ctime = mktime(&time) * 1000; 
        x += ctime;
        x %= 192929;
    }
    printf("%llu", x);
    fin.close();
}

int main(int c, char *argv[]){
    bool fi = false;
    printf("c %d\n", c);
    if(c == 2){
        if(argv[1][0] != 'n'){
            fi = true;
            printf("fi\n");
            fflush(stdout);
        }
    }
    if(fi){
        while(1){
            one();
        }
    }else{
        one();
    }
}

数据可以像代码一样生成

#coding: utf8

import time, random, string

def one2(prev_t):
    t = prev_t + random.uniform(1, 100)
    ts = time.strftime("[%Y/%m/%d %H:%M:%S.123 +08:00]", time.localtime(t))
    msg_len = int(random.uniform(2, 20))
    msg = ''.join(random.choice(string.ascii_uppercase + string.digits) for _ in range(msg_len))
    level = random.choice(["DEBUG", "INFO"])
    return t, "{} [{}] [<unknown>] {}\n".format(ts, level, msg)

def make_log():
    t = time.time()
    with open("log3.txt", "w") as f:
        for i in range(1, 10000000):
            t, s = one2(t)
            f.write("{}".format(s))

if __name__ == '__main__':
    make_log()

现在我想用下面的代码来完成它。

g++ -g -O0 t.cpp -o tttzzz
./tttzzz &
ps aux | grep tttzzz
export TPID=$(ps aux | grep 'tttzzz' | grep -v grep | awk '{print $2}')
echo "TPID" $TPID
timeout -s INT 8s perf record -F 99 -e "cpu-clock" -g -p $TPID
perf report

但是，我发现结果是这样的，似乎__xstat64 花费了太多时间。

+   50.89%     0.00%  [.] __xstat64                                                                                          __xstat64+140186421776405       ◆
+   42.20%     0.00%  [k] system_call_fastpath                                                                               system_call_fastpath+18446603336▒
+   41.39%     0.00%  [k] sys_newstat                                                                                        sys_newstat+18446603336221188110▒
+   39.00%     0.00%  [k] SYSC_newstat                                                                                       SYSC_newstat+1844660333622118814▒
+   35.34%     0.00%  [k] vfs_fstatat                                                                                        vfs_fstatat+18446603336221188195▒
+   35.22%     0.00%  [k] user_path_at                                                                                       user_path_at+1844660333622118811▒
+   31.43%     0.00%  [k] user_path_at_empty                                                                                 user_path_at_empty+1844660333622▒
+   31.11%     0.00%  [k] filename_lookup                                                                                    filename_lookup+1844660333622118▒
+   19.80%     0.00%  [.] _IO_vsscanf                                                                                        _IO_vsscanf+140186421776487
+    3.07%     0.00%  [.] main                                                                                               main+4194414

...
     0.72%     0.22%  t        [kernel.kallsyms]    [k] path_get                                                                                             ▒
+    0.72%     0.72%  t        [kernel.kallsyms]    [k] generic_fillattr                                                                                     ▒
     0.69%     0.69%  t        [kernel.kallsyms]    [k] copy_user_enhanced_fast_string                                                                       ▒
+    0.69%     0.00%  t        libc-2.17.so         [.] __GI___libc_read                                                                                     ▒
+    0.67%     0.00%  t        [unknown]            [.] 0x00007fff4122a180                                                                                   ▒
     0.67%     0.67%  t        libc-2.17.so         [.] parse_tzname                                                                                         ▒
+    0.66%     0.66%  t        t                    [.] one    

我的问题是：

1. __xstat64 在哪里调用？我认为它一定是 main 或 one 之类的函数的子级？
2. 为什么这个功能成本这么高，而主要成本只有 3%？

Answer 1

本质上，mktime 是瓶颈：

将本地日历时间转换为自纪元以来的时间作为 time_t 对象

从本地日历时间转换为 Unix 纪元是一项不平凡的任务。在 Linux 上，至少在使用 gcc 编译时，它是由 libc 实现的。要了解本地时间在您的机器上的含义，它使用文件/etc/localtime。这就是statsystem 调用出现在strace 中的原因。

您的 strace 输出可能会有所不同，但这是我在使用 gcc 11.1.0 编译后在 Arch Linux 上得到的：

...
newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}, 0) = 0
newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}, 0) = 0
newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=2298, ...}, 0) = 0
... (repeating, as each call of "one" calls mktime, which triggers it)

这应该可以解释为什么__xstat64 主导分析输出。请注意，stat 是一个系统调用，您将控制权交给内核。太贵了。

附带说明，如果您知道时间戳是 UTC，那么将其转换为 Unix 纪元是一项更简单的任务。然而，对于一般当地时间来说，这很棘手，因为实现必须意识到像 daylight savings time 这样的特殊情况。

为什么这个功能成本这么高，而主要成本只有 3%？

Perf 使用采样和only counts the function that is on top of the stack。 main 中的 3% 表示，3% 的样本顶部有 main。在one 的执行过程中记录了大部分样本。因此，一些分析工具也会将main 视为热门。然而，默认情况下，perf 只认为 one 是热的，而不是它的调用者。