Linux - 从系统调用分析应用问题

Linux - 从系统调用分析应用问题

背景

Linux下应用的执行，遇到性能问题时，可参考下图对应的工具进行收集分析，

其中System Call Interface层，可以使用strace命令进行日志收集。

strace收集System Call Interface日志

$ strace -ttTffy -o /path/to/strace.log <command>
$ #或追踪已运行的进程，如下
$ strace -ttTffy -o /path/to/strace.log -p <PID>

分析代码

# Discription: strace log analyzer
# Author: WanlinWang Ben
# Date:   09/19/2021
# Usage:
#       步骤1：获取strace日志，使用命令：strace -ttTffy -o /path/to/strace.log <command>
#                                或：strace -ttTffy -o /path/to/strace.log -p <PID>
#
#       步骤2：分析strace输出日志，使用命令：strace_analyzer.py /path/to/strace.log*


import re
import pandas as pd
import argparse

parser = argparse.ArgumentParser(description='strace日志分析脚本')
parser.add_argument('log_file', type=str, nargs='+',
                    help='log file\'s name.')

args = parser.parse_args()
print(args.log_file)
print()


pd.set_option('display.max_colwidth', 256)
pd.set_option('display.max_columns', 10)
pd.set_option('display.expand_frame_repr', False)

log_file_list = args.log_file
regexp_pattern = re.compile(r"\d{2}:\d{2}:\d{2}.\d{6} ([^(]*).* <([\d\.]*)>")
df = pd.DataFrame(columns=["file", "line_num", "sys call", "time"])

for log_file in log_file_list:
    with open(log_file) as log:
        for num, line in enumerate(log, 1):
            # print(line)
            match = regexp_pattern.match(line)
            if match:
                syscall, time = match.groups()
                pd_line = {"file": log_file, "line_num": num, "sys call": syscall, "time": float(time)}
                df = df.append(pd_line, ignore_index=True)

# print(df)
print("Top 10 by sys call times".center(80, '-'))
print(df.sort_values(by="time", ascending=False)[:10].to_string(index=False))

print()
df_mean = df.groupby("sys call", as_index=False)["time"].mean().sort_values(by="time", ascending=False).rename(columns={"time": "Mean time"})
df_sum = df.groupby("sys call", as_index=False)["time"].sum()
df_sum = df_sum.rename(columns={"time": "Total time"})
df_count = df.groupby("sys call", as_index=False)["time"].count()
df_count = df_count.rename(columns={"time": "Count"})

print("Summary".center(80, '-'))
print(df_mean.join(df_count.set_index('sys call'), on='sys call').join(df_sum.set_index('sys call'), on='sys call').to_string(index=False))

效果

在日常中的使用

对正常场景，可以运行日志收集脚本，创建benchmark。
遇到有性能问题的场景时，运行日志收集脚本并使用strace_analyer.py脚本进行分析，针对相同的系统调用及参数，分别对比找出性能瓶颈。

常见案例：
在HPC场景中，在同一个集群下挂载了相同的NFS目录。用户在该NFS目录跑仿真任务，感受非常慢。
按照用户的经验来看，耗时是平时的5倍以上。使用该日志收集脚本，对用户的仿真任务进行追踪，发现其操作NFS目录下的文件时，耗时比平时长很多。再结合NFS在存储侧的指标（IOPS，latency，throughput，capacity）监控，可以发现性能瓶颈来自与NFS读写。

小结

本文对Linux的系统调用日志进行简单分析，看是否能够从耗时较长的系统调用入手，进一步分析与发现性能问题的根因。

strace除了可以分析性能问题，也能用来分析系统调用层的错误。如笔者曾遇到的：应用的文件选择框中选中文件，报错文件格式不支持，但将文件拷贝到另一个文件夹下就没有问题。使用strace追踪后发现是“EOVERFLOW (Value too large for defined data type)”错误，查资料并验证后，发现是32bit程序操作inode number>2^32的文件时导致的。