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:
- Where is
__xstat64called? I think it must be child of some function likemainorone? - Why this function cost that much, while main cost only 3%?