plantegg

java tcp mysql performance network docker Linux

SystemStap、BCC、bpftrace

Linux 4.4+ 支持 eBPF。基于 eBPF 可以将任何内核函数调用转换成可带任何 数据用户空间事件bcc 作为一个更上层的工具使这个过程更加方便。内核探测 代码用 C 写,数据处理代码用 Python。

从 Linux 3.15 开始,BPF 被扩展成了 eBPF,extended BPF 的缩写。它从 2 个 32bit 寄存器扩展到了 10 个 64bit 寄存器,并增加了后向跳转。Linux 3.18 中又进行了进一 步扩展,将它从网络子系统中移出来,并添加了 maps 等工具。为了保证安全性又引入了一 个检测器,用于验证内存访问的合法性和可能的代码路径。如果检测器不能推断出程序会在 有限的步骤内结束,就会拒绝程序的注入(内核)。

SystemTap 是一个 tracing 系统,简单来说,它提供了一种领域特定语言(DSL),代码编译成内核模块,然后热加 载到运行中的内核。但出于安全考虑,一些生产系统禁止动态模块加载,例如我研究 eBPF 时所用的系统就不允许。

perf 是 Linux 上的最重要的性能分析工具之一。它和内核出自同一个源码树(source tree),但编译需要针对指定的内核版本。perf 可以跟踪内核,也可以跟踪用户程序, 还可用于采样或者设置跟踪点。可以把它想象成开销更低,但功能更强大的 strace。 本文只会使用非常简单的 perf 命令。想了解更多,强烈建议访问 Brendan Gregg的博客。

图片

安装

sudo stap-prep //安装好systemtap所有依赖的(debugfs等等)

执行安装内核debug等等需要的一些包,然后才能运行systemtap

# 简单的脚本,打印4s内所有进程打开了哪些文件
#!/usr/bin/stap
probe begin
{
	log("begin to probe")
}
 
probe syscall.open
{
	printf ("%s(%d) open (%s)\n", execname(), pid(), argstr)
}
 
probe timer.ms(4000) # after 4 seconds
{
	exit ()
}
 
probe end
{
	log("end to probe")
}

主要需要两个包[“kernel-debuginfo”, “kernel-debuginfo-common”]
建议不要从yum装,可能会和内核小版本不同导致无法使用

1 获取内核的参数
uname -r

2 从下面的链接中取找对应内核的包

http://rpm.alibaba-inc.com/find.php?t=&os=&q=kernel-debuginfo&d=1&rid=1807
http://rpm.alibaba-inc.com/find.php?t=&os=&q=kernel-debuginfo-common-x86_64&d=1&rid=1805

如果小版本不对导致装不上的话,加上–nodeps 参数
rpm -ivh kernel-debuginfo-2.6.32-220.23.2.ali878.el6.x86_64.rpm –nodeps

#验证安装是否成功
sudo stap -v -e 'probe begin{printf("Hello, World"); exit();}'

检查OS是否支持 eBPF,你可以用这两个命令查看 ls /sys/fs/bpflsmod | grep bpf

案例

写好的默认脚本都在:/usr/share/doc/systemtap-client-2.8/examples/
stap 部分源代码: /usr/share/systemtap/tapset/linux/

  • sudo ./socktop -N 20 //每个进程的流量,取最多的20个
  • sudo stap netfilter_summary.stp -c “sleep 1” //每对IP之间的流量信息
  • stap tcp_connections.stp -c “sleep 1” //每个进来的新连接
  • sudo stap latencytap.stp –all-modules -w -t -x 38730 //监控进程38730最慢的内核操作
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53

#! /usr/bin/env stap

#################################################################
# tcp_retransmit.stp
# Author: Yang Bingwu (detailyang) <detailyang@gmail.com>
# This systemtap script will prints the tcp retransmission packet
#################################################################

global record%
global cwnd_record%

probe begin {
log("Printing tcp retransmission")
}

#probe kernel.function("tcp_retransmit_skb") {
#probe kernel.function("tcp_xmit_retransmit_queue") {
probe kernel.function("tcp_may_send_now") {
#print_usyms(ubacktrace())

print_backtrace()

#sudo stap tcp_retransmission.stp -x 19317 19317 is pid
if (pid() == target()) {

rto = tcp_get_info_rto($sk)
snd_cwnd = tcp_get_info_snd_cwnd($sk)
saddr = format_ipaddr(__ip_sock_saddr($sk), __ip_sock_family($sk))
daddr = format_ipaddr(__ip_sock_daddr($sk), __ip_sock_family($sk))
sport = __tcp_sock_sport($sk)
dport = __tcp_sock_dport($sk)
lastrto = record[saddr, sport, daddr, dport]
lastcwnd = cwnd_record[saddr, sport, daddr, dport]
state = tcp_ts_get_info_state($sk)

if (lastrto != rto) {
if (lastrto) {
printf("%s:%d => %s:%d STATE:%s RTO:%d -> %d (ms)\n", saddr, sport,
daddr, dport, tcp_sockstate_str(state), lastrto/1000, rto/1000)
} else {
printf("%s:%d => %s:%d STATE:%s RTO:%d (ms)\n", saddr, sport,
daddr, dport, tcp_sockstate_str(state), rto/1000)
}

printf("%s:%d => %s:%d STATE:%s snd_cwnd: %d -> %d\n", saddr, sport, daddr, dport, tcp_sockstate_str(state), snd_cwnd, lastcwnd);
}

record[saddr, sport, daddr, dport] = rto
cwnd_record[saddr, sport, daddr, dport] = snd_cwnd

}
}

https://sourceware.org/systemtap/examples/network/tcp_retransmission.stp

案例2:需要模拟磁盘hang导致的io延迟,可以用systemtab来搞

#!/usr/bin/env stap
# 使用方式: stap delay.stp -g  --all-modules -x 7222   只对7222进程进行延迟hack
 
# 延迟多少ms
global DELAY = 100;
global quit = 0;
global found;
 
probe begin {
	warn(sprintf("Tracing pid %d ...\\n", target()))
}
 
# 如果想要针对mysql的写入,可以将下面换成
#probe process("/u01/mysql/bin/mysqld").function("sync_binlog_file").call
probe syscall.write.return {
      if (pid() == target() && !quit ) {
	      mdelay( DELAY );
	      printf("write delay detail: tid: %d func:%s  sleep: %d \n",tid(),probefunc(),DELAY);
    }
}

 probe syscall.fsync.return {
​       if (pid() == target() && !quit ) {
​    	    mdelay( DELAY );
​    	    printf("fsync delay detail: tid: %d func:%s  sleep: %d \n",tid(),probefunc(),DELAY);
​        }
​     
​    }
​     
​    # 任务持续时间
​    probe timer.s(20) {
​        if (!found) {
​    	    warn("No backtraces found. Quitting now...\n")
​    	    exit()
​        } else {
​    	    warn("Time's up. Quitting now...(it may take a while)\n")
​    	    quit = 1
​        }
​    }

7U的系统自动封装了mtime函数 /usr/share/systemtap/tapset/linux/guru-delay.stp
如果是6U的系统,需要在上面的脚本中自己加上mdelay的函数

%{
#undef STP_OVERLOAD
#include <linux/delay.h>
%}
 
function mdelay(ms:long) %{
  mdelay(THIS->ms);
%}

使用Systemtap生成Flame Graph(火焰图)

案例3 追踪丢包

1
2
3
4
probe kernel.trace("kfree_skb")
{
printf("sock:%x,skb:%x,source:%d,dest:%d,%x:%x:%x,seq:%u,ack:%u %s\n",$skb->sk,$skb,ntohs(@cast($skb->data, "struct tcphdr")->source),ntohs(@cast($skb->data, "struct tcphdr")->dest),@cast($skb->data, "struct tcphdr")->syn,@cast($skb->data, "struct tcphdr")->ack,@cast($skb->data, "struct tcphdr")->rst,ntohl(@cast($skb->data, "struct tcphdr")->seq),ntohl(@cast($skb->data, "struct tcphdr")->ack_seq), symname($location));
}

img

以上systemtap输出可以看出包进了tcp_v4_rcv, 所以继续分析tcp_v4_rcv函数:

1
2
3
4
probe kernel.statement("tcp_v4_rcv@net/ipv4/tcp_ipv4.c:*")
{
printf("source:%d,dest:%d,skb:%x,sk:%x,syn:%x,ack:%x,%x-%x,%s\n",ntohs(@cast($skb->data, "struct tcphdr")->source),ntohs(@cast($skb->data, "struct tcphdr")->dest),$skb,$skb->sk,@cast($skb->data, "struct tcphdr")->syn,@cast($skb->data, "struct tcphdr")->ack,@cast($skb->data, "struct tcphdr")->source,@cast($skb->data, "struct tcphdr")->dest,pp())
}

img

以上输出对应的代码如下:

img

网络重传

image.png

image.png

image.png

网络包大小分布

bpftrace -e 'tracepoint:net:net_dev_queue{
@txsize=hist(args->len);
@txstat=stats(args->len);
}

tracepoint:net:netif_receive_skb
{
    @rxsize=hist(args->len);
    @rxstat=stats(args->len);
}'

image.png

或者,采集10秒中的网络包大小直方图

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
#bpftrace -e 'k:tcp_sendmsg { @size = hist(arg2); } interval:s:10 { exit(); }'
Attaching 2 probes...

@size:
[16, 32) 63 |@@@@@@@ |
[32, 64) 431 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[64, 128) 247 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ |
[128, 256) 26 |@@@ |
[256, 512) 80 |@@@@@@@@@ |
[512, 1K) 52 |@@@@@@ |
[1K, 2K) 70 |@@@@@@@@ |
[2K, 4K) 9 |@ |
[4K, 8K) 36 |@@@@ |
[8K, 16K) 1 | |

bpftrace 单行命令

这里有一些其他的单行命令来展示 bpftrace 的能力,你可以把这些换成其他的内核函数:

获取 tcp_sendmsg() szie 大于 8192 字节的所有事件:

1
bpftrace -e 'k:tcp_sendmsg /arg2 > 8192/ { printf("PID %d: %d bytes\n", pid, arg2); }'

获取每个进程(PID 和 comm)的请求大小的直方图:

1
bpftrace -e 'k:tcp_sendmsg { @size[pid, comm] = hist(arg2); }'

返回值出现频率统计:

1
bpftrace -e 'kr:tcp_sendmsg { @return[retval] = count(); }'

获取每秒的统计:事件数,平均大小,和总字节数:

1
2
bpftrace -e 'k:tcp_sendmsg { @size = stats(arg2); }
interval:s:1 { print(@size); clear(@size); }'

统计调用栈:

1
bpftrace -e 'k:tcp_sendmsg { @[kstack] = count(); }'

统计调用栈,深度为3:

1
bpftrace -e 'k:tcp_sendmsg { @[kstack(3)] = count(); }'

获取函数调用延时的直方图,纳秒级:

1
2
3
bpftrace -e 'k:tcp_sendmsg { @ts[tid] = nsecs; } kr:tcp_sendmsg /@ts[tid]/ { @ns = hist(nsecs - @ts[tid]); delete(@ts[tid]); }'

bpftrace -e 'k:net_rx_action { @ts[tid] = nsecs; } kr:tcp_sendmsg /@ts[tid]/ { @ns = hist(nsecs - @ts[tid]); delete(@ts[tid]); }'

最后一个例子在探测点(线程 ID 作为主键)保存时间戳,并在另外一个探测点获得这个时间戳。这个模式可以用来计算各种延时。

产看网络流量由哪个进程发出,或者说哪个进程在发包

image.png

网络连接创建rt?

# ./tools/bcc/tcpconnlat
PID    COMM         IP SADDR            DADDR            DPORT LAT(ms)
1935   java         4  10.81.177.14     100.100.110.2    80    0.21
6844   java         4  127.0.0.1        127.0.0.1        3406  0.05
6844   java         4  127.0.0.1        127.0.0.1        3406  0.02
1930   java         4  10.81.177.14     100.100.110.2    80    0.23
1914   java         4  10.81.177.14     100.100.110.2    80    0.26
6844   java         4  127.0.0.1        127.0.0.1        3406  0.04
6844   java         4  127.0.0.1        127.0.0.1        3406  0.02
1778   java         4  10.81.177.14     100.100.17.97    8000  1.62
1915   java         4  10.81.177.14     100.100.110.2    80    0.20
1944   java         4  10.81.177.14     100.100.110.2    80    0.23
6844   java         4  127.0.0.1        127.0.0.1        3406  0.05
6844   java         4  127.0.0.1        127.0.0.1        3406  0.03
1823   java         4  10.81.177.14     100.100.110.2    80    9.58
1928   java         4  10.81.177.14     100.100.110.2    80    9.61
6844   java         4  127.0.0.1        127.0.0.1        3406  0.05
6844   java         4  127.0.0.1        127.0.0.1        3406  0.03
1796   java         4  10.81.177.14     100.100.110.2    80    0.27
1949   java         4  10.81.177.14     100.100.110.2    80    0.22
1795   java         4  10.81.177.14     100.100.110.2    80    0.26
6844   java         4  127.0.0.1        127.0.0.1        3406  0.05
6844   java         4  127.0.0.1        127.0.0.1        3406  0.02
1916   java         4  10.81.177.14     100.100.110.2    80    3.70
1929   java         4  10.81.177.14     100.100.110.2    80    3.73
7059   java         4  127.0.0.1        127.0.0.1        3406  0.05
7059   java         4  127.0.0.1        127.0.0.1        3406  0.02
948    java         4  10.81.177.14     100.100.110.2    80    0.27
1917   java         4  10.81.177.14     100.100.110.2    80    0.20
1934   java         4  10.81.177.14     100.100.110.2    80    0.22
6844   java         4  127.0.0.1        127.0.0.1        3406  0.05
6844   java         4  127.0.0.1        127.0.0.1        3406  0.03

TCP队列实时查看

bpftrace工具包

cat tcpsynbl_example.txt
Demonstrations of tcpsynbl, the Linux bpftrace/eBPF version.
​	This tool shows the TCP SYN backlog size during SYN arrival as a histogram.
​	This lets you see how close your applications are to hitting the backlog limit
​	and dropping SYNs (causing performance issues with SYN retransmits). For
​	example:
​	
​	# ./tcpsynbl.bt 
​	Attaching 4 probes...
​	Tracing SYN backlog size. Ctrl-C to end.
​	^C
​	@backlog[backlog limit]: histogram of backlog size


​	
​	@backlog[500]: 
​	[0]                 2266 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
​	[1]                    3 |                                                    |
​	[2, 4)                 1 |                                                    |

$sudo bpftrace ./tcpsynbl.bt
Attaching 4 probes...
Tracing SYN backlog size. Ctrl-C to end.

^C
@backlog[backlog limit]: histogram of backlog size
@backlog[10]:
​	[0]                    3 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
​	
​	@backlog[256]:
​	[0]                   59 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|

或者 bpftrace tcpaccept.bt

cat tcpaccept_example.txt 
Demonstrations of tcpaccept, the Linux bpftrace/eBPF version.


​ This tool traces the kernel function accepting TCP socket connections (eg, a
​ passive connection via accept(); not connect()). Some example output (IP
​ addresses changed to protect the innocent):

​ # ./tcpaccept
​ Tracing tcp accepts. Hit Ctrl-C to end.
​ TIME PID COMM RADDR RPORT LADDR LPORT BL
​ 00:34:19 3949061 nginx 10.228.22.228 44226 10.229.20.169 8080 0/128
​ 00:34:19 3951399 ruby 127.0.0.1 52422 127.0.0.1 8000 0/128
​ 00:34:19 3949062 nginx 10.228.23.128 35408 10.229.20.169 8080 0/128


​ This output shows three connections, an IPv4 connections to PID 1463622, a “redis-server”
​ process listening on port 6379, and one IPv6 connection to a “thread.rb” process
​ listening on port 8000. The remote address and port are also printed, and the accept queue
​ current size as well as maximum size are shown.

​ The overhead of this tool should be negligible, since it is only tracing the
​ kernel function performing accept. It is not tracing every packet and then
​ filtering.

​ This tool only traces successful TCP accept()s. Connection attempts to closed
​ ports will not be shown (those can be traced via other functions).

​ There is another version of this tool in bcc: https://github.com/iovisor/bcc

最后一列就是backlog最大大小和已经多少

遍历端口状态

sudo stap -g walk_bhash.stp > /tmp/status

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
#cat walk_bhash.stp

%{#include <linux/tcp.h>
#include <net/tcp.h>
%}

function walk_bhash:long() %{
int i;
struct inet_bind_hashbucket *head;
struct inet_bind_bucket *tb;
const struct hlist_nulls_node *node;
unsigned long nr_ports = 0;

local_bh_disable();
rcu_read_lock();

for (i = 0; i < tcp_hashinfo. bhash_size; ++i) {
head = &tcp_hashinfo.bhash[i];
spin_lock(&head->lock);

inet_bind_bucket_for_each(tb, &head->chain) {
nr_ports++;
_stp_printf("port=%d, fastreuse=%d, fastreuseport=%d.\n",
tb->port, tb->fastreuse, tb->fastreuseport);
}
spin_unlock(&head->lock);
}

rcu_read_unlock();
local_bh_enable();

_stp_printf("nr_ports: %lu.\n", nr_ports);

THIS->__retvalue = 0;
return;
%}

probe begin
{
printf("Start traversing bhash ....\n");
walk_bhash();
exit();
}

抓在bind端口的进程,端口被bind后就会将 fastreuseport 从默认的-1 改成 0

1
2
3
4
stap -e 'probe kernel.function("inet_csk_get_port") {
printf("hook proc_fork_connector \n, execname = %s params:%d\n", execname(), $snum);
print_backtrace();
}'

DNS 域名解析时间

$sudo ./gethostlatency 
TIME      PID    COMM                  LATms HOST
15:40:01  10549  sendmail               0.19 localhost
15:40:03  1782   java                   0.11 iZbp143cmod4v59cgon4zwZ
15:40:13  10580  ping                   0.98 abck.akksda
15:40:18  1823   java                   0.12 iZbp143cmod4v59cgon4zwZ

可以明显抓到ping但是nslookup抓不到(因为nslookup 不调用 getaddrinfo/gethostbyname)

统计线程执行时间排名

$sudo stap thread-times.stp -T 5
        comm   tid   %user %kernel (of 19997 ticks)
        java 30474  20.06%   0.75%
   swapper/0     0   0.00%   2.55%
   swapper/2     0   0.00%   2.00%
   swapper/3     0   0.00%   1.49%
        java 19500   0.38%   0.72%
        java 19501   0.35%   0.64%
        java 19503   0.34%   0.65%
        java 19496   0.28%   0.69%
        java 19497   0.28%   0.67%
        java 19502   0.31%   0.61%
        java 19498   0.30%   0.58%
        java 19499   0.26%   0.52%
   swapper/1     0   0.00%   0.75%
        java 20004   0.45%   0.18%
        java 19995   0.40%   0.19%
        java 20061   0.43%   0.16%
        java 20066   0.41%   0.17%
        java 20083   0.44%   0.13%
        java 20027   0.41%   0.16%
        java 20195   0.43%   0.13%

如上java线程执行消耗在用户态和内核态的CPU占比,根据tid可以到jstack中对应,相当于是将top命令中的线程消耗CPU做了累积,分清了用户态和内核态

内核函数执行时间

$sudo ./funclatency 'c:connect'
Tracing 1 functions for "c:connect"... Hit Ctrl-C to end.
^C

Function = [unknown] [10997] 
     nsecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 0        |                                        |
      1024 -> 2047       : 0        |                                        |
      2048 -> 4095       : 0        |                                        |
      4096 -> 8191       : 4        |****************************************|
      8192 -> 16383      : 2        |********************                    |
     16384 -> 32767      : 1        |**********                              |

Function = connect [10999]  //telnet 连不上 tcp retry 
     nsecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 0        |                                        |
      1024 -> 2047       : 0        |                                        |
      2048 -> 4095       : 0        |                                        |
      4096 -> 8191       : 3        |****************************************|
      8192 -> 16383      : 2        |**************************              |
     16384 -> 32767      : 1        |*************                           |

内核收发包耗时分析

1
2
3
4
5
sudo ./funclatency -p mysqld_pid -T -u -i 1 -d 5 'pthread:__libc_send'
sudo ./funclatency -p mysqld_pid -T -u -i 1 -d 5 'pthread:__libc_recv'
sudo ./funclatency -p mysqld_pid -T -u -i 1 -d 5 'tcp_sendmsg'
sudo ./funclatency -p mysqld_pid -T -u -i 1 -d 5 'tcp_recvmsg'
sudo ./funclatency -p mysqld_pid -T -u -i 1 -d 5 'tcp_cleanup_rbuf'

磁盘

15:49:40 loadavg: 0.07 0.04 0.05 1/1008 11533

PID    COMM             D MAJ MIN DISK       I/O  Kbytes  AVGms
10784  kworker/u8:0     W 254 0   vda         31     140   2.41
416    jbd2/vda1-8      W 254 0   vda          2     100   0.93
Detaching...

[admin@iZbp143cmod4v59cgon4zwZ 15:49 /home/admin/tools/bcc]
$df -lh
Filesystem      Size  Used Avail Use% Mounted on
devtmpfs        3.8G     0  3.8G   0% /dev
tmpfs           3.9G     0  3.9G   0% /dev/shm
tmpfs           3.9G  620K  3.9G   1% /run
tmpfs           3.9G     0  3.9G   0% /sys/fs/cgroup
/dev/vda1        99G  5.1G   89G   6% /
tmpfs           779M     0  779M   0% /run/user/0
tmpfs           779M     0  779M   0% /run/user/1000

[admin@iZbp143cmod4v59cgon4zwZ 15:49 /home/admin/tools/bcc]
$sudo ./biotop 5 1

或者

$sudo stap iostats.stp -T 5
starting probe

                                       read     read             write    write
            name     open     read   KB tot    B avg    write   KB tot    B avg
            java        8   125797     5406       44   251673    44337      180
              ps      754      784      319      417        6       29     5105
            grep       39       27       73     2781        9       42     4891
              wc       10        6       17     2979        1        0        2
       AliYunDun       43       53        9      175        0        0        0
              sh        8        4        3      880        0        0        0
             fio       20       20        2      136        5        0       81
            sshd        0        6        0       70        6        0      121
 AliYunDunUpdate        2        4        0       75        0        0        0
   systemd-udevd        1        4        0       65        0        0        0
    DragoonAgent        0        0        0        0        1        0      100
          stapio        0       27        0        1        1        0       15
  aliyun-service        0       25        0        0        0        0        0

fs latency

[root@iZbp1d1tuijx3yqz46meimZ lwtools]# stap fslatency-nd.stp 1 1
Tracing FS sync reads and writes... Output every 1 secs.

Thu Sep 19 07:48:54 2019 FS latency (ns):

FS call: __vfs_read()
 value |-------------------------------------------------- count
   128 |                                                       0
   256 |                                                       0
   512 |                                                       2
  1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  12423
  2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@          10330
  4096 |@@                                                   514
  8192 |@@@@@@                                              1624
 16384 |@                                                    273
 32768 |                                                      48
 65536 |                                                       1
131072 |                                                       0
262144 |                                                       0

FS call: __vfs_write()
 value |-------------------------------------------------- count
    64 |                                                       0
   128 |                                                       0
   256 |                                                     169
   512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  32549
  1024 |@@@@@@@@@@@@@@@@@@@@@@@@@                          16276
  2048 |                                                     469
  4096 |                                                     385
  8192 |                                                     439
 16384 |                                                     100
 32768 |                                                       5
 65536 |                                                       1
131072 |                                                       0
262144 |                                                       0

读写时间分布:
[root@iZbp1d1tuijx3yqz46meimZ lwtools]# ./rwtime-nd.stp java
Tracing read/write syscalls for processes named “java”… Hit Ctrl-C to end.
^C
syscall read latency (ns):
value |————————————————– count
128 | 0
256 | 0
512 |@ 3129
1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 85897
2048 |@@@@@@@@@@@@@@@ 26032
4096 | 386
8192 | 1142
16384 | 63
32768 | 3
65536 | 1
131072 | 1
262144 | 0
524288 | 0

syscall write latency (ns):
value |————————————————– count
256 | 0
512 | 0
1024 | 1720
2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 104247
4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 105507
8192 |@@@@@@@@ 17768
16384 |@ 3715
32768 | 353
65536 | 44
131072 | 0
262144 | 3
524288 | 0
1048576 | 0

SLOW FS READ AND WRITE

[root@iZbp1d1tuijx3yqz46meimZ lwtools]# ./fsslower-nd.stp 5
Tracing FS sync reads and writes slower than 5 ms... Hit Ctrl-C to end.
TIME     PID    COMM             FUNC           SIZE     LAT(ms)
07:55:13 30941  grep             __vfs_read     32768         18
07:55:13 30942  grep             __vfs_read     32768          5
07:55:13 30943  grep             __vfs_read     32768         23
07:55:13 30944  wc               __vfs_read     16384         24
07:55:13 1102   java             __vfs_read     8192          39
07:55:13 1102   java             __vfs_read     8192          40

cache

$sudo ./cachestat -T 5 1
TIME         HITS   MISSES  DIRTIES HITRATIO   BUFFERS_MB  CACHED_MB
16:01:10     6297        0       52  100.00%           31        652

中断发生,主要是网卡

# sudo stap interrupts-by-dev.stp -c 'sleep 1'
  DEVICE 	 NUMBER OF INTERRUPTS 
    virtio2-req.0 :      1
 virtio0-output.0 :      2
  virtio0-input.0 :      1
 virtio0-output.0 :      1
  virtio0-input.0 :      2
 virtio0-output.0 :      1
 virtio0-output.0 :      1
  virtio0-input.0 :      1
 virtio0-output.0 :      1
  virtio0-input.0 :      1
 virtio0-output.0 :      1
  virtio0-input.0 :      1

futex

$sudo stap futexes.stp  -T 1
java[4457] lock 0x7f5da0bbd548 contended 1 times, 1 avg us
java[4457] lock 0x7f5d23c46188 contended 1 times, 27 avg us
java[4457] lock 0x7f5d52f3f154 contended 1 times, 1945 avg us
java[4457] lock 0x7f5da06a03f0 contended 1 times, 20 avg us
java[4457] lock 0x7f5da2baad54 contended 1 times, 267 avg us
java[4457] lock 0x7f5d23a8d574 contended 1 times, 60130 avg us
java[4457] lock 0x7f5d23c30154 contended 1 times, 664 avg us
java[4457] lock 0x7f5d23c5e1b4 contended 3 times, 70979 avg us
java[4457] lock 0x7f5d23bc3154 contended 1 times, 4342 avg us
java[4457] lock 0x7f5da2b897b4 contended 1 times, 70190 avg us
java[4457] lock 0x7f5d533a0d54 contended 1 times, 2202 avg us

给程序注入系统调用setsockopt

没有源代码,需要将应用的keepalive 打开。可以通过SystemTap,给进程注入一个setsockopt调用,使其开启SO_KEEPALIVE

accept调用返回的时候注入这个调用,脚本源码为, 必须要在有新连接进来的时候:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
%{
#include <net/sock.h>
%}

function set_sock_keepalive:long(fd) %{
int err = -1;
int keepalive = 1;
struct socket *sock = sockfd_lookup(STAP_ARG_fd, &err);
if (sock != NULL) {
/*
* sock_setsockopt 的参数在内核中声明为来自用户空间,
* 因此其内部会对该值的来源进行校验,该脚本注入的这段C
* 代码运行在内核空间,因此我们需要临时跳过这层校验。
* 下面三行就是跳过的方法。
*/
mm_segment_t oldfs;
oldfs = get_fs();
set_fs(KERNEL_DS);
err = sock_setsockopt(sock, SOL_SOCKET,
SO_KEEPALIVE, (char __user*)&keepalive, sizeof(keepalive));
set_fs(oldfs);
sockfd_put(sock);
}
STAP_RETURN(err);
%}

probe begin {
printf("inject begin... \n")
}

/*
* 注入点选择accept系统调用返回时,accept的返回值就是新建连接的文件描述符
* 当触发的进程pid是给定进程时,进行注入操作
* 在生产环境中,可以删除ok之后的打印以提升性能
*/
probe syscall.accept.return, syscall.accept4.return {
fd = $return
if ((pid() == $1) && (fd != -1)) {
ok = set_sock_keepalive(fd)
if (ok)
printf("set_sock_keepalive %d\n", ok)
}
}

probe end {
printf("inject end... \n")
}

执行的方式是,$pid为指定的进程pid:

1
> stap -g inject_keepalive.stp $pid

Systemtap 抓取 mysql insert 慢操作

主要抓取下面的函数

row_ins_clust_index_entry_low 主键insert

fsp_try_extend_data_file 文件扩展

mysql_insert mysql insert的最上层函数

os_aio_func mysql 调用aio的函数,我们测试时只抓取其中的同步io

stap 脚本

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
global start_time;
global quit = 0;
global found;
global threshold = 6000;

probe begin {
warn(sprintf("Tracing begin ...\\n"))
}

probe process("/u01/mysql/bin/mysqld").function("row_ins_clust_index_entry_low").call {
if (!quit ) {
start_time[tid(), ppfunc()] = gettimeofday_us()
}
else{
exit()
}
}


probe process("/u01/mysql/bin/mysqld").function("row_ins_clust_index_entry_low").return {
if (!quit) {
t = tid()
begin = start_time[t, ppfunc()]
if (begin > 0) {
elapsed = gettimeofday_us() - begin
if (elapsed >= threshold) {
printf("pid->%d tid->%d func->%s start_time->%d elapsed_time->%d \n",pid(), t, ppfunc(),begin, elapsed)
found = 1
}
delete start_time[t, ppfunc()]
}
}
}




probe process("/u01/mysql/bin/mysqld").function("fsp_try_extend_data_file").call {
if (!quit ) {
start_time[tid(), ppfunc()] = gettimeofday_us()
}
else{
exit()
}
}


probe process("/u01/mysql/bin/mysqld").function("fsp_try_extend_data_file").return {
if (!quit) {
t = tid()
begin = start_time[t, ppfunc()]
if (begin > 0) {
elapsed = gettimeofday_us() - begin
if (elapsed >= threshold) {
printf("pid->%d tid->%d func->%s start_time->%d elapsed_time->%d \n",pid(), t, ppfunc(),begin, elapsed)
found = 1
}
delete start_time[t, ppfunc()]
}
}
}



probe process("/u01/mysql/bin/mysqld").function("mysql_insert").call {
if (!quit ) {
start_time[tid(), ppfunc()] = gettimeofday_us()
}
else{
exit()
}
}


probe process("/u01/mysql/bin/mysqld").function("mysql_insert").return {
if (!quit) {
t = tid()
begin = start_time[t, ppfunc()]
if (begin > 0) {
elapsed = gettimeofday_us() - begin
if (elapsed >= threshold) {
printf("pid->%d tid->%d func->%s start_time->%d elapsed_time->%d sql:%s \n",pid(), t, ppfunc(),begin, elapsed, user_string($table_list->table_name))
found = 1
}
delete start_time[t, ppfunc()]
}
}
}


probe process("/u01/mysql/bin/mysqld").function("os_aio_func").call {
if (!quit ) {
if ($mode == 24){
start_time[tid(), ppfunc()] = gettimeofday_us()
}
}
else{
exit()
}
}

probe process("/u01/mysql/bin/mysqld").function("os_aio_func").return {
if (!quit) {
# 只抓取同步IO
if ($mode == 24){
t = tid()
begin = start_time[t, ppfunc()]
if (begin > 0) {
elapsed = gettimeofday_us() - begin
if (elapsed >= threshold) {
#针对mysql 5.6
printf("pid->%d tid->%d func->%s start_time->%d elapsed_time->%d %d %d %d\n",pid(), t, ppfunc(),begin, elapsed, $type ,$offset,$n)
found = 1
}
delete start_time[t, ppfunc()]
}
}
}
}


# 持续3000s
probe timer.s(3000) {
if (!found) {
warn("No backtraces found. Quitting now...\n")
exit()
} else {
warn("Time's up. Quitting now...(it may take a while)\n")
quit = 1
}
}

抓取结果

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
pid->30530   tid->90738   func->os_aio_func   start_time->1508234813956745    elapsed_time->11396
pid->30530 tid->90738 func->row_ins_clust_index_entry_low start_time->1508234813956724 elapsed_time->11463
pid->30530 tid->90738 func->mysql_insert start_time->1508234813956667 elapsed_time->11565 sql:__test_iss_schedule_job_instance_1015


pid->30530 tid->56144 func->os_aio_func start_time->1508236199976100 elapsed_time->7762 10 1304248320 16384
pid->30530 tid->56144 func->row_ins_clust_index_entry_low start_time->1508236199976072 elapsed_time->7840
pid->30530 tid->56144 func->mysql_insert start_time->1508236199976023 elapsed_time->7939 sql:iss_schedule_job_instance_0963


pid->129041 tid->35427 func->os_aio_func start_time->1508236506228913 elapsed_time->7686 10 188694528 16384
pid->129041 tid->35427 func->row_ins_clust_index_entry_low start_time->1508236506228896 elapsed_time->12958
pid->129041 tid->35427 func->mysql_insert start_time->1508236506228848 elapsed_time->13039 sql:iss_schedule_job_log_0115


pid->30530 tid->42311 func->os_aio_func start_time->1508236576977222 elapsed_time->7265 10 3863937024 16384
pid->30530 tid->42311 func->row_ins_clust_index_entry_low start_time->1508236576977200 elapsed_time->7338
pid->30530 tid->42311 func->mysql_insert start_time->1508236576977143 elapsed_time->7446 sql:iss_schedule_job_instance_0982

可以看出调用关系是 mysql_insert -> row_ins_clust_index_entry_low -> os_aio_func

pid 30530和129041 分别指两个mysqld 进程,怀疑IO问题

io逻辑以及涉及到的 perf 事件

image.png

如果想要准确知道是不是硬件设备的问题,可以抓取block layer层和device driver层之间的rt,也就是以下两个事件:

block:block_rq_issue IO块经过io调度算法,以及队列等待后,最终下发出去的事件

block:block_rq_complete IO块从device driver 返回的事件

除了上面两个,假如我们想排查是不是由于IO调度策略,及队列的问题,可以追踪block:block_rq_insertblock:block_rq_complete 之间的rt

perf是通过cpu的打点来计算事件发生的时间,我们只要通过后期进行处理,即可知道RT

1
2
3
4
5
6
7
8
# 抓取事件,会自动输出结果到当前目录下的perf.data中
perf record -ga -e block:block_rq_issue -e block:block_rq_complete sleep 10

# 读取perf.data 打印所有采集信息
perf script

# 只打印所有事件发生的信息(忽略具体堆栈)
perf script -G

结果如下

1
2
3
4
进程名    pid      cpu         time                    事件                
mysqld 117330 [002] 3630658.631426: block:block_rq_issue: 259,2 WS 0 () 3536832512 + 512 [mysqld]
swapper 0 [000] 3630658.631612: block:block_rq_complete: 259,2 WS () 3536832512 + 512 [0]
mysqld 117330 [002] 3630658.631462: block:block_rq_issue: 259,2 WS 0 () 3536833536 + 512 [mysqld]

bpftrace 同时 trace 多个事件

1
2
3
4
bpftrace -e 'k:tcp_bpf_recvmsg /comm=="nc"/ { printf("%s", kstack); } k:tcp_recvmsg /comm=="nc"/ { printf("%s", kstack); }'

//trace bash, uprobe 不存在 kstack
bpftrace -e 'uretprobe:/usr/bin/bash:readline{printf("User %d executed \"%s\" command\n", uid, str(retval));}'

参考资料

https://access.redhat.com/documentation/en-us/red_hat_enterprise_linux/6/html/systemtap_beginners_guide/futexcontentionsect

Demo集锦:openresty systemtap demo

SystemTap原理、安装、入门、脚本语言及技巧

eBCC性能分析最佳实践–开启性能分析新篇章

eBPF 内核探测:如何将任意系统调用转换成事件(2016)

使用 Linux tracepoint、perf 和 eBPF 跟踪数据包 (2017)

使用ftrace分析函数性能

eBPF学习笔记(二)—— eBPF开发工具 主要是关于 bpftrace 的使用实例

logback 日志异步化输出对性能的影响

场景

Java在每次请求结束后都会输出日志记录每次请求的相关信息,一个QPS对应一次日志的输出。

异步化基本百利而无一害,特定的场景、机器下可以数倍提升效率

结论

  • 异步化对性能的影响取决于日志的多少和机器CPU的核数
  • logback日志异步化主要是写日志逻辑变成了单线程,没有锁
  • 异步化后性能有10-15%的提升(Profiling看到日志相关的CPU占比从13%降到6.5%)
  • 异步输出条件下,日志多少对性能的影响有,但是不明显(15%以内)
  • 如果是同步输出日志,开启延迟flush log(false //flush policy)能有5%的性能提升
  • 异步化后再开启延迟flush log对性能提升不明显(Profiling看到log flush的CPU从1.2%降到0.4%)
  • slf4j只是个接口框架,JUL/log4j2和logback是具体实现,logback是log4j的升级版
  • 如果一秒钟日志输出达到6M(主要取决于条数),那么异步化能提升一倍的性能(日志太多的时候同步下CPU跑不满)
  • 同步日志输出场景下瓶颈主要在同步锁而不是磁盘写日志(顺序写磁盘)
  • 从Profiler堆栈来看异步后锁和日志输出部分占比明显降低
  • CPU核数越多意味着并发越多,那么同步异步和immediateFlush的影响越明显
  • 异步化输出日志后对avg rt 和 rt 95%线下降影响非常明显,也更稳定
  • immediateFlush 对同步影响比较明显(一倍),主要是因为每次刷盘慢导致别的线程等锁时间长,在异步场景下基本不明显
  • immediateFlush为false有丢日志的风险,异步后没有必要再设immediateFlush为false
  • 延迟Flush的cache取决于JDK的BufferedOutputStream缓冲大小,默认8K,不可更改
  • 异步后日志输出的瓶颈在于单核能力,Intel(R) Xeon(R) Platinum 8163 CPU @ 2.50GHz 输出能力大概是每秒20万条日志

测试数据

4核的机器下性能提升没这么明显,因为锁争抢没这么激烈

image.png

4.9内核下, 异步对rt影响明显, 似乎是4.9对锁的处理更好:

image.png

2.6.32下异步对rt影响不是很大

image.png

image.png

加大120线程并发,可以看到tps提升明显但是rt仍然不明显

image.png

如果将 sql.log 改为error级别,tps上升到30000,rt比info也有将近10%的提升,这个rt的提升是因为tps提升导致的。(都是异步输出的场景下)

image.png

同步情况下的profiler

recordSQL: 12.9%
logback.doAppend: 10%

image.png

异步情况下的profiler:

recordSQL: 3.7%
image.png

logback.doAppend: 2.63%

image.png

在16个core的机器上锁争抢更明显

99.8%的锁都是doApend

image.png

同步和异步以及immediateFlush的影响

16core的机器

image.png

结论:同步输出的情况下immediateFlush 为false性能有一倍的提升(但是异常退出的情况下有丢日志风险)
异步输出是同步的4倍(这个差异依赖于cpu核数、业务逻辑的特点等),在异步的情况下immediateFlush无所谓,所以王者还是异步输出,同时异步输出对rt 95%线下降非常明显

一个业务逻辑稍微慢点的场景

异步输出日志点查场景tps11万+,同步输出日志后点查tps4万+,同时jstack堆栈也能看到333个BLOCKED堆栈:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
#[ 210s] threads: 400, tps: 0.00, reads/s: 115845.43, writes/s: 0.00, response time: 7.57ms (95%)
#[ 220s] threads: 400, tps: 0.00, reads/s: 116453.12, writes/s: 0.00, response time: 7.28ms (95%)
#[ 230s] threads: 400, tps: 0.00, reads/s: 116400.31, writes/s: 0.00, response time: 7.33ms (95%)
#[ 240s] threads: 400, tps: 0.00, reads/s: 116025.35, writes/s: 0.00, response time: 7.48ms (95%)
#[ 250s] threads: 400, tps: 0.00, reads/s: 45260.97, writes/s: 0.00, response time: 29.57ms (95%)
#[ 260s] threads: 400, tps: 0.00, reads/s: 41598.41, writes/s: 0.00, response time: 29.07ms (95%)
#[ 270s] threads: 400, tps: 0.00, reads/s: 41939.98, writes/s: 0.00, response time: 28.96ms (95%)
#[ 280s] threads: 400, tps: 0.00, reads/s: 40875.48, writes/s: 0.00, response time: 29.16ms (95%)
#[ 290s] threads: 400, tps: 0.00, reads/s: 41053.73, writes/s: 0.00, response time: 29.07ms (95%)

--- 1687260767618 ns (100.00%), 91083 samples
[ 0] ch.qos.logback.classic.sift.SiftingAppender
[ 1] ch.qos.logback.core.AppenderBase.doAppend
[ 2] ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders
[ 3] ch.qos.logback.classic.Logger.appendLoopOnAppenders
[ 4] ch.qos.logback.classic.Logger.callAppenders
[ 5] ch.qos.logback.classic.Logger.buildLoggingEventAndAppend
[ 6] ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus
[ 7] ch.qos.logback.classic.Logger.info
[ 8] com.taobao.tddl.common.utils.logger.slf4j.Slf4jLogger.info
[ 9] com.taobao.tddl.common.utils.logger.support.FailsafeLogger.info
[10] com.alibaba.cobar.server.util.LogUtils.recordSql
[11] com.alibaba.cobar.server.ServerConnection.innerExecute
[12] com.alibaba.cobar.server.ServerConnection.innerExecute
[13] com.alibaba.cobar.server.ServerConnection$1.run
[14] com.taobao.tddl.common.utils.thread.FlowControlThreadPool$RunnableAdapter.run
[15] java.util.concurrent.Executors$RunnableAdapter.call
[16] java.util.concurrent.FutureTask.run
[17] java.util.concurrent.ThreadPoolExecutor.runWorker
[18] java.util.concurrent.ThreadPoolExecutor$Worker.run
[19] java.lang.Thread.run

"ServerExecutor-3-thread-480" #753 daemon prio=5 os_prio=0 tid=0x00007f8265842000 nid=0x26f1 waiting for monitor entry [0x00007f82270bf000]
java.lang.Thread.State: BLOCKED (on object monitor)
at ch.qos.logback.core.AppenderBase.doAppend(AppenderBase.java:64)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:282)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:269)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:470)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:424)
at ch.qos.logback.classic.Logger.info(Logger.java:628)
at com.taobao.tddl.common.utils.logger.slf4j.Slf4jLogger.info(Slf4jLogger.java:42)
at com.taobao.tddl.common.utils.logger.support.FailsafeLogger.info(FailsafeLogger.java:102)
at com.alibaba.cobar.server.util.LogUtils.recordSql(LogUtils.java:115)
at com.alibaba.cobar.server.ServerConnection.innerExecute(ServerConnection.java:874)
- locked <0x00007f87382cb108> (a com.alibaba.cobar.server.ServerConnection)
at com.alibaba.cobar.server.ServerConnection.innerExecute(ServerConnection.java:569)
- locked <0x00007f87382cb108> (a com.alibaba.cobar.server.ServerConnection)
at com.alibaba.cobar.server.ServerConnection$1.run(ServerConnection.java:402)
at com.taobao.tddl.common.utils.thread.FlowControlThreadPool$RunnableAdapter.run(FlowControlThreadPool.java:480)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1152)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:627)
at java.lang.Thread.run(Thread.java:861)

- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- locked <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)
- waiting to lock <0x00007f866dcec208> (a ch.qos.logback.classic.sift.SiftingAppender)

immediateFlush true/false 以及同步异步对tps的影响

image.png

结论:同步输出的情况下immediateFlush 为false性能有一倍的提升(但是异常退出的情况下有丢日志风险)异步输出是同步的4倍(这个差异依赖于cpu核数、业务逻辑的特点等),在异步的情况下immediateFlush无所谓,所以王者还是异步输出,同时异步输出对rt 95%线下降非常明显

异步配置

    <appender name="asyncROOT" class="ch.qos.logback.classic.AsyncAppender">
        <queueSize>1000</queueSize>
        <maxFlushTime>3000</maxFlushTime>
				<discardingThreshold>0</discardingThreshold>
        <neverBlock>true</neverBlock>
        <appender-ref ref="ROOT"/>
		</appender>

JDK中BufferedOutputStream Buffer大小

/** 
 * Creates a new buffered output stream to write data to the 
 * specified underlying output stream. 
 * 
 * @param   out   the underlying output stream. 
 */  
public BufferedOutputStream(OutputStream out) {  
    this(out, 8192);  
}  

尝试改大buffer基本没什么明显的影响

测试环境2个节点的DRDS-Server,每个节点4Core8G(机型sn1)

tps 100秒每个节点输出日志大小
不输出日志 35097
sql.log+同步 28891 292M
sql.log+异步 32164 292M
sql.log+com.taobao/trace+异步 28894 670M
sql.log+com.taobao/trace+同步 13248

com.taobao/trace 指的是将com.taobao.*设为trace输出,以增加输出日志量。

是否开启immediateFlush(默认true)

tps 100秒每个节点输出日志大小
同步+immediateFlush 27610 282M
同步 29554 303M
异步+immediateFlush 31100 245M
异步 31150 260M

(这个表格和前面的表格整体tps不一致,前一个表格是晚上测试,这个表格是上午测试的,不清楚是否环境受到了影响)

总结

关键结论见最前面,但是要结合自己场景输出日志的速度,日志输出越少影响越不明显,机器核数越多会越明显,总的原因就是logback的 AppenderBase的doAppend()函数需要同步

public synchronized void doAppend(E eventObject)

案例

Logback 异步日志处理能力分析

环境信息

32C128G

单条日志较大 len=1137

top

1
2
3
4
5
6
7
  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
13200 admin 20 0 128.6g 78.6g 22864 R 85.1 63.5 15:13.50 AsyncAppende //异步写日志
13389 admin 20 0 128.6g 78.6g 22864 R 42.1 63.5 1:33.49 logback-5 --压缩

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
13200 admin 20 0 128.6g 78.5g 22864 R 85.1 63.5 15:54.71 AsyncAppender-W
13456 admin 20 0 128.6g 78.5g 22864 R 73.5 63.5 1:49.45 logback-6

日志内容

1
2
3
4
5
6
[len=1137] select 1 /*skkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkk*/

[ 408s] threads: 360, tps: 0.00, reads/s: 78817.18, writes/s: 0.00, response time: 15.55ms (95%)
[ 409s] threads: 360, tps: 0.00, reads/s: 85020.78, writes/s: 0.00, response time: 12.70ms (95%)
[ 410s] threads: 360, tps: 0.00, reads/s: 86073.08, writes/s: 0.00, response time: 12.83ms (95%)
[ 411s] threads: 360, tps: 0.00, reads/s: 84357.86, writes/s: 0.00, response time: 12.90ms (95%)

平均每分钟输出日志内容 13个512MB日志文件,每秒100MB的输出能力

每条日志len=150

1
2
3
4
5
6
7
[len=150] SELECT 1 /*skkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkkk*/ 

[ 10s] threads: 120, tps: 0.00, reads/s: 185004.17, writes/s: 0.00, response time: 1.77ms (95%)
[ 11s] threads: 120, tps: 0.00, reads/s: 188139.08, writes/s: 0.00, response time: 1.73ms (95%)
[ 12s] threads: 120, tps: 0.00, reads/s: 185597.99, writes/s: 0.00, response time: 1.74ms (95%)
[ 13s] threads: 120, tps: 0.00, reads/s: 188732.07, writes/s: 0.00, response time: 1.74ms (95%)
[ 14s] threads: 120, tps: 0.00, reads/s: 188982.57, writes/s: 0.00, response time: 1.74ms (95%)

减小日志

1
2
3
4
5
6
7
8
9
10
[len=46] SELECT 1 /*skkkkkkkkkkkkkkkkkkkkkkkkkkkkkkk*/ 

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
15646 admin 20 0 128.4g 78.1g 22976 R 82.8 63.2 4:45.75 AsyncAppender-W
15958 admin 20 0 128.4g 78.1g 22976 R 46.0 63.2 0:27.01 logback-5
15664 admin 20 0 128.4g 78.1g 22976 R 29.8 63.2 1:47.70 Processor2-W
15666 admin 20 0 128.4g 78.1g 22976 R 29.8 63.2 1:48.03 Processor3-W

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND15646 admin 20 0 128.4g 78.1g 22976 R 82.8 63.2 4:45.75 AsyncAppender-W
15958 admin 20 0 128.4g 78.1g 22976 R 46.0 63.2 0:27.01 logback-515664 admin 20 0 128.4g 78.1g 22976 R 29.8 63.2 1:47.70 Processor2-W15666 admin 20 0 128.4g 78.1g 22976 R 29.8 63.2 1:48.03 Processor3-W

select 1日志

1
2
3
4
5
6
7
8
9
10
11
12
[len=8] SELECT 1 

[ 10s] threads: 120, tps: 0.00, reads/s: 185004.17, writes/s: 0.00, response time: 1.77ms (95%)
[ 11s] threads: 120, tps: 0.00, reads/s: 188139.08, writes/s: 0.00, response time: 1.73ms (95%)
[ 12s] threads: 120, tps: 0.00, reads/s: 185597.99, writes/s: 0.00, response time: 1.74ms (95%)
[ 13s] threads: 120, tps: 0.00, reads/s: 188732.07, writes/s: 0.00, response time: 1.74ms (95%)
[ 14s] threads: 120, tps: 0.00, reads/s: 188982.57, writes/s: 0.00, response time: 1.74ms (95%)

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
15646 admin 20 0 128.3g 78.1g 22976 R 81.5 63.2 3:37.77 AsyncAppender-W
16849 admin 20 0 128.3g 78.1g 22976 R 37.7 63.2 0:26.85 logback-8
16066 admin 20 0 128.3g 78.1g 22976 S 33.8 63.2 0:33.07 logback-7

点查日志

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
[len=43] SELECT *, pad FROM sbtest1 WHERE id=5000089

[ 31s] threads: 360, tps: 0.00, reads/s: 120084.93, writes/s: 0.00, response time: 3.20ms (95%)
[ 32s] threads: 360, tps: 0.00, reads/s: 119897.70, writes/s: 0.00, response time: 3.21ms (95%)
[ 33s] threads: 360, tps: 0.00, reads/s: 120158.21, writes/s: 0.00, response time: 3.20ms (95%)
[ 34s] threads: 360, tps: 0.00, reads/s: 119777.94, writes/s: 0.00, response time: 3.22ms (95%)
[ 35s] threads: 360, tps: 0.00, reads/s: 120047.95, writes/s: 0.00, response time: 3.20ms (95%)
[ 36s] threads: 360, tps: 0.00, reads/s: 118585.32, writes/s: 0.00, response time: 3.23ms (95%)
[ 37s] threads: 360, tps: 0.00, reads/s: 119351.12, writes/s: 0.00, response time: 3.20ms (95%)

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
15644 admin 20 0 128.5g 78.3g 22976 R 99.9 63.3 1:12.14 logback-1
15646 admin 20 0 128.5g 78.3g 22976 R 65.6 63.3 8:46.11 AsyncAppender-W
15659 admin 20 0 128.5g 78.3g 22976 R 25.5 63.3 2:53.82 Processor0-R
15662 admin 20 0 128.5g 78.3g 22976 S 25.5 63.3 3:06.63 Processor1-W

后端RDS快打满了

案例总结

len表示日志长度

len=43 ,点查 len=8 select 1 [len=150] SELECT 1 [len=1137] select 1
QPS 12万(rds瓶颈) 18.6万(写日志单线程瓶颈) 18.5万 8.5万(磁盘瓶颈)

因为调度问题 异步写日志进程很难跑满CPU, 最多跑到80%左右

单核按条输出能力在 18万条每秒左右(Intel(R) Xeon(R) Platinum 8269CY CPU @ 2.50GHz)

如果日志太大会受限于物理磁盘写出能力,测试环境最大输出能力是每秒 100MB

16core VS 32 Core 案例比较

如果都是用一半超线程,32 Core基本能达到16Core的1.9倍性能

下图上半部分是32C,下半部分是16C

image-20220810160155192

对应CPU状态

image-20220810160241298

image-20220810160249972

如果都改用物理核后,32Core VS 16Core是 25万 VS 15万,大概提升有1.67倍,不到2倍

同时看到perf 也是打了7折,这应该是core太多后应用代码内部锁竞争太激励

横向比较

logback、log4j2等横向关系和性能比较分析

日志框架

紫色为接口类,蓝色为实现,白色为转换
image.png

log4j-over-slf4j和slf4j-log4j12之所以不能共存,是因为它俩可以造成循环依赖!从图中可以看到,有不少会造成循环依赖的场景,比如jul-to-slf4j与slf4j-jdk14、jcl-over-slf4j与JCL等,有些jar的共存会让调用方产生困惑,不知道具体调用哪个

image-20220907151035617

性能比较

image.png

  • 可见在同步日志模式下, Logback的性能是最糟糕的.
  • 而log4j2的性能无论在同步日志模式还是异步日志模式下都是最佳的.

其根本原因在于log4j2使用了LMAX, 一个无锁的线程间通信库代替了, logback和log4j之前的队列. 并发性能大大提升。有兴趣的同学,可以深入探索。

来自log4j2官方的比较数据(同步,在不同的瓶颈下)

https://logging.apache.org/log4j/2.x/performance.html

image.png

image.png

异步场景下的性能比较

AsyncAppender to FileAppender
image.png

Log4j2中的异步日志(AsyncAppender)

默认用ArrayBlockingQueue.队列大小为128.

关于ArrayBlockingQueue

ArrayBlockingQueue是一种地节省了空间,对于记日志有很好的适用性,同时避免内存的伸缩产生波动,也降低了GC的负担。入队出队时由内部的重入锁来控制并发,同时默认采用非公平锁的性质来处理活跃线程的闯入(Barge),从而提高吞吐量。
ArrayBlockingQueue在处理数据的入队提供了offer和put方法。两者的区别是:如果队列满了,offer直接返回给调用线程false, 而不用等待,这种场景较适合异步写日志,即使没有入队成功,仍然可以接受。而put方法则会让当前线程进入等待队列,并再次去竞争锁。
类似的,处理出队时提供了poll和take方法,区别也是是否阻塞调用线程。

参考资料

flush cache 大小8K

就是要你懂TCP队列–通过实战案例来展示问题

详细理论和实践部分可以看这篇

再写这篇原因是,即使我在上篇文章里将这个问题阐述的相当清晰,但是当我再次碰到这个问题居然还是费了一些周折,所以想再次总结下。

问题描述

使用其他团队的WEBShell 调试问题的时候非常卡,最开始怀疑是定时任务导致压力大,然后重启Server端的Tomcat就恢复了,当时该应用的开发同学看到机器磁盘、cpu、内存、gc等都正常,实在不知道为什么会这么卡

分析问题

因为每天都是上午出现问题,拿到权限后,也跟着先检查一遍定时任务,没发现什么异常。

既然在客户端表现出来卡顿,那么tsar先看看网络吧,果然大致是卡顿的时候网络重传率有点高,不过整个问题不是一直出现,只是间歇性的。

抓包、netstat -s 看重传、reset等都还好、ss -lnt 看也没有溢出,我看了很多次当前队列都是0

重启Tomcat

问题恢复,所以基本觉得问题还是跟Tomcat非常相关,抓包看到的重传率非常低(不到0.01%—被这里坑了一下),因为中间链路还有nginx等,一度怀疑是不是抓包没抓到本地回环网卡导致的,要不不会tsar看到的重传率高,而tcpdump抓下来的非常低。

重启后 jstack 看看tomcat状态,同时跟正常的server对比了一下,发现明显有一个线程不太对,一直在增加

image.png

所以到这里大概知道问题的原因了,只是还不能完全确认。

应该是Tomcat里面的线程越来越多导致Tomcat越来越慢,这个慢不是表现在gc、cpu等上,所以开发同学发现卡顿上去也没看出端倪来。

那么对于网络很熟悉的同学,上去看到网络重传很高也没找到原因有点不太应该,主要是问题出现的时候间歇性非常低,通过ss -lnt去看溢出队列和netstat -s |grep -i listen 的时候基本都没什么问题,就忽视了,再说在tcpdump抓包只看到很少的几个重传,反倒是几百个reset包干扰了问题(几百个reset肯定不对,但是没有影响我所说的应用)。

调整参数,加速问题重现

因为总是每天上午一卡顿、有人抱怨、然后重启恢复,第二天仍是这个循环,也就是问题轻微出现后就通过重启解决了

故意将全连接队列从当前的128改成16,重启后运行正常,实际并发不是很高的时候16也够了,改成16是为了让问题出现的时候如果是全连接队列不够导致的,那么会影响更明显一些,经过一天的运行后,可以清晰地观察到:

image.png

tsar的重传率稳定的很高,ss -lnt也能明显地看到全连接队列完全满了,这个满不是因为压力大了,压力一直还是差不多的,所以只能理解是Tomcat处理非常慢了,同时netstat -s 看到 overflowed也稳定增加

这个时候客户端不只是卡顿了,是完全连不上。

Tomcat jstack也能看到这几个线程创建了2万多个:

image.png

抓包(第二次抓包的机会,所以这次抓了所有网卡而不只是eth0)看到 Tomcat的8080端口上基本是这样的:

image.png

而看所有网卡的所有重传的话,这次终于可以看到重传率和tsar看到的一致,同时也清晰的看到主要127.0.0.1的本地流量,也就是Nginx过来的,而之前的抓包只抓了eth0,只能零星看到几个eth0上的重传包,跟tsar对不上,也导致问题跑偏了(重点去关注reset了)

image.png

或者这个异常状态的截图

image-20230315143053615

一些疑问

为什么之前抓包看不到这些重传

因为对业务部署的不了解只抓了eth0, 导致没抓到真正跟客户端表现出来的卡顿相关的重传。比如这是只抓eth0上的包,看到的重传:

image.png

可以看到明显非常少,这完全不是问题。

为什么 ss -lnt / netstat -s 都没发现问题

当时抱怨的时候都是间歇性的,所以 ss -lnt看了10多次都是当前连接0, netstat -s 倒是比较疏忽没仔细比较

为什么线程暴涨没有监控到

边缘业务,本身就是监控管理其它服务的,本身监控不健全。

网络重传和业务的关系

一般我们通过tsar等看到的是整个机器的重传率,而实际影响我们业务的(比如这里的8080端口)只是我这个端口上的重传率,有时候tsar看到重传率很高,那可能是因为机器上其他无关应用拉高的,所以这里需要一个查看具体业务(或者说具体端口上的重传率的工具)

如何快速定位网络重传发生的端口

bcc、bpftrace或者systemtap等工具都提供了观察网络重传包发生的时候的网络四元组以及发生重传的阶段(握手、建立连接后……),这样对我们定位问题就很容易了

image.png

image.png

image.png

总结

问题的根本原因不是因为TCP连接队列不够,而是 Tomcat中线程泄露,导致Tomcat反应越来越慢,进而导致TCP连接队列溢出,然后网络重传率升高,最终导致了client端操作卡顿。

这种问题最快的是 jstack 发现,但是因为这只是一个后台Manager,所以基本没有监控,当时也漏看了jstack,所以导致问题定位花的时间长一些。当然通过tcpdump(漏抓了 lo 网卡,主要重传都是本地nginx和本地tomcat的,所以没有发现问题),通过 ss -lnt 和 netstat -s 本来也应该可以发现的,但是因为干扰因素太多而导致也没有发现,这个时候tcp_retrans等工具可以帮我们看的更清楚。

当然从发现连接队列不够到Tomcat处理太慢这个是紧密联系的,一般应用重启的时候也会短暂连接队列不够,那是因为重启的时候Tomcat前累积了太多连接,这个时候Tomcat重启中,需要热身,本身处理也慢,所以短暂会出现连接队列不够,等Tomcat启动几分钟后就正常了。

NIO、EPOLL和协程

从IO说起

用户线程发起IO操作后(比如读),网络数据读取过程分两步:

  • 用户线程等待内核将数据从网卡拷贝到内核空间
  • 内核将数据从内核空间拷贝到用户空间

同步阻塞IO

用户线程发起read后让出CPU一直阻塞直到内核把网卡数据读到内核空间,然后再拷贝到用户空间,然后唤醒用户线程

同步非阻塞IO

用户线程发起read后,不阻塞,反复尝试读取,直到内核把网卡数据读到内核空间,用户线程继续read,这时进入阻塞直到数据拷贝到用户空间

undefined

阻塞和非阻塞指的是发起IO操作后是等待还是返回,同步和异步指的是应用程序与内核通信时数据从内核空间拷贝到用户空间的操作是内核主动触发(异步)还是应用程序触发(同步)

IO多路复用、Epoll

一个进程虽然任一时刻只能处理一个请求,但是处理每个请求的事件时,耗时控制在 1 毫秒以内,这样 1 秒内就可以处理上千个请求,把时间拉长来看,多个请求复用了一个进程,这就是多路复用,这种思想很类似一个 CPU 并发多个进程,所以也叫做时分多路复用。

epoll作用:进程内同时刻找到缓冲区或者连接状态变化的所有TCP连接,主要是基于同一时刻活跃连接只在总连接中占一小部分

image.png

image.png

用户线程读取分成两步,用户线程先发起select调用(确认内核是否准备好数据),准备好后才调用read,将数据从内核空间读取到用户空间(read这里还是阻塞)。主要是一个select线程可以向内核查多个数据通道的状态

undefined

IO多路复用和同步阻塞、非阻塞的区别主要是用户线程发起read的时机不一样,IO多路复用是等数据在内核空间准备好了再通过同步read去读取;而阻塞和非阻塞因为没法预先知道数据是否在内核空间准备好,所以早早触发了read然后等待,只是阻塞会一直等,而非阻塞是指触发read后不用等,反复read直到read到数据。

Tomcat中的NIO指的是同步非阻塞,但是触发时机又是通过Java中的Selector,可以理解成通过Selector跳过了前面的阻塞和非阻塞,实际用户线程在数据Ready前没有触发read操作,数据到了才出发read操作。

阻塞IO和NIO的主要区别是:NIO面对的是Buffer,可以做到读取完毕后再一次性处理;而阻塞IO面对的是流,只能边读取边处理

多路复用 API 返回的事件并不一定可读写的,如果使用阻塞 I/O, 那么在调用 read/write 时则会发生程序阻塞,因此最好搭配非阻塞 I/O,以便应对极少数的特殊情况

epoll JStack 堆栈

像Redis采取的是一个进程绑定一个core,然后处理所有连接的所有事件,因为redis主要是内存操作,速度比较快,这样做避免了加锁,权衡下来更有利(实践上为了利用多核会部署多个redis实例;另外新版本的redis也开始支持多线程了)。但是对大多服务器就不可取了,毕竟单核处理能力是瓶颈,另外就是IO速度和CPU速度的差异非常大,所以不能采取Redis的设计。

Nginx采取的是多个Worker通过reuseport来监听同一个端口,一个Worker对应一个Epoll红黑树,上面挂着所有这个Worker负责处理的连接。默认多个worker是由OS来调度,可以通过 worker_cpu_affinity 来指定某个worker绑定到哪个core。

eg: 启动4个worker,分别绑定到CPU0~CPU3上

1
2
worker_processes    4;
worker_cpu_affinity 0001 0010 0100 1000;

or
启动2个worker;worker 1 绑定到CPU0/CPU2上;worker 2 绑定到CPU1/CPU3上

1
2
worker_processes    2;
worker_cpu_affinity 0101 1010;

or 自动绑定(推荐方式)

1
2
3
4
5
worker_processes auto;
worker_cpu_affinity auto; //自动绑核

或者 限制CPU资源的使用,只将nginx worker绑定到特定的一些cpu核心上:
worker_cpu_affinity auto 01010101;

分析worker和core的绑定关系(psr–当前进程跑在哪个core上,没有绑定就会飘来飘去,没有意义)

1
ps -eo pid,ni,pri,pcpu,psr,comm|grep nginx|awk '{++s[$(NF-1)]}END{for (i in s)print "core-id",i,"\t",s[i]}'|sort -nr -k 3

而Tomcat等服务器会专门有一个(或多个)线程处理新连接IO(Accept),然后老的连接全部交给一个线程池(Reactor)来处理,这个线程池的线程数量可以根据机器CPU core数量来调整

Image

完整的NIO中Acceptor逻辑JStack:

//3306 acceptor端口
"HTTPServer" #32 prio=5 os_prio=0 tid=0x00007fb76cde6000 nid=0x4620 runnable [0x00007fb6db5f6000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
        at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:275)
        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
        - locked <0x000000070007fde0> (a sun.nio.ch.Util$3)
        - locked <0x000000070007fdc8> (a java.util.Collections$UnmodifiableSet)
        - locked <0x000000070002cbc8> (a sun.nio.ch.EPollSelectorImpl)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
        at com.alibaba.cobar.net.NIOAcceptor.run(NIOAcceptor.java:63)

   Locked ownable synchronizers:
        - None

Acceptor Select Java源代码

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
 33     public NIOAcceptor(String name, int port, FrontendConnectionFactory factory, boolean online) throws IOException{
34 super.setName(name);
35 this.port = port;
36 this.factory = factory;
37 if (online) {
38 this.selector = Selector.open();
39 this.serverChannel = ServerSocketChannel.open();
40 this.serverChannel.socket().bind(new InetSocketAddress(port), 65535);
41 this.serverChannel.configureBlocking(false);
42 this.serverChannel.register(selector, SelectionKey.OP_ACCEPT);
43 }
44 }
53
54 public void setProcessors(NIOProcessor[] processors) {
55 this.processors = processors;
56 }
57
58 @Override
59 public void run() {
60 for (;;) {
61 ++acceptCount;
62 try {
63 selector.select(1000L);
64 Set<SelectionKey> keys = selector.selectedKeys();
65 try {
66 for (SelectionKey key : keys) {
67 if (key.isValid() && key.isAcceptable()) {
68 accept();
69 } else {
70 key.cancel();
71 }
72 }
73 } finally {
74 keys.clear();
75 }
76 } catch (Throwable e) {
77
91 }
92 }
93 }
94
95 private void accept() {
96 SocketChannel channel = null;
97 try {
98 channel = serverChannel.accept();
99 channel.setOption(StandardSocketOptions.TCP_NODELAY, true);
100 channel.configureBlocking(false);
101 FrontendConnection c = factory.make(channel);
102 c.setAccepted(true);
103
104 NIOProcessor processor = nextProcessor();
105 c.setProcessor(processor);
106 processor.postRegister(c);
107 } catch (Throwable e) {
108 closeChannel(channel);
109 logger.info(getName(), e);
110 }
111 }

synchronized public void online() {
if (this.serverChannel != null && this.serverChannel.isOpen()) {
return;
}

try {
this.selector = Selector.open();
this.serverChannel = ServerSocketChannel.open();
this.serverChannel.socket().bind(new InetSocketAddress(port));
this.serverChannel.configureBlocking(false);
//NIOAccept 只处理accept事件
this.serverChannel.register(selector, SelectionKey.OP_ACCEPT);
statusLogger.info(this.getName() + " is started and listening on " + this.getPort());
} catch (IOException e) {
logger.error(this.getName() + " online error", e);
throw GeneralUtil.nestedException(e);
}
}

创建server(Listen端口)就是创建一个NIOAcceptor,监听在特定端口上,NIOAcceptor有多个(一般和core一致) NIOProcessor 线程,一个NIOProcessor 中还可以有一个 NIOReactor

NIOAcceptor(一般只有一个,可以有多个)是一个Thread,只负责处理新建连接(建立新连接会设置这个Socket的Options,比如buffer size、keepalived等),将新建连接绑定到一个NIOProcessor(NIOProcessor数量一般和CPU Core数量一致,一个NIOProcessor对应一个NIOReactor),连接上的收发包由NIOReactor来处理。也就是一个连接(Socket)创建后就绑定到了一个固定的 NIOReactor来处理,每个NIOReactor 有一个 R线程和一个 W线程(写不走epoll的话用这个W线程按queue写出)。这个 R线程一直阻塞在selector,等待新连接或者读写事件的到来。

新连接进来后NIOAcceptor.select 阻塞解除,执行accept逻辑,accept返回一个channel(对socket封装),设置channel TCP options,将这个channel和一个 NIOProcessor绑定(一个NIOProcessor可以绑定多个channel,反之一个channel只能绑定到一个NIOProcessor),同时将这个channel插入(offer)到NIOProcessor里面的NIOReactor的队列中,并唤醒NIOReactor的selector,将新连接注册到 NIOReactor的selector中(进行连接的mysql协议认证)。然后阻塞在这个selector等待事件中,等待读写事件的到来

也就是只有Acceptor阶段会有惊群(但是上面的代码只有一个Acceptor,所以也没有惊群了),收发数据阶段因为Socket已经绑定到了一个固定的Thread,所以不会有惊群了,但是可能会存在某个Thread有慢处理导致新进来的请求长时间得不到响应。

Select 触发 read/write 堆栈:

"Processor2-R" #26 prio=5 os_prio=0 tid=0x00007fb76cc9a000 nid=0x4611 runnable [0x00007fb6dbdfc000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
        at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:275)
        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
        - locked <0x000000070006e090> (a sun.nio.ch.Util$3)
        - locked <0x000000070006cd68> (a java.util.Collections$UnmodifiableSet)
        - locked <0x00000007000509e0> (a sun.nio.ch.EPollSelectorImpl)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
        at com.alibaba.cobar.net.NIOReactor$R.run(NIOReactor.java:88)
        at java.lang.Thread.run(Thread.java:852)

NIOReactor.java:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
 82         @Override
83 public void run() {
84 final Selector selector = this.selector;
85 for (;;) {
86 ++reactCount;
87 try {
88 selector.select(1000L);
89 register(selector);
90 Set<SelectionKey> keys = selector.selectedKeys();
91 try {
92 for (SelectionKey key : keys) {
93 Object att = key.attachment();
94 if (att != null && key.isValid()) {
95 int readyOps = key.readyOps();
96 if ((readyOps & SelectionKey.OP_READ) != 0) {
97 read((NIOConnection) att); //读
98 } else if ((readyOps & SelectionKey.OP_WRITE) != 0) {
99 write((NIOConnection) att); //写
100 } else {
101 key.cancel();
102 }
103 } else {
104 key.cancel();
105 }
106 }
107 } finally {
108 keys.clear();
109 }
110 } catch (Throwable e) {
111 logger.warn(name, e);
112 }
113 }
114 }

Socket是一个阻塞的IO,一个Socket需要一个Thread来读写;SocketChannel对Socket进行封装,是一个NIO的Socket超集,一个Select线程就能处理所有的SocketChannel(也就是所有的Socket)

Java的Netty框架和 Corba的NIOProcessor 就是基于java的NIO库,用的(多)selector形式

NIO 多路复用Java example

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
public class SelectorNIO {
/**
* linux 多路复用器 默认使用epoll,可通过启动参数指定使用select poll或者epoll ,
*/
private Selector selector = null;
int port = 3306;

public static void main(String[] args) {
SelectorNIO service = new SelectorNIO();
service.start();
}

public void initServer() {
try {
ServerSocketChannel server = ServerSocketChannel.open();
server.configureBlocking(false);
server.bind(new InetSocketAddress(port));

//epoll模式下 open会调用一个调用系统调用 epoll_create 返回文件描述符 fd3
selector = Selector.open();

/**
*对应系统调用
*select,poll模式下:jvm里开辟一个文件描述符数组,并吧 fd4 放入
*epoll模式下: 调用内核 epoll_ctl(fd3,ADD,fd4,EPOLLIN)
*/
server.register(selector, SelectionKey.OP_ACCEPT);
} catch (IOException e) {
e.printStackTrace();
}
}

public void start() {
initServer();
System.out.println("server start");
while (true) {
try {
Set<SelectionKey> keys = selector.keys();
System.out.println("可处理事件数量 " + keys.size());
/**
*对应系统调用
*1,select,poll模式下: 调用 内核 select(fd4) poll(fd4)
*2,epoll: 调用内核 epoll_wait()
*/
while (selector.select() > 0) {
//返回的待处理的文件描述符集合
Set<SelectionKey> selectionKeys = selector.selectedKeys();
Iterator<SelectionKey> iterator = selectionKeys.iterator();
while (iterator.hasNext()) {
SelectionKey key = iterator.next();
//使用后需移除,否则会被一直处理
iterator.remove();
if (key.isAcceptable()) {
/**
* 对应系统调用
* select,poll模式下:因为内核未开辟空间,那么在jvm中存放fd4的数组空间
* epoll模式下: 通过epoll_ctl把新客户端fd注册到内核空间
*/
acceptHandler(key);
} else if (key.isReadable()) {
/**
* 处理读事件
*/
readHandler(key);
}
}
}
} catch (IOException e) {
e.printStackTrace();
}
}
}

public void acceptHandler(SelectionKey key) {
try {
ServerSocketChannel ssc = (ServerSocketChannel)key.channel();
//接受新客户端
SocketChannel client = ssc.accept();
//重点,设置非阻塞
client.configureBlocking(false);
ByteBuffer buffer = ByteBuffer.allocate(1024);

/**
* 调用系统调用
* select,poll模式下:jvm里开辟一个数组存入 fd7
* epoll模式下: 调用 epoll_ctl(fd3,ADD,fd7,EPOLLIN
*/
client.register(selector, SelectionKey.OP_READ, buffer);
System.out.println("client connected:" + client.getRemoteAddress());
} catch (IOException e) {
e.printStackTrace();
}
}

public void readHandler(SelectionKey key) {
try {
// 可读事件,读取数据并向客户端发送响应
SocketChannel socketChannel = (SocketChannel)key.channel();
/**
* 简单介绍下Buffer
* Buffer本质上是一个内存块,要弄懂它首先要了解以下三个属性
* capacity(容量)、position(读写位置)和limit(读写的限制)。两种模式,读模式和写模式,
* capacity在读写模式下不变,但position和limit在读写模式下值是会变的
* 举个例子,
* 1.创建一个capacity为1024的Buffer,刚开始position=0,limit=capacity=1024
* 2.往Buffer写数据,每写一个数据,position指针向后移动一个位置,其值加一,limit则减1。比如
* 写入24个字节后,position=24(已经写入24),limit=1000(还可写入1024)
* 3.假设我们已经写完了,那我从哪里读?读多少呢?所以Buffer提供了一个读写模式翻转的方法flip方法
* 把写模式转换成读模式,底层就是把position和limit的值改成从哪里读,读多少,所以调用该方法后,我们
* 就能得到position=0 从0位置开始读,limit=24读24个位置
*/
ByteBuffer buffer = ByteBuffer.allocate(1024);
int len = socketChannel.read(buffer);
System.out.println("readHandler len" + len);
if (len > 0) {
buffer.flip();
byte[] bytes = new byte[buffer.remaining()];
buffer.get(bytes);
String message = new String(bytes, "UTF-8");
System.out.println("Received message from " + socketChannel.getRemoteAddress() + ": " + message);
// 向客户端发送响应
String response = "Hello, client!";
ByteBuffer responseBuffer = ByteBuffer.wrap(response.getBytes("UTF-8"));
socketChannel.write(responseBuffer);
}
//If the peer closes the socket:
//read() returns -1; readLine() returns null; readXXX() throws EOFException, for any other X.
//As InputStream only has read() methods, it only returns -1: it doesn't throw an IOException at EOS.
if(len==-1){
socketChannel.close();
throw new EOFException("read eof exception");
}
} catch (Exception e) {
e.printStackTrace();
}
}
}

Channel

Channel 类位于 java.nio.channels 包中,但并不是 Channel 仅仅支持 NIO,其分为两种类型:

  • FileChannel:完全不支持 NIO;
  • SocketChannel/ServerSocketChannel 等 Channel 默认情况下并不支持 NIO,只有显式地调用配置方法才能够进入非阻塞模式(ServerSocketChannel.configBlocking(false))。

下面主要以 SocketChannel 的角度来介绍 Channel 类。

Channel 我们可以理解为对应于 BIO 中的 Socket,也可以理解为 Scoket.inputStream/SocketOutputStream。如果认为是流,那么我们做一个比较:

  • 传统 Socket:我们调用 Socket 的 getInputStream() 以及 getOutputStream() 进行数据的读和写。
  • Channel:我们不再需要得到输入输出流进行读和写,而是通过 Channel 的 read() 以及 write() 方法进行读和写。

Channel 如此实现也付出了代价(如下图所示):

  • 读写模式需要调用 flip() 方法进行切换,读模式下调用 write() 试图进行写操作会报错。
  • 读写不再能够接受一个简单的字节数组,而是必须是封装了字节数组的 Buffer 类型。

image-20200516195346349

目前已知 Channel 的实现类有:

  • FileChannel 一个用来写、读、映射和操作文件的通道。

  • DatagramChannel

  • SocketChannel

    SocketChannel 可以看做是具有非阻塞模式的 Socket。其可以运行在阻塞模式,也可以运行在非阻塞模式。其只能依靠 ByteBuffer 进行读写,而且是尽力读写,尽力的含义是:

    • ByteBuffer 满了就不能再读了;
    • 即使此次 Socket 流没有传输完毕,但是一旦 Channel 中的数据读完了,那么就返回了,这就是非阻塞读。所以读的方法有 -1(EOF),0(Channel 中的数据读完了,但是整个数据流本身没有消耗完),其他整数,此次读的数据(因为 ByteBuffer 并不是每次都是空的,原来就有数据时只能够尽力装满)。
  • ServerSocketChannel 这个类似于 ServerSocket 起到的作用。

一个比喻比较他们的不同

打个不是极其恰当的比方:假如你去餐馆吃饭,厨师(内核)给你准备饭菜(数据)

  • 阻塞IO:老板,饭好了吗?于是你傻傻在窗口等着。等着厨师把饭做好给你。干等着,不能玩手机。
  • 非阻塞IO:老板,饭好了吗?没好?那我玩手机。哈哈,刷个微博。十分钟过去了,你又去问,饭好了吗?还没好,那我再斗个地主吧。过了一会儿,你又去问。。。。等饭的过程中可以玩手机,不过你得时不时去问一下好了没。
  • IO多路复用:你们一帮人一口气点了十几个菜,其他人坐着该做啥做啥,派一个人等着厨房的通知。。。问厨师,这么多个菜,有哪几个菜好了呢?厨师告诉你A、C、E好了,你可以取了;又过了一会儿,你去问厨师,有哪些菜好了呢?厨师告诉你D、F好了,可以取了。。。
  • 异步IO:老板,饭好了麻烦通知我一下。我去看电视,不用再去问饭好了没有了,饭好厨师会给你的。等饭的过程中当然可以玩手机。完全托管的机制。
  • 同步:端菜上桌过程必须是阻塞,异步相当于厨师将菜送到桌子上后通知你吃

Tomcat中的NIO+多路复用的实现

NIOEndpoint组件实现了NIO和IO多路复用,IO多路复用指的是Poller通过Selector处理多个Socket(SocketChannel)

undefined

  • LimitLatch 是连接控制器,负责控制最大连接数,NIO模式下默认是10000,达到阈值后新连接被拒绝
  • Acceptor 跑在一个单独的线程里,一旦有新连接进来accept方法返回一个SocketChannel对象,接着把SocketChannel对象封装在一个PollerEvent对象中,并将PollerEvent对象压入Poller的Queue里交给Poller处理。 Acceptor和Poller之间是典型的生产者-消费者模式
  • Poller的本质是一个Selector,内部维护一个Channel数组,通过一个死循环不断地检测Channel中的数据是否就绪,一旦就绪就生成一个 SocketProcessor任务对象扔给 Executor处理。同时Poller还会循环遍历自己所管理的SocketChannel是否已经超时,如果超时就关闭这个SocketChannel
  • Executor是线程池,主要处理具体业务逻辑,Poller主要处理读取Socket数据逻辑。Executor主要负责执行 SocketProcessor对象中的run方法,SocketProcessor对象的run方法用 Http11Processor来读取和解析请求数据。
  • Http11Processor是应用层协议的封装,他会调用容器获得请求(ServletRequest),再将响应通过Channel写出给请求

因为Tomcat支持同步非阻塞IO模型和异步IO模型,所以Http11Processor不是直接读取Channel。针对不同的IO模型在Java API中对Channel有不同的实现,比如:AsynchronousSocketChannel 和 SocketChannel,为了对 Http11Processor屏蔽这些差异,Tomcat设计了一个包装类SocketWrapper,Http11Processor只需要调用SocketWrapper的读写方法

Tomcat核心参数

  • acceptorThreadCount: Acceptor线程数量,多核情况下充分利用多核来应对大量连接的创建,默认值是1
  • acceptCount: TCP全连接队列大小,默认值是100,这个值是交给内核,由内核来维护这个队列的大小,满了后Tomcat无感知
  • maxConnections: NIO模式默认10000,最大同时处理的连接数量。如果是BIO,一个connections需要一个thread来处理,不应设置太大。
  • maxThreads: 专门处理IO操作的Worker线程数量,默认值是200

Acceptor

Acceptor实现了Runnable接口,可以跑在单线程里,一个Listen Port只能对应一个ServerSocketChannel,因此这个ServerSocketChannel是在多个Acceptor线程之间共享

serverSock = ServerSocketChannel.open();
serverSock.socket().bind(addr,getAcceptCount());
serverSock.configureBlocking(true);
  • bind方法的第二个参数是操作系统的等待队列长度,也就是TCP的全连接队列长度,对应着Tomcat的 acceptCount 参数配置,默认是100
  • ServerSocketChannel被设置成阻塞模式,也就是连接创建的时候是阻塞的方式。

多路复用–多个socket共用同一个线程来读取socket中的数据

多路复用可以是对accept,也可以是read,一般而言对于accept一个listen port就是一个线程,但是对于read,如果是高并发情况下,一个线程来读取N多socket肯定性能不够好,同时也没用利用上物理上的多核,所以一般是core+1或者2*core数量的线程来读取N多socket,因为有些read还做一些其它逻辑所以会设置的比core数量略微多些。

正常一个连接一个线程(tomcat的BIO模型),导致的问题连接过多的话线程也过多,而大部分连接都是空闲的。如果活跃连接数比较多的话,导致CPU主要用在了线程调度、切换以及过高的内存消耗上(C10K)。而对于NIO即使活跃连接数非常多,但是实际处理他们的线程也就几个(一般设置跟core数差不多),所以也不会有太高的上下文切换(参考后面阐述的协程的原理)。

Select和epoll本质是为了IO多路复用(多个连接共用一个线程–监听是否连接有数据到达)。有报文进来的时候触发Select,Select轮询所有连接确认是哪个连接有报文进来了。连接过多放大了这种无用轮询。
epoll通过一颗红黑树维护所有连接,同时将有数据进来的连接通过回调更新到一个队列中,那么epoll每次检查的时候只需要检查队列而不是整个红黑树,效率大大提高了。

事件驱动适合于I/O密集型服务,多进程或线程适合于CPU密集型服务
多路复用有很多种实现,在linux上,2.4内核前主要是select和poll,现在主流是epoll
select解决了一个线程监听多个socket的问题,但是因为依靠fd_set结构体记录所监控的socket,带来了能监听的socket数量有限(不超过1024)
poll在select的基础上解决了1024个的问题,但是还是要依次轮询这1024个socket,效率太低
epoll 异步非阻塞多路复用

闲置线程或进程不会导致系统上下文切换过高(但是每个线程都会消耗内存)。只有ready状态过多时上下文切换才不堪重负。对于CPU连说调度10M的线程、进程不现实,这个时候适合用协程

image.png

netty自带telnet server的example中,一个boss epoll负责listen新连接,新连接分配给多个worker epoll(worker则使用默认的CPU数*2.),每个连接之后的读写都由固定的一个worker来处理

以上netty结构中:

  • BOSS负责accept连接(通过BOSS监听的channel的read事件),然后实例化新连接的channel

  • 该channel绑定到worker线程组下的某个eventloop上,后续所有该channel的事件、任务 均有该eventloop执行。这是单个channel无锁的关键

  • BOSS 提交Channel.regist任务到worker线程组,之后BOSS任务结束,转入继续listen

协程

协程是一种轻量级的,用户态的执行单元。相比线程,它占用的内存非常少,在很多实现中(比如 Go 语言)甚至可以做到按需分配栈空间。

它主要有三个特点:

  • 占用的资源更少 ;
  • 所有的切换和调度都发生在用户态;
  • 它的调度是协商式的,而不是抢占式的。

协程的全部精神就在于控制流的主动让出和恢复,工程实现得考虑如何让协程的让出与恢复高效。一般在协程中调用 yield_to 来主动把执行权从本协程让给另外一个协程。yield_to 机器码:

1
2
3
4
5
6
7
8
9
10
11
12
000000000040076d <_Z8yield_toP9coroutineS0_>:
40076d: 55 push %rbp
40076e: 48 89 e5 mov %rsp,%rbp
400771: 48 89 7d f8 mov %rdi,-0x8(%rbp)
400775: 48 89 75 f0 mov %rsi,-0x10(%rbp)
400779: 48 8b 45 f0 mov -0x10(%rbp),%rax
40077d: 48 8b 00 mov (%rax),%rax
400780: 48 8b 55 f8 mov -0x8(%rbp),%rdx
400784: 48 89 22 mov %rsp,(%rdx)
400787: 48 89 c4 mov %rax,%rsp
40078a: 5d pop %rbp
40078b: c3 retq

yield_to 中,参数 old_co 指向老协程,co 则指向新的协程,也就是我们要切换过去执行的目标协程。

这段代码的作用是,首先,把当前 rsp 寄存器的值存储到 old_co 的 stack_pointer 属性(第 9 行),并且把新的协程的 stack_pointer 属性更新到 rsp 寄存器(第 10 行),然后,retq 指令将会从栈上取出调用者的地址,并跳转回调用者继续执行(第 12 行)。

当调用这一次 yield_to 时,rsp 寄存器刚好就会指向新的协程 co 的栈,接着就会执行”pop rbp”和”retq”这两条指令。这里你需要注意一下,栈的切换,并没有改变指令的执行顺序,因为栈指针存储在 rsp 寄存器中,当前执行到的指令存储在 IP 寄存器中,rsp 的切换并不会导致 IP 寄存器发生变化。

这个协程切换过程并没有使用任何操作系统的系统调用,就实现了控制流的转移。也就是说,在同一个线程中,我们真正实现了两个执行单元。这两个执行单元并不像线程那样是抢占式地运行,而是相互主动协作式执行,所以,这样的执行单元就是协程。我们可以看到,协程的切换全靠本执行单元主动调用 yield_to 来把执行权让渡给其他协程。

每个协程都拥有自己的寄存器上下文和栈。协程调度切换时,将寄存器上下文和栈保存到其他地方(上述例子中,保存在 coroutine 对象中),在切回来的时候,恢复先前保存的寄存器上下文和栈。

多进程和多线程优劣的比较

把进程看做是资源分配的单位,把线程才看成一个具体的执行实体。

进程间内存难以共享,多线程可以共享内存;多进程内核管理成本高。

每个线程消耗内存过多, 比如,64 位的 Linux 为每个线程的栈分配了 8MB 的内存,还预分配了 64MB 的内存作为堆内存池;切换请求是内核通过切换线程实现的,什么时候会切换线程呢?不只时间片用尽,当调用阻塞方法时,内核为了让 CPU 充分工作,也会切换到其他线程执行。一次上下文切换的成本在几十纳秒到几微秒间,当线程繁忙且数量众多时,这些切换会消耗绝大部分的 CPU 运算能力。

协程把内核态的切换工作交由用户态来完成.

目前主流语言基本上都选择了多线程作为并发设施,与线程相关的概念是抢占式多任务(Preemptive multitasking),而与协程相关的是协作式多任务。不管是进程还是线程,每次阻塞、切换都需要陷入系统调用 (system call),先让 CPU 执行操作系统的调度程序,然后再由调度程序决定该哪一个进程 (线程) 继续执行。

由于抢占式调度执行顺序无法确定,我们使用线程时需要非常小心地处理同步问题,而协程完全不存在这个问题。因为协作式的任务调度,是要用户自己来负责任务的让出的。如果一个任务不主动让出,其他任务就不会得到调度。这是协程的一个弱点,但是如果使用得当,这其实是一个可以变得很强大的优点。

同步、异步、协程的比较

同步调用

切换请求是内核通过切换线程实现的,什么时候会切换线程呢?不只时间片用尽,当调用阻塞方法时,内核为了让 CPU 充分工作,也会切换到其他线程执行。一次上下文切换的成本在几十纳秒到几微秒间,当线程繁忙且数量众多时,这些切换会消耗绝大部分的 CPU 运算能力。

image.png

改成异步化后:

把上图中本来由内核实现的请求切换工作,交由用户态的代码来完成就可以了,异步化编程通过应用层代码实现了请求切换,降低了切换成本和内存占用空间。异步化依赖于 IO 多路复用机制,比如 Linux 的 epoll 或者 Windows 上的 iocp,同时,必须把阻塞方法更改为非阻塞方法,才能避免内核切换带来的巨大消耗。Nginx、Redis 等高性能服务都依赖异步化实现了百万量级的并发。

image.png

然而,写异步化代码很容易出错。因为所有阻塞函数,都需要通过非阻塞的系统调用拆分成两个函数。虽然这两个函数共同完成一个功能,但调用方式却不同。第一个函数由你显式调用,第二个函数则由多路复用机制调用。这种方式违反了软件工程的内聚性原则,函数间同步数据也更复杂。特别是条件分支众多、涉及大量系统调用时,异步化的改造工作会非常困难。

用协程来实现

协程与异步编程相似的地方在于,它们必须使用非阻塞的系统调用与内核交互,把切换请求的权力牢牢掌握在用户态的代码中。但不同的地方在于,协程把异步化中的两段函数,封装为一个阻塞的协程函数。这个函数执行时,会使调用它的协程无感知地放弃执行权,由协程框架切换到其他就绪的协程继续执行。当这个函数的结果满足后,协程框架再选择合适的时机,切换回它所在的协程继续执行。

img

实际上,用户态的代码切换协程,与内核切换线程的原理是一样的。内核通过管理 CPU 的寄存器来切换线程,我们以最重要的栈寄存器和指令寄存器为例,看看协程切换时如何切换程序指令与内存。

每个线程有独立的栈,而栈既保留了变量的值,也保留了函数的调用关系、参数和返回值,CPU 中的栈寄存器 SP 指向了当前线程的栈,而指令寄存器 IP 保存着下一条要执行的指令地址。因此,从线程 1 切换到线程 2 时,首先要把 SP、IP 寄存器的值为线程 1 保存下来,再从内存中找出线程 2 上一次切换前保存好的寄存器值,写入 CPU 的寄存器,这样就完成了线程切换。(其他寄存器也需要管理、替换,原理与此相同,不再赘述。)

协程的切换

协程的切换与此相同,只是把内核的工作转移到协程框架实现而已,下图是协程切换前的状态:

image.png

从协程 1 切换到协程 2 后的状态如下图所示:

image.png

协程就是用户态的线程。然而,为了保证所有切换都在用户态进行,协程必须重新封装所有的阻塞系统调用,否则,一旦协程触发了线程切换,会导致这个线程进入休眠状态,进而其上的所有协程都得不到执行。比如,普通的 sleep 函数会让当前线程休眠,由内核来唤醒线程,而协程化改造后,sleep 只会让当前协程休眠,由协程框架在指定时间后唤醒协程。再比如,线程间的互斥锁是使用信号量实现的,而信号量也会导致线程休眠,协程化改造互斥锁后,同样由框架来协调、同步各协程的执行。

非阻塞+epoll+同步编程 = 协程

协程主要是将IO Wait等场景自动识别然后以非常小的代价切换到其它任务处理,一旦Wait完毕再切换回来。

协程在实现上都是试图用一组少量的线程来实现多个任务,一旦某个任务阻塞,则可能用同一线程继续运行其他任务,避免大量上下文的切换。每个协程所独占的系统资源往往只有栈部分。而且,各个协程之间的切换,往往是用户通过代码来显式指定的(跟各种 callback 类似),不需要内核参与,可以很方便的实现异步

这个技术本质上也是异步非阻塞技术,它是将事件回调进行了包装,让程序员看不到里面的事件循环。程序员就像写阻塞代码一样简单。比如调用 client->recv() 等待接收数据时,就像阻塞代码一样写。实际上是底层库在执行recv时悄悄保存了一个状态,比如代码行数,局部变量的值。然后就跳回到EventLoop中了。什么时候真的数据到来时,它再把刚才保存的代码行数,局部变量值取出来,又开始继续执行。

协程是异步非阻塞的另外一种展现形式。Golang,Erlang,Lua协程都是这个模型。

协程的优点是它比系统线程开销小,缺点是如果其中一个协程中有密集计算,其他的协程就不运行了。操作系统进程、线程切换的缺点是开销大,优点是无论代码怎么写,所有进程都可以并发运行。
协程也叫做用户态进程/用户态线程。区别就在于进程/线程是操作系统充当了EventLoop调度,而协程是自己用Epoll进行调度。

Erlang解决了协程密集计算的问题,它基于自行开发VM,并不执行机器码。即使存在密集计算的场景,VM发现某个协程执行时间过长,也可以进行中止切换。Golang由于是直接执行机器码的,所以无法解决此问题。所以Golang要求用户必须在密集计算的代码中,自行Yield。

操作系统调用不知道内部具体实现,代价包含:上下文切换(几百个指令?)、PageCache
语言自己调度(协程)一般是执行完,基于栈的切换只需要保存栈指针;一定是在同一个线程/进程内切换,各种Cache还有效。

多线程下的真正开销代价

系统调用开销其实不大,上下文切换同样也是数十条cpu指令可以完成

多线程调度下的热点火焰图:

image.png

多线程下真正的开销来源于线程阻塞唤醒调度,系统调用和上下文切换伴随着多线程,所以导致大家一直认为系统调用和上下文切换过多导致了多线程慢。

以ajdk的Wisp2协程为例

对于很快的锁,Wisp2可以很好地解决,因为任务切换不频繁,最多也就CPU核数量的任务在切换,拿到锁的协程会很快执行完然后释放锁,所以其他协程再执行的时候容易拿到锁。

但是对于像logback日志同步输出doAppend()的锁(比较慢,并发度高)Wisp2就基本无能为力了。

Wisp2的主线程跟CPU数量一致,Wisp1的时候碰到CPU执行很长的任务就容易卡主,Wisp2解决了这个问题,超过一定时间会让出这个协程。如果主线程比较闲的时候会尝试从其它主线程 steal 协程(任务)过来, steal的时候需要加锁(自旋锁)来尝试steal成功。如果碰到其他主线程也在steal就可能会失败,steal尝试几次加锁不成功(A线程尝试steal B线程的协程-任务,会尝试锁住A和B,但是比如C线程也在偷的话可能会导致A偷取失败)就放弃。

Wisp2碰到执行时间比较长的任务的话,有个线程会过一段时间去监控,如果超过100ms,就触发一个safepoint,触发抢占。

Node.js

Node.js:基于事件的异步非阻塞框架,基于V8,上层跑JavaScript应用。默认只有一个eventLoop导致也只能用一个核。

Node.js 只有一个 EventLoop,也就是只占用一个 CPU 内核,当 Node.js 被CPU 密集型任务占用,导致其他任务被阻塞时,却还有 CPU 内核处于闲置状态,造成资源浪费。

比喻

关于JAVA的网络,之前有个比喻形式的总结,分享给大家:

有一个养鸡的农场,里面养着来自各个农户(Thread)的鸡(Socket),每家农户都在农场中建立了自己的鸡舍(SocketChannel)

  • 1、BIO:Block IO,每个农户盯着自己的鸡舍,一旦有鸡下蛋,就去做捡蛋处理;
  • 2、NIO:No-Block IO-单Selector,农户们花钱请了一个饲养员(Selector),并告诉饲养员(register)如果哪家的鸡有任何情况(下蛋)均要向这家农户报告(select keys);
  • 3、NIO:No-Block IO-多Selector,当农场中的鸡舍逐渐增多时,一个饲养员巡视(轮询)一次所需时间就会不断地加长,这样农户知道自己家的鸡有下蛋的情况就会发生较大的延迟。怎么解决呢?没错,多请几个饲养员(多Selector),每个饲养员分配管理鸡舍,这样就可以减轻一个饲养员的工作量,同时农户们可以更快的知晓自己家的鸡是否下蛋了;
  • 4、Epoll模式:如果采用Epoll方式,农场问题应该如何改进呢?其实就是饲养员不需要再巡视鸡舍,而是听到哪间鸡舍的鸡打鸣了(活跃连接),就知道哪家农户的鸡下蛋了;
  • 5、AIO:Asynchronous I/O, 鸡下蛋后,以前的NIO方式要求饲养员通知农户去取蛋,AIO模式出现以后,事情变得更加简单了,取蛋工作由饲养员自己负责,然后取完后,直接通知农户来拿即可,而不需要农户自己到鸡舍去取蛋。

参考文章

https://www.atatech.org/articles/147345

LVS 20倍的负载不均衡,原来是内核的这个Bug

姊妹篇:就是要你懂负载均衡–lvs和转发模式

问题由来

最近用 sysbench 做压测的时候,sysbench每次创建100个长连接,lvs后面两台RS(通过wlc来均衡),发现每次都是其中一台差不多95个连接,另外一台大概5个连接,不均衡得太离谱了,并且稳定重现,所以想要搞清楚为什么会出现20倍的不均衡。

前面是啰嗦的基础知识部分,bug直达文章末尾

几个术语和缩写

vip:Virtual IP,LVS实例IP
RS: Real Server 后端真正提供服务的机器
LB: Load Balance 负载均衡器
LVS: Linux Virtual Server

负载均衡调度算法

LVS的负载调度算法有10种,其它不常用的就不说了,凑数没有意义。基本常用的如下四种,这四种又可以分成两大种:rr轮询调度和lc最小连接调度。

rr轮询调度(Round-Robin Scheduling)

轮询调度(Round Robin Scheduling)算法就是以轮询的方式依次将请求调度到不同的服务器,即每次调度执行i = (i + 1) mod n,并选出第i台服务器。算法的优点是其简洁性,它无需记录当前所有连接的状态,不管服务器上实际的连接数和系统负载,所以它是一种无状态调度。

wrr加权轮询调度(Weighted Round-Robin Scheduling)

加权轮询调度(Weighted Round-Robin Scheduling)算法可以解决服务器间性能不一的情况,它用相应的权值表示服务器的处理性能,服务器的缺省权值为1。假设服务器A的权值为1,B的权值为2,则表示服务器B的处理性能是A的两倍。加权轮叫调度算法是按权值的高低和轮叫方式分配请求到各服务器。权值高的服务器先收到的连接,权值高的服务器比权值低的服务器处理更多的连接,相同权值的服务器处理相同数目的连接数。

lc最小连接调度(Least-Connection Scheduling)

最小连接调度(Least-Connection Scheduling)算法是把新的连接请求分配到当前连接数最小的服务器。最小连接调度是一种动态调度算法,它通过服务器当前所活跃的连接数来估计服务器的负载情况。调度器需要记录各个服务器已建立连接的数目,当一个请求被调度到某台服务器,其连接数加1;当连接中止或超时,其连接数减一。

如果集群系统的真实服务器具有相近的系统性能,采用”最小连接”调度算法可以较好地均衡负载。

特别注意:这种调度算法还需要考虑active(权重*256)和inactive连接的状态,这个实现考量实际会带来严重的不均衡问题。

wlc加权最小连接调度(Weighted Least-Connection Scheduling)

加权最小连接调度(Weighted Least-Connection Scheduling)算法是最小连接调度的超集,各个服务器用相应的权值表示其处理性能。服务器的缺省权值为1,系统管理员可以动态地设置服务器的权值。加权最小连接调度在调度新连接时尽可能使服务器的已建立连接数和其权值成比例。

调度器可以自动问询真实服务器的负载情况,并动态地调整其权值。

其中wlc和lc可以看成一种,wrr和rr可以看成另外一种。下面只重点说wrr和wlc为什么不均衡

为什么会不均衡

wrr算法

非常简单,来了新连接向各个RS转发就行,比如一段时间内创建100个连接,那这100个连接能基本均匀分布在后端所有RS上。

长连接

如果所有请求都是长连接,如果后端有RS重启(宕机、OOM服务不响应、日常性重启等等),那么其上面的连接一般会重建,重建的新连接会均匀分布到其它RS上,当重启的RS正常加入到LVS后,它上面的连接是最少的,即使后面大批量建新的连接,也只是新连接在这些RS上均匀分布,重新加入的RS没法感知到历史已经存在的老连接所以容易导致负载不均衡。

批量重启所有RS(升级等,多个RS进入服务状态肯定有先后),第一个起来的RS最容易获取到更多的连接,压力明显比其它RS要大,这肯定也是不符合预期的。

总之wrr/rr算法因为不考虑已存在的连接问题,在长连接的情况下对RS重启、扩容(增加新的RS)十分不友好,容易导致长连接的不均衡。

当然对于短连接不存在这个问题,所以可以考虑让应用端的连接不要那么长,比如几个小时候断开重新连接一下。升级的时候等所有RS都启动好后再让LVS开始工作等

LVS 集群下不均衡

一般一个负载均衡由多个(4个)LVS 机器组成。

假设每批请求发来四个新连接,经过4台负载均衡机器每个机器一个连接,这一个连接都打到了 RS 的第一个节点上。主要是4台负载均衡机器之间没有协商机制,互相没有同步信息。

可以的解决方案:LVS 机器加入随机因子,让每个LVS 认为的第一个节点不一样

权值相等的WRR算法是否与RR算法等效?

不等效。原因是由于RR调试算法加入了初始随机因子,而WRR由于算法的限制没有此功能。因此在新建连接数少,同时并发连接少,也没有预热的情况下,RR算法会有更好的均衡性表现。

WRR在每一次健康检查抖动的时候,会重置调度器,从头开始WRR的逻辑,因此可能会导致调度部分调度不均匀。

案例

比如如下这个负载不均衡,因为第一个RS CPU特别忙,QPS的不均衡大致能说明工作连接的差异

image-20210422171244718

  1. 连接数差距大有一部分是因为机器忙,断开慢。lvs监控的累积连接数是200:250的差距, 流量差距是1:2
  2. wrr会经常重置调度逻辑,经常从第一台开始轮询,导致第一台压力更大

和lvs负载监控数据对比来看是一致的:

image-20210422171155401

wlc算法

针对wrr对长连接的上述不均衡,所以wlc算法考虑当前已存在的连接数,尽量把新连接发送到连接数较少的RS上,看起来比较完美地修复了wrr的上述不均衡问题。

wlc将连接分成active(ESTABLISHED)和inactive(syn/fin等其它状态),收到syn包后LVS按照如下算法判定该将syn发给哪个RS

static inline int
ip_vs_dest_conn_overhead(struct ip_vs_dest *dest)
{
        /* We think the overhead of processing active connections is 256
         * times higher than that of inactive connections in average. (This
         * 256 times might not be accurate, we will change it later) We
         * use the following formula to estimate the overhead now:
         *                dest->activeconns*256 + dest->inactconns
         */
        return (atomic_read(&dest->activeconns) << 8) +
                atomic_read(&dest->inactconns);
}

也就是一个active状态的连接权重是256,一个inactive权重是1,然后将syn发给总连接负载最轻的RS。

这里会导致不均衡过程: 短时间内有一批syn冲过来(同时并发创建一批连接),必然有一个RS(假如这里总共两个RS)先建立第一个active的连接,在第二个RS也建立第一个active连接之前,后面的syn都会发给第二个RS,那么最终会看到第二个RS的连接远大于第一个RS,这样就导致了最终连接数的负载不均衡。

主要是因为这里对inactive 连接的判定比较糙,active连接的权重直接256就更糙了(作者都说了是拍脑袋的)。实际握手阶段的连接直接都判定为active比较妥当,挥手阶段的连接判定为inactive是可以的,但是active的权重取4或者8就够了,256有点夸张。

这个不均衡场景可以通过 sysbench 稳定重现,如果两个RS的rt差异大一点会更明显

RS到LVS之间的时延差异会放大这个不均衡,这个差异必然会存在,再就是vpc网络环境下首包延时很大(因为overlay之类的网络,连接的首包都会去网关拉取路由信息,所以首包都很慢),差异会更明显,因为这些都会影响第一个active连接的建立。

What is an ActiveConn/InActConn (Active/Inactive) connnection?

  • ActiveConn in ESTABLISHED state
  • InActConn any other state

只对NAT模式下有效:

With LVS-NAT, the director sees all the packets between the client and the realserver, so always knows the state of tcp connections and the listing from ipvsadm is accurate. However for LVS-DR, LVS-Tun, the director does not see the packets from the realserver to the client.

Example with my Apache Web server.

Client  	    <---> Server

A client request an object on the web server on port 80 :

SYN REQUEST     ---->
SYN ACK 	    <----
ACK             ----> *** ActiveConn=1 and 1 ESTABLISHED socket on realserver.
HTTP get        ----> *** The client request the object
HTTP response   <---- *** The server sends the object
APACHE closes the socket : *** ActiveConn=1 and 0 ESTABLISHED socket on realserver
The CLIENT receives the object. (took 15 seconds in my test)
ACK-FIN         ----> *** ActiveConn=0 and 0 ESTABLISHED socket on realserver

slb下的wlc

阿里slb集群下多台LVS服务器之间是开启的session同步功能,因此WLC在计算后端RS的连接权重时会将其它LVS服务器同步的连接计算进来,所以说实际上是一个准全局的调度算法,因此它的调度均衡性最好

WLC由于要计算所有连接的权重,因此消耗的CPU最多,性能最差。由于Session同步不是实时的,同时WLC算法对完成三次握手连接与半开连接的计算权重不同,因此WLC算法不适合突发新建连接的场景。

sysbench验证wlc均衡逻辑

lvs(多个LVS节点的集群)后面总共两个RS,如果一次性同时创建100个连接,那么基本上这个100个连接都在第一个RS上,如果先创建50个,这时这50个基本在第一个RS上,休息几秒钟,再创建50个,那么第二批的50个基本落在第二个RS上。

如果先创建50个,这时这50个基本在第一个RS上,休息几秒钟,再创建100个,那么第二批的100个中前50个基本落在第二个RS上,后面50个又都跑到第一个RS上了。

Session Persistence 导致的负载不均衡

LB 上开启了“会话保持”(Session Persistence),会将会话黏在某个RS上,如果刚好某个请求端访问量大,就会导致这个RS访问量大,从而不均衡

LVS的会话保持有这两种

  1. 把同一个client的请求信息记录到lvs的hash表里,保存时间使用persistence_timeout控制,单位为秒。 persistence_granularity 参数是配合persistence_timeout的,在某些情况特别有用,他的值是子网掩码,表示持久连接的粒度,默认是 255.255.255.255,也就是单独的client ip,如果改成,255.255.255.0就是client ip一个网段的都会被分配到同一个real server。

  2. 一个连接创建后空闲时的超时时间,这个时间为3种

    • tcp的空闲超时时间

    • lvs收到客户端tcp fin的超时时间

    • udp的超时时间

总结

  • wrr/rr在长连接下,RS比较害怕动态扩容、重启机器、升级应用等场景
  • wrr会因为没有随机因子在小流量、探活失败重置场景下导致第一个RS 压力大,总的来说推荐rr而不是wrr
  • wlc/lc在长连接下,如果同时创建的大量连接(比如sysbench压测),因为内核的lvs逻辑对active和inactive判定不太合理导致了这种场景下连接会严重不均衡。
  • 如果是druid这种连接池一个个创建的连接在wlc/lc算法是不会触发不均衡
  • 如果lvs到两个RS的rt差异越大会加剧wlc/lc的不平衡(rt差异肯定是会存在的)

参考文章

What is an ActiveConn/InActConn (Active/Inactive) connnection?

玩转TShark(Wireshark的命令行版)

在我感叹Wireshark图形界面的强大时候,有时候也抱怨有点慢,或者感叹下要是有命令行界面版该多好啊,实际上TShark就是WireShark的命令行版,WireShark的功能基本都有,还能组合grep/awk等编程处理分析抓包文件。

下面让我们通过一些例子来学习TShark的常用功能,所有用到的*.cap/*.pcap等都是通过tcpdump抓到的包。请收藏好,下次碰到类似问题直接用文章中的命令跑一下。

wireshark问题

配置文件路径

macOS 下

1
~/.config/wireshark

查看有哪些plugins 以及路径

image-20240614105158403

不再展示协议内容

比如,info列不再显示mysql 的request、response,但是下方的二进制解析能看到select等语句,这种一般是配置文件中 disable 了mysql协议。

配置文件名:C:\Users\admin\AppData\Roaming\Wireshark\disabled_protos

如果抓包缺失很大(比如进出走两个网卡,实际只抓了一个网卡),那么协议解析后也不会正确显示。

IO graph图表无法展示数据

一般是缺数据,先把IO graph关掉再重新打开就可以了,注意图表title显示

tcp segment of a reassembled pdu

这个提示是指,wireshark需要将多个tcp协议包重新组合成特定协议内容(比如MySQL,HTTP),但是因为包缺失(或者每个包大小截断了)导致reassembled失败。实际上wireshark已经成功检测到该协议,只是在解析这个协议的时候缺失包导致解析不好。

这个时候可以试试将指定协议的reassembled属性关掉

image.png

PDU:Protocol Data Unit

If the reassembly is successful, the TCP segment containing the last part of the packet will show the packet.
The reassembly might fail if some TCP segments are missing.

TCP segment of a reassembled PDU means that:

  1. Wireshark/TShark thinks it knows what protocol is running atop TCP in that TCP segment;
  2. that TCP segment doesn’t contain all of a “protocol data unit” (PDU) for that higher-level protocol, i.e. a packet or protocol message for that higher-level protocol, and doesn’t contain the last part of that PDU, so it’s trying to reassemble the multiple TCP segments containing that higher-level PDU.

常用命令

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
#parse 8507/4444 as mysql protocol, default only parse 3306 as mysql.
sudo tshark -i eth0 -d tcp.port==8507,mysql -T fields -e mysql.query 'port 8507'

sudo tshark -i any -c 50 -d tcp.port==4444,mysql -Y " ((tcp.port eq 4444 ) )" -o tcp.calculate_timestamps:true -T fields -e frame.number -e frame.time_epoch -e frame.time_delta_displayed -e ip.src -e tcp.srcport -e tcp.dstport -e ip.dst -e tcp.time_delta -e tcp.stream -e tcp.len -e mysql.query

#query time
sudo tshark -i eth0 -Y " ((tcp.port eq 3306 ) and tcp.len>0 )" -o tcp.calculate_timestamps:true -T fields -e frame.number -e frame.time_epoch -e frame.time_delta_displayed -e ip.src -e tcp.srcport -e tcp.dstport -e ip.dst -e tcp.time_delta -e tcp.stream -e tcp.len -e mysql.query

#每隔3秒钟生成一个新文件,总共生成5个文件后(15秒后)终止抓包,然后包名也按时间规范好了
sudo tcpdump -t -s 0 tcp port 3306 -w 'dump_%Y-%m-%d_%H:%M:%S.pcap' -G 3 -W 5 -Z root

#每隔30分钟生成一个包并压缩
nohup sudo tcpdump -i eth0 -t -s 0 tcp and port 3306 -w 'dump_%Y-%m-%d_%H:%M:%S.pcap' -G 1800 -W 48 -Z root -z gzip &

#file size 1000M
nohup sudo tcpdump -i eth0 -t -s 0 tcp and port 3306 -w 'dump_' -C 1000 -W 300 -Z root -z gzip &

#抓取详细SQL语句, 快速确认client发过来的具体SQL内容:
sudo tshark -i any -f 'port 8527' -s 0 -l -w - |strings
sudo tshark -i eth0 -d tcp.port==3306,mysql -T fields -e mysql.query 'port 3306'
sudo tshark -i eth0 -R "ip.addr==11.163.182.137" -d tcp.port==3306,mysql -T fields -e mysql.query 'port 3306'
sudo tshark -i eth0 -R "tcp.srcport==62877" -d tcp.port==3001,mysql -T fields -e tcp.srcport -e mysql.query 'port 3001'

#直接展示,省掉wireshark
$tshark -i bond0 port 3306 -T fields -e frame.number -e frame.time_delta -e col.Source -e col.Destination -e col.Protocol -e ip.len -e col.Info -e mysql.query
$tshark -i bond0 port 3306 -T fields -e frame.number -e frame.time_delta -e tcp.srcport -e tcp.dstport -e col.Info -e mysql.query
$tshark -i bond0 port 3306 -T fields -E separator=, -E quote=d -e frame.number -e frame.time_delta -e tcp.srcport -e tcp.dstport -e col.Info
"1","0.000000000","1620","3306","faxportwinport > mysql [SYN] Seq=0 Win=42340 Len=0 MSS=1460 SACK_PERM=1 WS=512"
"2","0.000026993","3306","1620","mysql > faxportwinport [SYN, ACK] Seq=0 Ack=1 Win=29200 Len=0 MSS=1460 SACK_PERM=1 WS=128"

分析mysql的每个SQL响应时间

应用有输出的日志显示DB慢,DB监控到的日志显示自己很快,经常扯皮,如果直接在应用机器的网卡抓包,然后分析到每个SQL的响应时间,那么DB、网络都可以甩锅了(有时候应用统计的时间包含了应用自身的时间、取连接的时间等)

tshark -r 213_php.cap -Y "mysql.query or (  tcp.srcport==3306)" -o tcp.calculate_timestamps:true -T fields -e frame.number -e frame.time_epoch  -e frame.time_delta_displayed  -e ip.src -e tcp.srcport -e tcp.dstport -e ip.dst -e tcp.time_delta -e tcp.stream -e tcp.len -e mysql.query |sort -nk9 -nk1
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
34143	1475902394.645073000	0.000342000	10.100.53.17	3306	40383	10.100.10.213	0.000153000	2273	0	
34145 1475902394.645333000 0.000260000 10.100.53.17 3306 40383 10.100.10.213 0.000253000 2273 77
34150 1475902394.645537000 0.000204000 10.100.53.17 3306 40383 10.100.10.213 0.000146000 2273 0
34151 1475902394.645706000 0.000169000 10.100.53.17 3306 40383 10.100.10.213 0.000169000 2273 11
34153 1475902394.645737000 0.000031000 10.100.10.213 40383 3306 10.100.53.17 0.000031000 2273 21 SET NAMES 'utf8'
34161 1475902394.646390000 0.000158000 10.100.53.17 3306 40383 10.100.10.213 0.000653000 2273 11
34162 1475902394.646418000 0.000028000 10.100.10.213 40383 3306 10.100.53.17 0.000028000 2273 22 START TRANSACTION
34164 1475902394.646713000 0.000295000 10.100.53.17 3306 40383 10.100.10.213 0.000295000 2273 11
34166 1475902394.646776000 0.000063000 10.100.10.213 40383 3306 10.100.53.17 0.000063000 2273 46 select AUTO_SEQ_t_order.nextval from dual
34194 1475902394.651468000 0.000909000 10.100.53.17 3306 40383 10.100.10.213 0.004692000 2273 100
34195 1475902394.651782000 0.000314000 10.100.10.213 40383 3306 10.100.53.17 0.000314000 2273 576 insert into t_order (`out_order_no`,`pk_order`,`uid`,`ytid`,`platform`,`origin_price`,`price`,`partner_id`,`ip`,`sources`,`pay_state`,`type`,`product_type`,`device`,`extension`,`spm`,`ext2`,`createtime`,`pay_channel`,`use_ytid`,`updatetime`) values ('2016100822003361672230261573284','261573284','336167223','336167223','1','500','500','100000','42.49.141.142','2','1','1','2','3','{\"showid\":\"286083\",\"play_url\":\"http:\\/\\/v.youku.com\\/v_show\\/id_XMTczOTM5NjU1Mg==.html\",\"permit_duration\":172800}','','','2016-10-08 12:53:14','201','0','2016-10-08 12:53:14')
34196 1475902394.653275000 0.001493000 10.100.53.17 3306 40383 10.100.10.213 0.001493000 2273 19
34197 1475902394.653410000 0.000135000 10.100.10.213 40383 3306 10.100.53.17 0.000135000 2273 370 insert into t_order_product (`fk_order`,`product_id`,`origin_price`,`price`,`discount`,`deliver_state`,`product_url`,`product_name`,`amount`,`ytid`,`sub_product_id`,`createtime`) values ('2016100822003361672230261573284','4000010000','500','500','0','1','http://vip.youku.com','���������������������2:���������������','1','336167223','286083','2016-10-08 12:53:14')
34198 1475902394.658326000 0.004916000 10.100.53.17 3306 40383 10.100.10.213 0.004916000 2273 19
34199 1475902394.658407000 0.000081000 10.100.10.213 40383 3306 10.100.53.17 0.000081000 2273 11 commit
34200 1475902394.659626000 0.001219000 10.100.53.17 3306 40383 10.100.10.213 0.001219000 2273 11
34201 1475902394.659811000 0.000185000 10.100.10.213 40383 3306 10.100.53.17 0.000185000 2273 22 START TRANSACTION
34202 1475902394.660054000 0.000243000 10.100.53.17 3306 40383 10.100.10.213 0.000243000 2273 11
34203 1475902394.660126000 0.000072000 10.100.10.213 40383 3306 10.100.53.17 0.000072000 2273 125 SELECT * FROM t_order where ( out_order_no = '2016100822003361672230261573284' ) AND ( ytid = '336167223' ) FOR UPDATE
34209 1475902394.661970000 0.001844000 10.100.53.17 3306 40383 10.100.10.213 0.001844000 2273 2214
34211 1475902394.662069000 0.000099000 10.100.10.213 40383 3306 10.100.53.17 0.000089000 2273 122 update t_order set `pay_state`='2',`updatetime`='2016-10-08 12:53:14' where pk_order='261573284' and ytid='336167223'
34213 1475902394.662917000 0.000848000 10.100.53.17 3306 40383 10.100.10.213 0.000848000 2273 19
34216 1475902394.663049000 0.000088000 10.100.10.213 40383 3306 10.100.53.17 0.000132000 2273 11 commit
34225 1475902394.664204000 0.000264000 10.100.53.17 3306 40383 10.100.10.213 0.001155000 2273 11
34226 1475902394.664269000 0.000065000 10.100.10.213 40383 3306 10.100.53.17 0.000065000 2273 115 SELECT * FROM t_order where ( out_order_no = '2016100822003361672230261573284' ) AND ( ytid = '336167223' )
34235 1475902394.665694000 0.000061000 10.100.53.17 3306 40383 10.100.10.213 0.001425000 2273 2214
34354 1475902394.681464000 0.000157000 10.100.53.17 3306 40383 10.100.10.213 0.000187000 2273 0
34174 1475902394.648046000 0.001123000 10.100.53.19 3306 33471 10.100.10.213 0.000151000 2275 0
34176 1475902394.648331000 0.000285000 10.100.53.19 3306 33471 10.100.10.213 0.000278000 2275 77
34179 1475902394.648482000 0.000151000 10.100.53.19 3306 33471 10.100.10.213 0.000127000 2275 0
34180 1475902394.648598000 0.000116000 10.100.53.19 3306 33471 10.100.10.213 0.000116000 2275 11
34181 1475902394.648606000 0.000008000 10.100.10.213 33471 3306 10.100.53.19 0.000008000 2275 21 SET NAMES 'utf8'
34182 1475902394.648846000 0.000240000 10.100.53.19 3306 33471 10.100.10.213 0.000240000 2275 11
34183 1475902394.648885000 0.000039000 10.100.10.213 33471 3306 10.100.53.19 0.000039000 2275 380 select pk_auto_renew_account as account_id,fk_user as uid,platform,ytid,fk_member_conf_id as member_id,fk_product_id as product_id,price,fk_pay_channel as pay_channel,renew_type,fk_order,fk_auto_renew_subscribe_log as fk_subscribe_log,state,memo,nexttime,createtime,updatetime from t_auto_renew_account where ( ytid = '354295193' ) AND ( platform = '1' ) AND ( state <> '3' )
34184 1475902394.650040000 0.001155000 10.100.53.19 3306 33471 10.100.10.213 0.001155000 2275 1727
34189 1475902394.650559000 0.000519000 10.100.53.19 3306 33471 10.100.10.213 0.000198000 2275 0

或者:
tshark -r gege_drds.pcap -Y “ ((tcp.srcport eq 3306 ) and tcp.len>0 )” -o tcp.calculate_timestamps:true -T fields -e frame.number -e frame.time_epoch -e frame.time_delta_displayed -e ip.src -e tcp.srcport -e tcp.dstport -e ip.dst -e tcp.time_delta -e tcp.stream -e tcp.len -e tcp.analysis.ack_rtt

这个命令跑出来,倒数第四列基本就是rt

967     1548148159.346612000    0.000442000     192.168.4.18    3306    44026   192.168.100.30  0.005255000     17      1576    0.005255000
969     1548148159.346826000    0.000214000     192.168.4.18    3306    44090   192.168.100.30  0.005425000     15      1576    0.005425000
973     1548148159.347428000    0.000602000     192.168.4.18    3306    44070   192.168.100.30  0.005517000     8       2500    0.005517000
979     1548148159.348640000    0.001212000     192.168.4.18    3306    44048   192.168.100.30  0.005517000     22      2462    0.005517000
981     1548148159.348751000    0.000111000     192.168.4.18    3306    44066   192.168.100.30  0.005855000     21      2692    0.005855000
983     1548148159.348844000    0.000093000     192.168.4.18    3306    44046   192.168.100.30  0.004589000     3       2692    0.004589000
985     1548148159.348981000    0.000137000     192.168.4.18    3306    44012   192.168.100.30  0.004885000     19      2443    0.004885000
990     1548148159.349293000    0.000312000     192.168.4.18    3306    44074   192.168.100.30  0.005923000     5       2692    0.005923000
994     1548148159.349671000    0.000378000     192.168.4.18    3306    44080   192.168.100.30  0.004889000     4       2730    0.004889000
1009    1548148159.350591000    0.000920000     192.168.4.18    3306    44022   192.168.100.30  0.004187000     14      1448    0.004187000
1010    1548148159.350592000    0.000001000     192.168.4.18    3306    44022   192.168.100.30  0.000001000     14      1052    
1013    1548148159.350790000    0.000198000     192.168.4.18    3306    44002   192.168.100.30  0.005998000     0       1576    0.005998000
1026    1548148159.352207000    0.001417000     192.168.4.18    3306    44026   192.168.100.30  0.005348000     17      1448    0.005348000
1027    1548148159.352217000    0.000010000     192.168.4.18    3306    44026   192.168.100.30  0.000010000     17      1052    
1036    1548148159.352973000    0.000756000     192.168.4.18    3306    44090   192.168.100.30  0.005940000     15      2500    0.005940000
1041    1548148159.353683000    0.000710000     192.168.4.18    3306    44070   192.168.100.30  0.005190000     8       2692    0.005190000
1043    1548148159.353737000    0.000054000     192.168.4.18    3306    44066   192.168.100.30  0.004635000     21      1448    0.004635000
1044    1548148159.353749000    0.000012000     192.168.4.18    3306    44066   192.168.100.30  0.000012000     21      128     
1051    1548148159.354289000    0.000540000     192.168.4.18    3306    44046   192.168.100.30  0.004911000     3       1576    0.004911000
1054    1548148159.354511000    0.000222000     192.168.4.18    3306    44080   192.168.100.30  0.004515000     4       1576    0.004515000
1055    1548148159.354530000    0.000019000     192.168.4.18    3306    44074   192.168.100.30  0.004909000     5       1576    0.004909000
1065    1548148159.355412000    0.000882000     192.168.4.18    3306    44012   192.168.100.30  0.005217000     19      2692    0.005217000
1067    1548148159.355496000    0.000084000     192.168.4.18    3306    44048   192.168.100.30  0.005231000     22      2610    0.005231000
1072    1548148159.356111000    0.000615000     192.168.4.18    3306    44052   192.168.100.30  0.005830000     24      2730    0.005830000
1076    1548148159.356545000    0.000434000     192.168.4.18    3306    44022   192.168.100.30  0.005615000     14      2692    0.005615000
1079    1548148159.357012000    0.000467000     192.168.4.18    3306    44002   192.168.100.30  0.005966000     0       2462    0.005966000
1082    1548148159.357235000    0.000223000     192.168.4.18    3306    44072   192.168.100.30  0.004817000     23      2692    0.004817000
1093    1548148159.359244000    0.002009000     192.168.4.18    3306    44070   192.168.100.30  0.005188000     8       1576    0.005188000

MySQL响应时间直方图【第八列的含义– Time since previous frame in this TCP stream: seconds】

tshark -r gege_drds.pcap -Y "mysql.query or (tcp.srcport==3306  and tcp.len>60)" -o tcp.calculate_timestamps:true -T fields -e frame.number -e frame.time_epoch  -e frame.time_delta_displayed  -e ip.src -e tcp.srcport -e tcp.dstport -e ip.dst -e tcp.time_delta -e tcp.stream -e tcp.len | awk 'BEGIN {sum0=0;sum3=0;sum10=0;sum30=0;sum50=0;sum100=0;sum300=0;sum500=0;sum1000=0;sumo=0;count=0;sum=0} {rt=$8; if(rt>=0.000) sum=sum+rt; count=count+1; if(rt<=0.000) sum0=sum0+1; else if(rt<0.003) sum3=sum3+1 ; else if(rt<0.01) sum10=sum10+1; else if(rt<0.03) sum30=sum30+1; else if(rt<0.05) sum50=sum50+1; else if(rt < 0.1) sum100=sum100+1; else if(rt < 0.3) sum300=sum300+1; else if(rt < 0.5) sum500=sum500+1; else if(rt < 1) sum1000=sum1000+1; else sum=sum+1 ;} END{printf "-------------\n3ms:\t%s \n10ms:\t%s \n30ms:\t%s \n50ms:\t%s \n100ms:\t%s \n300ms:\t%s \n500ms:\t%s \n1000ms:\t%s \n>1s:\t %s\n-------------\navg: %.6f \n" , sum3,sum10,sum30,sum50,sum100,sum300,sum500,sum1000,sumo,sum/count;}'
 
 -------------
3ms:	145037 
10ms:	78811 
30ms:	7032 
50ms:	2172 
100ms:	1219 
300ms:	856 
500ms:	449 
1000ms:118
>1s:	0
-------------
avg: 0.005937 

对于rt分析,要注意一个query多个response情况(response结果多,分包了),分析这种rt的时候只看query之后的第一个response,其它连续response需要忽略掉。

有时候应用说修改库存的代码都加了事务,但是数据库里库存对不上,这锅压力好大,抓个包看看应用发过来的SQL是啥

开发测试环境上通过如下命令也可以直接用tshark抓包分析SQL语句:

sudo tshark -i eth0 -d tcp.port==3306,mysql -T fields -e mysql.query 'port 3306'

这样就直接看到发出的SQL是否是autocommit=1了

HTTP响应时间分析

1
2
3
4
5
//按秒汇总每个http response 耗时
tshark -r dump.pcap -Y 'http.time>0 ' -T fields -e frame.number -e frame.time_epoch -e frame.time_delta_displayed -e ip.src -e ip.dst -e tcp.stream -e http.request.full_uri -e http.response.code -e http.time | awk '{ print int($2), $8 }' | awk '{ sum[$1]+=$2; count[$1]+=1 ;} END { for (key in count) { printf "time= %s \t count=%s \t avg=%.6f \n", key, count[key], sum[key]/count[key] } }' | sort -k2n | awk '{ print strftime("%c",$2), $0 }'

//on macOS
tshark -r dump.pcap -Y 'http.response_for.uri contains "health" ' -T fields -e frame.number -e frame.time_epoch -e frame.time_delta_displayed -e ip.src -e ip.dst -e tcp.stream -e http.request.full_uri -e http.response_for.uri -e http.time | awk '{ print int($2/10), $8 }' | awk '{ sum[$1]+=$2; count[$1]+=1 ;} END { for (key in count) { printf "time= %s \t count=%s \t avg=%.6f \n", key, count[key], sum[key]/count[key] } }' | sort -k2n | gawk '{ print strftime("%c",$2), $0 }'

按http response分析响应时间

第三列是RT,倒数第二列是stream,同一个stream是一个连接。对应http response 200的是请求响应结果的RT

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
# tshark -nr 10.cap -o tcp.calculate_timestamps:true  -Y "http.request or http.response" -T fields -e frame.number -e frame.time_epoch  -e tcp.time_delta  -e ip.src -e ip.dst -e tcp.stream  -e http.request.full_uri -e http.response.code -e http.response.phrase | sort -nk6 -nk1

82579 1631791992.105383000 0.000113000 172.26.2.13 172.26.13.107 1198 http://plantegg/ajax.sword
83167 1631791992.261663000 0.156042000 172.26.13.107 172.26.2.13 1198 200
84917 1631791992.775011000 0.513106000 172.26.2.13 172.26.13.107 1198 http://plantegg/ajax.sword
86388 1631791993.188458000 0.413018000 172.26.13.107 172.26.2.13 1198 200
87391 1631791993.465156000 0.276608000 172.26.2.13 172.26.13.107 1198 http://plantegg/ajax.sword
88067 1631791993.645780000 0.179832000 172.26.13.107 172.26.2.13 1198 200
89364 1631791993.994322000 0.348324000 172.26.2.13 172.26.13.107 1198 http://plantegg/ajax.sword
89843 1631791994.140131000 0.145169000 172.26.13.107 172.26.2.13 1198 200
91387 1631791994.605527000 0.465245000 172.26.2.13 172.26.13.107 1198 http://plantegg/ajax.sword
92271 1631791994.920607000 0.314639000 172.26.13.107 172.26.2.13 1198 200
93491 1631791995.323424000 0.402724000 172.26.2.13 172.26.13.107 1198 http://plantegg/ajax.sword
93860 1631791995.403614000 0.079834000 172.26.13.107 172.26.2.13 1198 200
97221 1631791996.347307000 0.943423000 172.26.2.13 172.26.13.107 1198 http://plantegg/ajax.sword
97862 1631791996.544563000 0.196448000 172.26.13.107 172.26.2.13 1198 200
99613 1631791997.065735000 0.521095000 172.26.2.13 172.26.13.107 1198 http://plantegg/ajax.sword
82714 1631791992.141943000 0.000122000 172.26.2.13 172.26.12.147 1199 http://plantegg/ajax.sword
83055 1631791992.235637000 0.093471000 172.26.12.147 172.26.2.13 1199 200
84789 1631791992.739133000 0.503423000 172.26.2.13 172.26.12.147 1199 http://plantegg/ajax.sword
85525 1631791992.946220000 0.206860000 172.26.12.147 172.26.2.13 1199 200
88208 1631791993.677995000 0.731490000 172.26.2.13 172.26.12.147 1199 http://plantegg/ajax.sword
88638 1631791993.800956000 0.122637000 172.26.12.147 172.26.2.13 1199 200
91010 1631791994.476918000 0.675911000 172.26.2.13 172.26.12.147 1199 http://plantegg/ajax.sword
92079 1631791994.874566000 0.397357000 172.26.12.147 172.26.2.13 1199 200
94480 1631791995.581990000 0.707200000 172.26.2.13 172.26.12.147 1199 http://plantegg/ajax.sword
94764 1631791995.665365000 0.082906000 172.26.12.147 172.26.2.13 1199 200
96241 1631791996.090803000 0.425378000 172.26.2.13 172.26.12.147 1199 http://plantegg/ajax.sword
96731 1631791996.215406000 0.124276000 172.26.12.147 172.26.2.13 1199 200
98832 1631791996.818172000 0.602695000 172.26.2.13 172.26.12.147 1199 http://plantegg/ajax.sword
99735 1631791997.105453000 0.286845000 172.26.12.147 172.26.2.13 1199 200
83462 1631791992.351494000 0.000042000 172.26.2.13 172.26.9.77 1200 http://plantegg/ajax.sword
84309 1631791992.558541000 0.206305000 172.26.9.77 172.26.2.13 1200 200
86253 1631791993.152426000 0.593767000 172.26.2.13 172.26.9.77 1200 http://plantegg/ajax.sword
86740 1631791993.270402000 0.117311000 172.26.9.77 172.26.2.13 1200 200
89775 1631791994.112908000 0.842414000 172.26.2.13 172.26.9.77 1200 http://plantegg/ajax.sword
90429 1631791994.312254000 0.199015000 172.26.9.77 172.26.2.13 1200 200
92840 1631791995.086191000 0.773857000 172.26.2.13 172.26.9.77 1200 http://plantegg/ajax.sword
93262 1631791995.257123000 0.170488000 172.26.9.77 172.26.2.13 1200 200

改进版本,每10秒钟统计http response耗时,最后按时间排序输出:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
tshark -r 0623.pcap -Y 'http.time>0 ' -T fields -e frame.number -e frame.time_epoch  -e frame.time_delta_displayed  -e ip.src -e ip.dst -e tcp.stream  -e http.request.full_uri -e http.response_for.uri  -e http.time  | awk '{ print int($2/10), $8 }' | awk '{ sum[$1]+=$2; count[$1]+=1 ;} END { for (key in count) {  printf  "time= %s  \t count=%s   \t avg=%.6f \n", key,  count[key], sum[key]/count[key] } }' | sort -k2n | gawk '{ print strftime("%c",$2*10), $0 }'
四 6/23 14:17:30 2022 time= 165596505 count=15289 avg=0.012168
四 6/23 14:17:40 2022 time= 165596506 count=38725 avg=0.013669
四 6/23 14:17:50 2022 time= 165596507 count=42545 avg=0.014140
四 6/23 14:18:00 2022 time= 165596508 count=45613 avg=0.016915
四 6/23 14:18:10 2022 time= 165596509 count=49033 avg=0.018768
四 6/23 14:18:20 2022 time= 165596510 count=49797 avg=0.025015
四 6/23 14:18:30 2022 time= 165596511 count=49670 avg=0.034057
四 6/23 14:18:40 2022 time= 165596512 count=49524 avg=0.040647
四 6/23 14:18:50 2022 time= 165596513 count=49204 avg=0.034251
四 6/23 14:19:00 2022 time= 165596514 count=48024 avg=0.037120
四 6/23 14:19:10 2022 time= 165596515 count=49301 avg=0.041453
四 6/23 14:19:20 2022 time= 165596516 count=42174 avg=0.049191
四 6/23 14:19:30 2022 time= 165596517 count=49437 avg=0.050924
四 6/23 14:19:40 2022 time= 165596518 count=49563 avg=0.050709
四 6/23 14:19:50 2022 time= 165596519 count=49517 avg=0.047916
四 6/23 14:20:00 2022 time= 165596520 count=48256 avg=0.057453
四 6/23 14:20:10 2022 time= 165596521 count=49412 avg=0.053587
四 6/23 14:20:20 2022 time= 165596522 count=51361 avg=0.053422
四 6/23 14:20:30 2022 time= 165596523 count=45610 avg=0.067171
四 6/23 14:20:40 2022 time= 165596524 count=54 avg=2.886536

解析已知协议与IP域名映射

以下技巧抄自:https://www.ilikejobs.com/posts/wireshark/

wireshark

查询当前已经解析了哪些域名

wireshark

设置私有IP名称

先确认下图红框选项是选上的:

image-20240315110305420

wireshark

查看刚设置自定义的名称:

wireshark

保存文件(含host对应名称)

wireshark

分析包的总概览

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
$ capinfos rsb2.cap 
File name: rsb2.cap
File type: Wireshark/tcpdump/... - pcap
File encapsulation: Ethernet
Packet size limit: file hdr: 65535 bytes
Number of packets: 510 k
File size: 143 MB
Data size: 135 MB
Capture duration: 34 seconds
Start time: Tue Jun 7 11:15:31 2016
End time: Tue Jun 7 11:16:05 2016
Data byte rate: 3997 kBps
Data bit rate: 31 Mbps
Average packet size: 265.62 bytes
Average packet rate: 15 kpackets/sec
SHA1: a8367d0d291eab6ba78732d092ae72a5305756a2
RIPEMD160: ec991772819f316d2f629745d4b58fb861e41fc6
MD5: 53975139fa49581eacdb42bd967cbd58
Strict time order: False

分析每两个IP之间的流量

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
$ tshark -r retrans.cap -q -z 'conv,ip' 
================================================================================
IPv4 Conversations
Filter:<No Filter>
| <- | | -> | | Total | Relative | Duration |
| Frames Bytes | | Frames Bytes | | Frames Bytes | Start | |
100.98.50.214 <-> 10.117.41.213 425 60647 544 350182 969 410829 0.856983000 88.7073
10.252.138.13 <-> 10.117.41.213 381 131639 451 45706 832 177345 3.649894000 79.5370
10.168.127.178 <-> 10.117.41.213 335 118164 390 39069 725 157233 3.456698000 81.2639
10.168.246.105 <-> 10.117.41.213 435 23490 271 14634 706 38124 0.000000000 89.7614
10.117.49.244 <-> 10.117.41.213 452 24408 221 11934 673 36342 0.289990000 89.6024
100.97.197.0 <-> 10.117.41.213 45 4226 107 7310 152 11536 0.538867000 88.0736
100.97.196.0 <-> 10.117.41.213 48 4576 102 6960 150 11536 0.524268000 89.0840
100.97.196.128 <-> 10.117.41.213 39 3462 90 6116 129 9578 0.573839000 88.0728
100.97.197.128 <-> 10.117.41.213 27 1998 81 5562 108 7560 1.071232000 87.0382
100.98.148.129 <-> 10.117.41.213 55 3630 37 2442 92 6072 0.571963000 86.7362
================================================================================

分析每个会话的流量

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
$ tshark -r retrans.cap -q -z 'conv,tcp' 
================================================================================
TCP Conversations
Filter:<No Filter>
| <- | | -> | | Total | Relative | Duration |
| Frames Bytes | | Frames Bytes | | Frames Bytes | Start | |
10.117.41.213:33362 <-> 100.98.50.214:3306 143 107183 108 17345 251 124528 9.556973000 79.9993
10.117.41.213:32695 <-> 100.98.50.214:3306 131 95816 118 17843 249 113659 3.464596000 54.7814
10.117.41.213:33737 <-> 100.98.50.214:3306 107 67199 82 11842 189 79041 69.539519000 13.0781
10.117.41.213:33736 <-> 100.98.50.214:3306 58 37851 31 4895 89 42746 69.539133000 8.2015
10.117.41.213:33735 <-> 100.98.50.214:3306 51 37654 27 3338 78 40992 69.538573000 20.0257
10.117.41.213:33681 <-> 100.98.50.214:3306 22 2367 15 2480 37 4847 58.237482000 0.0082
10.252.138.13:17926 <-> 10.117.41.213:3306 13 3454 17 1917 30 5371 77.462089000 0.2816
10.168.127.178:21250 <-> 10.117.41.213:3306 13 4926 17 2267 30 7193 77.442197000 0.6282
10.252.138.13:17682 <-> 10.117.41.213:3306 13 5421 17 2267 30 7688 34.945805000 0.7274
10.168.127.178:21001 <-> 10.117.41.213:3306 18 9872 11 1627 29 11499 21.220800000 35.0242
10.252.138.13:17843 <-> 10.117.41.213:3306 13 4453 15 1510 28 5963 59.176447000 10.8169
10.168.127.178:20927 <-> 10.117.41.213:3306 12 4414 15 1510 27 5924 13.686763000 0.1860
10.252.138.13:17481 <-> 10.117.41.213:3306 11 4360 16 1564 27 5924 3.649894000 0.1810
10.252.138.13:17928 <-> 10.117.41.213:3306 11 3077 15 1461 26 4538 77.467248000 0.6720
10.168.127.178:21241 <-> 10.117.41.213:3306 11 3077 15 1461 26 4538 77.376858000 0.4669
10.168.127.178:21201 <-> 10.117.41.213:3306 12 3971 14 2571 26 6542 64.890147000 5.4010
10.168.127.178:21184 <-> 10.117.41.213:3306 12 6775 14 1794 26 8569 64.073021000 5.6804
10.252.138.13:17545 <-> 10.117.41.213:3306 11 4379 15 1510 26 5889 13.940379000 0.1845
10.168.127.178:20815 <-> 10.117.41.213:3306 11 4360 15 1510 26 5870 3.456698000 0.1901
10.252.138.13:17864 <-> 10.117.41.213:3306 12 2985 12 1129 24 4114 59.855131000 9.7005
10.252.138.13:17820 <-> 10.117.41.213:3306 11 5529 13 1740 24 7269 49.537379000 0.1669
10.252.138.13:17757 <-> 10.117.41.213:3306 11 6006 13 1740 24 7746 45.507148000 0.7587
10.252.138.13:17677 <-> 10.117.41.213:3306 11 5529 13 1740 24 7269 34.806484000 0.5017
10.168.127.178:21063 <-> 10.117.41.213:3306 11 3848 13 1390 24 5238 29.902032000 0.0133
10.252.138.13:17516 <-> 10.117.41.213:3306 11 5985 13 1740 24 7725 11.505585000 0.1494
10.252.138.13:17507 <-> 10.117.41.213:3306 11 3570 13 1424 24 4994 9.652955000 0.0151
10.252.138.13:17490 <-> 10.117.41.213:3306 11 5985 13 1740 24 7725 4.865639000 0.1275

分析每个包的response time

$ tshark -r rsb2.cap -o tcp.calculate_timestamps:true -T fields -e frame.number -e frame.time_epoch -e ip.src -e ip.dst -e tcp.stream -e tcp.len -e tcp.analysis.initial_rtt -e tcp.time_delta

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
1481	1465269331.308138000	100.98.199.36	10.25.92.13	302	0		0.002276000
1482 1465269331.308186000 10.25.92.13 100.98.199.36 361 11 0.000063000
1483 1465269331.308209000 100.98.199.36 10.25.92.13 496 0 0.004950000
1484 1465269331.308223000 100.98.199.36 10.25.92.13 513 0 0.000000000
1485 1465269331.308238000 100.98.199.36 10.25.92.13 326 0 0.055424000
1486 1465269331.308246000 100.98.199.36 10.25.92.13 514 0 0.000000000
1487 1465269331.308261000 10.25.92.71 10.25.92.13 48 0 0.000229000
1488 1465269331.308277000 100.98.199.36 10.25.92.13 254 0 0.055514000
1489 1465269331.308307000 100.98.199.36 10.25.92.13 292 0 0.002096000
1490 1465269331.308383000 100.98.199.36 10.25.92.13 308 0 0.055406000
1491 1465269331.308403000 100.98.199.36 10.25.92.13 75 0 0.041664000
1492 1465269331.308421000 100.98.199.36 10.25.92.13 291 0 0.001973000
1493 1465269331.308532000 100.98.199.36 10.25.92.13 509 0 0.002100000
1494 1465269331.308567000 100.98.199.36 10.25.92.13 123 0 0.041560000
1495 1465269331.308576000 100.98.199.36 10.25.92.13 232 11 0.063317000
1496 1465269331.308584000 100.98.199.36 10.25.92.13 465 655 0.018121000
1497 1465269331.308626000 100.98.199.36 10.25.92.13 61 655 0.042409000
1498 1465269331.308637000 100.98.199.36 10.25.92.13 146 0 0.001520000
1499 1465269331.308639000 100.98.199.36 10.25.92.13 510 0 0.001460000
1500 1465269331.308645000 100.98.199.36 10.25.92.13 237 11 0.063273000

分析有问题的包、概览

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
$ tshark -r retrans.cap -q -z 'expert,note'

Errors (22)
=============
Frequency Group Protocol Summary
22 Malformed MySQL Malformed Packet (Exception occurred)

Warns (749)
=============
Frequency Group Protocol Summary
538 Sequence TCP ACKed segment that wasn't captured (common at capture start)
192 Sequence TCP Connection reset (RST)
19 Sequence TCP Previous segment not captured (common at capture start)

Notes (1162)
=============
Frequency Group Protocol Summary
84 Sequence TCP TCP keep-alive segment
274 Sequence TCP Duplicate ACK (#1)
37 Sequence TCP ACK to a TCP keep-alive segment
23 Sequence TCP This frame is a (suspected) retransmission
262 Sequence TCP Duplicate ACK (#2)
259 Sequence TCP Duplicate ACK (#3)
141 Sequence TCP Duplicate ACK (#4)
69 Sequence TCP Duplicate ACK (#5)
7 Sequence TCP Duplicate ACK (#6)
5 Sequence TCP This frame is a (suspected) spurious retransmission
1 Sequence TCP Duplicate ACK (#7)

分析rtt、丢包、deplicate等等

$ tshark -r retrans.cap -q -z io,stat,1,”AVG(tcp.analysis.ack_rtt)tcp.analysis.ack_rtt”,”COUNT(tcp.analysis.retransmission) tcp.analysis.retransmission”,”COUNT(tcp.analysis.fast_retransmission) tcp.analysis.fast_retransmission”,”COUNT(tcp.analysis.duplicate_ack) tcp.analysis.duplicate_ack”,”COUNT(tcp.analysis.lost_segment) tcp.analysis.lost_segment”,”MIN(tcp.window_size)tcp.window_size”

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34

===================================================================================
| IO Statistics |
| |
| Duration: 89.892365 secs |
| Interval: 2 secs |
| |
| Col 1: AVG(tcp.analysis.ack_rtt)tcp.analysis.ack_rtt |
| 2: COUNT(tcp.analysis.retransmission) tcp.analysis.retransmission |
| 3: COUNT(tcp.analysis.fast_retransmission) tcp.analysis.fast_retransmission |
| 4: COUNT(tcp.analysis.duplicate_ack) tcp.analysis.duplicate_ack |
| 5: COUNT(tcp.analysis.lost_segment) tcp.analysis.lost_segment |
| 6: AVG(tcp.window_size)tcp.window_size |
|---------------------------------------------------------------------------------|
| |1 |2 |3 |4 |5 |6 | |
| Interval | AVG | COUNT | COUNT | COUNT | COUNT | AVG | |
|-------------------------------------------------------------| |
| 0 <> 2 | 0.001152 | 0 | 0 | 0 | 0 | 4206 | |
| 2 <> 4 | 0.002088 | 0 | 0 | 0 | 1 | 6931 | |
| 4 <> 6 | 0.001512 | 0 | 0 | 0 | 0 | 7099 | |
| 6 <> 8 | 0.002859 | 0 | 0 | 0 | 0 | 7171 | |
| 8 <> 10 | 0.001716 | 0 | 0 | 0 | 0 | 6472 | |
| 10 <> 12 | 0.000319 | 0 | 0 | 0 | 2 | 5575 | |
| 12 <> 14 | 0.002030 | 0 | 0 | 0 | 0 | 6922 | |
| 14 <> 16 | 0.003371 | 0 | 0 | 0 | 2 | 5884 | |
| 16 <> 18 | 0.000138 | 0 | 0 | 0 | 1 | 3480 | |
| 18 <> 20 | 0.000999 | 0 | 0 | 0 | 4 | 6665 | |
| 20 <> 22 | 0.000682 | 0 | 0 | 41 | 2 | 5484 | |
| 22 <> 24 | 0.002302 | 2 | 0 | 19 | 0 | 7127 | |
| 24 <> 26 | 0.000156 | 1 | 0 | 22 | 0 | 3042 | |
| 26 <> 28 | 0.000000 | 1 | 0 | 19 | 1 | 152 | |
| 28 <> 30 | 0.001498 | 1 | 0 | 24 | 0 | 5615 | |
| 30 <> 32 | 0.000235 | 0 | 0 | 44 | 0 | 1880 | |

分析丢包、duplicate ack

$ tshark -r retrans.cap -q -z io,stat,5,”COUNT(tcp.analysis.retransmission) tcp.analysis.retransmission”,”COUNT(tcp.analysis.fast_retransmission) tcp.analysis.fast_retransmission”,”COUNT(tcp.analysis.duplicate_ack) tcp.analysis.duplicate_ack”,”COUNT(tcp.analysis.lost_segment) tcp.analysis.lost_segment”

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
===================================================================================
| IO Statistics |
| |
| Duration: 89.892365 secs |
| Interval: 5 secs |
| |
| Col 1: COUNT(tcp.analysis.retransmission) tcp.analysis.retransmission |
| 2: COUNT(tcp.analysis.fast_retransmission) tcp.analysis.fast_retransmission |
| 3: COUNT(tcp.analysis.duplicate_ack) tcp.analysis.duplicate_ack |
| 4: COUNT(tcp.analysis.lost_segment) tcp.analysis.lost_segment |
|---------------------------------------------------------------------------------|
| |1 |2 |3 |4 | |
| Interval | COUNT | COUNT | COUNT | COUNT | |
|------------------------------------------| |
| 0 <> 5 | 0 | 0 | 0 | 1 | |
| 5 <> 10 | 0 | 0 | 0 | 0 | |
| 10 <> 15 | 0 | 0 | 0 | 4 | |
| 15 <> 20 | 0 | 0 | 0 | 5 | |
| 20 <> 25 | 3 | 0 | 67 | 2 | |
| 25 <> 30 | 2 | 0 | 58 | 1 | |
| 30 <> 35 | 0 | 0 | 112 | 0 | |
| 35 <> 40 | 1 | 0 | 156 | 0 | |
| 40 <> 45 | 0 | 0 | 127 | 2 | |
| 45 <> 50 | 1 | 0 | 91 | 0 | |
| 50 <> 55 | 0 | 0 | 63 | 0 | |
| 55 <> 60 | 0 | 0 | 65 | 2 | |
| 60 <> 65 | 2 | 0 | 41 | 0 | |
| 65 <> 70 | 3 | 0 | 34 | 2 | |
| 70 <> 75 | 7 | 0 | 55 | 0 | |
| 75 <> 80 | 3 | 0 | 68 | 0 | |
| 80 <> 85 | 1 | 0 | 46 | 0 | |
| 85 <> Dur| 0 | 0 | 30 | 0 | |
===================================================================================

分析rtt 时间

$ tshark -r ~/ali/metrics/tcpdump/rsb2.cap -q -z io,stat,1,”MIN(tcp.analysis.ack_rtt)tcp.analysis.ack_rtt”,”MAX(tcp.analysis.ack_rtt)tcp.analysis.ack_rtt”,”AVG(tcp.analysis.ack_rtt)tcp.analysis.ack_rtt”

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
========================================================
| IO Statistics |
| |
| Duration: 33.914454 secs |
| Interval: 1 secs |
| |
| Col 1: MIN(tcp.analysis.ack_rtt)tcp.analysis.ack_rtt |
| 2: MAX(tcp.analysis.ack_rtt)tcp.analysis.ack_rtt |
| 3: AVG(tcp.analysis.ack_rtt)tcp.analysis.ack_rtt |
|------------------------------------------------------|
| |1 |2 |3 | |
| Interval | MIN | MAX | AVG | |
|-------------------------------------------| |
| 0 <> 1 | 0.000005 | 0.248840 | 0.009615 | |
| 1 <> 2 | 0.000004 | 0.458952 | 0.009601 | |
| 2 <> 3 | 0.000002 | 0.251274 | 0.009340 | |
| 3 <> 4 | 0.000006 | 0.290993 | 0.010843 | |
| 4 <> 5 | 0.000004 | 0.390800 | 0.008995 | |
| 5 <> 6 | 0.000008 | 0.407525 | 0.011133 | |
| 6 <> 7 | 0.000004 | 0.239225 | 0.008763 | |
| 7 <> 8 | 0.000003 | 0.177203 | 0.009211 | |
| 8 <> 9 | 0.000007 | 0.265505 | 0.010294 | |
| 9 <> 10 | 0.000007 | 0.354278 | 0.008475 | |
| 10 <> 11 | 0.000005 | 5.337388 | 0.011211 | |
| 11 <> 12 | 0.000004 | 0.320651 | 0.008231 | |
| 12 <> 13 | 0.000008 | 0.272029 | 0.008526 | |
| 13 <> 14 | 0.000005 | 0.663421 | 0.014589 | |
| 14 <> 15 | 0.000005 | 0.277754 | 0.009128 | |
| 15 <> 16 | 0.000002 | 0.260320 | 0.010388 | |
| 16 <> 17 | 0.000006 | 0.429298 | 0.009155 | |
| 17 <> 18 | 0.000005 | 0.668089 | 0.010008 | |
| 18 <> 19 | 0.000005 | 0.452897 | 0.009574 | |
| 19 <> 20 | 0.000006 | 0.850698 | 0.010345 | |
| 20 <> 21 | 0.000007 | 0.270671 | 0.012368 | |
| 21 <> 22 | 0.000005 | 0.295439 | 0.008660 | |
| 22 <> 23 | 0.000008 | 0.710938 | 0.010321 | |
| 23 <> 24 | 0.000003 | 0.269014 | 0.010238 | |
| 24 <> 25 | 0.000005 | 0.287966 | 0.009604 | |
| 25 <> 26 | 0.000009 | 0.661160 | 0.010807 | |
| 26 <> 27 | 0.000006 | 0.310515 | 0.009439 | |
| 27 <> 28 | 0.000003 | 0.346298 | 0.011302 | |
| 28 <> 29 | 0.000004 | 0.375117 | 0.008333 | |
| 29 <> 30 | 0.000006 | 1.323647 | 0.008799 | |
| 30 <> 31 | 0.000006 | 0.283616 | 0.010187 | |
| 31 <> 32 | 0.000007 | 0.649273 | 0.008613 | |
| 32 <> 33 | 0.000004 | 0.440265 | 0.010663 | |
| 33 <> Dur| 0.000004 | 0.337023 | 0.011477 | |
========================================================

计算window size

$ tshark -r rsb-single2.cap -q -z io,stat,5,”COUNT(tcp.analysis.retransmission) tcp.analysis.retransmission”,”AVG(tcp.window_size) tcp.window_size”,”MAX(tcp.window_size) tcp.window_size”,”MIN(tcp.window_size) tcp.window_size”

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
=========================================================================
| IO Statistics |
| |
| Duration: 30.776061 secs |
| Interval: 5 secs |
| |
| Col 1: COUNT(tcp.analysis.retransmission) tcp.analysis.retransmission |
| 2: AVG(tcp.window_size) tcp.window_size |
| 3: MAX(tcp.window_size) tcp.window_size |
| 4: MIN(tcp.window_size) tcp.window_size |
|-----------------------------------------------------------------------|
| |1 |2 |3 |4 | |
| Interval | COUNT | AVG | MAX | MIN | |
|------------------------------------------| |
| 0 <> 5 | 0 | 4753 | 15744 | 96 | |
| 5 <> 10 | 0 | 8067 | 431616 | 96 | |
| 10 <> 15 | 0 | 5144 | 18688 | 96 | |
| 15 <> 20 | 0 | 11225 | 611072 | 81 | |
| 20 <> 25 | 0 | 5104 | 24448 | 96 | |
| 25 <> 30 | 0 | 10103 | 506880 | 96 | |
| 30 <> Dur| 0 | 5716 | 12423 | 96 | |
=========================================================================

有用的命令(这些命令也都是安装WireShark就装好了的):

capinfos rsb2.cap

tshark -q -n -r rsb2.cap -z “conv,ip” 分析流量总况

tshark -q -n -r rsb2.cap -z “conv,tcp” 分析每一个连接的流量、rtt、响应时间、丢包率、重传率等等

editcap -c 100000 ./rsb2.cap rsb00.cap //把大文件rsb2.cap按每个文件100000个package切成小文件

常用排错过滤条件:

对于排查网络延时/应用问题有一些过滤条件是非常有用的:

  • tcp.analysis.lost_segment:表明已经在抓包中看到不连续的序列号。报文丢失会造成重复的ACK,这会导致重传。
  • tcp.analysis.duplicate_ack:显示被确认过不止一次的报文。大量的重复ACK是TCP端点之间高延时的迹象。
  • tcp.analysis.retransmission:显示抓包中的所有重传。如果重传次数不多的话还是正常的,过多重传可能有问题。这通常意味着应用性能缓慢和/或用户报文丢失。
  • tcp.analysis.window_update:将传输过程中的TCP window大小图形化。如果看到窗口大小下降为零,这意味着发送方已经退出了,并等待接收方确认所有已传送数据。这可能表明接收端已经不堪重负了。
  • tcp.analysis.bytes_in_flight:某一时间点网络上未确认字节数。未确认字节数不能超过你的TCP窗口大小(定义于最初3此TCP握手),为了最大化吞吐量你想要获得尽可能接近TCP窗口大小。如果看到连续低于TCP窗口大小,可能意味着报文丢失或路径上其他影响吞吐量的问题。
  • tcp.analysis.ack_rtt:衡量抓取的TCP报文与相应的ACK。如果这一时间间隔比较长那可能表示某种类型的网络延时(报文丢失,拥塞,等等)。

抓包常用命令

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
#tshark 解析MySQL协议
tshark -r ./mysql-compress.cap -o tcp.calculate_timestamps:true -T fields -e mysql.caps.cp -e frame.number -e frame.time_epoch -e frame.time_delta_displayed -e ip.src -e tcp.srcport -e tcp.dstport -e ip.dst -e tcp.time_delta -e frame.time_delta_displayed -e tcp.stream -e tcp.len -e mysql.query

#用tcpdump抓取并保存包:
sudo tcpdump -i eth0 port 3306 -w drds.cap

#每隔3秒钟生成一个新文件,总共生成5个文件后(15秒后)终止抓包,然后包名也按时间规范好了
sudo tcpdump -t -s 0 tcp port 3306 -w 'dump_%Y-%m-%d_%H:%M:%S.pcap' -G 3 -W 5 -Z root

#每隔30分钟��成一个包并压缩
nohup sudo tcpdump -i eth0 -t -s 0 tcp and port 3306 -w 'dump_%Y-%m-%d_%H:%M:%S.pcap' -G 1800 -W 48 -Zroot -z gzip &

#file size 1000M
nohup sudo tcpdump -i eth0 -t -s 0 tcp and port 3306 -w 'dump_' -C 1000 -W 300 -Z root -z gzip &

#抓取详细SQL语句, 快速确认client发过来的具体SQL内容:
sudo tshark -i any -f 'port 8527' -s 0 -l -w - |strings
sudo tshark -i eth0 -d tcp.port==3306,mysql -T fields -e mysql.query 'port 3306'
sudo tshark -i eth0 -R "ip.addr==11.163.182.137" -d tcp.port==3306,mysql -T fields -e mysql.query 'port 3306'
sudo tshark -i eth0 -R "tcp.srcport==62877" -d tcp.port==3001,mysql -T fields -e tcp.srcport -e mysql.query 'port 3001'

#如果RDS开启了SSL,那么抓包后的内容tshark/wireshark分析不到MySQL的具体内容,可以强制关闭:connectionProperties里加上useSSL=false

tshark -r ./manager.cap -o tcp.calculate_timestamps:true -Y " tcp.analysis.retransmission " -T fields-e tcp.stream -e frame.number -e frame.time -e ip.src -e tcp.srcport -e tcp.dstport -e ip.dst | sort

#分析MySQL rt,倒数第四列基本就是rt
tshark -r gege_drds.pcap -Y " ((tcp.srcport eq 3306 ) and tcp.len>0 )" -o tcp.calculate_timestamps:true -T fields -e frame.number -e frame.time_epoch -e frame.time_delta_displayed -e ip.src -e tcp.srcport -e tcp.dstport -e ip.dst -e tcp.time_delta -e tcp.stream -e tcp.len -e tcp.analysis.ack_rtt

#或者排序一下
tshark -r 213_php.cap -Y "mysql.query or ( tcp.srcport==3306)" -o tcp.calculate_timestamps:true -T fields -e frame.number -e frame.time_epoch -e frame.time_delta_displayed -e ip.src -e tcp.srcport -e tcp.dstport -e ip.dst -e tcp.time_delta -e tcp.stream -e tcp.len -e mysql.query |sort -nk9 -nk1

Wireshark 插件安装

1
2
3
4
5
6
7
8
9
插件是使用lua开发的,安装比较简单,以OS X平台为例:
1. 将协议解析脚本copy到/Applications/Wireshark.app/Contents/Resources/share/wireshark/ 目录
2. 编辑init.lua文件,设置disable_lua = false,确保lua支持打开
3. 在init.lua文件末尾增加
dofile("hsf2.lua")

再次启动Wireshark,会对12200端口的数据流使用脚本解析,已经可以识别HSF协议了。

补充下Windows平台下的安装,步骤类似,将hsf2.lua拷贝到wireshark的根目录,例如c:\Program Files\Wireshark\,在这个目录下也有init.lua,然后参照上面的步骤2和3。

一个案例

问题:客户现场不管怎么样增加应用机器,tps就是上不去,同时增加机器后,增加的机器CPU还都能被用完,但是tps没有变化(这点比较奇怪) 整体服务调用慢,数据库没有慢查询,不知道到具体时间花在哪里,各个环节都尝试过增加服务器(或提升配置),但是问题一直得不到解决

tshark分析抓包文件数据库服务器网卡中断瓶颈导致rtt非常高,进一步导致每个Query的ResponseTime非常高(图中左边都是出问题、右边都是问题解决后的响应时间)

下面两个图是吧tshark解析结果丢到了数据库中好用SQL可以进一步分析

image.png

** 问题修复后数据库每个查询的平均响应时间从47毫秒下降到了4.5毫秒 **

image.png

从wireshark中也可以看到类似的rtt不正常(超过150ms的比较多)

image.png

从wireshark中也可以看到类似的rtt正常(99%都在10ms以内)

image.png

tcprstat

推荐一个快速统计rt的工具tcprstat,实测在CPU打满的高压力情况下会丢失大量请求数据,但是作为统计平均值这问题不大。支持http、mysql协议等。实际测试在每秒2万个SQL的时候,对于一台4C的机器,只能采集到70%的请求。

或者看这个支持设置RT阈值的统计改进版

tcprstat 统计抓包离线文件

1
2
3
4
5
# -l 166.100.128.148  向目标端口80发起请求的地址
# -p 80 发出response端口
# -t 10 间隔10s一次汇总统计
# -f 后面的分位置可以随便指定(90%、95%、99%等)
tcprstat -r pts.pcap -p 80 -l 166.100.128.148 -t 10 -f "%T\t%n\t%M\t%m\t%a\t%h\t%S\t%95M\t%90a\t%95S\t%99M\t%99a\t%90S\n"

其它工具 packetdrill

https://github.com/google/packetdrill

https://mp.weixin.qq.com/s/CcM3rINPn54Oean144kvMw

http://beta.computer-networking.info/syllabus/default/exercises/tcp-2.html

https://segmentfault.com/a/1190000019193928

TCP性能优化大全

先从一个问题看起,客户通过专线访问云上的DRDS,专线100M,时延20ms,一个SQL查询了22M数据,结果花了大概25秒,这慢得不太正常,如果通过云上client访问云上DRDS那么1-2秒就返回了。如果通过http或者scp传输这22M的数据大概两秒钟也传送完毕了,所以这里问题的原因基本上是DRDS在这种网络条件下有性能问题,需要找出为什么。

抓包 tcpdump+wireshark

这个查询结果22M的需要25秒,如下图(wireshark 时序图),横轴是时间纵轴是sequence number:

image.png

粗一看没啥问题,把这个图形放大看看

image.png

换个角度,看看窗口尺寸图形:

image.png

从bytes in flight也大致能算出来总的传输时间 16K*1000/20=800Kb/秒

DRDS会默认设置 socketSendBuffer 为16K:

socket.setSendBufferSize(16*1024) //16K send buffer

来看一下tcp包发送流程:

(图片来自:https://www.atatech.org/articles/9032)

如果sendbuffer不够就会卡在上图中的第一步 sk_stream_wait_memory, 通过systemtap脚本可以验证:

#!/usr/bin/stap
# Simple probe to detect when a process is waiting for more socket send
# buffer memory. Usually means the process is doing writes larger than the
# socket send buffer size or there is a slow receiver at the other side.
# Increasing the socket's send buffer size might help decrease application
# latencies, but it might also make it worse, so buyer beware.
#
# Typical output: timestamp in microseconds: procname(pid) event
#
# 1218230114875167: python(17631) blocked on full send buffer
# 1218230114876196: python(17631) recovered from full send buffer
# 1218230114876271: python(17631) blocked on full send buffer
# 1218230114876479: python(17631) recovered from full send buffer

probe kernel.function("sk_stream_wait_memory")
{
	printf("%u: %s(%d) blocked on full send buffer\n",
		gettimeofday_us(), execname(), pid())
}

probe kernel.function("sk_stream_wait_memory").return
{
	printf("%u: %s(%d) recovered from full send buffer\n",
		gettimeofday_us(), execname(), pid())
}

如果tcp发送buffer也就是SO_SNDBUF只有16K的话,这些包很快都发出去了,但是这16K不能立即释放出来填新的内容进去,因为tcp要保证可靠,万一中间丢包了呢。只有等到这16K中的某些ack了,才会填充一些进来然后继续发出去。由于这里rt基本是20ms,也就是16K发送完毕后,等了20ms才收到一些ack,这20ms应用、内核什么都不能做,所以就是如第二个图中的大概20ms的等待平台。这块请参考这篇文章

sendbuffer相当于发送仓库的大小,仓库的货物都发走后,不能立马腾出来发新的货物,而是要等发走的获取对方确认收到了(ack)才能腾出来发新的货物, 仓库足够大了之后接下来的瓶颈就是高速公路了(带宽、拥塞窗口)

如果是UDP,就没有send buffer的概念,有数据统统发出去,根本不关心对方是否收到。

几个发送buf相关的内核参数

vm.lowmem_reserve_ratio = 256   256     32
net.core.wmem_max = 1048576
net.core.wmem_default = 124928
net.ipv4.tcp_wmem = 4096        16384   4194304
net.ipv4.udp_wmem_min = 4096

net.ipv4.tcp_wmem 默认就是16K,而且是能够动态调整的,只不过我们代码中这块的参数是很多年前从Corba中继承过来的,一直没有修改。代码中设置了这个参数后就关闭了内核的动态调整功能,所以能看到http或者scp都很快。

接收buffer是有开关可以动态控制的,发送buffer没有开关默认就是开启,关闭只能在代码层面来控制

net.ipv4.tcp_moderate_rcvbuf

优化

调整 socketSendBuffer 到256K,查询时间从25秒下降到了4秒多,但是比理论带宽所需要的时间略高

继续查看系统 net.core.wmem_max 参数默认最大是130K,所以即使我们代码中设置256K实际使用的也是130K,调大这个系统参数后整个网络传输时间大概2秒(跟100M带宽匹配了,scp传输22M数据也要2秒),整体查询时间2.8秒。测试用的mysql client短连接,如果代码中的是长连接的话会块300-400ms(消掉了慢启动阶段),这基本上是理论上最快速度了

image.png

如果指定了tcp_wmem,则net.core.wmem_default被tcp_wmem的覆盖。send Buffer在tcp_wmem的最小值和最大值之间自动调节。如果调用setsockopt()设置了socket选项SO_SNDBUF,将关闭发送端缓冲的自动调节机制,tcp_wmem将被忽略,SO_SNDBUF的最大值由net.core.wmem_max限制。

BDP 带宽时延积

这个buf调到1M测试没有帮助,从理论计算BDP(带宽时延积) 0.02秒*(100MB/8)=250Kb 所以SO_SNDBUF为256Kb的时候基本能跑满带宽了,再大实际意义也不大了。

因为BDP是250K,也就是拥塞窗口即将成为新的瓶颈,所以调大buffer没意义了。

用tc构造延时和带宽限制的模拟重现环境

sudo tc qdisc del dev eth0 root netem delay 20ms
sudo tc qdisc add dev eth0 root tbf rate 500kbit latency 50ms burst 15kb

这个案例的结论

默认情况下Linux系统会自动调整这个buf(net.ipv4.tcp_wmem), 也就是不推荐程序中主动去设置SO_SNDBUF,除非明确知道设置的值是最优的。

平时看到的一些理论在实践中用起来比较难,最开始看到抓包结果的时候比较怀疑发送、接收窗口之类的,没有直接想到send buffer上,理论跟实践的鸿沟

需要调整tcp_rmem 的问题 Case

发送和接收Buffer对性能的完整影响参考这篇

总结下TCP跟速度相关的几个概念

  • CWND:Congestion Window,拥塞窗口,负责控制单位时间内,数据发送端的报文发送量。TCP 协议规定,一个 RTT(Round-Trip Time,往返时延,大家常说的 ping 值)时间内,数据发送端只能发送 CWND 个数据包(注意不是字节数)。TCP 协议利用 CWND/RTT 来控制速度。这个值是根据丢包动态计算出来的
  • SS:Slow Start,慢启动阶段。TCP 刚开始传输的时候,速度是慢慢涨起来的,除非遇到丢包,否则速度会一直指数性增长(标准 TCP 协议的拥塞控制算法,例如 cubic 就是如此。很多其它拥塞控制算法或其它厂商可能修改过慢启动增长特性,未必符合指数特性)。
  • CA:Congestion Avoid,拥塞避免阶段。当 TCP 数据发送方感知到有丢包后,会降低 CWND,此时速度会下降,CWND 再次增长时,不再像 SS 那样指数增,而是线性增(同理,标准 TCP 协议的拥塞控制算法,例如 cubic 是这样,很多其它拥塞控制算法或其它厂商可能修改过慢启动增长特性,未必符合这个特性)。
  • ssthresh:Slow Start Threshold,慢启动阈值。当数据发送方感知到丢包时,会记录此时的 CWND,并计算合理的 ssthresh 值(ssthresh <= 丢包时的 CWND),当 CWND 重新由小至大增长,直到 sshtresh 时,不再 SS 而是 CA。但因为数据确认超时(数据发送端始终收不到对端的接收确认报文),发送端会骤降 CWND 到最初始的状态。
  • SO_SNDBUF、SO_RCVBUF 发送、接收buffer

image.png

上图一旦发生丢包,cwnd降到1 ssthresh降到cwnd/2,一夜回到解放前,太保守了,实际大多情况下都是公网带宽还有空余但是链路过长,非带宽不够丢包概率增大,对此没必要这么保守(tcp诞生的背景主要针对局域网、双绞线来设计,偏保守)。RTT越大的网络环境(长肥管道)这个问题越是严重,表现就是传输速度抖动非常厉害。

所以改进的拥塞算法一旦发现丢包,cwnd和ssthresh降到原来的cwnd的一半。

image.png

TCP性能优化点

  • 建连优化:TCP 在建立连接时,如果丢包,会进入重试,重试时间是 1s、2s、4s、8s 的指数递增间隔,缩短定时器可以让 TCP 在丢包环境建连时间更快,非常适用于高并发短连接的业务场景。
  • 首包优化:此优化其实没什么实质意义,若要说一定会有意义的话,可能就是满足一些评测标准的需要吧,例如有些客户以首包时间作为性能评判的一个依据。所谓首包时间,简单解释就是从 HTTP Client 发出 GET 请求开始计时,到收到 HTTP 响应的时间。为此,Server 端可以通过 TCP_NODELAY 让服务器先吐出 HTTP 头,再吐出实际内容(分包发送,原本是粘到一起的),来进行提速和优化。据说更有甚者先让服务器无条件返回 “HTTP/“ 这几个字符,然后再去 upstream 拿数据。这种做法在真实场景中没有任何帮助,只能欺骗一下探测者罢了,因此还没见过有直接发 “HTTP/“ 的,其实是一种作弊行为。

image.png

  • 平滑发包:如前文所述,在 RTT 内均匀发包,规避微分时间内的流量突发,尽量避免瞬间拥塞,此处不再赘述。
  • 丢包预判:有些网络的丢包是有规律性的,例如每隔一段时间出现一次丢包,例如每次丢包都连续丢几个等,如果程序能自动发现这个规律(有些不明显),就可以针对性提前多发数据,减少重传时间、提高有效发包率。
  • RTO 探测:如前文讲 TCP 基础时说过的,若始终收不到 ACK 报文,则需要触发 RTO 定时器。RTO 定时器一般都时间非常长,会浪费很多等待时间,而且一旦 RTO,CWND 就会骤降(标准 TCP),因此利用 Probe 提前与 RTO 去试探,可以规避由于 ACK 报文丢失而导致的速度下降问题。
  • 带宽评估:通过单位时间内收到的 ACK 或 SACK 信息可以得知客户端有效接收速率,通过这个速率可以更合理的控制发包速度。
  • 带宽争抢:有些场景(例如合租)是大家互相挤占带宽的,假如你和室友各 1Mbps 的速度看电影,会把 2Mbps 出口占满,而如果一共有 3 个人看,则每人只能分到 1/3。若此时你的流量流量达到 2Mbps,而他俩还都是 1Mbps,则你至少仍可以分到 2/(2+1+1) * 2Mbps = 1Mbps 的 50% 的带宽,甚至更多,代价就是服务器侧的出口流量加大,增加成本。(TCP 优化的本质就是用带宽换用户体验感)
  • 链路质量记忆(后面有反面案例):如果一个 Client IP 或一个 C 段 Network,若已经得知了网络质量规律(例如 CWND 多大合适,丢包规律是怎样的等),就可以在下次连接时,优先使用历史经验值,取消慢启动环节直接进入告诉发包状态,以提升客户端接收数据速率。

image.png

这些经验都来自CDN @辟拾 的 网络优化 - TCP 是如何做到提速 20 倍的

重要参数

net.ipv4.tcp_slow_start_after_idle

内核协议栈参数 net.ipv4.tcp_slow_start_after_idle 默认是开启的,这个参数的用途,是为了规避 CWND 无休止增长,因此在连接不断开,但一段时间不传输数据的话,就将 CWND 收敛到 initcwnd,kernel-2.6.32 是 10,kernel-2.6.18 是 2。因此在 HTTP Connection: keep-alive 的环境下,若连续两个 GET 请求之间存在一定时间间隔,则此时服务器端会降低 CWND 到初始值,当 Client 再次发起 GET 后,服务器会重新进入慢启动流程

RFC2414中关于拥塞窗口初始化的3个场景:

TCP implementations use slow start in as many as three different ways:

(1) to start a new connection (the initial window);

(2) to restart a transmission after a long idle period (the restart window); and

(3) to restart after a retransmit timeout (the loss window).

这种友善的保护机制,但是对于目前的网络坏境没必要这么谨慎和彬彬有礼,建议将此功能关闭,以提高长连接环境下的用户体验感。

 sysctl net.ipv4.tcp_slow_start_after_idle=0

确认运行中每个连接 CWND/ssthresh(slow start threshold)

$ss -itn dst  11.163.187.32 |grep -v "Address:Port" | xargs -L 1 | grep ssthresh
ESTAB 0 0 11.163.187.33:33833 11.163.187.32:2181 cubic wscale:7,7 rto:201 rtt:0.16/0.186 ato:40 mss:1448 cwnd:10 ssthresh:7 send 724.0Mbps lastsnd:2813 lastrcv:2813 lastack:2813 pacing_rate 1445.7Mbps rcv_rtt:52081.5 rcv_space:29344
ESTAB 0 0 11.163.187.33:2376 11.163.187.32:46793 cubic wscale:7,7 rto:201 rtt:0.169/0.137 ato:40 mss:1448 cwnd:59 ssthresh:48 send 4044.1Mbps lastsnd:334 lastrcv:409 lastack:334 pacing_rate 8052.5Mbps retrans:0/759 reordering:34 rcv_rtt:50178 rcv_space:137603
ESTAB 0 0 11.163.187.33:33829 11.163.187.32:2181 cubic wscale:7,7 rto:201 rtt:0.065/0.002 ato:40 mss:1448 cwnd:10 ssthresh:7 send 1782.2Mbps lastsnd:2825 lastrcv:2825 lastack:2825 pacing_rate 3550.7Mbps rcv_rtt:51495.8 rcv_space:29344
ESTAB 0 0 11.163.187.33:33828 11.163.187.32:2181 cubic wscale:7,7 rto:201 rtt:0.113/0.061 ato:40 mss:1448 cwnd:10 ssthresh:7 send 1025.1Mbps lastsnd:2826 lastrcv:2826 lastack:2826 pacing_rate 2043.5Mbps rcv_rtt:54801.8 rcv_space:29344
ESTAB 0 0 11.163.187.33:2376 11.163.187.32:47047 cubic wscale:7,7 rto:206 rtt:5.977/9.1 ato:40 mss:1448 cwnd:10 ssthresh:51 send 19.4Mbps lastsnd:522150903 lastrcv:522150906 lastack:522150903 pacing_rate 38.8Mbps retrans:0/44 reordering:31 rcv_rtt:86067 rcv_space:321882
ESTAB 0 0 11.163.187.33:2376 11.163.187.32:46789 cubic wscale:7,7 rto:201 rtt:0.045/0.003 ato:40 mss:1448 cwnd:10 ssthresh:9 send 2574.2Mbps lastsnd:522035639 lastrcv:1589957951 lastack:522035639 pacing_rate 5077.9Mbps retrans:0/12 reordering:20 rcv_space:28960
ESTAB 0 0 11.163.187.33:33831 11.163.187.32:2181 cubic wscale:7,7 rto:201 rtt:0.071/0.01 ato:40 mss:1448 cwnd:10 ssthresh:7 send 1631.5Mbps lastsnd:2825 lastrcv:2825 lastack:2825 pacing_rate 3263.1Mbps rcv_rtt:54805.8 rcv_space:29344

从系统cache中查看 tcp_metrics item

$sudo ip tcp_metrics show | grep  100.118.58.7
100.118.58.7 age 1457674.290sec tw_ts 3195267888/5752641sec ago rtt 1000us rttvar 1000us ssthresh 361 cwnd 40 metric_5 8710 metric_6 4258

如果因为之前的网络状况等其它原因导致tcp_metrics缓存了一个非常小的ssthresh(这个值默应该非常大),ssthresh太小的话tcp的CWND指数增长阶段很快就结束,然后进入CWND+1的慢增加阶段导致整个速度感觉很慢

清除 tcp_metrics 
sudo ip tcp_metrics flush all 

关闭 tcp_metrics 功能
net.ipv4.tcp_no_metrics_save = 1
sudo ip tcp_metrics delete 100.118.58.7

tcp_metrics会记录下之前已关闭TCP连接的状态,包括发送端CWND和ssthresh,如果之前网络有一段时间比较差或者丢包比较严重,就会导致TCP的ssthresh降低到一个很低的值,这个值在连接结束后会被tcp_metrics cache 住,在新连接建立时,即使网络状况已经恢复,依然会继承 tcp_metrics 中cache 的一个很低的ssthresh 值,对于rt很高的网络环境,新连接经历短暂的“慢启动”后(ssthresh太小),随即进入缓慢的拥塞控制阶段(rt太高,CWND增长太慢),导致连接速度很难在短时间内上去。而后面的连接,需要很特殊的场景之下(比如,传输一个很大的文件)才能将ssthresh 再次推到一个比较高的值更新掉之前的缓存值,因此很有很能在接下来的很长一段时间,连接的速度都会处于一个很低的水平。

ssthresh 是如何降低的

在网络情况较差,并且出现连续dup ack情况下,ssthresh 会设置为 cwnd/2, cwnd 设置为当前值的一半,
如果网络持续比较差那么ssthresh 会持续降低到一个比较低的水平,并在此连接结束后被tcp_metrics 缓存下来。下次新建连接后会使用这些值,即使当前网络状况已经恢复,但是ssthresh 依然继承一个比较低的值。

ssthresh 降低后为何长时间不恢复正常

ssthresh 降低之后需要在检测到有丢包的之后才会变动,因此就需要机缘巧合才会增长到一个比较大的值。
此时需要有一个持续时间比较长的请求,在长时间进行拥塞避免之后在cwnd 加到一个比较大的值,而到一个比较
大的值之后需要有因dup ack 检测出来的丢包行为将 ssthresh 设置为 cwnd/2, 当这个连接结束后,一个
较大的ssthresh 值会被缓存下来,供下次新建连接使用。

也就是如果ssthresh 降低之后,需要传一个非常大的文件,并且网络状况超级好一直不丢包,这样能让CWND一直慢慢稳定增长,一直到CWND达到带宽的限制后出现丢包,这个时候CWND和ssthresh降到CWND的一半那么新的比较大的ssthresh值就能被缓存下来了。

tcp windows scale

网络传输速度:单位时间内(一个 RTT)发送量(再折算到每秒),不是 CWND(Congestion Window 拥塞窗口),而是 min(CWND, RWND)。除了数据发送端有个 CWND 以外,数据接收端还有个 RWND(Receive Window,接收窗口)。在带宽不是瓶颈的情况下,单连接上的速度极限为 MIN(cwnd, slide_windows)*1000ms/rt

tcp windows scale用来协商RWND的大小,它在tcp协议中占16个位,如果通讯双方有一方不支持tcp windows scale的话,TCP Windows size 最大只能到2^16 = 65535 也就是64k

如果网络rt是35ms,滑动窗口<CWND,那么单连接的传输速度最大是: 64K*1000/35=1792K(1.8M)

如果网络rt是30ms,滑动窗口>CWND的话,传输速度:CWND*1500(MTU)*1000(ms)/rt

一般通讯双方都是支持tcp windows scale的,但是如果连接中间通过了lvs,并且lvs打开了 synproxy功能的话,就会导致 tcp windows scale 无法起作用,那么传输速度就被滑动窗口限制死了(rt小的话会没那么明显)。

RTT越大,传输速度越慢

RTT大的话导致拥塞窗口爬升缓慢,慢启动过程持续越久。RTT越大、物理带宽越大、要传输的文件越大这个问题越明显
带宽B越大,RTT越大,低带宽利用率持续的时间就越久,文件传输的总时间就会越长,这是TCP慢启动的本质决定的,这是探测的代价。
TCP的拥塞窗口变化完全受ACK时间驱动(RTT),长肥管道对丢包更敏感,RTT越大越敏感,一旦有一个丢包就会将CWND减半进入避免拥塞阶段

RTT对性能的影响关键是RTT长了后丢包的概率大,一旦丢包进入拥塞阶段就很慢了。如果一直不丢包,只是RTT长,完全可以做大增加发送窗口和接收窗口来抵消RTT的增加

以上经验来自 tcp metrics 在长肥网络下引发性能问题

经典的 nagle 和 dalay ack对性能的影响

请参考这篇文章:就是要你懂 TCP– 最经典的TCP性能问题

最后的经验

抓包解千愁


就是要你懂TCP相关文章:

关于TCP 半连接队列和全连接队列

MSS和MTU导致的悲剧

双11通过网络优化提升10倍性能

就是要你懂TCP的握手和挥手

参考文章:

https://access.redhat.com/solutions/407743

http://www.stuartcheshire.org/papers/nagledelayedack/

https://en.wikipedia.org/wiki/Nagle%27s_algorithm

https://en.wikipedia.org/wiki/TCP_delayed_acknowledgment

https://www.kernel.org/doc/Documentation/networking/ip-sysctl.txt

https://www.atatech.org/articles/109721

https://www.atatech.org/articles/109967

https://www.atatech.org/articles/27189

https://www.atatech.org/articles/45084

https://www.atatech.org/articles/9032

tcp_rmem case

高性能网络编程7–tcp连接的内存使用

基础知识的力量–lvs和转发模式

本文希望阐述清楚LVS的各种转发模式,以及他们的工作流程和优缺点,同时从网络包的流转原理上解释清楚优缺点的来由,并结合阿里云的slb来说明优缺点。

大家都背过LVS的几种转发模式,DR模式性能最好但是部署不灵活;NAT性能差部署灵活多了…… 实际都是没理解好这几个模式背后代表的网络连通性的原理和网络包路由原理,导致大多时候都是死背那几个概念。

如果我们能从网络包背后流转的流程和原理来看LVS的转发模式,那么那些优缺点简直就太直白了,这就是基础知识的力量。

如果对网络包是怎么流转的不太清楚,推荐先看这篇基础:程序员的网络知识 – 一个网络包的旅程 ,对后面理解LVS的各个转发模式非常有帮助。

几个术语和缩写

cip:Client IP,客户端地址
vip:Virtual IP,LVS实例IP
rip:Real IP,后端RS地址
RS: Real Server 后端真正提供服务的机器
LB: Load Balance 负载均衡器
LVS: Linux Virtual Server
sip: source ip
dip: destination

LVS的几种转发模式

  • DR模型 – (Director Routing-直接路由)
  • NAT模型 – (NetWork Address Translation-网络地址转换)
  • fullNAT – (full NAT)
  • ENAT – (enhence NAT 或者叫三角模式/DNAT,阿里云提供)
  • IP TUN模型 – (IP Tunneling - IP隧道)

DR模型(Director Routing–直接路由)

image.png

如上图所示基本流程(假设 cip 是200.200.200.2, vip是200.200.200.1):

  1. 请求流量(sip 200.200.200.2, dip 200.200.200.1) 先到达 LVS(图中Director)
  2. 然后LVS,根据负载策略挑选众多 RS中的一个,然后将这个网络包的MAC地址修改成这个选中的RS的MAC
  3. 然后丢给Director,Director将这个包丢给选中的RS
  4. 选中的RS看到MAC地址是自己的、dip也是自己的,愉快地收下并处理、回复
  5. 回复包(sip 200.200.200.1, dip 200.200.200.2)
  6. 经过交换机直接回复给client了(不再走LVS)

我们看到上面流程,请求包到达LVS后,LVS只对包的目的MAC地址作了修改,回复包直接回给了client。

同时要求多个RS和LVS(Director)都配置的是同一个IP地址,但是用的不同的MAC。这就要求所有RS和LVS在同一个子网,在二层路由不需要IP,他们又在同一个子网,所以这里联通性没问题。

RS上会将vip配置在lo回环网卡上,同时route中添加相应的规则,这样在第四步收到的包能被os正常处理。

image.png

优点:

  • DR模式是性能最好的一种模式,入站请求走LVS,回复报文绕过LVS直接发给Client

缺点:

  • 要求LVS和rs在同一个子网,扩展性不够好;
  • RS需要配置vip同时特殊处理arp;
  • 配置比较复杂;
  • 不支持端口映射。

为什么要求LVS和RS在同一个vlan(或者说同一个二层网络里)

因为DR模式依赖多个RS和LVS共用同一个VIP,然后依据MAC地址来在LVS和多个RS之间路由,所以LVS和RS必须在一个vlan或者说同一个二层网络里

DR 模式为什么性能最好

因为回复包不走LVS了,大部分情况下都是请求包小,回复包大,LVS很容易成为流量瓶颈,同时LVS只需要修改进来的包的MAC地址。

DR 模式为什么回包不需要走LVS了

因为RS和LVS共享同一个vip,回复的时候RS能正确地填好sip为vip,不再需要LVS来多修改一次(后面讲的NAT、Full NAT都需要)

总结下 DR的结构

image.png

绿色是请求包进来,红色是修改过MAC的请求包,SW是一个交换机。

NAT模型(NetWork Address Translation - 网络地址转换)

nat模式的结构图如下:

image.png

基本流程:

  1. client发出请求(sip 200.200.200.2,dip 200.200.200.1)
  2. 请求包到达LVS(图中Director),LVS修改请求包为(sip 200.200.200.2, dip rip)
  3. 请求包到达rs, rs回复(sip rip,dip 200.200.200.2)
  4. 这个回复包不能直接给client,因为rip不是VIP会被reset掉(client看到的连接是vip,突然来一个rip就reset)
  5. 但是因为lvs是网关,所以这个回复包先走到网关,网关有机会修改sip
  6. 网关修改sip为VIP,修改后的回复包(sip 200.200.200.1,dip 200.200.200.2)发给client

image.png

优点:

  • 配置简单
  • 支持端口映射(看名字就知道)
  • RIP一般是私有地址,主要用户LVS和RS之间通信

缺点:

  • LVS和所有RS必须在同一个vlan
  • 进出流量都要走LVS转发
  • LVS容易成为瓶颈
  • 一般而言需要将VIP配置成RS的网关

为什么NAT要求lvs和RS在同一个vlan

因为回复包必须经过lvs再次修改sip为vip,client才认,如果回复包的sip不是client包请求的dip(也就是vip),那么这个连接会被reset掉。如果LVS不是网关,因为回复包的dip是cip,那么可能从其它路由就走了,LVS没有机会修改回复包的sip

总结下NAT结构

image.png

注意这里LVS修改进出包的(sip, dip)的时候只改了其中一个,所以才有接下来的full NAT。当然NAT最大的缺点是要求LVS和RS必须在同一个vlan,这样限制了LVS集群和RS集群的部署灵活性,尤其是在阿里云这种对外售卖的公有云环境下,NAT基本不实用。

full NAT模型(full NetWork Address Translation-全部网络地址转换)

基本流程(类似NAT):

  1. client发出请求(sip 200.200.200.2 dip 200.200.200.1)
  2. 请求包到达lvs,lvs修改请求包为**(sip 200.200.200.1, dip rip)** 注意这里sip/dip都被修改了
  3. 请求包到达rs, rs回复(sip rip,dip 200.200.200.1)
  4. 这个回复包的目的IP是VIP(不像NAT中是 cip),所以LVS和RS不在一个vlan通过IP路由也能到达lvs
  5. lvs修改sip为vip, dip为cip,修改后的回复包(sip 200.200.200.1,dip 200.200.200.2)发给client

优点:

  • 解决了NAT对LVS和RS要求在同一个vlan的问题,适用更复杂的部署形式

缺点:

  • RS看不到cip(NAT模式下可以看到)
  • 进出流量还是都走的lvs,容易成为瓶颈(跟NAT一样都有这个问题)

为什么full NAT解决了NAT中要求的LVS和RS必须在同一个vlan的问题

因为LVS修改进来的包的时候把(sip, dip)都修改了(这也是full的主要含义吧),RS的回复包目的地址是vip(NAT中是cip),所以只要vip和rs之间三层可通就行,这样LVS和RS可以在不同的vlan了,也就是LVS不再要求是网关,从而LVS和RS可以在更复杂的网络环境下部署。

为什么full NAT后RS看不见cip了

因为cip被修改掉了,RS只能看到LVS的vip,在阿里内部会将cip放入TCP包的Option中传递给RS,RS上一般部署自己写的 toa(Tcp Option as Address)模块来从Options中读取的cip,这样RS能看到cip了, 当然这不是一个开源的通用方案。

总结下full NAT的结构

image.png

注意上图中绿色的进包和红色的出包他们的地址变化

那么到现在full NAT解决了NAT的同vlan的要求,基本上可以用于公有云了,但是还是没解决进出流量都走LVS的问题(LVS要修改进出的包)。

比较下NAT和Full NAT

两者进出都要走LVS,NAT必须要求vip是RS的网关,这个限制在公有云这种应用场景下不能忍,于是Full NAT通过修改请求包的source ip,将原来的source ip从cip改成vip,这样RS回复的时候回复包的目标IP也是vip,所以LVS和RS之间不再要求是同一vlan的关系了。当然带来了新的问题,RS看不见cip了(这个可以通过自定义的vtoa模块来复原)

那么有没有一个方案能够像full NAT一样不限制lvs和RS之间的网络关系,同时出去的流量跟DR模式一样也不走LVS呢?

比较下DR、NAT和Full NAT

DR只修改目标Mac地址;
NAT只修改目标IP,LVS做网关得到修改回包的机会,RS能看到client ip;
Full-NAT同时修改 源ip和 目标ip, LVS通过三层路由和RS相通,RS看到的源ip是LVS IP。

阿里云的ENAT模式(enhence NAT) 或者叫 三角模式

前后端都是经典类型,属于NAT模式的特例,LVS转发给RS报文的源地址是客户端的源地址。

与NAT模式的差异在于 RS响应客户端的报文不再经过LVS机器,而是直接发送给客户端(源地址是VIP的地址, 后端RS需要加载一个ctk模块, lsmod | grep ctk 确认 ,主要是数据库产品使用)

优点:

  • 不要求LVS和RS在同一个vlan
  • 出去的流量不需要走LVS,性能好

缺点:

  • 阿里集团内部实现的自定义方案,需要在所有RS上安装ctk组件(类似full NAT中的vtoa)

基本流程:

  1. client发出请求(cip,vip)
  2. 请求包到达lvs,lvs修改请求包为(vip,rip),并将cip放入TCP Option中
  3. 请求包根据ip路由到达rs, ctk模块读取TCP Option中的cip
  4. 回复包(RIP, vip)被ctk模块截获,并将回复包改写为(vip, cip)
  5. 因为回复包的目的地址是cip所以不需要经过lvs,可以直接发给client

ENAT模式在内部也会被称为 三角模式或者DNAT/SNAT模式

为什么ENAT的回复包不需要走回LVS了

因为之前full NAT模式下要走回去是需要LVS 再次改写回复包的IP,而ENAT模式下,这件事情在RS上被ctk模块提前做掉了

为什么ENAT的LVS和RS可以在不同的vlan

跟full NAT一样

总结下 ENAT的结构

image.png

最后说一下不太常用的 TUN模型

IP TUN模型(IP Tunneling - IP隧道)

基本流程:

  1. 请求包到达LVS后,LVS将请求包封装成一个新的IP报文
  2. 新的IP包的目的IP是某一RS的IP,然后转发给RS
  3. RS收到报文后IPIP内核模块解封装,取出用户的请求报文
  4. 发现目的IP是VIP,而自己的tunl0网卡上配置了这个IP,从而愉快地处理请求并将结果直接发送给客户

优点:

  • 集群节点可以跨vlan
  • 跟DR一样,响应报文直接发给client

缺点:

  • RS上必须安装运行IPIP模块
  • 多增加了一个IP头
  • LVS和RS上的tunl0虚拟网卡上配置同一个VIP(类似DR)

DR模式中LVS修改的是目的MAC

为什么IP TUN不要求同一个vlan

因为IP TUN中不是修改MAC来路由,所以不要求同一个vlan,只要求lvs和rs之间ip能通就行。DR模式要求的是lvs和RS之间广播能通

IP TUN性能

回包不走LVS,但是多做了一次封包解包,不如DR好

总结下 IP TUN的结构

image.png

图中红线是再次封装过的包,ipip是操作系统的一个内核模块。

DR可能在小公司用的比较多,IP TUN用的少一些,相对而言NAT、FullNAT、ENAT这三种在集团内部比较类似,用的也比较多,他们之间的可比较性很强,所以放在一块了。

阿里云 SLB 的 FNAT

本质就是前面所讲的 fullnat模式,为了解决RS看不到真正的client ip问题,在阿里云公网上的物理机/宿主机默认都会帮你将source-ip(本来是lvs ip)替换成真正的client ip,这样当包进到ecs的时候source ip已经是client ip了,所以slb默认的fnat模式会让你直接能拿到client ip。回包依然会经过lvs(虽然理论上可以不需要了,但是要考虑rs和client不能直接通,以及管理方便等)

这个进出的替换过程在物理机/宿主机上是avs来做,如果没有avs就得安装slb的toa模块来做了。

这就是为什么slb比直接用lvs要方便些,也就是云服务商提供这种云产品的价值所在。

但是进出流量都走lvs,导致lvs流量过大,大象流容易打挂单core(目前限制单流不超过5GB),时延有所增加

所以推出NGLB来解决这个问题

阿里云的NGLB

下一代负载均衡,只有首包经过slb节点,后续client和RS直接通信,只支持RS是物理机的场景。这个模块slb基本没有负载,性能最好。

NGLB_pic.png

SLB模块简介

  1. toa模块主要用在Classic网络SLB/ALB的FNAT场景下后端RS(NC)获取实际Client端的真实地址和端口(FNAT模式下SLB/ALB发送给后端RS的报文中源IP已经被替换为SLB/ALB的localIP,将ClientIP[后续简写为cip]通过tcp option携带到RS),用户通过特定getpeername接口获取cip。toa模块已经内置到ali内核版本中,无需再单独安装(见/lib/modules/uname -r/kernel/net/toa/toa.ko)。
  2. vtoa模块属于增强版toa,同时支持VPC网络和Classic网络SLB/ALB的FNAT场景下后端RS获取实际客户端的真实地址和端口(FNAT模式下SLB/ALB发送给后端RS的报文中源IP已经被替换为SLB/ALB的localIP,将cip通过tcp option携带到RS),用户通过特定getsockopt接口获取vid:vip:vport和cip:cport,兼容toa接口。
  3. ctk: 包括ALB_ctk_debugfs.ko,ALB_ctk_session.ko,ALB_ctk_proxy.ko模块。ctk是一个NAT模块,对于ENAT场景,从ALB过来的带tcp option的tcp流量(cip:cport<->rip:rport带vip:vport opt)做了DNAT和反向DNAT转换,使得到上层应用层时看到的流被恢复为原始形态(cip:cport<->vip:vport)
  4. vctk:VPC NGLB模式下,只有建立TCP连接的首包(SYN包)经过ALB转发,后端vctk做Local的SNAT(避免VPC间地址冲突)和DNAT, 返回包做反向SNAT和DNAT转换,再做VXLAN封装,直接返回Source NC。

!!注意:一般来说,ctk与toa/vtoa模块不同时使用,toa和vtoa不同时使用:

vtoa模块的功能是toa模块的超集,也就是说toa提供的功能在vtoa模块中都是提供的,并且接口,功能都是保持不变的。所以加载了vtoa之后,就不需要加载toa模块,如果加载了vtoa后再加载toa,获取vpcid以及cip/vip可能失败。

当toa/vtoa单独工作时,toa/vtoa模块工作在tcp层,通过修改内核把tcp opt中的cip,rip保存在sock结构中,并通过getpeername/getsockname系统接口给用户提供服务。

如果同时加载ctk和toa/vtoa模块,FNAT场景下ctk不起作用;ENAT场景下, 因ctk工作在IP层(NAT),tcp opt先被ctk处理并去除并保存在session中,vtoa接口依赖ctk的session获取toa/vtoa信息。

阿里云 SLB 的双机房高可用

主备模式,备用机房没有流量。

SLB 的双机房容灾主要通过lvs机器和网络设备lsw之间通过动态路由协议(OSPF、ECMP、BGP)发布大小段路由实现主备机房容灾,40G集群采用bgp协议(10G集群采用ospf协议)。

案例

主机房通过bgp协议发送 /27 的路由到lsw,csr,备机房发布 /26 路由到lsw, csr。

正常情况下,如果应用访问192.168.0.2的话,路由器会选择掩码最长的路由为最佳路由,获选进入路由表,也就是会选择192.168.0.1/27这条路由。从而实现流量主要在主机房,备机房冷备的效果。
当主机房发生故障,仅当主机房所有lvs机器都不能提供服务,即ABTN中无法收到主机房的/27明细路由时,流量才会发生主备切换,切换到备机房,实现主备机房容灾。

image.png

LVS节点之间的均衡

内核版的lvs 最开始就采用集群化的部署,每个group 4台lvs 机器,支持group 级别横向扩展。使用ospf 作为引流方式。每台lvs机器有两块10G 网卡T1、T2口,分别上联lsw1 和 lsw2,通过ospf 动态路由协议与lsw 之间建立邻居关系,四台lvs机器发布相同的network 给lsw,实现流量转发的ecmp。lsw 打开multicast 以支持4台lvs机器之间的session 同步。通过session 同步保证当单台lvs机器宕机或者下线时,长连接 rehash 到其他lvs 机器时能够继续转发而不产生中断。

LVS节点单机高可用

每台lvs机器有两块10G网卡,每块网卡上联一台lsw,单机双上联容灾;

LVS Group

每个lvs_group 4台lvs 机器,同group机器提供对等服务,同时4台lvs机器之间有实时的session 同步,发生单机宕机的场景,流量会均摊到同组其他lvs机器上,长连接可以保持不断;

一些数据

内核版的lvs只支持10G带宽,采用dpdk后能支持25、40G带宽。

dpdk基于内核的uio机制,提供了PMD(Poll Mode Driver)的收包模式,uio旁路了内核,主动轮询去掉硬中断,DPDK从而可以在用户态做收发包处理。带来Zero Copy、无系统调用的好处,同步处理减少上下文切换带来的Cache Miss。

另外dpdk也采用了hugepage,LVS使用单页内存1G,基本上避免了TLB MISS,对于LVS这种内存大户来说,对性能提升非常有利。并且dpdk提供了一系列高质量的基础库比如内存池(Mempool)、MBuf、无锁环(Ring),便于开发者迅速构建自己的包转发平台。

性能优化

LVS侧针对内存的访问所做的优化如下:

1.session/svc 数据结构调整 热点字段聚集到同个cache line

2.结合性能测试数据,调整session的prefecth

3.消除false sharing。

目前LVS 40G机型,单机4块 40G网卡。

平均包长1k的情况下能跑满4个网口(160G)

64bytes小包的转发pps为4200W,kernel版本为1000W。

限流对性能的影响

通过令牌桶限流的话令牌桶加锁就是瓶颈

lvs的优化方案为大小桶算法:

per core维护一个小的令牌桶,当小桶中的令牌取完之后,才会加锁从大桶中获取,如果大桶中也拿不到令牌,本周期(令牌更新间隔)内也不会再次访问大桶。

从而去除每包必须加锁访问令牌桶,降低中心化限速对性能的影响。

单流瓶颈

四层负载均衡lvs作为阿里云的核心产品已经走过了10个年头,在这期间lvs不断的进行技术的革新和演进,从最初的单机10g内核版本、10g用户态到现在主流的线上40g的版本,机器的带宽越来越大,cpu核数越来越多处理能力也越来越强,但存在一个问题一直没有解,对于同一条流会hash分到同一个cpu上,如果是单流的流量比较大超过lvs单核的处理能力,就会导致lvs的单cpu使用率飙高从而导致丢包。mellnex cx5 100g网卡平台提供了流offload的能力,lvs基于该硬件的特性开发了offload的功能,可以将大象流offload到网卡中防止单流消耗cpu的性能。

经测试offload后最高性能单卡单流可以达到2800wpps,具备应对大象流的能力。

经过十年来的不断演进,目前SLB四层监听的单LVS集群,已经可以达到PPS 4亿,网卡单向带宽1.6T,单集群新建连接8000w,并发13.4亿以及Offload单流2800万PPS的处理能力。

参考资料

LVS 20倍的负载不均衡,原来是内核的这个Bug

章文嵩(正明)博士和他背后的负载均衡(LOAD BANLANCER)帝国

https://yizhi.ren/2019/05/03/lvs/

一文搞懂域名解析DNS相关问题

本文希望通过一篇文章解决所有域名解析中相关的问题

最后会通过实际工作中碰到的不同场景下几个DNS问题的分析过程来理解DNS

这几个Case描述如下:

  1. 一批ECS nslookup 域名结果正确,但是 ping 域名 返回 unknown host
  2. Docker容器中的域名解析过程和原理
  3. 中间件的VipClient服务在centos7上域名解析失败
  4. 在公司网下,我的windows7笔记本的wifi总是报dns域名异常无法上网(通过IP地址可以上网)

因为这些问题都不一样,但是都跟DNS服务相关所以打算分四篇文章挨个介绍,希望看完后能加深对DNS原理的理解并独立解决任何DNS问题。

下面我们就先开始介绍下DNS解析原理和流程。

Linux下域名解析流程

  • DNS域名解析的时候先根据 /etc/host.conf、/etc/nsswitch.conf 配置的顺序进行dns解析(name service switch),一般是这样配置:hosts: files dns 【files代表 /etc/hosts ; dns 代表 /etc/resolv.conf】(ping是这个流程,但是nslookup和dig不是)
  • 如果本地有DNS Client Cache,先走Cache查询,所以有时候看不到DNS网络包。Linux下nscd可以做这个cache,Windows下有 ipconfig /displaydns ipconfig /flushdns
  • 如果 /etc/resolv.conf 中配置了多个nameserver,默认使用第一个,只有第一个失败【如53端口不响应、查不到域名后再用后面的nameserver顶上】

image.png

上述描述主要是阐述的图中 stub resolver部分的详细流程。这部分流程出问题才是程序员实际中更多碰到的场景

所以默认的nsswitch流程是

image.png

以下是一个 /etc/nsswitch.conf

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
# cat /etc/nsswitch.conf |grep -v "^#" |grep -v "^$"
passwd: files sss
shadow: files sss
group: files sss
hosts: files dns myhostname <<<<< 重点是这一行三个值的顺序
bootparams: nisplus [NOTFOUND=return] files
ethers: files
netmasks: files
networks: files
protocols: files
rpc: files
services: files sss
netgroup: nisplus sss
publickey: nisplus
automount: files nisplus sss
aliases: files nisplus

这个配置中的解析顺序是:files->dns->myhostname, 这个顺序可以调整和配置。

Linux下域名解析流程需要注意的地方

Linux下域名解析诊断工具

  • ping
  • nslookup (nslookup domain @dns-server-ip)
  • dig (dig +trace domain)
  • tcpdump (tcpdump -i eth0 host server-ip and port 53 and udp)
  • strace

img

1
2
//指定本地 ip 端口:192.168.0.201#20202,将 dns 解析任务发送给 172.21.0.10 
dig +retry=0 -b192.168.0.201#20202 aliyun.com @172.21.0.10

案例

如下,向 /etc/hosts 中添加两条记录,一条是test.unknow.host 无法解析到,但是另一条 test.localhost 可以解析到,为啥呢?

$head -2 /etc/hosts
127.0.0.1  test.unknow.host
127.0.0.1   test.localhost
$ping test.unknow.host
ping: unknown host test.unknow.host
$ping -c 1 test.localhost
PING test.localhost (127.0.0.1) 56(84) bytes of data.
64 bytes from test.localhost (127.0.0.1): icmp_seq=1 ttl=64 time=0.016 ms

为什么 test.unknow.host 没法解析到? 可能有哪些因素导致这种现象?尝试 ping -c 1 test.localhost 的目的是做什么?

看完前面的理论我的猜测是两种可能导致这种情况:

  • /etc/hosts 没有启用
  • 有本地缓存记录了一个unknow host记录

验证

strace -e trace=open -f ping -c 1 test.localhost

可以通,说明 /etc/hosts 是在起作用的,所以最好验证 /etc/hosts 在起作用的方法是往其中添加一条新纪录,然后验证一下

那接下来只能看本地有没有启动 nscd 这样的缓存了,见后发现也没有,这个时候就可以上 strace 追踪ping的流程了
undefined

从上图可以清晰地看到读取了 /etc/host.conf, 然后读了 /etc/hosts, 再然后读取到我们添加的那条记录,似乎没问题,仔细看这应该是 ip地址后面带的是一个中文字符的空格,这就是问题所在。

到这里可能的情况要追加第三种了:

  • /etc/hosts 中添加的记录没生效(比如中文符号)

dhcp

如果启用了dhcp,那么dhclient会更新在Network Manager启动的时候更新 /etc/resolv.conf

dnsmasq

一般会在127.0.0.1:53上启动dns server服务,配置文件对应在:/run/dnsmasq/resolv.conf。集团内部的vipclient就是类似这个原理。

微服务下的域名解析、负载均衡

微服务中多个服务之间一般都是通过一个vip或者域名之类的来做服务发现和负载均衡、弹性伸缩,所以这里也需要域名解析(一个微服务申请一个域名)

域名解析通过jar、lib包

基本与上面的逻辑没什么关系,jar包会去通过特定的协议联系server,解析出域名对应的多个ip、机房、权重等

域名解析通过dns server

跟前面介绍逻辑一致,一般是/etc/resolv.conf中配置的第一个nameserver负责解析微服务的域名,解析不到的(如baidu.com)再转发给上一级通用的dns server,解析到了说明是微服务自定义的域名,就可以返回来了

如果这种情况下/etc/resolv.conf中配置的第一个nameserver是127.0.0.1,意味着本地跑了一个dns server, 这个服务使用dns协议监听本地udp 53端口

验证方式: nslookup 域名 @127.0.0.1 看看能否解析到你想要的地址

kubernetes 和 docker中的域名解析

一般是通过iptables配置转发规则来实现,这种用iptables和tcpdump基本都可以看清楚。如果是集群内部的话可以通过CoreDNS来实现,通过K8S动态向CoreDNS增删域名,增删ip,所以这种域名肯定只能在k8s集群内部使用

nginx 中的域名解析

nginx可以自定义resolver,也可以通过读取 /etc/resolv.conf转换而来,要注意对 /etc/resolv.conf中 注释的兼容

https://github.com/blacklabelops-legacy/nginx/issues/36 可能是nginx读取 /etc/resolv.conf没有处理好 # 注释的问题

进一步的Case学习:

  1. 一批ECS nslookup 域名结果正确,但是 ping 域名 返回 unknown host
  2. Docker容器中的域名解析过程和原理
  3. 中间件的VipClient服务在centos7上域名解析失败
  4. 在公司网下,我的windows7笔记本的wifi总是报dns域名异常无法上网(通过IP地址可以上网)

参考文章:

GO DNS 原理解析

Linux 系统如何处理名称解析

Anatomy of a Linux DNS Lookup – Part I

史上最全 SSH 暗黑技巧详解

我见过太多的老鸟、新手对ssh 基本只限于 ssh到远程机器,实际这个命令我们一天要用很多次,但是对它的了解太少了,他的强大远远超出你的想象。当于你也许会说够用就够了,确实没错,但是你考虑过效率没有,或者还有哪些脑洞大开的功能会让你爱死他,这些功能又仅仅是一行命令就够了。

疫情期间一行SSH命令让我节省了70%的出差时间,来,让我们一起走一遍,看看会不会让你大开眼界

本文试图解决的问题

  • 如何通过ssh命令科学上网
  • docker 镜像、golang仓库总是被墙怎么办
  • 公司跳板机要输入动态token,太麻烦了,如何省略掉这个token;
  • 比如多机房总是要走跳板机,如何绕过跳板机直连;
  • 我的开发测试机器如何免打通、免密码、直达;
  • 如何访问隔离环境中(k8s)的Web服务 – 将隔离环境中的web端口映射到本地
  • 如何让隔离环境的机器用上yum、apt
  • 如何将服务器的图形界面映射到本地(类似vnc的作用)
  • ssh如何调试诊断,这才是终极技能……

注意事项

  • ssh是指的openSSH 命令工具
  • 本文适用于各种Linux、macOS下命令行操作,Windows的话各种可视化工具都可以复制session、配置tunnel来实现类似功能。
  • 如果文章中提到的文件、文件夹不存在可以直接创建出来。
  • 所有配置都是在你的笔记本上(相当于ssh client上)

科学上网

有时候科学上网还得靠自己,一行ssh命令来科学上网:

1
nohup ssh -qTfnN -D 127.0.0.1:38080 root@1.1.1.1 "vmstat 10" 2>&1 >/dev/null &

上面的 1.1.1.1 是你在境外的一台服务器,已经做好了免密登陆(免密见后面,要不你还得输一下密码),这句话的意思就是在本地启动一个38080的端口,上面收到的任何东西都会转发给 1.1.1.1:22(做了ssh加密),1.1.1.1:22 会解密收到的东西,然后把他们转发给google之类的网站(比如你要访问的是google),结果依然通过原路返回

127.0.0.1:38080 socks5 就是要填入到你的浏览器中的代理服务器,什么都不需要装,非常简单

image.png

原理图如下(灰色矩形框就是你本地ssh命令,ssh 线就是在穿墙, 国外服务器就是命令中的1.1.1.1):
undefined

科学上网之http特殊代理–利用ssh 本地转发是HTTP协议

前面所说的代理是socks5代理,一般浏览器都有插件支持,但是比如你的docker(或者其他程序)需要通过http去拉取镜像就会出现如下错误:

Sending build context to Docker daemon 8.704 kB
Step 1 : FROM k8s.gcr.io/kube-cross:v1.10.1-1
Get https://k8s.gcr.io/v1/_ping: dial tcp 108.177.125.82:443: i/o timeout

如果是git这样的应用内部可以配置socks5和http代理服务器,请参考另外一篇文章,但是有些应用就不能配置了,当然最终通过ssh大法还是可以解决这个问题:

sudo ssh -L 443:108.177.125.82:443 root@1.1.1.1 //在本地监听443,转发给远程108.177.125.82的443端口

然后再在 /etc/hosts 中将域名 k8s.gcr.io 指向 127.0.0.1, 那么本来要访问 k8s.gcr.io:443的,变成了访问本地 127.0.0.1:443 而 127.0.0.1:443 又通过ssh重定向到了 108.177.125.82:443 这样就实现了http代理或者说这种特殊情况下的科学上网。这个方案不需要装任何东西,但是每个访问目标都要这样处理,好在这种情况不多

内部堡垒机、跳板机都需要密码+动态码,太复杂了,怎么解?

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
$ cat ~/.ssh/config 
#reuse the same connection --关键配置
ControlMaster auto
ControlPath ~/tmp/ssh_mux_%h_%p_%r

#查了下ControlPersist是在OpenSSH5.6加入的,5.3还不支持
#不支持的话直接把这行删了,不影响功能
#keep one connection in 72hour
#ControlPersist 72h
#复用连接的配置到这里,后面的配置与复用无关

#其它也很有用的配置
GSSAPIAuthentication=no
#这个配置在公网因为安全原因请谨慎关闭
StrictHostKeyChecking=no
TCPKeepAlive=yes
CheckHostIP=no
# "ServerAliveInterval [seconds]" configuration in the SSH configuration so that your ssh client sends a "dummy packet" on a regular interval so that the router thinks that the connection is active even if it's particularly quiet
ServerAliveInterval=15
#ServerAliveCountMax=6
ForwardAgent=yes

UserKnownHostsFile /dev/null

在你的ssh配置文件增加上述参数,意味着72小时内登录同一台跳板机只有第一次需要输入密码,以后都是重用之前的连接,所以也就不再需要输入密码了。

加了如上参数后的登录过程就有这样的东东(默认没有,这是debug信息):

1
2
3
4
5
6
7
8
9
10
11
12
13
14
debug1: setting up multiplex master socket
debug3: muxserver_listen: temporary control path /home/ren/tmp/ssh_mux_10.16.*.*_22_corp.86g3C34vy36tvCtn
debug2: fd 3 setting O_NONBLOCK
debug3: fd 3 is O_NONBLOCK
debug3: fd 3 is O_NONBLOCK
debug1: channel 0: new [/home/ren/tmp/ssh_mux_10.16.*.*_22_corp]
debug3: muxserver_listen: mux listener channel 0 fd 3
debug1: control_persist_detach: backgrounding master process
debug2: control_persist_detach: background process is 15154
debug2: fd 3 setting O_NONBLOCK
debug1: forking to background
debug1: Entering interactive session.
debug2: set_control_persist_exit_time: schedule exit in 259200 seconds
debug1: multiplexing control connection

/home/ren/tmp/ssh_mux_10.16.._22_corp 这个就是保存好的socket,下次可以重用,免密码。 in 259200 seconds 对应 72小时

我有很多不同机房(或者说不同客户)的机器都需要跳板机来登录,能一次直接ssh上去吗?

比如有一批客户机房的机器IP都是192.168.., 然后需要走跳板机100.10.1.2才能访问到,那么我希望以后在笔记本上直接 ssh 192.168.1.5 就能直接连上

$ cat /etc/ssh/ssh_config

Host 192.168.*.*
ProxyCommand ssh -l ali-renxijun 100.10.1.2 exec /usr/bin/nc %h %p

上面配置的意思是执行 ssh 192.168.1.5的时候命中规则 Host 192.168.. 所以执行 ProxyCommand 先连上跳板机再通过跳板机连向192.168.1.5 。这样在你的笔记本上就跟192.168.. 的机器仿佛在一起,ssh可以上去,但是ping不通这个192.168.1.5的ip

划重点:公司的线上跳板机做了特殊限制,限制了这个技能。日常环境跳板机支持这个功能

比如我的跳板配置:

#到美国的机器用美国的跳板机速度更快
Host 10.74.*
ProxyCommand ssh -l user us.jump exec /bin/nc %h %p 2>/dev/null
#到中国的机器用中国的跳板机速度更快
Host 10.70.*
ProxyCommand ssh -l user cn.jump exec /bin/nc %h %p 2>/dev/null
   
Host 192.168.0.*
ProxyCommand ssh -l user 1.1.1.1 exec /usr/bin/nc %h %p

其实我的配置文件里面还有很多规则,懒得一个个隐藏IP了,这些规则是可以重复匹配的

来看一个例子

ren@ren-VirtualBox:/$ ping -c 1 10.16.1.*
        PING 10.16.1.* (10.16.1.*) 56(84) bytes of data.^C
    --- 10.16.1.* ping statistics ---
    1 packets transmitted, 0 received, 100% packet loss, time 0ms
    
ren@ren-VirtualBox:~$ ssh -l corp 10.16.1.* -vvv
OpenSSH_6.7p1 Ubuntu-5ubuntu1, OpenSSL 1.0.1f 6 Jan 2014
debug1: Reading configuration data /home/ren/.ssh/config
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: /etc/ssh/ssh_config line 28: Applying options for *
debug1: /etc/ssh/ssh_config line 44: Applying options for 10.16.*.*
debug1: /etc/ssh/ssh_config line 68: Applying options for *
debug1: auto-mux: Trying existing master
debug1: Control socket "/home/ren/tmp/ssh_mux_10.16.1.*_22_corp" does not exist
debug1: Executing proxy command: exec ssh -l corp 139.*.*.* exec /usr/bin/nc 10.16.1.* 22

本来我的笔记本跟 10.16.1.* 是不通的(ping 不通),但是ssh可以直接连上,实际ssh登录过程中自动走跳板机139...* 就连上了

-vvv 参数是debug,把ssh登录过程的日志全部打印出来。

将隔离环境中的web端口映射到本地(本地代理)

远程机器部署了WEB Server(端口 8083),需要通过浏览器来访问这个WEB服务,但是server在隔离环境中,只能通过ssh访问到。一般来说会在隔离环境中部署一个windows机器,通过这个windows机器来访问到这个web server。能不能省掉这个windows机器呢?

现在我们试着用ssh来实现本地浏览器直接访问到这个隔离环境中的WEB Server。

假设web server是:10.1.1.123:8083, ssh账号是:user

先配置好本地直接 ssh user@10.1.1.123 (参考前面的 ProxyCommand配置过程,最好是免密也配置好),然后在你的笔记本上执行:

ssh -CNfL 0.0.0.0:8088:10.1.1.123:8083 user@10.1.1.123

或者:(root@100.1.2.3 -p 54900 是可达10.1.1.123的代理服务器)

ssh -CNfL 0.0.0.0:8089:10.1.1.123:8083 root@100.1.2.3 -p 54900

这表示在本地启动一个8088的端口,将这个8088端口映射到10.1.1.123的8083端口上,用的ssh账号是user

然后在笔记本上的浏览器中输入: 127.0.0.1:8088 就看到了如下界面:

image.png

反过来,也可以让隔离环境机器通过代理上网,比如安装yum

为什么有时候ssh 比较慢,比如总是需要30秒钟后才能正常登录

先了解如下知识点,在 ~/.ssh/config 配置文件中:

GSSAPIAuthentication=no

禁掉 GSSAPI认证,GSSAPIAuthentication是个什么鬼东西请自行 Google(多一次没必要的授权认证过程,然后等待超时)。 这里要理解ssh登录的时候有很多种认证方式(公钥、密码等等),具体怎么调试请记住强大的命令参数 ssh -vvv 上面讲到的技巧都能通过 -vvv 看到具体过程。

比如我第一次碰到ssh 比较慢总是需要30秒后才登录,不能忍受,于是登录的时候加上 -vvv明显看到控制台停在了:GSSAPIAuthentication 然后Google了一下,禁掉就好了

当然还有去掉每次ssh都需要先输入yes

批量打通所有机器之间的ssh登录免密码

Expect在有些公司是被禁止的

ssh免密码的原理是将本机的pub key复制到目标机器的 ~/.ssh/authorized_keys 里面。可以手工复制粘贴,也可以 ssh-copy-id 等

如果有100台机器,互相两两打通还是比较费事(大概需要100*99次copy key)。 下面通过 expect 来解决输入密码,然后配合shell脚本来批量解决这个问题。

这个脚本需要四个参数:目标IP、用户名、密码、home目录,也就是ssh到一台机器的时候帮我们自动填上yes,和密码,这样就不需要人肉一个个输入了。

再在外面写一个循环对每个IP执行如下操作:

if代码部分检查本机~/.ssh/下有没有id_rsa.pub,也就是是否以前生成过密钥对,没生成的话就帮忙生成一次。

for循环部分一次把生成的密钥对和authorized_keys复制到所有机器上,这样所有机器之间都不需要输入密码就能互相登陆了(当然本机也不需要输入密码登录所有机器)

最后一行代码:

ssh $user@$n "hostname -i"

验证一下没有输密码是否能成功ssh上去。

思考一下,为什么这么做就可以打通两两之间的免密码登录,这里没有把所有机器的pub key复制到其他所有机器上去啊

答案:其实这个脚本做了一个取巧投机的事,那就是让所有机器共享一套公钥、私钥。
有时候我也会把我的windows笔记本和我专用的某台虚拟机共享一套秘钥,这样任何新申请的机器打通一次账号就可以在两台机器上随便登录。请保护好自己的私钥

如果免密写入 authorized_keys 成功,但是通过ssh pubkey认证的时候还是有可能失败,这是因为pubkey认证要求:

  • authorized_keys 文件权限要对
  • .ssh 文件夹权限要对
  • /home/user 文件夹权限要对 —-这个容易忽视掉

留个作业:第一次ssh某台机器的时候总是出来一个警告,需要yes确认才能往下走,怎么干掉他?

StrictHostKeyChecking=no
UserKnownHostsFile=/dev/null

如果按照文章操作不work,推荐就近问身边的同学。问我的话请cat 配置文件 然后把ssh -vvv user@ip (user、ip请替换成你的),再截图发给我。**

测试成功的同学也请留言说下什么os、版本,以及openssl版本,我被问崩溃了


这里只是帮大家入门了解ssh,掌握好这些配置文件和-vvv后有好多好玩的可以去挖掘,同时也请在留言中说出你的黑技能

~/.ssh/config 参考配置

下面是我个人常用的ssh config配置

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
$cat ~/.ssh/config
#GSSAPIAuthentication=no
StrictHostKeyChecking=no
#TCPKeepAlive=yes
CheckHostIP=no
# "ServerAliveInterval [seconds]" configuration in the SSH configuration so that your ssh client sends a "dummy packet" on a regular interval so that the router thinks that the connection is active even if it's particularly quiet
ServerAliveInterval=15
#ServerAliveCountMax=6
ForwardAgent=yes

UserKnownHostsFile /dev/null

#reuse the same connection
ControlMaster auto
ControlPath /tmp/ssh_mux_%h_%p_%r

#keep one connection in 72hour
ControlPersist 72h

Host 192.168.1.*
ProxyCommand ssh user@us.jump exec /usr/bin/nc %h %p 2>/dev/null
Host 192.168.2.*
ProxyCommand ssh user@cn.jump exec /usr/bin/nc %h %p 2>/dev/null
#ProxyCommand /bin/nc -x localhost:12346 %h %p

Host 172
HostName 10.172.1.1
Port 22
User root
ProxyJump root@1.2.3.4:12345

Host 176
HostName 10.176.1.1
Port 22
User root
ProxyJump admin@1.2.3.4:12346

Host 10.5.*.*, 10.*.*.*
port 22
user root
ProxyJump plantegg@1.2.3.4:12347

ProxyJump完全可以取代 ProxyCommand,比如ProxyJump 不再依赖nc、也更灵活一些

/etc/ssh/ssh_config 参考配置

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
Host *
Protocol 2
ServerAliveInterval 30
User admin

host 10.10.55.*
ProxyCommand ssh -l admin admin.jump exec /usr/bin/nc %h %p

# uos is a hostname
Host 10.10.1.13* 192.168.2.133 uos
ProxyCommand ssh -l root -p 54900 1.1.1.1 exec /usr/bin/nc %h %p

#debug for git proxy
Host github.com
# LogLevel DEBUG3
# ProxyCommand ssh -l root gfw.jump exec /usr/bin/nc %h %p
# ProxyCommand ssh -oProxyCommand='ssh -l admin gfw.jump:22' -l root gfw.jump2 exec /usr/bin/nc %h %p


ForwardAgent yes
ForwardX11 yes
ForwardX11Trusted yes

SendEnv LANG LC_*
HashKnownHosts yes
GSSAPIAuthentication no
GSSAPIDelegateCredentials no
Compression yes

其他知识点

参数的优先级是:命令行配置选项 > ~/.ssh/config > /etc/ssh/ssh_config

在SSH的**身份验证阶段,SSH只支持服务端保留公钥,客户端保留私钥的方式,**所以方式只有两种:客户端生成密钥对,将公钥分发给服务端;服务端生成密钥对,将私钥分发给客户端。只不过出于安全性和便利性,一般都是客户端生成密钥对并分发公钥(阿里云服务器秘钥对–服务器将一对密钥中的公钥放在 authorized_keys, 私钥给client登陆用)

服务器上的 /etc/ssh/ssh_host* 是用来验证服务器身份的秘钥对(对应client的 known_hosts), 在主机验证阶段,服务端持有的是私钥,客户端保存的是来自于服务端的公钥。注意,这和身份验证阶段密钥的持有方是相反的。

SSH支持多种身份验证机制,它们的验证顺序如下:gssapi-with-mic,hostbased,publickey,keyboard-interactive,password,但常见的是密码认证机制(password)和公钥认证机制(public key). 当公钥认证机制未通过时,再进行密码认证机制的验证。这些认证顺序可以通过ssh配置文件(注意,不是sshd的配置文件)中的指令PreferredAuthentications改变。

永久隧道

大多时候隧道会失效,或者断开,我们需要有重连机制,一般可以通过autossh(需要单独安装)搞定自动重连,再配合systemd或者crond搞定永久自动重连

比如以下代码在gf开启2个远程转发端口

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
remote_port=(30081 30082)
for port in "${remote_port[@]}"
do
line=`ps aux |grep ssh |grep $port | wc -l`
if [[ "$line" -lt 1 ]]; then
#等价: ssh -fN -R gf:$port:127.0.0.1:22 root@gf
autossh -M 0 -fNR gf:$port:127.0.0.1:22 root@gf
fi;
done

line=`ps aux |grep ssh |grep 13129 | wc -l`
if [[ "$line" -lt 1 ]]; then
nohup ssh -fNR gf:13129:172.16.1.2:3129 root@gf
fi;

#cat /etc/cron.d/jump
#* * * * * root sh /root/drds_private_cloud/jump.sh

或者另外创建一个service服务

1
2
3
4
5
6
7
8
9
10
[Unit]
Description=AutoSSH tunnel on 31081 to gf server
After=network.target

[Service]
Environment="AUTOSSH_GATETIME=0"
ExecStart=/usr/bin/autossh -M 0 -q -N -o "ServerAliveInterval 60" -o "ServerAliveCountMax 3" -NR gf:31081:172.16.1.2:22 -i /root/.ssh/id_rsa root@gf

[Install]
WantedBy=multi-user.target

调试ssh–终极大招

好多问题都是可以 debug 发现的

  • 客户端增加参数 -vvv 会把所有流程在控制台显示出来。卡在哪个环节;密码不对还是key不对一看就知道
  • server端还可以:/usr/sbin/sshd -ddd -p 2222 在2222端口对sshd进行debug,看输出信息验证为什么pub key不能login等. 一般都是权限不对,/root 以及 /root/.ssh 文件夹的权限和owner都要对,更不要说 /root/.ssh/authorized_keys 了
1
/usr/sbin/sshd -ddd -p 2222 

ssh 提示信息

可以用一下脚本生成一个彩色文件,放到 /etc/motd 中就行

Basic colors are numbered:

  • 1 – Red
  • 2 – Green
  • 3 – Yellow
  • 4 – Blue
  • 5 – Magenta
  • 6 – Cyan
  • 7 – White
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
#!/bin/sh
export TERM=xterm-256color

read one five fifteen rest < /proc/loadavg
echo "$(tput setaf 2)
Kernel: `uname -v | awk -v OFS=' ' '{print $4, $5}'`

\\ ^__^
\\ (oo)\\_______
(__)\\ )\\\/\\
||----w |
|| ||

本机器为长稳测试环境, 千万不要kill进程, 不要跑负载过重的任务

有任何需要请联系 ** 多谢!

$(tput setaf 4)Load Averages......: ${one}, ${five}, ${fifteen} (1, 5, 15 min)
$(tput setaf 5)
______________
本机器为长稳测试环境, 千万不要kill进程, 不要跑负载过重的任务

有任何需要请联系 ** 多谢!
--------------
\\ ^__^
\\ (oo)\\_______
(__)\\ )\\\/\\
||----w |
|| ||

$(tput sgr0)"

以上脚本运行结果

image-20210902224011450

sshd Banner

Banner指定用户登录后,sshd 向其展示的信息文件(Banner /usr/local/etc/warning.txt),默认不展示任何内容。

或者配置:

1
2
3
4
5
cat /etc/ssh/sshd_config
# no default banner path
#Banner none
#在配置文件末尾添加Banner /etc/ssh/my_banner这一行内容:
Banner /etc/ssh/my_banner

/etc/ssh/my_banner 中可以放置提示内容

验证秘钥对

-y Read a private OpenSSH format file and print an OpenSSH public key to stdout.

cd ~/.ssh/ ; ssh-keygen -y -f id_rsa | cut -d’ ‘ -f 2 ; cut -d’ ‘ -f 2 id_rsa.pub

ssh-keygen -y -e -f <private key>获取一个私钥并打印相应的公钥,该公钥可以直接与您可用的公钥进行比较

github 上你的公钥

github可以取到你的公钥,如果别人让你查看他的服务器,直接给 https://github.com/plantegg.keys 这个链接,让他把下载的key 加到 ~/.ssh/authorized_keys 里面就行了

ssh-keygen

静默生成

1
2
3
4
5
6
7
8
9
ssh-keygen -q -t rsa -N '' -f ~/.ssh/id_rsa <<<y

ssh-keygen -q -t rsa -N '' -f ~/.ssh/id_rsa <<<y >/dev/null 2>&1

//修改 passphrase
ssh-keygen -p -P "12345" -N "abcde" -f .ssh/id_rsa
//ssh-keygen -p [-P old_passphrase] [-N new_passphrase] [-f keyfile]
//或者直接通过提示一步步修改:
ssh-keygen -p

删除或者修改 passphrase

run ssh-keygen -p in a terminal. It will then prompt you for a keyfile (defaulted to the correct file for me, ~/.ssh/id_rsa), the old passphrase (enter what you have now) and the new passphrase (enter nothing).

要注意openssh 不同版本使用的不同 format,用openssh 8.0 默认用 “RFC4716” 格式,老的 4.0 默认是 PKCS8 格式

去修改dsa密钥后 openssh 4.0 不认

-m key_format
Specify a key format for the -i (import) or -e (export) conversion options. The sup‐
ported key formats are: “RFC4716” (RFC 4716/SSH2 public or private key), “PKCS8” (PEM
PKCS8 public key) or “PEM” (PEM public key). The default conversion format is
“RFC4716”.

如果用 8.0 去修改 PKCS8 格式的 key 可以指定格式参数

1
ssh-keygen -p  -m "PKCS8" -f ./id_dsa

ssh-agent

私钥设置了密码以后,每次使用都必须输入密码,有时让人感觉非常麻烦。比如,连续使用scp命令远程拷贝文件时,每次都要求输入密码。

ssh-agent命令就是为了解决这个问题而设计的,它让用户在整个 Bash 对话(session)之中,只在第一次使用 SSH 命令时输入密码,然后将私钥保存在内存中,后面都不需要再输入私钥的密码了。

第一步,使用下面的命令新建一次命令行对话。

1
$ eval `ssh-agent`

上面命令中,ssh-agent会先自动在后台运行,并将需要设置的环境变量输出在屏幕上,类似下面这样。

1
2
3
4
$ ssh-agent
SSH_AUTH_SOCK=/tmp/ssh-barrett/ssh-22841-agent; export SSH_AUTH_SOCK;
SSH_AGENT_PID=22842; export SSH_AGENT_PID;
echo Agent pid 22842;

eval命令的作用,就是运行上面的ssh-agent命令的输出,设置环境变量。

第二步,在新建的 Shell 对话里面,使用ssh-add命令添加默认的私钥(比如~/.ssh/id_rsa,或~/.ssh/id_dsa,或~/.ssh/id_ecdsa,或~/.ssh/id_ed25519)。

1
2
3
$ ssh-add
Enter passphrase for /home/you/.ssh/id_dsa: ********
Identity added: /home/you/.ssh/id_dsa (/home/you/.ssh/id_dsa)

上面例子中,添加私钥时,会要求输入密码。以后,在这个对话里面再使用密钥时,就不需要输入私钥的密码了,因为私钥已经加载到内存里面了。

如果添加的不是默认私钥,ssh-add命令需要显式指定私钥文件。

1
$ ssh-add my-other-key-file

上面的命令中,my-other-key-file就是用户指定的私钥文件。

SSH agent 程序能够将您的已解密的私钥缓存起来,在需要的时候用它来解密key chanllge返回给 SSHD https://webcache.googleusercontent.com/search?q=cache:7OfvSBFki10J:https://www.ibm.com/developerworks/cn/linux/security/openssh/part2/+&cd=7&hl=en&ct=clnk&gl=hk keychain介绍

安装sshd和debug

sshd 有自己的一对或多对密钥。它使用密钥向客户端证明自己的身份。所有密钥都是公钥和私钥成对出现,公钥的文件名一般是私钥文件名加上后缀.pub

DSA 格式的密钥文件默认为/etc/ssh/ssh_host_dsa_key(公钥为ssh_host_dsa_key.pub),RSA 格式的密钥为/etc/ssh/ssh_host_rsa_key(公钥为ssh_host_rsa_key.pub)。如果需要支持 SSH 1 协议,则必须有密钥/etc/ssh/ssh_host_key

如果密钥不是默认文件,那么可以通过配置文件sshd_configHostKey配置项指定。默认密钥的HostKey设置如下。

1
2
3
4
5
6
# HostKey for protocol version 1
# HostKey /etc/ssh/ssh_host_key

# HostKeys for protocol version 2
# HostKey /etc/ssh/ssh_host_rsa_key
# HostKey /etc/ssh/ssh_host_dsa_ke

注意,如果重装 sshd,/etc/ssh下的密钥都会重新生成(这些密钥对用于验证Server的身份),导致客户端重新 ssh 连接服务器时,会跳出警告,拒绝连接。为了避免这种情况,可以在重装 sshd 时,先备份/etc/ssh目录,重装后再恢复这个目录。

调试:非后台(-D)和debug(-d)模式启动sshd,同时监听2222和3333端口

sshd -D -d -p 2222 -p 3333

sshd config 配置多端口

1
2
3
4
5
#cat /etc/ssh/sshd_config
Port 22022
Port 22
#AddressFamily any
#ListenAddress 0.0.0.0

scp设置socks代理

scp -o “ProxyCommand=nc -X 5 -x [SOCKS_HOST]:[SOCKS_PORT] %h %p” [LOCAL/FILE/PATH] [REMOTE_USER]@[REMOTE_HOST]:[REMOTE/FILE/PATH]

其中[SOCKS_HOST]和[SOCKS_PORT]是socks代理的LOCAL_ADDRESS和LOCAL_PORT。[LOCAL/FILE/PATH]、[REMOTE_USER]、[REMOTE_HOST]和[REMOTE/FILE/PATH]分别是要复制文件的本地路径、要复制到的远端主机的用户名、要复制到的远端主机名、要复制文件的远端路径,这些参数与不使用代理时一样。“ProxyCommand=nc”表示当前运行命令的主机上需要有nc命令。

ProxyCommand

Specifies the proxy command for the connection. This command is launched prior to making the connection to Hostname. %h is replaced with the host defined in HostName and %p is replaced with 22 or is overridden by a Port directive.

在ssh连接目标主机前先执行ProxyCommand中的命令,比如 .ssh/config 中有如下配置

1
2
3
4
5
6
7
8
9
host remote-host
ProxyCommand ssh -l root -p 52146 1.2.3.4 exec /usr/bin/nc %h %p

//以上配置等价下面的命令
ssh -o ProxyCommand="ssh -l root -p 52146 1.2.3.4 exec /usr/bin/nc %h %p" remote-host
//or 等价
ssh -o ProxyCommand="ssh -l root -p 52146 -W %h:%p 1.2.3.4 " remote-host
//or 等价 debug1: Setting implicit ProxyCommand from ProxyJump: ssh -l root -p 52146 -vvv -W '[%h]:%p' 1.2.3.4
ssh -J root@1.2.3.4:52146 remote-host

如上配置指的是,如果执行ssh remote-host 命中host规则,那么先执行命令 ssh -l root -p 52146 1.2.3.4 exec /usr/bin/nc 同时把remote-host和端口(默认22)传给nc

ProxyCommand和ProxyJump很类似,ProxyJump使用:

1
2
//ssh到centos8机器上,走的是gf这台跳板机,本地一般和centos8不通
ssh -J gf:22 centos8

ProxyJump

需要 OpenSSH 7.3 以上版本才可以使用 ProxyJump, 相对 ProxyCommand 更简洁方便些

1
2
3
4
5
6
7
8
9
10
11
12
#ssh 116 就可以通过 jumpserver:50023 连上 root@1.116.2.1:22
Host 116
HostName 1.116.2.1
Port 22
User root
ProxyJump admin@jumpserver:50023

#ssh 1.112.任意ip 都会默认走 jumpserver 跳转过去
Host 1.112.*.*
Port 22
User root
ProxyJump root@jumpserver

加密算法

列出本地所支持默认的加密算法

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
#ssh -Q key                                                            
ssh-ed25519
ssh-ed25519-cert-v01@openssh.com
ssh-rsa
ssh-dss
ecdsa-sha2-nistp256
ecdsa-sha2-nistp384
ecdsa-sha2-nistp521
ssh-rsa-cert-v01@openssh.com
ssh-dss-cert-v01@openssh.com
ecdsa-sha2-nistp256-cert-v01@openssh.com
ecdsa-sha2-nistp384-cert-v01@openssh.com
ecdsa-sha2-nistp521-cert-v01@openssh.com

ssh -Q cipher # List supported ciphers
ssh -Q mac # List supported MACs
ssh -Q key # List supported public key types
ssh -Q kex # List supported key exchange algorithms

比如连服务器报如下错误:

1
2
debug1: kex: algorithm: (no match)
Unable to negotiate with server port 22: no matching key exchange method found. Their offer: diffie-hellman-group1-sha1,diffie-hellman-group14-sha1

表示服务端支持 diffie-hellman-group1-sha1,diffie-hellman-group14-sha1 加密,但是client端不支持,那么可以指定算法来强制client端使用某种和server一致的加密方式

1
2
3
4
5
ssh -oKexAlgorithms=+diffie-hellman-group14-sha1 -l user

或者config中配置:
host server_ip
KexAlgorithms +diffie-hellman-group1-sha1

如果仍然报以下错误:

1
2
3
4
5
debug2: first_kex_follows 0
debug2: reserved 0
debug1: kex: algorithm: diffie-hellman-group14-sha1
debug1: kex: host key algorithm: (no match)
Unable to negotiate with server_ip port 22: no matching host key type found. Their offer: ssh-rsa

那么可以配置来解决:

1
2
3
Host *
HostKeyAlgorithms +ssh-rsa
PubkeyAcceptedKeyTypes +ssh-rsa

When an SSH client connects to a server, each side offers lists of connection parameters to the other. These are, with the corresponding ssh_config keyword:

  • KexAlgorithms: the key exchange methods that are used to generate per-connection keys
  • HostkeyAlgorithms: the public key algorithms accepted for an SSH server to authenticate itself to an SSH client
  • Ciphers: the ciphers to encrypt the connection
  • MACs: the message authentication codes used to detect traffic modification

无所不能的 SSH 三大转发模式

了解完前面的一些小知识,再来看看无所不能的三大杀招。上面的各种代理基本都是由这三种转发模式实现的。

SSH能够做动态转发、本地转发、远程转发。先简要概述下他们的特点和使用场景

三个转发模式的比较

  • 动态转发完全可以代替本地转发,只是动态转发是socks5协议,当科学上网用,本地转发是tcp协议
  • 本地转发完全是把动态转发特例化到访问某个固定目标的转发,类似 iptable 的 port forwarding
  • 远程转发是启动转端口的机器同时连上两端的两个机器,把本来不连通的两端拼接起来,中间显得多了个节点。
  • 三个转发模式可以串联使用

动态转发常用来科学上网,本地转发用来打洞,这两种转发启动的端口都是在本地;远程转发也是打洞的一种,只不过启用的端口在远程机器上。

img

动态转发 (-D) SOCKS5 协议

动态转发指的是,本机与 SSH 服务器之间创建了一个加密连接,然后本机内部针对某个端口的通信,都通过这个加密连接转发。它的一个使用场景就是,访问所有外部网站,都通过 SSH 转发。

动态转发需要把本地端口绑定到 SSH 服务器。至于 SSH 服务器要去访问哪一个网站,完全是动态的,取决于原始通信,所以叫做动态转发

动态的意思就是:需要访问的目标、端口还不确定。后面要讲的本地转发、远程转发都是针对具体IP、port的转发。

1
2
3
$ ssh -D 4444 ssh-server -N
//或者如下方式:
nohup ssh -qTfnN -D *:13658 root@jump vmstat 10 >/dev/null 2>&1

注意,这种转发采用了 SOCKS5 协议。访问外部网站时,需要把 HTTP 请求转成 SOCKS5 协议,才能把本地端口的请求转发出去。-N参数表示,这个 SSH 连接不能执行远程命令,只能充当隧道。

image-20210913143129749

下面是 ssh 隧道建立后的一个使用实例

1
2
3
curl -x socks5://localhost:4444 http://www.example.com
or
curl --socks5-hostname localhost:4444 https://www.twitter.com

上面命令中,curl 的-x参数指定代理服务器,即通过 SOCKS5 协议的本地3000端口,访问http://www.example.com

官方文档关于 -D的介绍

-D [bind_address:]port
Specifies a local “dynamic” application-level port forwarding. This works by allocat‐
ing a socket to listen to port on the local side, optionally bound to the specified
bind_address. Whenever a connection is made to this port, the connection is forwarded
over the secure channel, and the application protocol is then used to determine where
to connect to from the remote machine. Currently the SOCKS4 and SOCKS5 protocols are
supported, and ssh will act as a SOCKS server. Only root can forward privileged ports.
Dynamic port forwardings can also be specified in the configuration file.

特别注意,如果ssh -D 要启动的本地port已经被占用了是不会报错的,但是实际socks代理会没启动成功

本地转发 (-L)

本地转发(local forwarding)指的是,SSH 服务器作为中介的跳板机,建立本地计算机与特定目标网站之间的加密连接。本地转发是在本地计算机的 SSH 客户端建立的转发规则。

典型使用场景就是,打洞,经过跳板机访问无法直接连通的服务。

它会指定一个本地端口(local-port),所有发向那个端口的请求,都会转发到 SSH 跳板机(ssh-server),然后 SSH 跳板机作为中介,将收到的请求发到目标服务器(target-host)的目标端口(target-port)。

1
$ ssh -L :local-port:target-host:target-port ssh-server  //target-host是ssh-server的target-host, target-host 域名解析、路由都是由ssh-server完成

上面命令中,-L参数表示本地转发,local-port是本地端口,target-host是你想要访问的目标服务器,target-port是目标服务器的端口,ssh-server是 SSH 跳板机。当你访问localhost:local-port 的时候会通过ssh-server把请求转给target-host:target-port

img

上图对应的命令是:

1
ssh -L 53682:remote-server:53682 ssh-server

然后,访问本机的53682端口,就是访问remote-server的53682端口.

1
$ curl http://localhost:53682

注意,本地端口转发采用 HTTP 协议,不用转成 SOCKS5 协议。如果需要HTTP的动态代理,可以先起socks5动态代理,然后再起一个本地转发给动态代理的socks5端口,这样就有一个HTTP代理了,能给yum、docker之类的使用。

这个命令最好加上-N参数,表示不在 SSH 跳板机执行远程命令,让 SSH 只充当隧道。另外还有一个-f参数表示 SSH 连接在后台运行。

如果经常使用本地转发,可以将设置写入 SSH 客户端的用户个人配置文件。

1
2
Host test.example.com
LocalForward client-IP:client-port server-IP:server-port

远程转发(-R)

远程端口指的是在远程 SSH 服务器建立的转发规则。主要是执行ssh转发的机器别人连不上,所以需要一台client能连上的机器当远程转发端口,要不就是本地转发了。

由于本机无法访问内网 SSH 跳板机,就无法从外网发起 SSH 隧道,建立端口转发。必须反过来,从 SSH 跳板机发起隧道,建立端口转发,这时就形成了远程端口转发。

1
ssh -fNR 30.1.2.3:30081:166.100.64.1:3128 root@30.1.2.3 -p 2728

上面的命令,首先需要注意,不是在30.1.2.3 或者166.100.64.1 上执行的,而是找一台能联通 30.1.2.3 和166.100.64.1的机器来执行,在执行前Remote clients能连上 30.1.2.3 但是 30.1.2.3 和 166.100.64.1 不通,所以需要一个中介将 30.1.2.3 和166.100.64.1打通,这个中介就是下图中的MobaXterm所在的机器,命令在MobaXterm机器上执行

image-20210913163036410

执行上面的命令以后,跳板机30.1.2.3 到166.100.64.1的隧道已经建立了,这个隧道是依赖两边都能连通的MobaXterm机器。然后,就可以从Remote Client访问目标服务器了,即在Remote Client上执行下面的命令。

1
$ curl http://30.1.2.3:30081

执行上面的命令以后,命令就会输出服务器 166.100.64.1 的3128端口返回的内容。

如果经常执行远程端口转发,可以将设置写入 SSH 客户端的用户个人配置文件。

1
2
Host test.example.com
RemoteForward local-IP:local-port target-ip:target-port

注意远程转发需要:

  1. sshd_config里要打开AllowTcpForwarding选项,否则-R远程端口转发会失败。
  2. 默认转发到远程主机上的端口绑定的是127.0.0.1如要绑定0.0.0.0需要打开sshd_config里的GatewayPorts选项(然后ssh -R 后加上*:port )。这个选项如果由于权限没法打开也有办法,可配合ssh -L将端口绑定到0.0.0.0

开通远程转发后,如果需要动态代理(比如访问所有web服务),那么可以在30081端口机器上(30.1.2.3)执行:

1
nohup ssh -qTfnN -D *:13658 root@127.0.0.1 -p 30081 vmstat 10  >/dev/null 2>&1

表示在30081机器上(30.1.2.3)启动了一个socks5动态代理服务

调试转发、代理是否能联通

命令行调试

1
2
ssh -o 'ProxyCommand nc -X 5 -x 127.0.0.1:1080 %h %p' admin@1.1.1.1
ssh -o 'ProxyCommand ssh root@5.5.5.5 nc -X 5 -x 127.0.0.1:1088 %h %p' root@1.1.1.1

curl

curl -I –socks5-hostname localhost:13659 twitter.com

curl -x socks5://localhost:13659 twitter.com

Suppose you have a socks5 proxy running on localhost:13659 .

In curl >= 7.21.7, you can use

1
curl -x socks5h://localhost:13659 http://www.google.com/

In a proxy string, socks5h:// and socks4a:// mean that the hostname is
resolved by the SOCKS server. socks5:// and socks4:// mean that the
hostname is resolved locally. socks4a:// means to use SOCKS4a, which is
an extension of SOCKS4. Let’s make urllib3 honor it.

In curl >= 7.18.0, you can use

1
curl --socks5-hostname localhost:13659 http://www.google.com/

–proxy 参数含义如下:

1
The --socks5 option is basically considered obsolete since curl 7.21.7. This is because starting in that release, you can now specify the proxy protocol directly in the string that you specify the proxy host name and port number with already. The server you specify with --proxy. If you use a socks5:// scheme, curl will go with SOCKS5 with local name resolve but if you instead use socks5h:// it will pick SOCKS5 with proxy-resolved host name.

wget

指定命令行参数,通过命令行指定HTTP代理服务器的方式如下:

wget -Y on -e “http_proxy=http://[HTTP_HOST]:[HTTP_PORT]http://facebook.com/其中:[HTTP_HOST]和[HTTP_PORT]是http proxy的ADDRESS和PORT。

-Y表示是否使用代理,on表示使用代理。

-e执行后面跟的命令,相当于在.wgetrc配置文件中添加了一条命令,将http_proxy设置为需要使用的代理服务器。

wget –limit-rate=2.5k 限制下载速度,进行测试

PKI (Public Key Infrastructure)证书

X.509 只是一种常用的证书格式,一般以PEM编码,PEM 编码的证书通常以 .pem.crt.cer 为后缀。再次提醒,这只是“通常”情况,实际上某些工具可能并不遵循这些惯例。通过pem证书可以访问需要认证的https服务(比如etcd、apiserver等)

  • ASN.1 用于定义数据类型,例如证书(certificate)和秘钥(key)——就像用 JSON 定义一个 request body —— X.509 用 ASN.1 定义。
  • DER 是一组将 ASN.1 编码成二进制(比特和字节)的编码规则(encoding rules)。
  • PKCS#7 and PKCS#12 是比 X.509 更大的数据结构(封装格式),也用 ASN.1 定义,其中能包含除了证书之外的其他东西。二者分别在 Java 和 Microsoft 产品中使用较多。
  • DER 编码之后是二进制数据,不方便复制粘贴,因此大部分证书都是用 PEM 编码的,它用 base64 对 DER 进行编码,然后再加上自己的 label。
  • 私钥通常用是 PEM 编码的 PKCS#8 对象,但有时也会用密码来加密。

通过命令 cat /etc/kubernetes/pki/ca.crt | openssl x509 -text 也可以得到下图信息

image

公钥、私钥常见扩展名

  • 公钥:.pub or .pemca.crt
  • 私钥:.prv, .key, or .pem , ca.key

证书生成过程演示

并不是所有的场景都需要向这些大型的 CA 机构申请公钥证书,在任何一个企业,组织或是团体内都可以自己形这样的“小王国”,也就是说,你可以自行生成这样的证书,只需要你自己保证自己的生成证书的私钥的安全,以及不需要扩散到整个互联网。下面,我们用 openssl命令来演示这个过程。

1)生成 CA 机构的证书(公钥) ca.crt 和私钥 ca.key

1
2
3
4
5
6
openssl req -newkey rsa:2048 \
-new -nodes -x509 \
-days 365 \
-out ca.crt \
-keyout ca.key \
-subj "/C=SO/ST=Earth/L=Mountain/O=CoolShell/OU=HQ/CN=localhost"
  1. 生成 alice 的私钥
1
openssl genrsa -out alice.key 2048

3)生成 Alice 的 CSR – Certificate Signing Request

1
2
openssl req -new -key alice.key -days 365 -out alice.csr \
-subj "/C=CN/ST=Beijing/L=Haidian/O=CoolShell/OU=Test/CN=localhost.alice"

4)使用 CA 给 Alice 签名证书

1
2
3
4
5
openssl x509  -req -in alice.csr \
-extfile <(printf "subjectAltName=DNS:localhost.alice") \
-CA ca.crt -CAkey ca.key \
-days 365 -sha256 -CAcreateserial \
-out alice.crt

参考资料:

http://docs.corp-inc.com/pages/editpage.action?pageId=203555361
https://wiki.archlinux.org/index.php/SSH_keys_(%E7%AE%80%E4%BD%93%E4%B8%AD%E6%96%87)

https://wangdoc.com/ssh/key.html

https://robotmoon.com/ssh-tunnels/

通过SSH动态转发来建立Socks代以及各种场景应用案例

https://daniel.haxx.se/blog/2020/05/26/curl-ootw-socks5/

SSH Performance

Why when I transfer a file through SFTP, it takes longer than FTP?

一行代码解决scp在Internet传输慢的问题

关于证书(certificate)和公钥基础设施(PKI)的一切

网络数字身份认证术

0%