身为一个SRE,在工作中经常遇到一些问题,这些问题在staging(测试环境)测不出来,却总在线上碰到,最关键的是难以复现,总是等待再发生。
本文是我看了春哥(章亦春)和 Brendan Gregg 博客后的小计
动态追踪技术漫谈
http://www.brendangregg.com/
所以这个时候就需要一种动态的追踪技术了,线上的服务不能随意的停止,gdb调试虽然好用,但是身为sre,这种工具就不适合我们在线上生产环境使用了,gdb调试会可能会导致程序的中断运行,一般不太熟悉这种工具的人刚开始使用就会将线上服务搞挂。当gdb接到attach命令后的第一件事情就是停止进程的运行,经常会遇到什么gdb调试,把程序调试挂掉了。而动态追踪技术强调的是非交互式,尽可能的降低性能的损耗。而GDB所基于的古老的ptrace,不考虑生产安全性,也不在乎性能损耗。
动态追踪技术
动态追踪技术是一种后现代的高级调试技术。现如今的软件系统愈发的复杂,一旦线上的页面500了,可能的情况是业务逻辑问题、也可能是依赖的环境挂了、更有可能是服务面临性能问题。而且最关键的是这些都是不可预见的,说不定哪天就突然挂了,让人发狂。到底是哪里出现问题了?
动态追踪技术孕育而生,在动态追踪里,通常是通过探针这样的机制来发起查询的。在软件系统的某一层次,或者某几个层次上面,安插一些探针,然后我们会自定义这些探针所关联的处理程序。动态追踪一般来说也是不需要目标来配合的,因为我们的服务上线之前是不知道会出现什么样的性能问题,就算知道,也不可能尽详细的去埋点。动态追踪的好处就是“随时随地,按需采集”,其另一大优势就是自身性能损耗极小。据说是在百分之五或者更低的水平。
调试符号
调试符号是我这里需要提到的一点,调试符号一般是软件在编译的时候,由编译器提供的调试使用的元信息。比如函数和变量的地址,数据结构和内存布局等等。映射回源代码里的抽象实体的名称,如函数名,变量,类型名之类的。通常,也只有开源的软件才容易生成调试符号。要不抓到的都是16进制地址,是很痛苦的。
动态追踪的事件源
根据事件类型的不同,分为三类。静态探针,动态探针以及硬件事件。
- 静态探针,是指事先在代码中定义好,并编译进应用程序或者内核中的探针。常见的有内核中的跟踪点(tracepoints,散落在内核源代码中的一些hook,使能后一旦特定的代码被运行到时就会被触发)和USDT(Userland Statically Defined Tracing)探针。
- 动态探针,是事先没有在代码中定义,但是可以在运行的时候动态添加。比如函数的调用和返回值。常见的有uprobes(跟踪用户态函数)和kprobes(跟踪内核态函数)。
- 硬件事件,一般由性能监控计数器PMC产生。比如intel的CPU,一般会内置统计性能的寄存器(Hardware Performance Counter)。
Dtrace
Dtrace 是动态追踪技术的鼻祖,讲故事的内容就不在这里细说了,有兴趣的可以看看春哥的原文(动态追踪技术漫谈)
Dtrace使用了一种类似与C语言的脚本语言,叫做D语言。基于Dtrace的调试工具都是用这种D语言编写的,D语言支持特殊的语法用于指定“探针”,可以定位某个内核函数的入口和出口,或者是某个用户态函数的入口或出口。
优点:
- D语言是运行时常驻内核的,而且十分小巧,每个调试工具启动和退出都十分的快速。
缺点:
- 缺乏循环结构,对目标进程的复杂数据结构的分析工具异常难以编写。(官方称是为了避免过热的循环)
- 对用户态的追踪支持比较弱,没有自动加载用户态的调试符号的功能,需要自己在D语言中声明用到的用户态C语言结构体之类的类型。
- 对Linux的支持不太好。
既然Dtrace 到现如今都不能很好的运行在Linux上,那我们也就看个热闹,大致了解下就行了。
SystemTap
SystemTap目前是Linux世界功能最强大,最实用的动态追踪框架。同时也支持火焰图。
优点:
- 非常成熟的用户态调试符号的自动加载
- 对复杂探针处理程序的编写上比较友好。
缺点:
- 不是Linux内核的一部分,需要不停一直追赶主线内核的变化。
- 启动慢
既然介绍到systemtap了,就先一个例子入门吧。
这里模拟一个网络上的问题。(这里真的需要感谢下geektime的倪鹏飞老师,这里的例子就用这个吧)
$ docker run --name nginx --privileged -p 8080:8080 -itd feisky/nginx:nat
运行ab压测竟然失败了
$ ab -c 1000 -n 10000 -r -s 2 http://localhost:8080/
This is ApacheBench, Version 2.3 <$Revision: 1430300 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 1000 requests
apr_pollset_poll: The timeout specified has expired (70007)
Total of 1015 requests completed
这里只完成了5602个请求,可以看到,设为超市时间为2秒影响了其性能。
来用systemtap试一下吧。
创建脚本 dropwatch.stp 。
#! /usr/bin/env stap
############################################################
# Dropwatch.stp
# Author: Neil Horman <nhorman@redhat.com>
# An example script to mimic the behavior of the dropwatch utility
# http://fedorahosted.org/dropwatch
############################################################
# Array to hold the list of drop points we find
global locations
# Note when we turn the monitor on and off
probe begin { printf("Monitoring for dropped packets\n") }
probe end { printf("Stopping dropped packet monitor\n") }
# increment a drop counter for every location we drop at
probe kernel.trace("kfree_skb") { locations[$location] <<< 1 }
# Every 5 seconds report our drop locations
probe timer.sec(5)
{
printf("\n")
foreach (l in locations-) {
printf("%d packets dropped at %s\n",
@count(locations[l]), symname(l))
}
delete locations
}
这个脚本跟踪内核函数kfree_skb() 的调用,并统计丢包位置。
$ stap --all-modules dropwatch.stp
Monitoring for dropped packets
这里可以观察到大量的丢包都是发生在nf_hook_slow 位置。接下来只需要跟踪nf_hook_slow 就可以了。
10031 packets dropped at nf_hook_slow
676 packets dropped at tcp_v4_rcv
7284 packets dropped at nf_hook_slow
268 packets dropped at tcp_v4_rcv
更多可直接用的脚本可以在这里找到
https://sourceware.org/systemtap/SystemTap_Beginners_Guide/useful-systemtap-scripts.html
perf
perf 是 Liunx2.6.31以后内置的性能分析工具。可以利用他来追踪应用程序或者内核中的热点函数。其相当高效,有个缺点它不是内核可编程的,除非eBPF支持。但其不妨碍成为我最喜欢的一个工具。而且其相当的安全。
perf list
perf 可触发的采样事件可以通过perf list 展示。
$ perf list
List of pre-defined events (to be used in -e):
alignment-faults [Software event]
bpf-output [Software event]
context-switches OR cs [Software event]
cpu-clock [Software event]
cpu-migrations OR migrations [Software event]
... ...
通过如上命令,可以看到很多事件,大致可以分为三类。
- HardWare Event ,由PMU硬件产生的事件,比如cache命中等。
- Software Event,是内核软件产生的事件,比如进程切换等
- Tracepoint Event,是有内核的静态tracepoint所触发的事件,比如slab调度其的调度次数等。
perf stat
perf stat 可以提供应用程序的整体情况和汇总数据。
这里我提供一个疯狂循环的c代码
void longa()
{
int i,j;
for(i = 0; i < 10000000; i++)
j=i;
}
void foo2()
{
int i;
for(i=0 ; i < 100; i++)
longa();
}
void foo1()
{
int i;
for(i = 0; i< 1000; i++)
longa();
}
int main(void)
{
foo1();
foo2();
}
这个程序十分疯狂,看样子这是一个计算密集型的程序,会大量耗费cpu的计算资源,且其对I/O没有什么要求。
使用 perf stat 看看结果。
$ perf stat ./a.out
Performance counter stats for './a.out':
30249.723058 task-clock (msec) # 1.000 CPUs utilized
150 context-switches # 0.005 K/sec
2 cpu-migrations # 0.000 K/sec
113 page-faults # 0.004 K/sec
<not supported> cycles
<not supported> instructions
<not supported> branches
<not supported> branch-misses
30.260523538 seconds time elapsed
perf stat 的输出可以看到
- task-clock-msecs :cpu 使用率高,达到惊人的30249 。
- context-switches:上下文切换。
- cpu-migrations :程序运行中发生的cpu迁移,即被调度其从一个cpu转移到另一个cpu上。
- page-faults:缺页错误。
perf top
有些时候,需要在复杂的系统中找出一些形迹可疑的程序,但又不知道是要追踪谁,那么就要让 perf top 出马了。
这里还是以刚才的可怕的循环为例
Samples: 15K of event 'cpu-clock', Event count (approx.): 3665492182
Overhead Shared Object Symbol
99.49% a.out [.] longa
0.04% [kernel] [k] _raw_spin_unlock_irqrestore
0.03% [e1000] [k] e1000_xmit_frame
0.02% [kernel] [k] finish_task_switch
0.02% perf [.] machine__resolve
0.02% libslang.so.2.2.4 [.] SLsmg_write_chars
0.02% [kernel] [k] __do_softirq
0.01% perf [.] thread__find_addr_map
0.01% perf [.] dso__find_symbol
0.01% perf [.] perf_evsel__parse_sample
0.01% [kernel] [k] tick_nohz_idle_enter
一目了然了,系统中有个用户态进程叫 langa 在疯狂耗费cpu。
其中第一行包含三个数据,分别是1、采样数(Samples)2、事件类型(event)和事件总数量(Event count)。
下面的数据分为四列
- Overhead:该符号的性能事件在采样比列中的百分比。
- Shared:该函数或指令所在的动态共享对象,如进程名或者内核模块名称。
- Object:[.] 是用户态,[k]是内核态。
- Symbol:符号名,也就是函数名。未知的话用16进制表示。
perf record && perf report
更多可以参考