Why this `__xstat64` cost this much in perf?

Viewed 184

I have a C++ program which parses timestamps.

#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();
    }
}

Data can be generated like with code

#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()

Now I want to perf that with the following codes.

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

However, I found result it like this, seems that __xstat64 cost too much time.

+   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    

My question is:

  1. Where is __xstat64 called? I think it must be child of some function like main or one?
  2. Why this function cost that much, while main cost only 3%?
1 Answers

Essentially, mktime is the bottleneck:

Converts local calendar time to a time since epoch as a time_t object

Converting from local calendar time to a Unix epoch is a non-trivial task. On Linux, at least when compiling with gcc, it is implemented by libc. To understand what local time means on your machine, it uses the file /etc/localtime. That is why the statsystem call shows up in strace.

Your strace output might differ, but this is what I got on Arch Linux after compiling with gcc 11.1.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
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)

That should explain why __xstat64 dominates the profiling output. Note that stat is a system call, where you hand over the control to the Kernel. That is expensive.

As a side-note, if you know that the timestamps are UTC, then converting it to a Unix epoche is a simpler task. Yet for general local time, it is tricky as the implementation has to be aware of special cases like daylight savings time.

Why this function cost that much, while main cost only 3%?

Perf uses sampling and only counts the function that is on top of the stack. 3% in main means, 3% of the sample had main on top. Most of the samples have been recorded during the execution of one. Some profiling tools would therefore count main as hot, too. Yet, by default, perf only considers one to be hot, not its caller.

Related