该死的错误

virtualbox+ubuntu用了快10年了，各种莫名其妙的问题，一直没有换掉，也怪自己 virtualbox+ubuntu组合也许确实奇葩吧，每次碰到问题都没法google到真正的答案了。

问题

用的过程中突然发现挂载的数据盘找不到了（主要存放工作文件）， 看历史记录发现自己执行了：

sudo dd if=/dev/urandom of=/dev/sdb1 bs=1M count=512

/dev/sdb1 对应的正是我的大磁盘，哭死去，怪自己不认识 /dev/sdb1！！ 从来不知道自己挂载的磁盘的真正名字，df -lh 也没仔细看过，导致了这次故障

出问题的history:

29214  01/11/19 10:29:05 vi /tmp/tmp.txt
29215  01/11/19 10:29:18 cat /tmp/tmp.txt |grep "^172.16"
29216  01/11/19 10:29:27 cat /tmp/tmp.txt |grep "^172.16" >cainiao.txt
29217  01/11/19 10:29:31 wc -l cainiao.txt
29218  01/11/19 10:33:13 cat cainiao.txt 
29219  01/11/19 13:36:55 sudo dd if=/dev/urandom of=/dev/sdb1 bs=1M count=512 //故障发生
29220  01/11/19 13:37:08 cd ..
29221  01/11/19 13:37:46 cd / //尝试解决
29222  01/11/19 19:13:45 ls -lh
29223  01/11/19 19:13:49 cd ali 
29224  03/11/19 10:24:56 dmesg
29225  03/11/19 10:27:28 dmesg |grep -i sda
29226  03/11/19 10:27:59 dmesg |grep -i sata
29227  04/11/19 10:19:46 dmesg
29228  04/11/19 10:20:20 dmesg |grep -i sda
29229  04/11/19 10:25:21 dmesg 
29230  04/11/19 10:25:25 dmesg 
29231  04/11/19 10:25:34 dmesg |grep -i sda

尝试

各种重启还是无效，重新删掉数据盘再次挂载启动后依然看不见

mount

virtualbox的启动参数里明确能看到这快盘，和挂载配置

启动后通过fdisk可以看见这块大硬盘

$sudo fdisk -l

Disk /dev/sda: 20 GiB, 21474836480 bytes, 41943040 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: dos
Disk identifier: 0x01012f4d

Device     Boot    Start      End  Sectors Size Id Type
/dev/sda1  *        2048 33554431 33552384  16G 83 Linux
/dev/sda2       33556478 41940991  8384514   4G  5 Extended
/dev/sda5       33556480 41940991  8384512   4G 82 Linux swap / Solaris

Disk /dev/sdb: 50 GiB, 53687091200 bytes, 104857600 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: dos
Disk identifier: 0x000e88f6

Device     Boot    Start       End  Sectors Size Id Type
/dev/sdb1  *        2048  96471039 96468992  46G 83 Linux
/dev/sdb2       96473086 104855551  8382466   4G  5 Extended
/dev/sdb5       96473088 104855551  8382464   4G 82 Linux swap / Solaris

Disk /dev/sdc: 50 GiB, 53687091200 bytes, 104857600 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: dos
Disk identifier: 0x000e88f6

Device     Boot    Start       End  Sectors Size Id Type
/dev/sdc1  *        2048  96471039 96468992  46G 83 Linux
/dev/sdc2       96473086 104855551  8382466   4G  5 Extended
/dev/sdc5       96473088 104855551  8382464   4G 82 Linux swap / Solaris

尝试手工mount （这时看到的才是root cause）

write-protected, mounting read-only 和 bad superblock 错误

尝试 fsck(危险动作）

sudo fsck -y /dev/sdb1

然后再次mount成功了

sudo mount  /dev/sdb1 /media/ren/a64abcac-657d-42ee-8e7b-575eac99bce3

lsblk(修复后）

$sudo lsblk
NAME   MAJ:MIN RM  SIZE RO TYPE MOUNTPOINT
sda      8:0    0   20G  0 disk 
├─sda1   8:1    0   16G  0 part /
├─sda2   8:2    0    1K  0 part 
└─sda5   8:5    0    4G  0 part [SWAP]
sdb      8:16   0   50G  0 disk 
├─sdb1   8:17   0   46G  0 part /media/ren/a64abcac-657d-42ee-8e7b-575eac99bce3
├─sdb2   8:18   0    1K  0 part 
└─sdb5   8:21   0    4G  0 part 
sr0     11:0    1 73.6M  0 rom  /media/ren/VBox_GAs_6.0.10

进到mount后的目录中，查看磁盘大小正常，但是文件看不见了

du 发现文件都在lost+found目录下，但是文件夹名字都改成了 inode名字

根据文件夹大小找出之前的文件夹（比较大的），将其复制出来，一切正常了

修复记录

其中sda是系统盘，sdb是修复后的大磁盘， sdc 是修复前的大磁盘（备份过的）

$sudo fdisk -l

Disk /dev/sda: 20 GiB, 21474836480 bytes, 41943040 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: dos
Disk identifier: 0x01012f4d

Device     Boot    Start      End  Sectors Size Id Type
/dev/sda1  *        2048 33554431 33552384  16G 83 Linux
/dev/sda2       33556478 41940991  8384514   4G  5 Extended
/dev/sda5       33556480 41940991  8384512   4G 82 Linux swap / Solaris

Disk /dev/sdb: 50 GiB, 53687091200 bytes, 104857600 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: dos
Disk identifier: 0x000e88f6

Device     Boot    Start       End  Sectors Size Id Type
/dev/sdb1  *        2048  96471039 96468992  46G 83 Linux
/dev/sdb2       96473086 104855551  8382466   4G  5 Extended
/dev/sdb5       96473088 104855551  8382464   4G 82 Linux swap / Solaris

Disk /dev/sdc: 50 GiB, 53687091200 bytes, 104857600 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: dos
Disk identifier: 0x000e88f6

Device     Boot    Start       End  Sectors Size Id Type
/dev/sdc1  *        2048  96471039 96468992  46G 83 Linux
/dev/sdc2       96473086 104855551  8382466   4G  5 Extended
/dev/sdc5       96473088 104855551  8382464   4G 82 Linux swap / Solaris

可以看到没有修复的磁盘 uuid不太正常，类型也识别为 dos(正常应该是ext4）

[ren@vb 18:12 /home/ren]
$sudo blkid /dev/sdc
/dev/sdc: PTUUID="000e88f6" PTTYPE="dos"

[ren@vb 18:12 /home/ren]
$sudo blkid /dev/sdc1
/dev/sdc1: PARTUUID="000e88f6-01"

[ren@vb 18:12 /home/ren]
$sudo blkid /dev/sdb
/dev/sdb: PTUUID="000e88f6" PTTYPE="dos"

[ren@vb 18:12 /home/ren]
$sudo blkid /dev/sdb1
/dev/sdb1: UUID="a64abcac-657d-42ee-8e7b-575eac99bce3" TYPE="ext4" PARTUUID="000e88f6-01"

尝试mount失败

[ren@vb 18:14 /home/ren]
$sudo mkdir /media/ren/hd

[ren@vb 18:15 /home/ren]
$sudo mount /dev/sd
sda   sda1  sda2  sda5  sdb   sdb1  sdb2  sdb5  sdc   sdc1  sdc2  sdc5  

[ren@vb 18:15 /home/ren]
$sudo mount /dev/sdc1 /media/ren/hd
mount: /dev/sdc1 is write-protected, mounting read-only
mount: wrong fs type, bad option, bad superblock on /dev/sdc1,
       missing codepage or helper program, or other error

       In some cases useful info is found in syslog - try
       dmesg | tail or so.

dmesg中比较正常和不正常的磁盘日志，是看不出来差别的（还没有触发mount动作）

[ren@vb 18:16 /home/ren]
$dmesg |grep sdc
[一 11月  4 18:06:47 2019] sd 4:0:0:0: [sdc] 104857600 512-byte logical blocks: (53.6 GB/50.0 GiB)
[一 11月  4 18:06:47 2019] sd 4:0:0:0: [sdc] Write Protect is off
[一 11月  4 18:06:47 2019] sd 4:0:0:0: [sdc] Mode Sense: 00 3a 00 00
[一 11月  4 18:06:47 2019] sd 4:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[一 11月  4 18:06:47 2019]  sdc: sdc1 sdc2 < sdc5 >
[一 11月  4 18:06:47 2019] sd 4:0:0:0: [sdc] Attached SCSI disk

[ren@vb 18:17 /home/ren]
$dmesg |grep sdb
[一 11月  4 18:06:47 2019] sd 3:0:0:0: [sdb] 104857600 512-byte logical blocks: (53.6 GB/50.0 GiB)
[一 11月  4 18:06:47 2019] sd 3:0:0:0: [sdb] Write Protect is off
[一 11月  4 18:06:47 2019] sd 3:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[一 11月  4 18:06:47 2019] sd 3:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[一 11月  4 18:06:47 2019]  sdb: sdb1 sdb2 < sdb5 >
[一 11月  4 18:06:47 2019] sd 3:0:0:0: [sdb] Attached SCSI disk
[一 11月  4 18:07:02 2019] EXT4-fs (sdb1): mounted filesystem without journal. Opts: (null)

复盘捞到的 syslog 日志

Nov  4 18:06:57 vb systemd[1]: Device dev-disk-by\x2duuid-5241a10b\x2d5dde\x2d4051\x2d8d8b\x2d05718dd56445.device appeared twice with different sysfs paths /sys/devices/pci0000:00/0000:00:0d.0/ata4/host3/target3:0:0/3:0:0:0/block/sdb/sdb5 and /sys/devices/pci0000:00/0000:00:0d.0/ata5/host4/target4:0:0/4:0:0:0/block/sdc/sdc5
Nov  4 18:06:57 vb kernel: [    6.754716] sd 4:0:0:0: [sdc] 104857600 512-byte logical blocks: (53.6 GB/50.0 GiB)
Nov  4 18:06:57 vb kernel: [    6.754744] sd 4:0:0:0: [sdc] Write Protect is off
Nov  4 18:06:57 vb kernel: [    6.754747] sd 4:0:0:0: [sdc] Mode Sense: 00 3a 00 00
Nov  4 18:06:57 vb kernel: [    6.754757] sd 4:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Nov  4 18:06:57 vb kernel: [    6.767797]  sdc: sdc1 sdc2 < sdc5 >
Nov  4 18:06:57 vb kernel: [    6.768061] sd 4:0:0:0: [sdc] Attached SCSI disk

磁盘自检失败，进入emergency mode

修复参考方案：https://www.jianshu.com/p/7433e0bb38e9

1
2
3

welcome to emergency mode. ......  journalctl -xb...
Press enter for maintenance
(or type Control-D to continue): 

解决方法有两个：

第一种：跳过检测受损分区

１、按照提示　执行　journalctl -xb

　　在日志记录中向下翻页找到损坏的分区是哪个，一般是红色的字体，也可以输入/ fsck fail，按N/n来快速查找（我的是/dev/sda11，这个分区我挂载的是/home）

２、vi /etc/fstab

编辑fstab这个文件，注释掉对应的mount行。或将损坏的分区后面的数字从２改为０（０代表启动时不检查该分区）

３、执行reboot 　重启

第二种方法：修复受损的分区

１、执行命令 umount /dev/sdb1 （对应自己出错的设备）卸载设备;

２、执行命令 fsck -y /dev/sdb1 执行fsck校验并修复文件;

3、重新mount就可以使用了

两种方法我都解决了我的问题，不过我还是使用了第二种，第一种总感觉治标不治本！

奇葩问题

virtualbox 太多命名其妙的问题了，争取早日换掉

磁盘uuid重复后，生成新的uuid

[/drives/c/Program Files/Oracle/VirtualBox]
$./VBoxManage.exe internalcommands sethduuid “D:\vb\ubuntu-disk.vmdk”

Windows系统突然dns不工作了

VirtualBox为啥导致了这个问题就是一个很偏的方向，我实在无能为力了，尝试找到了一个和VirtualBox的DNS相关的开关命令，只能死马当活马医了（像极了算命大师和老中医）

./VBoxManage.exe  modifyvm "ubuntu" --natdnshostresolver1 on

ubuntu 鼠标中键不能复制粘贴的恢复办法 gpointing-device-settings

http://askubuntu.com/questions/302077/how-to-enable-paste-in-terminal-with-middle-mouse-button

ubuntu无法关闭锁屏，无法修改配置：

sudo mv ~/.config/dconf ~/.config/dconf.bak //删掉dconf就好了
https://unix.stackexchange.com/questions/296231/cannot-save-changes-made-in-gnome-settings

感受

自己不懂 /dev/sdb 导致了这次问题

这种错误居然从virtualbox或者ubuntu的系统日志中找不到相关信息，这个应该是没有触发挂载。自己对mount、fsck不够熟悉也是主要原因，运气好在fsck 居然没丢任何数据

历史老问题

这种额外挂载的磁盘在ubuntu下启动后不会出现，需要在ubuntu文件系统中人肉访问一次，就触发了挂载动作，然后在bash中才可以正常使用，这个问题我折腾了N年都没解决，实际这次发现是自己对挂载、fstab不够了解。

在 /etc/fstab 中增加boot时挂载这个问题终于解决掉了

UUID=a64abcac-657d-42ee-8e7b-575eac99bce3 /media/ren/a64abcac-657d-42ee-8e7b-575eac99bce3  ext4 defaults 1 1

epoll和惊群

本文尝试追踪不同的内核版本增加的方案来看内核是如何来尝试解决惊群问题的。以及像 SO_REUSEPORT 和EPOLLEXCLUSIVE又带来了什么小问题。

什么是惊群

惊群效应也有人叫做雷鸣群体效应，惊群就是多进程（多线程）在同时阻塞等待同一个事件的时候（休眠状态），如果等待的这个事件发生，那么他就会唤醒等待的所有进程（或者线程），但是最终却只可能有一个进程（线程）获得这个事件的“控制权”，对该事件进行处理，而其他进程（线程）获取“控制权”失败，只能重新进入休眠状态，这种现象和性能浪费就叫做惊群。

惊群的本质在于多个线程处理同一个事件。

为了更好的理解何为惊群，举一个很简单的例子，当你往一群鸽子中间扔一粒谷子，所有的鸽子都被惊动前来抢夺这粒食物，但是最终只有一只鸽子抢到食物。这里鸽子表示进程（线程），那粒谷子就是等待处理的事件。

linux 内核通过睡眠队列来组织所有等待某个事件的 task，而 wakeup 机制则可以异步唤醒整个睡眠队列上的 task，wakeup 逻辑在唤醒睡眠队列时，会遍历该队列链表上的每一个节点，调用每一个节点的 callback，从而唤醒睡眠队列上的每个 task，为什么要欢行所有的task，关键在于内核不知道这个消息是一个task处理就够了还是从逻辑上这些wakeup的所有task都要处理，所以只能全部唤醒。这样，在一个 connect 到达这个 lisent socket 的时候，内核会唤醒所有睡眠在 accept 队列上的 task。N 个 task 进程(线程)同时从 accept 返回，但是，只有一个 task 返回这个 connect 的 fd，其他 task 都返回-1(EAGAIN)。这是典型的 accept”惊群”现象。

如果一个连接的请求需要通知多个线程，就容易出现惊群。比如accept，一般都是一个线程负责accept新连接然后分发，这样不会有惊群，但是如果一个线程成为瓶颈那么就要安排多个线程来accept，当有新连接进来默认只能通知所有线程都来处理，这就是惊群。如果用reuseport来用多个线程监听同一个端口的话，在内核层面会通过hash将新连接派发给一个具体的worker这样也不会有惊群了。

连接建立后，一般的处理逻辑就是将连接一对一挂到一个epoll 红黑树上，一般会有多个epoll 红黑树，然后每个epoll都由一个固定的线程来处理上面的消息，这种是不会有惊群的。也是典型的server处理模式（nginx、tomcat、netty都是如此）

关键点：多个进程监听相同事件（或者说一个epoll有多个进程来处理）

先上总结

如果服务器采用accept阻塞调用方式群在2.6内核就通过增加WQ_FLAG_EXCLUSIVE在内核中就行排他解决惊群了；

只有epoll的accept才有惊群，这是因为epoll监听句柄中后续可能是accept(建连接)，也有可能是read/write网络IO事件，accept有时候一个进程处理不过来、或者accept跟读写混用进程处理，所以内核层面没直接解决epoll的惊群，交由上层应用来根据IO事件如何处理。

epoll的惊群在3.10内核加了SO_REUSEPORT来解决惊群，但如果处理accept的worker也要处理read/write（Nginx的工作方式）就可能导致不同的worker有的饥饿有的排队假死一样；4.5的内核增加EPOLLEXCLUSIVE在内核中直接将worker放在一个大queue，同时感知worker状态来派发任务更好地解决了惊群，但是因为LIFO的机制导致在压力不大的情况下，任务主要派发给少数几个worker（能接受，压力大就会正常了）。

无IO复用时Accept

无IO复用（就只能一个进程监听listen 端口）的accept 不会有惊群，epoll_wait 才会。accept一定是只需要一个进程处理消息，内核可以解决。但是select、epoll就不一定了，所以内核只能唤醒所有的。

在linux2.6版本以后，linux内核已经解决了accept()函数的“惊群”现象，大概的处理方式就是，当内核接收到一个客户连接后，只会唤醒等待队列上的第一个进程（线程）,所以如果服务器采用accept阻塞调用方式，在2.6的linux系统中已经没有“惊群效应”了。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

 /* nr_exclusive的值默认设为1 */
 #define wake_up_interruptible_sync_poll(x, m)              \
    __wake_up_sync_key((x), TASK_INTERRUPTIBLE, 1, (void *) (m))

tcp_v4_rcv
tcp_v4_do_rcv
tcp_child_process
sock_def_readable
wake_up_interruptible_sync_poll
__wake_up_common
 /* 从头遍历监听socket的等待队列，唤醒等待进程，有EXCLUSIVE标识时只唤醒一个进程 */
list_for_each_entry_safe(curr, next, &q->task_list, task_list)
    /* func最终调用try_to_wake_up，设置进程状态为TASK_RUNNING，并把进程插入CPU运行队列，来唤醒睡眠的进程 */
    if (curr->func(curr, mode, wake_flags, key) && (flags & WQ_FLAG_EXCLUSIVE)  &&
       !--nr_exclusive)
       break; 

sock中定义了几个I/O事件，当协议栈遇到这些事件时，会调用它们的处理函数。当监听socket收到新的连接时，会触发有数据可读事件，调用sock_def_readable，唤醒socket等待队列中的进程。进程被唤醒后，会执行accept的后续操作，最终返回新连接的描述符。

这个socket等待队列是一个FIFO，所以最终是均衡的，也不需要惊群，有tcp connection ready的话直接让等待队列中第一个的线程出队就好了。

2.6内核层面添加了一个WQ_FLAG_EXCLUSIVE标记，告诉内核进行排他性的唤醒，即唤醒一个进程后即退出唤醒的过程(适合accept，但是不适合 epoll–因为epoll除了有accept，还有其它IO事件）

所以这就是大家经常看到的accept不存在惊群问题，内核10年前就解决了这个问题的场景，实际指的是非epoll下的accept 惊群。

epoll的Accept

epoll监听句柄，后续可能是accept，也有可能是read/write网络IO事件，这些IO事件不一定只能由一个进程处理（很少见需要多个进程处理的），所以内核层面没直接解决epoll的惊群，交由上层应用来根据IO事件如何处理。

也就是只要是epoll事件，os默认会唤醒监听这个epoll的所有线程。所以常见的做法是一个epoll绑定到一个thread。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

//主进程中：
ngx_init_cycle
ngx_open_listening_sockets
    socket
    bind
    listen
    epoll_create
    epoll_ctl

//子进程中：
ngx_event_process_init
ngx_prcocess_events_and_timers
ngx_epoll_process_events
    epoll_wait
    rev->handler(rev) // 对于listening socket，handler是ngx_event_accept

和普通的accept不同，使用epoll时，是在epoll_wait()返回后，发现监听socket有可读事件，才调用accept()。由于epoll_wait()是LIFO，导致多个子进程在accept新连接时，也变成了LIFO。

epoll_wait
ep_poll
    /* 创建等待任务，把等待任务加入到epfd等待队列的头部，而不是尾部 */
    init_waitqueue_entry(&wait, current) 
    __add_wait_queue_exclusive(&ep->wq, &wait)
    ...
    __remove_wait-queue(&ep->wq, &wait) /* 最终从epfd等待队列中删除 */

回调触发逻辑：

tcp_v4_rcv
tcp_v4_do_rcv
tcp_child_process
sock_def_readable /* sock I/O 有数据可读事件 */
wake_up_interruptible_sync_poll
__wake_up_common
    /* curr->func是等待任务的回调函数，在ep_insert初始化等待任务时，设置为ep_poll_callback */
    if (curr->func(curr, mode, wake_flags, key) && (flags & WQ_FLAG_EXCLUSIVE)  &&
        !--nr_exclusive)
        break;

那么这种情况下内核如何来解决惊群呢？

SO_REUSEPORT

虽然通过将一个epoll绑定到一个thread来解决竞争问题，但是对于高并发的处理一个thread明显不够，所以有时候不得不设置多个thread来处理一个epoll上的所有socket事件（比如accept）

在3.10的内核中通过引入SO_REUSEPORT解决了这个epoll accept惊群的问题。

linux man文档中一段文字描述其作用：

The new socket option allows multiple sockets on the same host to bind to the same port, and is intended to improve the performance of multithreaded network server applications running on top of multicore systems.

SO_REUSEPORT支持多个进程或者线程绑定到同一端口，提高服务器程序的性能，解决的问题：

• 允许多个套接字 bind()/listen() 同一个TCP/UDP端口
• 每一个线程拥有自己的服务器套接字
• 在服务器套接字上没有了锁的竞争
• 内核层面实现负载均衡，内核通过socket的五元组来hash到不同的socket listener上
• 安全层面，监听同一个端口的套接字只能位于同一个用户下面

其核心的实现主要有三点：

• 扩展 socket option，增加 SO_REUSEPORT 选项，用来设置 reuseport。
• 修改 bind 系统调用实现，以便支持可以绑定到相同的 IP 和端口
• 修改处理新建连接的实现，查找 listener 的时候，能够支持在监听相同 IP 和端口的多个 sock 之间均衡选择。

• Nginx的accept_mutex通过抢锁来控制是否将监听套接字加入到epoll 中。监听套接字只在一个子进程的 epoll 中，当新的连接来到时，其他子进程当然不会惊醒了。通过 accept_mutex加锁性能要比reuseport差
• Linux内核解决了epoll_wait 惊群的问题，Nginx 1.9.1利用Linux3.10 的reuseport也能解决惊群、提升性能。
• 内核的reuseport中相当于所有listen同一个端口的多个进程是一个组合，内核收包时不管查找到哪个socket，都能映射到他们所属的 reuseport 数组，再通过五元组哈希选择一个socket，这样只有这个socket队列里有数据，所以即便所有的进程都添加了epoll事件，也只有一个进程会被唤醒。

以nginx为例，一个worker处理一个epoll(对应一个红黑树)上的所有事件，一般连接新建由accept线程专门处理，连接建立后会加入到某个epoll上，也就是以后会由一个固定的worker/线程来处理。

• 每个 Worker 都会有一个属于自己的 epoll 对象
• 每个 Worker 会关注所有的 listen 状态上的新连接事件（可以通过accept_mutex或者reuseport来解决惊群）
• 对于用户连接，只有一个 Worker 会处理，其它 Worker 不会持有该用户连接的 socket（不会惊群）

当有包进来，根据5元组，如果socket是ESTABLISHED那么直接给对应的socket，如果是握手，则跟据SO_REUSEPORT匹配到对应的监听port的多个线程中的一个

因为Established socket对应于一个唯一的worker，其上所有的读写事件一般是只有一个worker在监听一个的epoll，所以不存在惊群。Listen Socket才可能会对应多个worker，才有可能惊群。

图片来自：https://wenfh2020.com/2021/11/22/question-thundering-herd/

Nginx下SO_REUSEPORT 带来的小问题

从下图可以看出Nginx的一个worker即处理上面的accept也处理对应socket的read/write，如果一个read/write比较耗时的话也会影响到这个worker下的别的socket上的read/write或者accept

SO_REUSEPORT打开后，去掉了上图的共享锁，变成了如下结构：

再有请求进来不再是各个进程一起去抢，而是内核通过五元组Hash来分配，所以不再会惊群了。但是可能会导致撑死或者饿死的问题，比如一个worker一直在做一件耗时的任务（比如压缩、解码），但是内核通过hash分配新连接过来的时候是不知道worker在忙（抢锁就不会发生这种情况，你没空就不会去抢），以Nginx为例

因为Nginx是ET模式，epoll处理worker要一直将事件处理完毕才能进入epoll_wait（才能响应新的请求）。带来了新的问题：如果有一个慢请求（比如gzip压缩文件需要2分钟），那么处理这个慢请求的进程在reuseport模式下还是会被内核分派到新的连接（或者这个worker上的其它请求），但是这个时候worker一直在压缩如同hang死了，新分配进来的请求无法处理。如果不是reuseport模式，他在处理慢请求就根本腾不出来时间去在惊群中抢到锁。但是还是会影响Established 连接上的请求，这个影响和Reuseport没有关系，是一个线程处理多个Socket带来的必然结果 当然这里如果Nginx把accept和read/write分开用不同的线程来处理也不会有这个问题，毕竟accept正常都很快。

上面Nginx Hang死的原因是：Nginx 使用了边缘触发模式，因此Nginx 在套接字有可读性事件的情况下，必须把所有数据都读掉才行，在gzip buffer < connection rcvbuf 同时后端比较快时候，一次性读不完连接上所有数据，就会出现读数据->压缩->新数据到达->继续读数据-> 继续压缩… 的循环，由于压缩需要时间，此时套接字上又来了新的数据，只要数据来的速度比压缩的快，就会出现数据一直读不完的情况，CPU 就一直切不出去。

解决：OSS gzip_buffers 配置为 64*8k = 512K，给后端进程增加了设置sndbuf/rcvbuf 指令之后通过配置Tengine 与后 oss_server 之间的连接的rcvbuf 到512k 以内，这样就能解决这个问题了，实测这个修改几乎不影响后端整体吞吐，同时也不会出现Nginx worker Hang 的情况。

如果不开启SO_REUSEPORT模式，那么即使有一个worker在处理慢请求，那么他就不会去抢accept锁，也就没有accept新连接，这样就不应影响新连接的处理。当然也有极低的概率阻塞accept（准确来说是刚accept，还没处理完accept后的请求，就又切换到耗时的处理去了，导致这个新accept的请求没得到处理）

开了reuse_port 之后每个worker 都单独有个syn 队列，能按照nginx worker 数成倍提升抗synflood 攻击能力。

但是开启了SO_REUSEPORT后，内核没法感知你的worker是不是特别忙，只是按Hash逻辑派发accept连接。也就是SO_REUSEPORT会导致rt偏差更大（抖动明显一些）。这跟MySQL Thread Pool导致的卡顿原理类似，多个Pool类似这里的SO_REUSEPORT。

用图形展示大概如下：

比如中间的worker即使处理得很慢，内核还是正常派连接过来，即使其它worker空闲, 这会导致 RT 抖动加大：

Here is the same test run against the SO_REUSEPORT multi-queue NGINX setup (c):

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

$ ./benchhttp -n 100000 -c 200 -r target:8181 http://a.a/
        | cut -d " " -f 1
        | ./mmhistogram -t "Duration in ms (multiple queues)"
min:1.49 avg:31.37 med=24.67 max:144.55 dev:25.27 count:100000
Duration in ms (multiple queues):
 value |-------------------------------------------------- count
     0 |                                                   0
     1 |                                                 * 1023
     2 |                                         ********* 5321
     4 |                                 ***************** 9986
     8 |                  ******************************** 18443
    16 |    ********************************************** 25852
    32 |************************************************** 27949
    64 |                              ******************** 11368
   128 |                                                   58

相对地一个accept queue多个 worker的模式 running against a single-queue NGINX:

1
2
3
4
5
6
7
8
9
10
11
12
13
14

$ ./benchhttp -n 100000 -c 200 -r target:8181 http://a.a/
        | cut -d " " -f 1
        | ./mmhistogram -t "Duration in ms (single queue)"
min:3.61 avg:30.39 med=30.28 max:72.65 dev:1.58 count:100000
Duration in ms (single queue):
 value |-------------------------------------------------- count
     0 |                                                   0
     1 |                                                   0
     2 |                                                   1
     4 |                                                   16
     8 |                                                   67
    16 |************************************************** 91760
    32 |                                              **** 8155
    64 |                                                   1

可以看到一个accept queue多个 worker的模式下 RT 极其稳定

SO_REUSEPORT另外的问题

在OS层面一个连接hash到了某个socket fd，但是正好这个 listen socket fd 被关了，已经被分到这个 listen socket fd 的 accept 队列上的请求会被丢掉，具体可以参考 和 LWN 上的 comment

从 Linux 4.5 开始引入了 SO_ATTACH_REUSEPORT_CBPF 和 SO_ATTACH_REUSEPORT_EBPF 这两个 BPF 相关的 socket option。通过巧妙的设计，应该可以避免掉建连请求被丢掉的情况。

EPOLLEXCLUSIVE

epoll引起的accept惊群，在4.5内核中再次引入EPOLLEXCLUSIVE来解决，且需要应用层的配合，Ngnix 在 1.11.3 之后添加了NGX_EXCLUSIVE_EVENT来支持。像tengine尚不支持，所以只能在应用层面上来避免惊群，开启accept_mutex才可避免惊群。

在epoll_ctl ADD描述符时设置 EPOLLEXCLUSIVE 标识。

1
2
3
4
5
6
7
8
9
10
11
12
13
14

epoll_ctl
ep_insert
ep_ptable_queue_proc
    /* 在这里，初始化等待任务，把等待任务加入到socket等待队列的头部 */
     * 注意，和标准accept的等待任务不同，这里并没有给等待任务设置WQ_FLAG_EXCLUSIVE。
     */
    init_waitqueue_func_entry(&pwq->wait, ep_poll_callback);
    /* 检查应用程序是否设置了EPOLLEXCLUSIVE标识 */
    if (epi->event.events & EPOLLEXCLUSIVE)
        /* 新增逻辑，等待任务携带WQ_FLAG_EXCLUSIVE标识，之后只唤醒一个进程 */
        add_wait_queue_exclusive(whead, &pwq->wait);
    else
        /* 原来逻辑，等待任务没有WQ_FLAG_EXCLUSIVE标识，会唤醒所有等待进程 */
        add_wait_queue(whead, &pwq->wait);

在加入listen socket的sk_sleep队列的唤醒队列里使用了 add_wait_queue_exculsive()函数，当tcp收到三次握手最后一个 ack 报文时调用sock_def_readable时，只唤醒一个等待源，从而避免‘惊群’.
调用栈如下：

//  tcp_v4_do_rcv()
//  -->tcp_child_process()
//  --->sock_def_readable()
//  ---->wake_up_interruptible_sync_poll()
//  ----->__wake_up_sync_key()

EPOLLEXCLUSIVE可以在单个Listen Queue对多个Worker Process的时候均衡压力，不会惊群。

连接从一个队列里由内核分发，不需要惊群，对worker是否忙也能感知（忙的worker就不分发连接过去）

图中的电话机相当于一个worker，只是实际内核中空闲的worker像是在一个堆栈中（LIFO），有连接过来，worker堆栈会出栈，处理完毕又入栈，如此反复。而需要处理的消息是一个队列（FIFO），所以总会发现栈顶的几个worker做的事情更多。

多个worker共享一个 accept queue 带来的问题

下面这个case是观察发现Nginx在压力不大的情况下会导致最后几个核cpu消耗时间更多一些，如下图看到的：

这是如前面所述，所有worker像是在一个栈（LIFO）中等着任务处理，在压力不大的时候会导致连接总是在少数几个worker上（栈底的worker没什么机会出栈），如果并发任务多，导致worker栈经常空掉，这个问题就不存在了。当然最终来看EPOLLEXCLUSIVE没有产生什么实质性的不好的影响。值得推荐

图中LIFO场景出现是在多个worker共享一个accept queue的epoll场景下，如果用 SO_REUSEPORT 搞成每个worker一个accept queue就不存在这个问题了

epoll的accept模型为LIFO，倾向于唤醒最活跃的进程。多进程场景下：默认的accept(非复用)是FIFO，进程加入到监听socket等待队列的尾部，唤醒时从头部开始唤醒；epoll的accept是LIFO，在epoll_wait时把进程加入到监听socket等待队列的头部，唤醒时从头部开始唤醒。

当并发数较小时，只有最后几个进程会被唤醒，它们使用的CPU时间会远高于其它进程。当并发数较大时，所有的进程都有机会被唤醒，各个进程之间的差距不大。内核社区中关于epoll accept是使用LIFO还是RR有过讨论，在4.9内核和最新版本中使用的都是LIFO。

比如这个case，压力低的worker进程和压力高的worker进程差异比较大：

比较下EPOLLEXCLUSIVE 和 SO_REUSEPORT

EPOLLEXCLUSIVE 和 SO_REUSEPORT 都是在内核层面将连接分到多个worker，解决了epoll下的惊群，SO_REUSEPORT 会更均衡一些，EPOLLEXCLUSIVE在压力不大的时候会导致连接总是在少数几个worker上（但这个不会产生任何不利影响）。 SO_REUSEPORT在最坏的情况下会导致一个worker即使Hang了，OS也依然会派连接过去，这是非常致命的，所以4.5内核引入了 EPOLLEXCLUSIVE（总是给闲置等待队列的第一个worker派连接）

相对 SO_REUSEPORT导致的stuck, EPOLLEXCLUSIV 还是更好接受一些。

参考资料

Linux惊群效应详解（最详细的了吧）

再谈Linux epoll惊群问题的原因和解决方案

epoll lifo引发的nginx “负载不均”

Why does one NGINX worker take all the load?

一次Nginx Gzip 导致的诡异健康检查失败问题调查

Gzip 导致 Nginx worker Hang 问题解法

Socket多进程分发原理

从SO_REUSEPORT服务器的一个弊端看多队列服务模型

https://my.oschina.net/alchemystar/blog/3008840

前言

本文希望解析清楚，当我们在代码中写下 socket.setSendBufferSize 和 sysctl 看到的rmem/wmem系统参数以及最终我们在TCP常常谈到的接收发送窗口的关系，以及他们怎样影响TCP传输的性能，同时如何通过图形来展示哪里是传输瓶颈。

拥塞窗口相关文章比较多，他们跟带宽紧密相关，所以大家比较好判断，反而是接收、发送窗口一旦出现瓶颈，就没这么好判断了。

先明确一下：文章标题中所说的Buffer指的是sysctl中的 rmem或者wmem，如果是代码中指定的话对应着SO_SNDBUF或者SO_RCVBUF，从TCP的概念来看对应着发送窗口或者接收窗口

最后补充各种场景下的传输案例，一站式将影响传输速度的各种原因都拿下，值得收藏。

本文主要分析rt、buffer如何影响TCP的传输性能，更多其他因素影响TCP性能的案例见：TCP传输速度案例分析

TCP性能和发送接收Buffer的关系

先从碰到的一个实际问题看起：

应用通过专线跨网络访问云上的服务，专线100M，时延20ms，一个SQL查询了22M数据，结果花了大概25秒，这太慢了，不正常。

如果通过云上client访问云上服务执行这个SQL那么1-2秒就返回了（不跨网络服务是正常的，说明服务本身没有问题）。

如果通过http或者scp从云下向云上传输这22M的数据大概两秒钟也传送完毕了（说明网络带宽不是瓶颈），

所以这里问题的原因基本上是我们的服务在这种网络条件下有性能问题，需要找出为什么。

抓包分析 tcpdump+wireshark

抓包分析这22M的数据传输，如下图（wireshark 时序图），横轴是时间，纵轴是sequence number：

粗一看没啥问题，因为时间太长掩盖了问题。把这个图形放大，只看中间50ms内的传输情况（横轴是时间，纵轴是sequence number，一个点代表一个包）

可以看到传输过程总有一个20ms的等待平台，这20ms没有发送任何包，换个角度，看看窗口尺寸图形：

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

我们的应用代码中会默认设置 socketSendBuffer 为16K:

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

原理解析

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

比如下图，wmem大小是8，发出1-8后，buffer不能释放，等到收到ack1-4后，释放1-4，buffer也就是释放了一半，这一半可以填充新的发送数据进来了。 上面的问题在于ack花了很久，导致buffer一直不能释放。

sendbuffer相当于发送仓库的大小，仓库的货物都发走后，不能立即腾出来发新的货物，而是要等对方确认收到了(ack)才能腾出来发新的货物。 传输速度取决于发送仓库（sendbuffer）、接收仓库（recvbuffer）、路宽（带宽）的大小，如果发送仓库（sendbuffer）足够大了之后接下来的瓶颈就会是高速公路了（带宽、拥塞窗口）。而实际上这个案例中带宽够、接收仓库也够，但是发送仓库太小了，导致发送过程断断续续，所以非常慢。

如果是UDP，就没有可靠的概念，有数据统统发出去，根本不关心对方是否收到，也就不需要ack和这个发送buffer了。

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

$sudo sysctl -a | egrep "rmem|wmem|tcp_mem|adv_win|moderate"
net.core.rmem_default = 212992
net.core.rmem_max = 212992
net.core.wmem_default = 212992 //core是给所有的协议使用的,
net.core.wmem_max = 212992
net.ipv4.tcp_adv_win_scale = 1 //
net.ipv4.tcp_moderate_rcvbuf = 1
net.ipv4.tcp_rmem = 4096	87380	6291456  //最小值  默认值  最大值
net.ipv4.tcp_wmem = 4096	16384	4194304 //tcp这种就自己的专用选项就不用 core 里面的值了
net.ipv4.udp_rmem_min = 4096
net.ipv4.udp_wmem_min = 4096
vm.lowmem_reserve_ratio = 256	256	32
net.ipv4.tcp_mem = 88560        118080  177120
vm.lowmem_reserve_ratio = 256   256     32

net.ipv4.tcp_wmem 默认就是16K，而且内核是能够动态调整的，只不过我们代码中这块的参数是很多年前从 Cobar 中继承过来的，初始指定了sendbuffer的大小。代码中设置了这个参数后就关闭了内核的动态调整功能，这就是为什么http或者scp都很快，因为他们的send buffer是动态调整的。

接收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（消掉了握手和慢启动阶段），这基本上是理论上最快速度了

如果调用setsockopt()设置了socket选项SO_SNDBUF，将关闭发送端缓冲的自动调节机制，tcp_wmem将被忽略，SO_SNDBUF的最大值由net.core.wmem_max限制。

这个案例关于wmem的结论

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

从这里我们可以看到，有些理论知识点虽然我们知道，但是在实践中很难联系起来，也就是常说的无法学以致用，最开始看到抓包结果的时候比较怀疑发送、接收窗口之类的，没有直接想到send buffer上，理论跟实践没联系上。

BDP(Bandwidth-Delay Product) 带宽时延积

BDP=rtt*(带宽/8)

这个 buffer 调到1M测试没有帮助，从理论计算BDP（带宽时延积） 0.02秒*(100Mb/8)=250KB 所以 *SO_SNDBUF为256Kb的时候基本能跑满带宽了，再大也没有什么实际意义了 。也就是前面所说的仓库足够后瓶颈在带宽上了。

因为这里根据带宽、rtt计算得到的BDP是250K，BDP跑满后拥塞窗口（带宽、接收窗口和rt决定的）即将成为新的瓶颈，所以调大buffer没意义了。

Bandwidth-delay product (BDP)

Product of data link’s capacity and its end-to-end delay. The result is the maximum amount of unacknowledged data that can be in flight at any point in time.

接下来看看接收buffer(rmem)和接收窗口的关系

用这样一个案例下来验证接收窗口的作用：

有一个batch insert语句，整个一次要插入5532条记录，所有记录大小总共是376K，也就是这个sql语句本身是376K。

SO_RCVBUF很小的时候并且rtt很大对性能的影响

如果rtt是40ms，总共需要5-6秒钟：

基本可以看到server一旦空出来点窗口，client马上就发送数据，由于这点窗口太小，rtt是40ms，也就是一个rtt才能传3456字节的数据，整个带宽才用到80-90K，完全没跑满。

比较明显间隔 40ms 一个等待台阶，台阶之间两个包大概3K数据，总的传输效率如下：

斜线越陡表示速度越快，从上图看整体SQL上传花了5.5秒，执行0.5秒。

此时对应的窗口尺寸：

窗口由最开始28K(20个1448）很快降到了不到4K的样子，然后基本游走在即将满的边缘，虽然读取慢，幸好rtt也大，导致最终也没有满。（这个是3.1的Linux，应用SO_RCVBUF设置的是8K，用一半来做接收窗口）

SO_RCVBUF很小的时候并且rtt很小对性能的影响

如果同样的语句在 rtt 是0.1ms的话

虽然明显看到接收窗口经常跑满，但是因为rtt很小，一旦窗口空出来很快就通知到对方了，所以整个过小的接收窗口也没怎么影响到整体性能

如上图11.4秒整个SQL开始，到11.41秒SQL上传完毕，11.89秒执行完毕（执行花了0.5秒），上传只花了0.01秒

接收窗口情况：

如图，接收窗口由最开始的28K降下来，然后一直在5880和满了之间跳动

从这里可以得出结论，接收窗口的大小对性能的影响，rtt越大影响越明显，当然这里还需要应用程序配合，如果应用程序一直不读走数据即使接收窗口再大也会堆满的。

SO_RCVBUF和tcp window full的坏case

上图中红色平台部分，停顿了大概6秒钟没有发任何有内容的数据包，这6秒钟具体在做什么如下图所示，可以看到这个时候接收方的TCP Window Full，同时也能看到接收方（3306端口）的TCP Window Size是8192（8K），发送方（27545端口）是20480.

这个状况跟前面描述的recv buffer太小不一样，8K是很小，但是因为rtt也很小，所以server总是能很快就ack收到了，接收窗口也一直不容易达到full状态，但是一旦接收窗口达到了full状态，居然需要惊人的6秒钟才能恢复，这等待的时间有点太长了。这里应该是应用读取数据太慢导致了耗时6秒才恢复，所以最终这个请求执行会非常非常慢（时间主要耗在了上传SQL而不是执行SQL）.

实际原因不知道，从读取TCP数据的逻辑来看这里没有明显的block，可能的原因：

• request的SQL太大，Server（3306端口上的服务）从TCP读取SQL需要放到一块分配好的内存，内存不够的时候需要扩容，扩容有可能触发fgc，从图形来看，第一次满就卡顿了，而且每次满都卡顿，不像是这个原因
• request请求一次发过来的是多个SQL，应用读取SQL后，将SQL分成多个，然后先执行第一个，第一个执行完后返回response，再读取第二个。图形中卡顿前没有response返回，所以也不是这个原因
• ……其它未知原因

接收方不读取数据导致的接收窗口满同时有丢包发生

服务端返回数据到client端，TCP协议栈ack这些包，但是应用层没读走包，这个时候 SO_RCVBUF 堆积满，client的TCP协议栈发送 ZeroWindow 标志给服务端。也就是接收端的 buffer 堆满了（但是服务端这个时候看到的bytes in fly是0，因为都ack了），这时服务端不能继续发数据，要等 ZeroWindow 恢复。

那么接收端上层应用不读走包可能的原因：

• 应用代码卡顿、GC等等
• 应用代码逻辑上在做其它事情（比如Server将SQL分片到多个DB上，Server先读取第一个分片，如果第一个分片数据很大很大，处理也慢，那么即使第二个分片数据都返回到了TCP 的recv buffer，应用也没去读取其它分片的结果集，直到第一个分片读取完毕。如果SQL带排序，那么Server会轮询读取多个分片，造成这种卡顿的概率小了很多）

上图这个流因为应用层不读取TCP数据，导致TCP接收Buffer满，进而接收窗口为0，server端不能再发送数据而卡住，但是ZeroWindow的探测包，client都有正常回复，所以1903秒之后接收方窗口不为0后（window update）传输恢复。

这个截图和前一个类似，是在Server上(3003端口)抓到的包，不同的是接收窗口为0后，server端多次探测（Server上抓包能看到），但是client端没有回复 ZeroWindow（也有可能是回复了，但是中间环节把ack包丢了,或者这个探测包client没收到），造成server端认为client死了、不可达之类，进而反复重传，重传超过15次之后，server端认为这个连接死了，粗暴单方面断开（没有reset和fin,因为没必要，server认为网络连通性出了问题）。

等到1800秒后，client的接收窗口恢复了，发个window update给server，这个时候server认为这个连接已经断开了，只能回复reset

网络不通，重传超过一定的时间（tcp_retries2)然后断开这个连接是正常的，这里的问题是：

1. 为什么这种场景下丢包了，而且是针对某个stream一直丢包

可能是因为这种场景下触发了中间环节的流量管控，故意丢包了（比如proxy、slb、交换机都有可能做这种选择性的丢包）

这里server认为连接断开，没有发reset和fin,因为没必要，server认为网络连通性出了问题。client还不知道server上这个连接清理掉了，等client回复了一个window update，server早就认为这个连接早断了，突然收到一个update，莫名其妙，只能reset

接收窗口和SO_RCVBUF的关系

ss 查看socket buffer大小

初始接收窗口一般是 mss乘以初始cwnd（为了和慢启动逻辑兼容，不想一下子冲击到网络），如果没有设置SO_RCVBUF，那么会根据 net.ipv4.tcp_rmem 动态变化，如果设置了SO_RCVBUF，那么接收窗口要向下面描述的值靠拢。

初始cwnd可以大致通过查看到：

ss -itmpn dst "10.81.212.8"
State      Recv-Q Send-Q Local Address:Port  Peer Address:Port
ESTAB      0      0      10.xx.xx.xxx:22     10.yy.yy.yyy:12345  users:(("sshd",pid=1442,fd=3))
         skmem:(r0,rb369280,t0,tb87040,f4096,w0,o0,bl0,d92)

Here we can see this socket has Receive Buffer 369280 bytes, and Transmit Buffer 87040 bytes.Keep in mind the kernel will double any socket buffer allocation for overhead. 
So a process asks for 256 KiB buffer with setsockopt(SO_RCVBUF) then it will get 512 KiB buffer space. This is described on man 7 tcp. 

初始窗口计算的代码逻辑，重点在17行：

    /* TCP initial congestion window as per rfc6928 */
    #define TCP_INIT_CWND           10
    /* 3. Try to fixup all. It is made immediately after connection enters

       established state.
             */
            void tcp_init_buffer_space(struct sock *sk)
            {
          int tcp_app_win = sock_net(sk)->ipv4.sysctl_tcp_app_win;
          struct tcp_sock *tp = tcp_sk(sk);
          int maxwin;
        
        if (!(sk->sk_userlocks & SOCK_SNDBUF_LOCK))
                tcp_sndbuf_expand(sk);

		//初始最大接收窗口计算过程
        tp->rcvq_space.space = min_t(u32, tp->rcv_wnd, TCP_INIT_CWND * tp->advmss);
        tcp_mstamp_refresh(tp);
        tp->rcvq_space.time = tp->tcp_mstamp;
        tp->rcvq_space.seq = tp->copied_seq;

        maxwin = tcp_full_space(sk);

        if (tp->window_clamp >= maxwin) {
                tp->window_clamp = maxwin;

                if (tcp_app_win && maxwin > 4 * tp->advmss)
                        tp->window_clamp = max(maxwin -
                                               (maxwin >> tcp_app_win),
                                               4 * tp->advmss);
        }

        /* Force reservation of one segment. */
        if (tcp_app_win &&
            tp->window_clamp > 2 * tp->advmss &&
            tp->window_clamp + tp->advmss > maxwin)
                tp->window_clamp = max(2 * tp->advmss, maxwin - tp->advmss);

        tp->rcv_ssthresh = min(tp->rcv_ssthresh, tp->window_clamp);
        tp->snd_cwnd_stamp = tcp_jiffies32;
}

传输过程中，最大接收窗口会动态调整，当指定了SO_RCVBUF后，实际buffer是两倍SO_RCVBUF，但是要分出一部分（2^net.ipv4.tcp_adv_win_scale)来作为乱序报文缓存以及metadata

1. net.ipv4.tcp_adv_win_scale = 2 //2.6内核，3.1中这个值默认是1

如果SO_RCVBUF是8K，总共就是16K，然后分出2^2分之一，也就是4分之一，还剩12K当做接收窗口；如果设置的32K，那么接收窗口是48K（64-16）

​ static inline int tcp_win_from_space(const struct sock sk, int space)
​ {//space 传入的时候就已经是 2SO_RCVBUF了
​ int tcp_adv_win_scale = sock_net(sk)->ipv4.sysctl_tcp_adv_win_scale;

        return tcp_adv_win_scale <= 0 ?
                (space>>(-tcp_adv_win_scale)) :
                space - (space>>tcp_adv_win_scale); //sysctl参数tcp_adv_win_scale 
}

tcp_adv_win_scale 的取值

接收窗口有最大接收窗口和当前可用接收窗口。

一般来说一次中断基本都会将 buffer 中的包都取走。

绿线是最大接收窗口动态调整的过程，最开始是1460*10，握手完毕后略微调整到1472*10（可利用body增加了12），随着数据的传输开始跳涨

上图是四个batch insert语句，可以看到绿色接收窗口随着数据的传输越来越大，图中蓝色竖直部分基本表示SQL上传，两个蓝色竖直条的间隔代表这个insert在服务器上真正的执行时间。这图非常陡峭，表示上传没有任何瓶颈.

设置 SO_RCVBUF 后通过wireshark观察到的接收窗口基本

下图是设置了 SO_RCVBUF 为8192的实际情况：

从最开始的14720，执行第一个create table语句后降到14330，到真正执行batch insert就降到了8192*1.5. 然后一直保持在这个值

实验：分别改小server wmem/client rmem 来对比对速度的影响

server 设置 wmem=4096, client curl get server的文件，速度60mbps, 两边的rtt都很好

client 设置 rmem=4096，client curl get server的文件，速度6mbps, 为什么速度差别这么大？

为什么server 设置 wmem=4096后速度还是很快，因为server 每次收到ack，立即释放wmem来发新的网络包(内存级别的时延)，但如果rmem比较小当rmem满了到应用读走rmem，rmem有空闲后需要rtt时间反馈到server端server才会继续发包（网络级时延比内存级时延高几个数量级）。一句话总结：就是rmem从有空到包进来会有很大的间隔(rtt), wmem有空到写包进来没有时延

从kernel来看buffer相关信息

kernel相关参数

sudo sysctl -a | egrep "rmem|wmem|tcp_mem|adv_win|moderate"
net.core.rmem_default = 212992
net.core.rmem_max = 212992
net.core.wmem_default = 212992 //core是给所有的协议使用的,
net.core.wmem_max = 212992
net.ipv4.tcp_adv_win_scale = 1
net.ipv4.tcp_moderate_rcvbuf = 1
net.ipv4.tcp_rmem = 4096	87380	6291456
net.ipv4.tcp_wmem = 4096	16384	4194304 //tcp有自己的专用选项就不用 core 里面的值了
net.ipv4.udp_rmem_min = 4096
net.ipv4.udp_wmem_min = 4096
vm.lowmem_reserve_ratio = 256	256	32
net.ipv4.tcp_mem = 88560        118080  177120

发送buffer系统比较好自动调节，依靠发送数据大小和rt延时大小，可以相应地进行调整；但是接受buffer就不一定了，接受buffer的使用取决于收到的数据快慢和应用读走数据的速度，只能是OS根据系统内存的压力来调整接受buffer。系统内存的压力取决于 net.ipv4.tcp_mem.

需要特别注意：tcp_wmem 和 tcp_rmem 的单位是字节，而 tcp_mem 的单位的页面

kernel相关源码

从内核代码来看如果应用代码设置了sndbuf(比如java代码中：socket.setOption(sndbuf, socketSendBuffer))那么实际会分配socketSendBuffer*2的大小出来

比如应用代码有如下设置：

1
2
3
4
5
6
7
8
9
10
11

protected int socketRecvBuffer = 32 * 1024;   //接收32K
protected int socketSendBuffer = 64 * 1024;   //发送64K，实际会分配128K

     // If bufs set 0, using '/etc/sysctl.conf' system settings on default
     // refer: net.ipv4.tcp_wmem / net.ipv4.tcp_rmem
     if (socketRecvBuffer > 0) {
         socket.setReceiveBufferSize(socketRecvBuffer);
     }
     if (socketSendBuffer > 0) {
         socket.setSendBufferSize(socketSendBuffer);
     }

实际会看到这样的：

1
2

tcp ESTAB 45 0 10.0.186.140:3306 10.0.186.70:26494 skmem:(r768,rb65536,t0,tb131072,f3328,w0,o0,bl0,d0)
tcp ESTAB 0 0 10.0.186.140:3306 10.0.186.70:26546 skmem:(r0,rb65536,t0,tb131072,f4096,w0,o0,bl0,d0)

为什么kernel要double 接收和发送buffer可以参考man7中的socket帮助信息

tcp包发送流程

用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

内核观测tcp_mem是否不足

因 tcp_mem 达到限制而无法发包或者产生抖动的问题，我们也是可以观测到的。为了方便地观测这类问题，Linux 内核里面预置了静态观测点：sock_exceed_buf_limit（需要 4.16+ 的内核版本）。

$ echo 1 > /sys/kernel/debug/tracing/events/sock/sock_exceed_buf_limit/enable

然后去看是否有该事件发生：

$ cat /sys/kernel/debug/tracing/trace_pipe

如果有日志输出（即发生了该事件），就意味着你需要调大 tcp_mem 了，或者是需要断开一些 TCP 连接了。

或者通过systemtap来观察

如下是tcp_sendmsg流程，sk_stream_wait_memory就是tcp_wmem不够的时候触发等待：

如果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.

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

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

# 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

其它案例分析

从如下案例可以看到在时延5ms和1ms的时候，分别执行相同的SQL，SQL查询结果13M，耗时分别为4.6和0.8秒

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

$time mysql  -h127.1  -e "select * from test;" >/tmp/result.txt
real    0m3.078s
user    0m0.273s
sys     0m0.028s

$ping -c 1 127.0.0.1
PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data.
64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=5.01 ms

--- 127.0.0.1 ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 5.018/5.018/5.018/0.000 ms

$ls -lh /tmp/result.txt
-rw-rw-r-- 1 admin admin 13M Mar 12 12:51 /tmp/result.txt

//减小时延后继续测试
$ping 127.0.0.1
PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data.
64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=1.01 ms
64 bytes from 127.0.0.1: icmp_seq=2 ttl=64 time=1.02 ms
^C
--- 127.0.0.1 ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1001ms
rtt min/avg/max/mdev = 1.016/1.019/1.022/0.003 ms

$time mysql  -h127.1  -e "select * from test;" >/tmp/result.txt
real    0m0.838s
user    0m0.271s
sys     0m0.030s

//通过ss可以看到这个连接的buffer 大小相关信息，3306端口socket的send buffer为32K；
//7226为客户端，发送buffer为128K，OS默认参数 
tcp ESTAB 0 0 127.0.0.1:7226 127.0.0.1:3306 skmem:(r0,rb131072,t2,tb2626560,f24576,w0,o0,bl0,d0)
tcp ESTAB 0 20480 127.0.0.1:3306 127.0.0.1:7226 skmem:(r0,rb16384,t0,tb32768,f1792,w26880,o0,bl0,d0)

在这个案例中 send buffer为32K（代码中设置的16K，内核会再翻倍，所以是32K），如果时延5毫秒时，一秒钟最多执行200次来回，也就是一秒钟能传输：200*32K=6.4M，总大小为13M，也就是最快需要2秒钟才能传输行完，另外MySQL innodb执行耗时0.5ms，也就是极限速度也就是2.5秒+了。

这个场景下想要快得减少rt或者增加send buffer， 增加接收端的buffer没有意义，比如如下代码增加client的 –net-buffer-length=163840000 没有任何帮助

time mysql –net-buffer-length=163840000 -h127.1 -e “select * from test;” >/tmp/result.txt

在2 MiB buffer下rt和 throughput的关系

wmem 和send_buffer的关系

设置 net.ipv4.tcp_wmem=4096 4096 4096（单位是bytes），目的是想控制wmem很小，实际测试发现bytes in flight(发走还没有ack的数据）超过了4096，那么tcp_wmem和 send_buffer/bytes in flight 到底是什么关系呢？

应用write->wmem/snd_buffer->wmem_queued(在这里等ack，ack没来queued不释放)->client

skmem:(r0,rb369280,t0,tb4096,f6000,w157840,o0,bl0

w157840–这个对应我们理解的send buffer. 也就是wmem 不负责等ack，send完就释放，wmem_queued负责等

总结

• 一般来说绝对不要在程序中手工设置SO_SNDBUF和SO_RCVBUF，内核自动调整比你做的要好；
• SO_SNDBUF一般会比发送滑动窗口要大，因为发送出去并且ack了的才能从SO_SNDBUF中释放；
• 代码中设置的SO_SNDBUF和SO_RCVBUF在内核中会翻倍分配；
• TCP接收窗口跟SO_RCVBUF关系很复杂；
• SO_RCVBUF太小并且rtt很大的时候会严重影响性能；
• 接收窗口比发送窗口复杂多了；
• 发送窗口/SO_SNDBUF–发送仓库，带宽/拥塞窗口–马路通畅程度，接收窗口/SO_RCVBUF–接收仓库；
• 发送仓库、马路宽度、长度（rt）、接收仓库一起决定了传输速度–类比一下快递过程。

总之记住一句话：不要设置socket的SO_SNDBUF和SO_RCVBUF

关于传输速度的总结：窗口要足够大，包括发送、接收、拥塞窗口等，自然就能将BDP跑满

相关和参考文章

2024 Netflix： Investigation of a Cross-regional Network Performance Issue 因为内核升级去掉了内核参数 sysctl_tcp_adv_win_scale，换了一个新的计算方式，导致原来30秒 内能传输完毕的请求在新内核机制下传输不完，从而导致了业务端的请求超时 This commit obsoleted sysctl_tcp_adv_win_scale and introduced a scaling_ratio that can more accurately calculate the overhead or window size, which is the right thing to do. With the change, the window size is now rcvbuf * scaling_ratio. 简而言之，内核升级后，接收缓存大小减半。因此，吞吐量也减半，导致数据传输时间翻倍。

Netflix 这次业务问题是Kafka， 其代码里不应该设置TCP 接收buffer 大小，而是要让kernel来自动调节

2022 https://blog.cloudflare.com/when-the-window-is-not-fully-open-your-tcp-stack-is-doing-more-than-you-think 你设置的rmem 不会全部用来存放数据，每个包还有一些meta数据需要存放，元数据的大小会有很大的差异，导致内核需要来保守预估

receive window is not fully opened immediately. Linux keeps the receive window small, as it tries to predict the metadata cost and avoid overshooting the memory budget, therefore hitting TCP collapse. By default, with the net.ipv4.tcp_adv_win_scale=1, the upper limit for the advertised window is 50% of “free” memory. rcv_ssthresh starts up with 64KiB and grows linearly up to that limit.

用stap从内核角度来分析buffer、rt和速度

[The story of one latency spike][https://blog.cloudflare.com/the-story-of-one-latency-spike/] : 应用偶发性出现了rt 很高的时延，通过两个差量 ping 来定位具体节点

Using a large chunk of receive buffer space for the metadata is not really what the programmer wants. To counter that, when the socket is under memory pressure complex logic is run with the intention of freeing some space. One of the operations is tcp_collapse and it will merge adjacent TCP packets into one larger sk_buff. This behavior is pretty much a garbage collection (GC)—and as everyone knows, when the garbage collection kicks in, the latency must spike.

原因：将 tcp_rmem 最大值设置得太大，在内存压力场景下触发了GC（tcp_collapse），将 tcp_rmem 调小后（32M->2M）不再有偶发性 rt 很高的延时

从 net_rx_action 追到 tcp_collapse 的逻辑没太理解（可能是对内核足够了解）

[What is rcv_space in the ‘ss –info’ output, and why it’s value is larger than net.core.rmem_max][28]

arthas常用命令速记

https://github.com/alibaba/arthas

thread

1
2

thread -n 3
thread 16

jad 反编译

jad org.slf4j.Logger
jad org.slf4j.Logger -c 61bbe9ba

jad com.taobao.tddl.common.IdGenerator
jad --source-only com.taobao.tddl.common.IdGenerator
jad --source-only com.taobao.tddl.common.IdGenerator > /tmp/IdGenerator.java

反编译生成java代码

mc 编译生成新的class

将修改后的java代码编译成class（因为依赖的关系可能失败）

mc /tmp/IdGenerator.java -d /tmp

redefine 加载新的class

将修改后的class代码热加载

redefine /tmp/IdGenerator.class
redefine -c 1e80bfe8 /tmp/com/alibaba/middleware/drds/worker/task/RegisterTask.class

可以再次jad 反编译确认class中是修改后的代码：

jad --source-only com.alibaba.cobar.server.ServerConnection > /tmp/SC.java

有时候 redefine 看到成功，可是实际并不一定，最好再次 jad 确认一下。

线上环境快速修改代码验证三部曲：jad反编译得到源代码、修改后mc编译成class、redefine替换新的class。

classload

classloader -l
classloader -c 1e80bfe8 -r com/alibaba/middleware/drds/worker/task/RegisterTask.class
classload -t
classload -c 6e0be858
classloader ch.qos.logback.core.AppenderBase

sc

sc -d com.taobao.tddl.common.IdGenerator
sc -df ch.qos.logback.core.AppenderBase

sm

列出class的方法

sm ch.qos.logback.core.AppenderBase -d

getstatic 查看静态成员

通过getstatic查看静态成员，来追踪一个logger没有设置level的话他的输出级别到底是什么？

先 sc 获取classloader的hash

sc -df io.netty.channel.nio.NioEventLoop

getstatic -c 1e80bfe8 io.netty.channel.nio.NioEventLoop logger 'getClass().getName()'
field: logger
@String[io.netty.util.internal.logging.Slf4JLogger]
Affect(row-cnt:1) cost in 5 ms.

然后查看 logger的具体内容，可以看到level等，level为null的话会从父logger继承：

getstatic -c 1e80bfe8 io.netty.channel.nio.NioEventLoop logger 'logger'
field: logger
@Logger[
    serialVersionUID=@Long[5454405123156820674],
    FQCN=@String[ch.qos.logback.classic.Logger],
    name=@String[io.netty.channel.nio.NioEventLoop],
    level=null,
    effectiveLevelInt=@Integer[20000],
    parent=@Logger[Logger[io.netty.channel.nio]],
    childrenList=null,
    aai=null,
    additive=@Boolean[true],
    loggerContext=@LoggerContext[ch.qos.logback.classic.LoggerContext[default]],
]

再次用getstatic命令来确定jar包的location：

getstatic -c 1e80bfe8 io.netty.channel.nio.NioEventLoop logger 'logger.getClass().getProtectionDomain().getCodeSource().getLocation()'
field: logger
@URL[
    BUILTIN_HANDLERS_PREFIX=@String[sun.net.www.protocol],
    serialVersionUID=@Long[-7627629688361524110],
    protocolPathProp=@String[java.protocol.handler.pkgs],
    protocol=@String[file],
    host=@String[],
    port=@Integer[-1],
    file=@String[/home/admin/drds-worker/lib/logback-classic-1.1.8.jar],
    query=null,
    authority=@String[],
    path=@String[/home/admin/drds-worker/lib/logback-classic-1.1.8.jar],
    userInfo=null,
    ref=null,
    hostAddress=null,
    handler=@Handler[sun.net.www.protocol.file.Handler@5a98007],
    hashCode=@Integer[-1217964899],
    tempState=null,
    factory=null,
    handlers=@Hashtable[isEmpty=false;size=3],
    streamHandlerLock=@Object[java.lang.Object@3bf379e9],
    serialPersistentFields=@ObjectStreamField[][isEmpty=false;size=7],
]

然后通过getstatic来获取到这个parent属性的内容。然后通过多个parent操作，可以发现level都是INFO，最终发现ROOT level是INFO：

getstatic -c 1e80bfe8 io.netty.channel.nio.NioEventLoop logger 'logger.parent.parent.parent.parent.parent'
field: logger
@Logger[
    serialVersionUID=@Long[5454405123156820674],
    FQCN=@String[ch.qos.logback.classic.Logger],
    name=@String[ROOT],
    level=@Level[INFO],
    effectiveLevelInt=@Integer[20000],
    parent=null,
    childrenList=@CopyOnWriteArrayList[isEmpty=false;size=4],
    aai=@AppenderAttachableImpl[ch.qos.logback.core.spi.AppenderAttachableImpl@3f0908e1],
    additive=@Boolean[true],
    loggerContext=@LoggerContext[ch.qos.logback.classic.LoggerContext[default]],
]

vmtool

查看任意成员变量

查看 Druid 参数

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

[arthas@922863]$ sc -df com.alibaba.druid.pool.DruidDataSource //Str 类名，通过类名获取 classload 
 class-info        Str
 code-source       /root/java/
 name              Str
 isInterface       false
 isAnnotation      false
 isEnum            false
 isAnonymousClass  false
 isArray           false
 isLocalClass      false
 isMemberClass     false
 isPrimitive       false
 isSynthetic       false
 simple-name       Str
 modifier
 annotation
 interfaces
 super-class       +-java.lang.Object
 class-loader      +-sun.misc.Launcher$AppClassLoader@4e0e2f2a  
                     +-sun.misc.Launcher$ExtClassLoader@3b9a45b3
 classLoaderHash   4e0e2f2a  //classload
 fields            name     name
                   type     java.lang.String
                   modifier private

//执行模板示例
[arthas@922863]$ vmtool --action getInstances --classLoaderClass sun.misc.Launcher$AppClassLoader --className Str  --express 'instances[0].name'

vmtool --action getInstances -c 6d06d69c  --className com.alibaba.druid.pool.DruidDataSource --express 'instances[0]'

//通过vmtool 列出DruidDataSource的所有对象
[arthas@80]$ vmtool --action getInstances -c 272ce069 --className com.alibaba.druid.pool.DruidDataSource --limit 5

vmtool --action getInstances -c 3e57cd70 --className com.alibaba.druid.pool.DruidDataSource --express 'instances[2]'

//列出其中的一个详细值
[arthas@80]$ vmtool --action getInstances -c 272ce069 --className com.alibaba.druid.pool.DruidDataSource --express 'instances[3]'
username=@String[test],
jdbcUrl=@String[jdbc:mysql://test.com:3006/plantegg?useUnicode=true&characterEncoding=UTF-8&rewriteBatchedStatements=true&amp&allowMultiQueries=true&socketTimeout=60000&connectTimeout=10000],
 driverClass=@String[com.mysql.jdbc.Driver],
 initialSize=@Integer[10],
 maxActive=@Integer[100],
 minIdle=@Integer[10],
 maxIdle=@Integer[8],
 maxWait=@Long[60000],
 connectTimeout=@Integer[10000],
 socketTimeout=@Integer[60000],
 connectTimeoutStr=@String[10000],
 socketTimeoutSr=null,
 queryTimeout=@Integer[0],
 transactionQueryTimeout=@Integer[0],
 createTimespan=@Long[909765246],
 maxWaitThreadCount=@Integer[-1],
 …………
 CreateTime:"2024-10-24 15:57:21",
  ActiveCount:1,
  PoolingCount:9,
  CreateCount:10, //对应 initialSize，没压力的服务
  DestroyCount:0,
  CloseCount:318741,
  ConnectCount:318742,
  Connections:[
    {ID:2079580272, ConnectTime:"2024-10-24 15:57:26", UseCount:0, LastActiveTime:"2024-10-24 15:57:26"},
    {ID:1498019812, ConnectTime:"2024-10-24 15:57:26", UseCount:0, LastActiveTime:"2024-10-24 15:57:26"},
    {ID:1803829323, ConnectTime:"2024-10-24 15:57:26", UseCount:0, LastActiveTime:"2024-10-24 15:57:26"},
    {ID:1735514761, ConnectTime:"2024-10-24 15:57:26", UseCount:0, LastActiveTime:"2024-10-24 15:57:26"},
    {ID:56972919, ConnectTime:"2024-10-24 15:57:26", UseCount:0, LastActiveTime:"2024-10-24 15:57:26"},
    {ID:352679720, ConnectTime:"2024-10-24 15:57:26", UseCount:1, LastActiveTime:"2024-10-24 16:00:12"},
    {ID:1556806619, ConnectTime:"2024-10-24 15:57:26", UseCount:59597, LastActiveTime:"2024-10-24 17:48:08"},
    {ID:889640793, ConnectTime:"2024-10-24 15:57:26", UseCount:104286, LastActiveTime:"2024-10-24 17:51:10"},
    {ID:486144352, ConnectTime:"2024-10-24 15:57:26", UseCount:89027, LastActiveTime:"2024-10-24 17:51:11"}
  ]
}],

//列出第一个对象的 createDirectCount 属性
[arthas@30019]$ vmtool --action getInstances -c 7852e922  --className com.alibaba.druid.pool.DruidDataSource --express 'instances[0].createDirectCount'
@Integer[0]

//MetaDBUtilImpl 会通过url 去构建DataSource， 这样展开能看到url 连接串参数
vmtool --action getInstances --className com.a.rds.ha.util.MetaDBUtilImpl -x 3 //-x 表示展开深度
               @DruidPooledConnection[com.a.rds.mysql.jdbc.S*Connection@6e567347]:@Object[java.lang.Object@4c3bd27b],
             @DruidPooledConnection[com.a.rds.mysql.jdbc.S*Connection@4e1884d5]:@Object[java.lang.Object@4c3bd27b],
                @DruidPooledConnection[com.a.rds.mysql.jdbc.S*Connection@33c4853b]:@Object[java.lang.Object@4c3bd27b],
              @DruidPooledConnection[com.a.rds.mysql.jdbc.S*Connection@6ca0fdd6]:@Object[java.lang.Object@4c3bd27b],
                @DruidPooledConnection[com.a.rds.mysql.jdbc.S*Connection@6fb0c93a]:@Object[java.lang.Object@4c3bd27b],

查看 Jedis 连接池：

1

vmtool --action getInstances --className redis.clients.jedis.util.Pool --express 'instances[0]'

logger 查看和修改 logger配置

列出所有logger，然后修改logger的level

classloader -l  //列出所有 classloader 一般是这个：sun.misc.Launcher$AppClassLoader
或者：
 sc -df com.aliyun.apsaradb.dbaasmetaapi.common.GlobalExceptionHandler  //class 名字可以到日志中取到
 
logger -c 27bc2616
ognl -c 6e0be858 '@com.alibaba.cobar.server.ServerConnection@logger'
ognl -c 6e0be858 '@org.slf4j.LoggerFactory@getLogger("root").setLevel(@ch.qos.logback.classic.Level@DEBUG)'

ognl -c 37f8bb67 '@org.slf4j.LoggerFactory@getLogger("root").setLevel(@ch.qos.logback.classic.Level@OFF)'


logger --include-no-appender //查看没有 appender 的日志
 name              com.aliyun.apsaradb.dbaasmetaapi.dao.mapper.CustinsReplicatorMapper.selectByExample
 class             ch.qos.logback.classic.Logger
 classLoader       org.springframework.boot.loader.LaunchedURLClassLoader@37f8bb67
 classLoaderHash   37f8bb67
 level             OFF //已被关
 effectiveLevel    OFF
 additivity        true
 codeSource        jar:file:/usr/local/rds/dbaas-meta-api/dbaas-meta-api.jar!/BOOT-INF/lib/logback-classic-1.2.3.jar!/
                   
 name              com.aliyun.apsaradb.dbaasmetaapi.dao.mapper.CcBuMapper.selectByExample
 class             ch.qos.logback.classic.Logger
 classLoader       org.springframework.boot.loader.LaunchedURLClassLoader@37f8bb67
 classLoaderHash   37f8bb67
 level             OFF //已被关
 effectiveLevel    OFF
 additivity        true
 codeSource        jar:file:/usr/local/rds/dbaas-meta-api/dbaas-meta-api.jar!/BOOT-INF/lib/logback-classic-1.2.3.jar!/              
 
ognl -c 37f8bb67 '@org.slf4j.LoggerFactory@getLogger("com.aliyun.apsaradb.dbaasmetaapi.dao.mapper.CustinsReplicatorMapper.selectByExample").setLevel(@ch.qos.logback.classic.Level@OFF)'

或者

logger --name ROOT --level debug

trace 耗时超过10ms的方法堆栈

查看调用耗时超过 10ms的函数堆栈

stack ch.qos.logback.core.AppenderBase doAppend
trace -j ch.qos.logback.core.AppenderBase doAppend '#cost > 10'

截图中红框的数字表示代码行号

ongl 调用static函数并查看返回值

ognl '#value1=@com.alibaba.middleware.drds.manager.common.utils.AddressUtil@getHostIp(), {#value1}'
@ArrayList[
	@String[10.0.174.135],
]


 ognl '#value1=@com.alibaba.middleware.drds.worker.Config@getInstance(), {#value1}'
	@ArrayList[
@Config[Config(receivedManagerInfo=true, registeredToManager=true, workerRpcPort=8188, managerIp=10.0.171.193, managerPort=8080, drdsServerPort=3306, drdsManagerPort=3406, host=10.0.118.18, vpcId=vpc-bp1tsocjn451k7ur52vwl, urlToGetVpcId=http://100.100.100.200/latest/meta-data/vpc-id, heartBeatIntervalSeconds=180, registerInveralSeconds=2, manageDrdsIntervalSeconds=60, miniVersion=1, version=0.0.0.41, registerUrl=http://hostPlaceHolder:portPlaceHolder/v1/worker/register, heartBeatUrl=http://hostPlaceHolder:portPlaceHolder/v1/worker/heartBeat, manageDrdsServerUrl=http://hostPlaceHolder:portPlaceHolder/v1/worker/manageDrdsServer, gotVpcId=true, nodeType=drds-server, watcher=null, scheduledThreadPoolExecutor=java.util.concurrent.ScheduledThreadPoolExecutor@3aa3f85f[Running, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0])],
]

#Netty的SelectorProvider.provider()创建Selector驱动的时候通过JDK create到的Selector驱动
#如果是windows平台：WindowsSelectorProvider(); macOS
#下面是Linux平台的默认Selector驱动：
$ options unsafe true
$ ognl  '#value1=@sun.nio.ch.DefaultSelectorProvider@create(), {#value1}'
@ArrayList[
    @EPollSelectorProvider[sun.nio.ch.EPollSelectorProvider@5bf6cb51],
]
#或者
$  ognl  '#value1=@java.nio.channels.spi.SelectorProvider@provider(), {#value1}'
@ArrayList[
    @EPollSelectorProvider[sun.nio.ch.EPollSelectorProvider@74c4ede7],
]

tt 观察函数调用和回放

先通过tt观察某个函数的调用，然后再用 tt -i 回放这个调用并查看返回值等

tt -t com.alibaba.middleware.drds.manager.common.utils.AddressUtil getHostIp
tt -t com.alibaba.middleware.drds.worker.task.RegisterTask getHostInfoIfNeeded
tt -i 1000
tt -i 1000 -p
tt -n 3 -t com.alibaba.middleware.drds.worker.task.RegisterTask getHostInfoIfNeeded
tt -n 3 -t com.alibaba.middleware.drds.manager.common.utils.AddressUtil getHostIp

 tt -i 1010 -p
	 RE-INDEX      1010
	 GMT-REPLAY    2019-09-27 12:59:05
	 OBJECT        NULL
	 CLASS         com.alibaba.middleware.drds.manager.common.utils.AddressUtil
	 METHOD        getHostIp
	 IS-RETURN     true
	 IS-EXCEPTION  false
	 COST(ms)      0.577817
	 RETURN-OBJ    @String[10.0.118.18]

watch 查看函数调用的参数内容和返回值

指定输出结果的属性遍历深度，默认为 1：

watch  com.alibaba.middleware.drds.manager.common.utils.AddressUtil getHostIp "{params,returnObj}" -x 2

watch com.alibaba.middleware.drds.worker.task.RegisterTask getHostInfoIfNeeded "{params,returnObj}" -x 2
	Press Q or Ctrl+C to abort.
	Affect(class-cnt:1 , method-cnt:1) cost in 56 ms.
	ts=2019-09-27 13:24:00; [cost=0.2698ms] result=@ArrayList[
	    @Object[][isEmpty=true;size=0],
	    @Boolean[true],
	]
	ts=2019-09-27 13:24:02; [cost=0.030039ms] result=@ArrayList[
	    @Object[][isEmpty=true;size=0],
	    @Boolean[true],
	]

可以看到处理请求的handler是 om.example.demo.arthas.user.UserController.findUserById：

$ watch org.springframework.web.servlet.DispatcherServlet getHandler returnObj
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 332 ms.
ts=2019-06-04 11:38:06; [cost=2.75218ms] result=@HandlerExecutionChain[
    logger=@SLF4JLocationAwareLog[org.apache.commons.logging.impl.SLF4JLocationAwareLog@665c08a],
    handler=@HandlerMethod[public com.example.demo.arthas.user.User com.example.demo.arthas.user.UserController.findUserById(java.lang.Integer)],
    interceptors=null,
    interceptorList=@ArrayList[isEmpty=false;size=2],
    interceptorIndex=@Integer[-1],
]

• watch 命令定义了4个观察事件点，即 -b 方法调用前，-e 方法异常后，-s 方法返回后，-f 方法结束后
• 4个观察事件点 -b、-e、-s 默认关闭，-f 默认打开，当指定观察点被打开后，在相应事件点会对观察表达式进行求值并输出
• 这里要注意方法入参和方法出参的区别，有可能在中间被修改导致前后不一致，除了 -b 事件点 params 代表方法入参外，其余事件都代表方法出参
• 当使用 -b 时，由于观察事件点是在方法调用前，此时返回值或异常均不存在

参考资料

官方文档

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/bpf 和 lsmod | 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));
}

以上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())
}

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

网络重传

网络包大小分布

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);
}'

或者，采集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 作为主键）保存时间戳，并在另外一个探测点获得这个时间戳。这个模式可以用来计算各种延时。

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

网络连接创建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 事件

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

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

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

除了上面两个，假如我们想排查是不是由于IO调度策略，及队列的问题，可以追踪block:block_rq_insert 和 block: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核的机器下性能提升没这么明显，因为锁争抢没这么激烈

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

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

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

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

同步情况下的profiler

recordSQL: 12.9%
logback.doAppend: 10%

异步情况下的profiler:

recordSQL: 3.7%

logback.doAppend: 2.63%

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

99.8%的锁都是doApend

同步和异步以及immediateFlush的影响

16core的机器

结论：同步输出的情况下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的影响

结论：同步输出的情况下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）

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

是否开启immediateFlush（默认true）

（这个表格和前面的表格整体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表示日志长度

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

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

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

16core VS 32 Core 案例比较

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

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

对应CPU状态

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

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

横向比较

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

日志框架

紫色为接口类，蓝色为实现，白色为转换

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

性能比较

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

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

来自log4j2官方的比较数据（同步，在不同的瓶颈下）

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

异步场景下的性能比较

AsyncAppender to FileAppender

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对比了一下，发现明显有一个线程不太对，一直在增加

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

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

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

调整参数，加速问题重现

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

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

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

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

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

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

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

或者这个异常状态的截图

一些疑问

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

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

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

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

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

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

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

网络重传和业务的关系

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

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

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

总结

问题的根本原因不是因为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，这时进入阻塞直到数据拷贝到用户空间

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

IO多路复用、Epoll

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

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

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

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数量来调整

完整的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 类型。

目前已知 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）

• 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的线程、进程不现实，这个时候适合用协程

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 运算能力。

改成异步化后：

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

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

用协程来实现

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

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

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

协程的切换

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

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

协程就是用户态的线程。然而，为了保证所有切换都在用户态进行，协程必须重新封装所有的阻塞系统调用，否则，一旦协程触发了线程切换，会导致这个线程进入休眠状态，进而其上的所有协程都得不到执行。比如，普通的 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指令可以完成

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

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

以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的不均衡大致能说明工作连接的差异

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

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

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 以及路径

不再展示协议内容

比如，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属性关掉

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/

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

设置私有IP名称

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

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

保存文件（含host对应名称）

分析包的总概览

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