Linux动态追踪

身为一个SRE,在工作中经常遇到一些问题,这些问题在staging(测试环境)测不出来,却总在线上碰到,最关键的是难以复现,总是等待再发生。

本文是我看了春哥(章亦春)和 Brendan Gregg 博客后的小计
动态追踪技术漫谈
http://www.brendangregg.com/

所以这个时候就需要一种动态的追踪技术了,线上的服务不能随意的停止,gdb调试虽然好用,但是身为sre,这种工具就不适合我们在线上生产环境使用了,gdb调试会可能会导致程序的中断运行,一般不太熟悉这种工具的人刚开始使用就会将线上服务搞挂。当gdb接到attach命令后的第一件事情就是停止进程的运行,经常会遇到什么gdb调试,把程序调试挂掉了。而动态追踪技术强调的是非交互式,尽可能的降低性能的损耗。而GDB所基于的古老的ptrace,不考虑生产安全性,也不在乎性能损耗。

动态追踪技术

动态追踪技术是一种后现代的高级调试技术。现如今的软件系统愈发的复杂,一旦线上的页面500了,可能的情况是业务逻辑问题、也可能是依赖的环境挂了、更有可能是服务面临性能问题。而且最关键的是这些都是不可预见的,说不定哪天就突然挂了,让人发狂。到底是哪里出现问题了?
动态追踪技术孕育而生,在动态追踪里,通常是通过探针这样的机制来发起查询的。在软件系统的某一层次,或者某几个层次上面,安插一些探针,然后我们会自定义这些探针所关联的处理程序。动态追踪一般来说也是不需要目标来配合的,因为我们的服务上线之前是不知道会出现什么样的性能问题,就算知道,也不可能尽详细的去埋点。动态追踪的好处就是“随时随地,按需采集”,其另一大优势就是自身性能损耗极小。据说是在百分之五或者更低的水平。

调试符号

调试符号是我这里需要提到的一点,调试符号一般是软件在编译的时候,由编译器提供的调试使用的元信息。比如函数和变量的地址,数据结构和内存布局等等。映射回源代码里的抽象实体的名称,如函数名,变量,类型名之类的。通常,也只有开源的软件才容易生成调试符号。要不抓到的都是16进制地址,是很痛苦的。

动态追踪的事件源

根据事件类型的不同,分为三类。静态探针,动态探针以及硬件事件。


动态追踪技术的事件源.png
  • 静态探针,是指事先在代码中定义好,并编译进应用程序或者内核中的探针。常见的有内核中的跟踪点(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

更多可以参考

http://www.brendangregg.com/perf.html

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 217,406评论 6 503
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 92,732评论 3 393
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 163,711评论 0 353
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 58,380评论 1 293
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 67,432评论 6 392
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 51,301评论 1 301
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,145评论 3 418
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 39,008评论 0 276
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 45,443评论 1 314
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,649评论 3 334
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,795评论 1 347
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,501评论 5 345
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,119评论 3 328
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,731评论 0 22
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,865评论 1 269
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,899评论 2 370
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,724评论 2 354

推荐阅读更多精彩内容