四种火焰图，快速定位Off-CPU性能问题

AshinZ

发布于 2023-11-01 17:07:08

8800

发布于 2023-11-01 17:07:08

文章被收录于专栏：程栩的性能优化笔记程栩的性能优化笔记

引

On-CPU性能问题可以借助On-CPU火焰图解决，但是无法了解进程和线程不在CPU上运行所花费的时间。如果有很多的时间花在同步请求上，也会很容易影响性能表现。

下图是一种Off-CPU时间的情况：

off-cpu event https://www.brendangregg.com/FlameGraphs/offcpuflamegraphs.html

这是一个引用线程被系统调用阻塞的情况。这个线程调用了一个系统调用，并等待这个系统调用的返回。请求的大部分时间都消耗在了等待系统调用的返回上，这通过On-CPU采样上是无法发现的。对于这种情况，我们可以通过Off-CPU分析方法来进行性能分析。

本文不会介绍Off-CPU分析相关的内容，本文将介绍如何四种使用火焰图来进行Off-CPU性能分析的方法：

I/O火焰图
Off-CPU火焰图
Wakeup火焰图
调用图(chain graphs)

I/O 火焰图

内核提供了很多追踪I/O的机制，比如可以磁盘I/O或I/O相关的系统调用。除了在一些情况例如文件系统缓存命中之外，进程往往在等待I/O时被阻塞。因此，追踪I/O也是做Off-CPU分析的一种方式。为了能够生成火焰图，我们需要捕获I/O的时间以及I/O对应的调用栈或者代码路径。我们可以用perf或eBpf来进行追踪。

我们需要注意I/O的上下文情况，主要是判断进程的请求是同步的还是异步的。如果是同步的请求，I/O延时就会直接导致进程延时，我们可以通过火焰图来进行判断。例如应用程序去读取文件内容，就可能会阻塞在磁盘I/O上。异步请求也有可能会影响到程序的性能，不过可能是以间接的方式影响。例如文件系统会对写入做缓冲，并稍后将它们刷到磁盘。最终的I/O和延迟可能会很高，但是不会直接由应用程序来承担。但是如果应用程序后续有同步读取操作，就可能会间接的承担这些延时。

文件I/O

下面是通过bcc工具包中的fileslower工具追踪VFS读写的例子：

fileslower

这里的fileslower 1 表示追踪时间超过1ms的文件I/O。这里设置成1ms是因为对于来自于cache的请求在通常情况下都会比1ms快，所以这里追踪的更多的是存储设备的慢I/O情况。如果想要生成火焰图的话，我们需要追踪堆栈信息。因此我们可以使用fileiostacks来进行追踪，其执行步骤如下：

on file read/write function entry: # 进入读写请求函数时
 start[thread_id] = timestamp   # 记录线程对应的时间戳
 
on file read/write function return: # 读写函数退出时
 if !start[thread_id]            # 如果没有记录线程开始读写的时间戳则退出
  return
 delta = timestamp - start[thread_id]  # 计算读取完成一共花的时间
 totaltime[PID, execname, user stack] += delta  # 记录该线程相关的信息，并累加时间
 start[thread_id] = 0  # 清空时间

on tracer exit: # 追踪结束时
 for each key in totaltime: # 打印全部信息
  print key
  print totaltime[key]

如图所示：

fileiostacks

fileiostacks.py L111缺少;会导致无法运行，读者可自行添加。

执行以后，我们就可以抓取到如下的信息：

fileiostacks

基于这些信息，我们可以和生成On-CPU火焰图类似，生成火焰图：

# ./fileiostacks.py -f 30 > out.stacks
# git clone https://github.com/brendangregg/FlameGraph
# cd FlameGraph
# ./flamegraph.pl --color=io --title="File I/O Time Flame Graph" --countname=us < out.stacks > out.svg

下图就是在mysql场景下基于fileiostacks.py数据生成的火焰图：

file io flame graphs - https://www.brendangregg.com/FlameGraphs/offcpuflamegraphs.html

由于折叠栈是单行条目，这里通过grep做了过滤，以便更多的查看do_command相关的逻辑：

grep do_command out.stacks | ./flamegraph.pl --color=io --title="File I/O Time Flame Graph" --countname=us > out.svg

块设备I/O

I/O 还可以从内核堆栈中的其他点进行跟踪，例如块设备 I/O、存储驱动程序 I/O、TCP/IP 堆栈中的不同层等。由于与调度程序事件相比，块设备 I/O（磁盘 I/O）通常相对不频繁。因此我们也可以用perf进行收集：

# perf record -e block:block_rq_insert -a -g -- sleep 30
# perf script --header > out.stacks
# git clone https://github.com/brendangregg/FlameGraph
# cd FlameGraph
# ./stackcollapse-perf.html < out.stacks | ./flamegraph.pl --color=io \
    --title="Block I/O Flame Graph" --countname="I/O" > out.svg

如下同样的在mysql场景下的火焰图：

block io - https://www.brendangregg.com/FlameGraphs/offcpuflamegraphs.html

基于调用栈和时间来衡量块设备I/O可以帮助我们更好的进行分析，所以我们可以通过biostacks来进行追踪：

on block I/O queue insertion: # 加入IO队列时
 start[request_id] = timestamp # 记录request_id对应的开始时间
 info[request_id] = [PID, execname, user stack, kernel stack] # 记录request相关的信息，如pid、execname等

on block I/O completion:  # IO完成时
 if !start[request_id] or !info[request_id] # 寻找是否有request_id的信息
  return
 delta = timestamp - start[request_id] # 计算IO时间
 totaltime[info[request_id]] += delta  # 记录request总的时间
 start[request_id] = 0  # 清空数据
 info[request_id] = 0   # 清空数据

on tracer exit: # 追踪结束
 for each key in totaltime: # 输出结果
  print key
  print totaltime[key]

追踪流程如下图所示：

biostacks

这里在加入队列时记录请求的相关信息是因为块I/O请求是异步的，当请求完成时，我们并不能知道是谁触发了这次请求。

我们可以基于biostacks获取火焰图：

# ./biostacks.py -f 30 > out.stacks
# git clone https://github.com/brendangregg/FlameGraph
# cd FlameGraph
# ./flamegraph.pl --color=io --title="Block I/O Time Flame Graph" --countname=us < out.stacks > out.svg

biostacks 同样缺少; ,会导致脚本无法运行，读者可自行添加。如下同样是在mysql场景下的火焰图：

block io - https://www.brendangregg.com/FlameGraphs/offcpuflamegraphs.html

从图中可以看出，大部分的样本都指向了JSON::optimize，在优化中我们需要更关注这里。

这些块I/O火焰图展示了导致I/O的原因和它们花的时间情况，但是并不一定直接影响程序延时。如果I/O 是同步的，它也会导致 mysqld 中的延迟，但情况可能并非如此：它可能是异步 I/O，不会阻塞mysqld。

小结

I/O火焰图可以帮助我们了解导致I/O的原因以及他们花的时间，适用于一些访存密集型的程序。

Off-CPU

Off-CPU分析是基于调用栈分析Off-CPU时间的方法，可以帮助我们了解进程/线程为什么被阻塞。我们可以基于如下的准则实现Off-CPU追踪分析：

Off-CPU时应用程序的调用栈不会改变。

这意味着我们只需要获取一次程序的调用栈即可，这要么在进程进入CPU执行时进行，要么在进程切换出CPU时进行。一般在进程离开CPU时进行比较简单，因为我们可以记录时间间隔。下面就是基于调用栈计算Off-CPU时间的方法：

on context switch finish: # 上下文切换结束的时候
 sleeptime[prev_thread_id] = timestamp  # 记录上一个进程A的sleep时间是当前时间
 if !sleeptime[thread_id] # 如果当前进程（切换进来的进程）没有记录或为 就说明当前进程不存在阻塞 return
  return
 delta = timestamp - sleeptime[thread_id]  # 通过现在的时间减去上次被切换出CPU时记录的时间来计算当前进程被阻塞的时间
 totaltime[pid, execname, user stack, kernel stack] += delta # 对当前进程添加阻塞时间
 sleeptime[thread_id] = 0 # 清空当前进程的sleep时间，当当前进程切换走的时候就会由下个进程来记录当前进程的sleep时间

on tracer exit:
 for each key in totaltime:
  print key
  print totaltime[key]

简单来说，就是当上下文切换发生时，对于被切换走的进程A，记录它在当前时间进入了sleep；而对于切换进来的进程B，则基于sleeptime这个map去寻找B被切换走的时间，从而计算差值。如下图所示：

Off-CPU时间计算

在计算时间的同时，追踪工具也可以记录下当前进程相关的上下文信息，如pid、用户栈、内核栈等。

我们可以通过bcc工具包中的offcputime工具来做这样的追踪：

[root@VM-16-2-centos ~]# /usr/share/bcc/tools/offcputime -K -p 996942
Tracing off-CPU time (us) of PID 996942 by kernel stack... Hit Ctrl-C to end.
^C
    finish_task_switch
    __sched_text_start
    schedule
    schedule_hrtimeout_range_clock
    poll_schedule_timeout.constprop.14
    do_select
    core_sys_select
    kern_select
    __x64_sys_select
    do_syscall_64
    entry_SYSCALL_64_after_hwframe
    -                barad_agent (996972)
        350404

这里我们通过-K来追踪了内核栈，我们也可以追踪用户栈：

[root@VM-16-2-centos ~]# /usr/share/bcc/tools/offcputime -U -p 996942
Tracing off-CPU time (us) of PID 996942 by user stack... Hit Ctrl-C to end.
^C
    -                barad_agent (3101808)
        6

Off-CPU分析可以生成火焰图，生成步骤如下所示：

/usr/share/bcc/tools/offcputime -df -p `pgrep -nx mysqld` 30 > out.stacks
git clone https://github.com/brendangregg/FlameGraph
./FlameGraph/flamegraph.pl --color=io --title="Off-CPU Time Flame Graph" --countname=us < out.stacks > out.svg

生成的火焰图如图所示：

Off-CPU火焰图

和On-CPU火焰图类似，我们可以借助其来找热点，然后进行针对性优化。

总结

Off-CPU可以帮助我们了解程序被阻塞的原因。

Wakeup

休眠的线程最终会被其他的线程唤醒，我们抓取唤醒线程的堆栈也可以构造出一个火焰图，通过这种方式我们可以知道休眠的线程到底在等待什么，这可以帮助我们解决更多的问题：唤醒信息可以帮助我们了解阻塞的真实原因。这对于锁竞争（lock contention）非常有效，因为从Off-CPU火焰图中我们只能知道线程是因为锁而阻塞，但是并不知道是谁拿了这把锁导致了线程的阻塞，通过唤醒的调用路径我们可以知道是谁拿了这把锁并且最后释放了锁，从而唤醒被阻塞的线程。与跟踪 Off-CPU事件一样，也需要小心开销，这些开销可能会根据事件的速率和使用的跟踪器而增加。

我们可以用bcc工具包中的wakeuptime来追踪唤醒信息，追踪原理如下：

on context switch start: # 上下文切换开始时 schedule
 sleeptime[thread_id] = timestamp # 记录thread_id的时间 也即开始被阻塞的时间

on wakeup:  # 唤醒时 try_to_wake_up
 if !sleeptime[target_thread_id]
  return
 delta = timestamp - sleeptime[target_thread_id] # 计算被唤醒的进程阻塞的时间
 totaltime[pid, execname, user stack, kernel stack, target_pid, target_execname] += delta # 记录总时间

原理如图所示：

wakeuptime

执行wakeuptime，结果如下图所示：

wakeuptime

对于每一个调用栈信息，我们需要自底向上读：

首先是在这个唤醒调用栈上花的时间，例如图中就是1，表示花了1ms在这个调用栈上；
接着我们可以看到waker，表示这个调用栈的唤醒者是sh；
接着我们可以看到调用栈，如bpf_get_stackid_raw_tp -> cleanup_module -> bpf_trace_run1...；
最后我们可以看到被唤醒的进程(target)，这里也是sh；

同样的，对于wakeuptime的结果，我们也可以生成火焰图：

# /usr/share/bcc/tools/wakeuptime -f 30 > out.stacks
# git clone https://github.com/brendangregg/FlameGraph
# cd FlameGraph
# ./flamegraph.pl --color=wakeup --title="Wakeup Time Flame Graph" --countname=us < out.stacks > out.svg

在mysql场景中使用，我们得到如下的火焰图：

wakeup time - https://www.brendangregg.com/FlameGraphs/offcpuflamegraphs.html

从图中我们可以看出，mysqld会经常性的唤醒sysbench，而sysbench也会经常性的唤醒mysqld。

总结

wakeup火焰图可以帮助我们了解唤醒时的相关情况，尤其适用于有锁这样相互关联的场景。

Chain Graphs

结合Off-CPU火焰图和wakeup火焰图，我们可以得到很多信息，那么是否有一种方式可以直接追踪整个过程呢？链图是一种实验性质的可视化方式，其将Off-CPU和wakeup堆栈关联起来，虽然开销会比较高，但是我们可以得到很多有用的信息。

Off-Wake Flame Graphs

作为尝试的第一步，我们可以将Off-CPU堆栈和单个wakeup堆栈进行关联。我们可以通过bcc工具包中的offwaketime来得到相关信息：

[root@VM-16-2-centos workplace]# /usr/share/bcc/tools/offwaketime 
Tracing blocked time (us) by user + kernel off-CPU and waker stack... Hit Ctrl-C to end.

    waker:           node 3502862
    b'[unknown]'
    b'entry_SYSCALL_64_after_hwframe'
    b'do_syscall_64'
    b'ksys_write'
    b'vfs_write'
    b'eventfd_write'
    b'__wake_up_common'
    b'ep_poll_callback'
    b'__wake_up_common'
    --               --
    b'finish_task_switch'
    b'__sched_text_start'
    b'schedule'
    b'schedule_hrtimeout_range_clock'
    b'ep_poll'
    b'do_epoll_wait'
    b'__x64_sys_epoll_wait'
    b'do_syscall_64'
    b'entry_SYSCALL_64_after_hwframe'
    b'epoll_wait'
    b'[unknown]'
    target:          A 3502847
        11

我们可以从中间（--）开始，下半部分是 Off-CPU 堆栈，上半部分是wakeup堆栈，但是读取顺序相反。例如这里node作为唤醒者，它的调用栈是[unknown] -> entry_SYSCALL_64_after_hwframe -> do_syscall_64 ... ，而它最后会唤醒target，也即A进程；反过来看，target也就是A进程，它的调用栈是[unknown] -> epoll_wait ...，最后它被切换出CPU。总结：「从上往下读取上半部分调用栈，了解waker如何唤醒target；从下往上读取下半部分调用栈，了解target进程是因为什么而离开CPU」。

同样的，我们可以基于这份数据生成Off-Wake火焰图：

# /usr/share/bcc/tools/offwaketime -f 30 > out.stacks
# git clone https://github.com/brendangregg/FlameGraph
# cd FlameGraph
# ./flamegraph.pl --color=chain --title="Off-Wake Time Flame Graph" --countname=us < out.stacks > out.svg

下图就是一个Off-Wake火焰图：

off-wake time - https://www.brendangregg.com/FlameGraphs/offcpuflamegraphs.html

Off-Wake火焰图的一个问题就是数据过多，我们需要进行一些数据的过滤。在上图中，如果我们聚焦于do_command：

do_command

我们会发现：从下往上看，mysqld因为要进行I/O(vfs_read)而离开CPU；从上往下看，mysqld在I/O操作完成后被唤醒。这两者恰好是对应的。

Chain Graphs

通过Wake-off火焰图，我们可以解决一些问题，但是我们并不知道完整的调用链是什么样的。

因此我们可以使用链图(Chain Graphs)来获取这些信息，如下图所示：

Chain Graph - https://www.brendangregg.com/FlameGraphs/offcpuflamegraphs.html

底部是Off-CPU的堆栈，往上是一条灰色的隔断。灰色隔断往上的是wakeup的堆栈，和Wake-off火焰图类似，我们要从上往下去读取；多个唤醒调用栈通过灰色隔断来进行区分。这个图中我们可以看到两次唤醒，vmstat通过tty-write -> n_tty_write...的调用栈唤醒了kworker，kworker以process_one_work -> flush_to_ldisc...的调用栈唤醒sshd。