Linux 性能优化实战 - 第一天学习

说明：文章内容来自专栏，非原创

 

46章节 为什么应用容器化后，启动慢了很多

工具：

 

dmesg - print or control the kernel ring buffer

 

47 章节 服务器总是时不时丢包，我该怎么办？

TCP 来说，丢包通常意味着网络拥塞和重传，进而会导致网络延迟增大以及吞吐量降低。

# -c表示发送10个请求，-S表示使用TCP SYN，-p指定端口为80
$ hping3 -c 10 -S -p 80 192.168.0.30
HPING 192.168.0.30 (eth0 192.168.0.30): S set, 40 headers + 0 data bytes
len=44 ip=192.168.0.30 ttl=63 DF id=0 sport=80 flags=SA seq=3 win=5120 rtt=7.5 ms
len=44 ip=192.168.0.30 ttl=63 DF id=0 sport=80 flags=SA seq=4 win=5120 rtt=7.4 ms
len=44 ip=192.168.0.30 ttl=63 DF id=0 sport=80 flags=SA seq=5 win=5120 rtt=3.3 ms
len=44 ip=192.168.0.30 ttl=63 DF id=0 sport=80 flags=SA seq=7 win=5120 rtt=3.0 ms
len=44 ip=192.168.0.30 ttl=63 DF id=0 sport=80 flags=SA seq=6 win=5120 rtt=3027.2 ms

--- 192.168.0.30 hping statistic ---
10 packets transmitted, 5 packets received, 50% packet loss
round-trip min/avg/max = 3.0/609.7/3027.2 ms

root@nginx:/# netstat -i
Kernel Interface table
Iface      MTU    RX-OK RX-ERR RX-DRP RX-OVR    TX-OK TX-ERR TX-DRP TX-OVR Flg
eth0       100       31      0      0 0             8      0      0      0 BMRU
lo       65536        0      0      0 0             0      0      0      0 LRU

root@nginx:/# netstat -s
Ip:
    Forwarding: 1          //开启转发
    31 total packets received    //总收包数
    0 forwarded            //转发包数
    0 incoming packets discarded  //接收丢包数
    25 incoming packets delivered  //接收的数据包数
    15 requests sent out      //发出的数据包数
Icmp:
    0 ICMP messages received    //收到的ICMP包数
    0 input ICMP message failed    //收到ICMP失败数
    ICMP input histogram:
    0 ICMP messages sent      //ICMP发送数
    0 ICMP messages failed      //ICMP失败数
    ICMP output histogram:
Tcp:
    0 active connection openings  //主动连接数
    0 passive connection openings  //被动连接数
    11 failed connection attempts  //失败连接尝试数
    0 connection resets received  //接收的连接重置数
    0 connections established    //建立连接数
    25 segments received      //已接收报文数
    21 segments sent out      //已发送报文数
    4 segments retransmitted    //重传报文数
    0 bad segments received      //错误报文数
    0 resets sent          //发出的连接重置数
Udp:
    0 packets received
    ...
TcpExt:
    11 resets received for embryonic SYN_RECV sockets  //半连接重置数
    0 packet headers predicted
    TCPTimeouts: 7    //超时数
    TCPSynRetrans: 4  //SYN重传数
  ...

49 | 案例篇：内核线程 CPU 利用率太高，我该怎么办？

案例分析输出结果

第一步：运行 hping3 命令，模拟 Nginx 的客户端请求 发现系统的响应明显变慢了

# -S参数表示设置TCP协议的SYN（同步序列号），-p表示目的端口为80
# -i u10表示每隔10微秒发送一个网络帧
# 注：如果你在实践过程中现象不明显，可以尝试把10调小，比如调成5甚至1
$ hping3 -S -p 80 -i u10 127.0.0.1 

第二步：从 top 的输出中，你可以看到，两个 CPU 的软中断使用率都超过了 30%；而 CPU 使用率最高的进程，正好是软中断内核线程 ksoftirqd/0 和 ksoftirqd/1

$ top
top - 08:31:43 up 17 min,  1 user,  load average: 0.00, 0.00, 0.02
Tasks: 128 total,   1 running,  69 sleeping,   0 stopped,   0 zombie
%Cpu0  :  0.3 us,  0.3 sy,  0.0 ni, 66.8 id,  0.3 wa,  0.0 hi, 32.4 si,  0.0 st
%Cpu1  :  0.0 us,  0.3 sy,  0.0 ni, 65.2 id,  0.0 wa,  0.0 hi, 34.5 si,  0.0 st
KiB Mem :  8167040 total,  7234236 free,   358976 used,   573828 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  7560460 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
    9 root      20   0       0      0      0 S   7.0  0.0   0:00.48 ksoftirqd/0
   18 root      20   0       0      0      0 S   6.9  0.0   0:00.56 ksoftirqd/1
 2489 root      20   0  876896  38408  21520 S   0.3  0.5   0:01.50 docker-containe
 3008 root      20   0   44536   3936   3304 R   0.3  0.0   0:00.09 top
    1 root      20   0   78116   9000   6432 S   0.0  0.1   0:11.77 systemd
 ...

画外音：

 

我们已经知道了 ksoftirqd 的基本功能，可以猜测是因为大量网络收发，引起了 CPU 使用率升高；但它到底在执行什么逻辑，我们却并不知道。

 

背景知识补充

与进程上下文切换不同，中断上下文切换并不涉及到进程的用户态。

所以，即便中断过程打断了一个正处在用户态的进程，也不需要保存和恢复这个进程的虚拟内存、全局变量等用户态资源。

中断上下文，其实只包括内核态中断服务程序执行所必须的状态，包括CPU寄存器、内核堆栈、硬件中断参数等。

 

第三步：那还有没有其他方法，来观察内核线程 ksoftirqd 的行为呢？

普通的命令不可以，perf ，这个内核自带的性能剖析工具

# 采样30s后退出
$ perf record -a -g -p 9 -- sleep 30
  perf report

第四步：分析

、网桥以及 netfilter 调用等，都是导致软中断 CPU 升高的重要因素，也就是影响网络性能的潜在瓶颈。

 

使用 perf 对系统内核线程进行分析时，内核线程依然还在正常运行中，所以这种方法也被称为动态追踪技术

 

而动态追踪技术的出现，就为这些问题提供了完美的方案：它既不需要停止服务，也不需要修改应用程序的代码；

所有一切还按照原来的方式正常运行时，就可以帮你分析出问题的根源。

 

同时，相比以往的进程级跟踪方法（比如 ptrace），动态追踪往往只会带来很小的性能损耗（通常在 5% 或者更少）。

 

实际上，火焰图方法同样适用于普通进程。比如，在分析 Nginx、MySQL 等各种应用场景的性能问题时，火焰图也能帮你更快定位热点函数，找出潜在性能问题

 

50 | 案例篇：动态追踪怎么用？（上）
当碰到内核线程的资源使用异常时，很多常用的进程级性能工具，并不能直接用到内核线程上。

这时，我们就可以使用内核自带的 perf 来观察它们的行为，找出热点函数，进一步定位性能瓶颈

。不过，perf 产生的汇总报告并不直观，所以我通常也推荐用火焰图来协助排查。

其实，使用 perf 对系统内核线程进行分析时，内核线程依然还在正常运行中，

所以这种方法也被称为动态追踪技术。

 

使用场景

此外，这类方式还有大量的性能问题。比如，出现的概率小，只有线上环境才能碰到。这种难以复现的问题，亦是一个巨大挑战。

动态追踪
DTrace 本身依然无法在 Linux 中运行，但它同样对 Linux 动态追踪产生了巨大的影响。

很多工程师都尝试过把 DTrace 移植到 Linux 中，这其中，

最著名的就是 RedHat 主推的 SystemTap。

 

故事
最初产生的时候，我记得有这样一个故事，当时 Solaris 操作系统的几个工程师花了几天几夜去排查一个看似非常诡异的线上问题。开始他们以为是很高级的问题，就特别卖力，结果折腾了几天，最后发现其实是一个非常愚蠢的、某个不起眼的地方的配置问题。自从那件事情之后，这些工程师就痛定思痛，创造了 DTrace 这样一个非常高级的调试工具，来帮助他们在未来的工作当中避免把过多精力花费在愚蠢问题上面。毕竟大部分所谓的“诡异问题”其实都是低级问题，属于那种“调不出来很郁闷，调出来了更郁闷”的类型。

我觉得 SystemTap 是目前 Linux 世界功能最强大，同时也是最实用的动态追踪框架

什么是动态追踪
我很高兴能在这里和大家分享动态追踪技术（Dynamic Tracing）这个主题，对我个人来说也是一个很激动人心的话题。那么，什么是动态追踪技术呢？

 

动态追踪技术其实是一种后现代的高级调试技术。它可以帮助软件工程师以非常低的成本，在非常短的时间内，回答一些很难的关于软件系统方面的问题，从而更快速地排查和解决问题。它兴起和繁荣的一个大背景是，我们正处在一个快速增长的互联网时代，作为工程师，面临着两大方面的挑战：一是规模，不管是用户规模还是机房的规模、机器的数量都处于快速增长的时代。

 

第二方面的挑战就是复杂度。我们的业务逻辑越来越复杂，我们运行的软件系统也变得越来越复杂，我们知道它会分成很多很多层次，包括操作系统内核然后上面是各种系统软件，像数据库和 Web 服务器，再往上有脚本语言或者其他高级语言的虚拟机、解释器及即时（JIT）编译器，顶上则是应用层面的各种业务逻辑的抽象层次和很多复杂的代码逻辑。

动态追踪机制而在这些探针的基础上，
Linux 也提供了一系列的动态追踪机制，比如 ftrace、perf、eBPF 等。ftrace 最早

 

今天的ftrace是实实在在的分析每次一的调用.
虽然都可以看调用堆栈和耗时比例. 但是ftrace应该是非常准确,而perf只是一个采样,比如采样频率1%.

https://leezhenghui.github.io/linux/2019/03/05/exploring-usdt-on-linux.html 
在 Linux 上，一些著名的跟踪工具，如 strace 和 ltrace，可以用来告诉系统调用什么，动态库调用什么，这些信息是有用的，但仍然是有限的，而且，打开这些类型的工具将引入重大的性能影响，这使得它们不太适合在生产环境中进行问题调试或监控
http://www.brendangregg.com/blog/

利用这些工具，我成功地定位了数不清的线上问题，有些问题甚至是我意外发现的。下面就随便举几个例子吧。

第一个例子是，我使用基于 SystemTap 的火焰图工具分析我们线上的 Nginx 进程，结果发现有相当一部分 CPU 时间花费在了一条非常奇怪的代码路径上面。这其实是我一位同事在很久之前调试一个老问题时遗留下来的临时的调试代码，有点儿像我们前面提到的“埋点代码”。结果它就这样被遗忘在了线上，遗忘在了公司代码仓库里，虽然当时那个问题其实早已解决。由于这个代价高昂的“埋点代码”一直没有去除，所以一直都产生着较大的性能损耗，而一直都没有人注意到。所以可谓是我意外的发现。当时我就是通过采样的方式，让工具自动绘制出一张火焰图。我一看这张图就可以发现问题并能采取措施。这是非常非常有效的方式。

 

第二个例子是，很少量的请求存在延时较长的问题，即所谓的“长尾请求”。这些请求数目很低，但可能达到「秒级」这样的延时。当时有同事乱猜说是我的 OpenResty 有 bug，我不服气，于是立即编写了一个 SystemTap 工具去在线进行采样，对那些超过一秒总延时的请求进行分析。该工具会直接测试这些问题请求内部的时间分布，包括请求处理过程中各个典型 I/O 操作的延时以及纯 CPU 计算延时。结果很快定位到是 OpenResty 在访问 Go 编写的 DNS 服务器时，出现延时缓慢。然后我再让我的工具输出这些长尾 DNS 查询的具体内容，发现都是涉及 CNAME 展开。显然，这与OpenResty 无关了，而进一步的排查和优化也有了明确的方向。

第三个例子是，我们曾注意到某一个机房的机器存在比例明显高于其他机房的网络超时的问题，但也只有 1% 的比例。一开始我们很自然的去怀疑网络协议栈方面的细节。但后来我通过一系列专门的 SystemTap 工具直接分析那些超时请求的内部细节，便定位到了是硬盘 配置方面的问题。从网络到硬盘，这种调试是非常有趣的。第一手的数据让我们快速走上正确的轨道。

 

还有一个例子是，我们曾经通过火焰图在 Nginx 进程里观察到文件的打开和关闭操作占用了较多的 CPU 时间，于是我们很自然地启用了 Nginx 自身的文件句柄缓存配置，但是优化效果并不明显。

 

于是再做出一张新的火焰图，便发现因为这回轮到 Nginx 的文件句柄缓存的元数据所使用的“自旋锁”占用很多 CPU 时间了。

 

这是因为我们虽然启用了缓存，但把缓存的大小设置得过大，所以导致元数据的自旋锁的开销抵消掉了缓存带来的好处。这一切都能在火焰图上面一目了然地看出来。假设我们没有火焰图，而只是盲目地试验，很可能会得出 Nginx 的文件句柄缓存没用的错误结论，而不会去想到去调整缓存的参数。

 

最后一个例子是，我们在某一次上线操作之后，在线上最新的火焰图中观察到正则表达式的编译操作占用了很多 CPU 时间，但其实我们已经在线上启用了正则编译结果的缓存。

 

很显然，我们业务系统中用到的正则表达式的数量，已然超出了我们最初设置的缓存大小，于是很自然地想到把线上的正则缓存调的更大一些。然后，我们在线上的火焰图中便再看不到正则编译操作了。

 

通过这些例子我们其实可以看到，不同的数据中心，不同的机器，乃至同一台机器的不同时段，都会产生自己特有的一些新问题。我们需要的是直接对问题本身进行分析，进行采样，而不是胡乱去猜测去试错。有了强大的工具，排错其实是一个事半功倍的事情。

自从我们成立了 OpenResty Inc. 公司以后，我们研发了 OpenResty XRay 这一款全新一代的动态追踪平台。我们已经不再手动去使用 SystemTap 这样的开源解决方案了

 

总结

strace ls
你估计在想，既然 strace 也能得到类似结果，本身又容易操作，为什么我们还要用 perf 呢？

$ perf trace ls
         ? (         ): ls/14234  ... [continued]: execve()) = 0
     0.177 ( 0.013 ms): ls/14234 brk(                                                                  ) = 0x555d96be7000
     0.224 ( 0.014 ms): ls/14234 access(filename: 0xad98082                                            ) = -1 ENOENT No such file or directory
     0.248 ( 0.009 ms): ls/14234 access(filename: 0xad9add0, mode: R                                   ) = -1 ENOENT No such file or directory
     0.267 ( 0.012 ms): ls/14234 openat(dfd: CWD, filename: 0xad98428, flags: CLOEXEC                  ) = 3
     0.288 ( 0.009 ms): ls/14234 fstat(fd: 3</usr/lib/locale/C.UTF-8/LC_NAME>, statbuf: 0x7ffd2015f230 ) = 0
     0.305 ( 0.011 ms): ls/14234 mmap(len: 45560, prot: READ, flags: PRIVATE, fd: 3                    ) = 0x7efe0af92000
     0.324 Dockerfile  test.sh
( 0.008 ms): ls/14234 close(fd: 3</usr/lib/locale/C.UTF-8/LC_NAME>                          ) = 0
     ...

当你想要了解某个内核函数的调用过程时，使用 ftrace ，就可以跟踪到它的执行过程。

# Ubuntu
$ apt-get install trace-cmd
# CentOS
$ yum install trace-cmd


$ trace-cmd record -p function_graph -g do_sys_open -O funcgraph-proc ls
$ trace-cmd report
...
              ls-12418 [000] 85558.075341: funcgraph_entry:                   |  do_sys_open() {
              ls-12418 [000] 85558.075363: funcgraph_entry:                   |    getname() {
              ls-12418 [000] 85558.075364: funcgraph_entry:                   |      getname_flags() {
              ls-12418 [000] 85558.075364: funcgraph_entry:                   |        kmem_cache_alloc() {
              ls-12418 [000] 85558.075365: funcgraph_entry:                   |          _cond_resched() {
              ls-12418 [000] 85558.075365: funcgraph_entry:        0.074 us   |            rcu_all_qs();
              ls-12418 [000] 85558.075366: funcgraph_exit:         1.143 us   |          }
              ls-12418 [000] 85558.075366: funcgraph_entry:        0.064 us   |          should_failslab();
              ls-12418 [000] 85558.075367: funcgraph_entry:        0.075 us   |          prefetch_freepointer();
              ls-12418 [000] 85558.075368: funcgraph_entry:        0.085 us   |          memcg_kmem_put_cache();
              ls-12418 [000] 85558.075369: funcgraph_exit:         4.447 us   |        }
              ls-12418 [000] 85558.075369: funcgraph_entry:                   |        __check_object_size() {
              ls-12418 [000] 85558.075370: funcgraph_entry:        0.132 us   |          __virt_addr_valid();
              ls-12418 [000] 85558.075370: funcgraph_entry:        0.093 us   |          __check_heap_object();
              ls-12418 [000] 85558.075371: funcgraph_entry:        0.059 us   |          check_stack_object();
              ls-12418 [000] 85558.075372: funcgraph_exit:         2.323 us   |        }
              ls-12418 [000] 85558.075372: funcgraph_exit:         8.411 us   |      }
              ls-12418 [000] 85558.075373: funcgraph_exit:         9.195 us   |    }
...

$ perf probe -V do_sys_open
Available variables at do_sys_open
        @<do_sys_open+0>
                char*   filename
                int     dfd
                int     flags
                struct open_flags       op
                umode_t mode
                
                
# Ubuntu
$ apt-get install linux-image-`uname -r`-dbgsym
# CentOS
$ yum --enablerepo=base-debuginfo install -y kernel-debuginfo-$(uname -r)