地方电商网站经典网站赏析

一、问题现象

实验室一台压力测试设备突然无法登录，无论web页面，ssh或者telnet登录，都是输入用户名密码后卡在哪里，无法进入管理页面。
如果这样子的话，根本无法调试。幸运的是，有个之前就打开的shell窗口可以使用。这给我们分析调试提供了方便。

二、初步观察

在shell中查看现存和hang住的命令行进程，看看有什么线索。

/var/log# ps | grep cli2812 root      720m S    cli admin 1 admin telnet(10.10.20.11)
15126 root      720m S    cli admin 1 admin telnet(10.10.20.11)
15264 root      720m S    cli admin 0 admin console
21947 root     16448 S    grep cli

这里有3个cli进程，有除了2812是我们当前在使用的，剩下两个都是无响应的。查看进程的内核栈信息。

/var/log# cat /proc/15264/stack
[<ffffffff8080a819>] netlink_attachskb+0x189/0x1d0
[<ffffffff8080a991>] netlink_unicast+0xa1/0x1f0
[<ffffffff8080ad81>] netlink_sendmsg+0x1c1/0x3e0
[<ffffffff80799b8a>] sock_sendmsg+0x1a/0x30
[<ffffffff8079a376>] ___sys_sendmsg+0x1e6/0x200
[<ffffffff8079b404>] SyS_sendmsg+0x44/0x80
[<ffffffff802016d5>] do_syscall_64+0x75/0x2c0
[<ffffffff80c0008d>] entry_SYSCALL_64_after_hwframe+0x59/0xbe
[<ffffffffffffffff>] 0xffffffffffffffff
/var/log# cat /proc/15126/stack
[<ffffffff8080a819>] netlink_attachskb+0x189/0x1d0
[<ffffffff8080a991>] netlink_unicast+0xa1/0x1f0
[<ffffffff8080ad81>] netlink_sendmsg+0x1c1/0x3e0
[<ffffffff80799b8a>] sock_sendmsg+0x1a/0x30
[<ffffffff8079a376>] ___sys_sendmsg+0x1e6/0x200
[<ffffffff8079b404>] SyS_sendmsg+0x44/0x80
[<ffffffff802016d5>] do_syscall_64+0x75/0x2c0
[<ffffffff80c0008d>] entry_SYSCALL_64_after_hwframe+0x59/0xbe
[<ffffffffffffffff>] 0xffffffffffffffff
/var/log# cat /proc/2812/stack
[<ffffffff80255f6a>] do_wait+0x1aa/0x210
[<ffffffff802570f7>] kernel_wait4+0x97/0x120
[<ffffffff802571ef>] SyS_wait4+0x6f/0x80
[<ffffffff802016d5>] do_syscall_64+0x75/0x2c0
[<ffffffff80c0008d>] entry_SYSCALL_64_after_hwframe+0x59/0xbe
[<ffffffffffffffff>] 0xffffffffffffffff

可以发现 15126和15264进程都卡在了 netlink发送等待上。怀疑netlink socket收包队列有积压，导致发送端处于等待发送状态。

三、继续深挖

查看netlink相关信息

/var/log# cat /proc/net/netlink 
sk       Eth Pid    Groups   Rmem     Wmem     Dump     Locks     Drops     Inode
ffff88880b2cb000 0   2851   00000000 0        0        0 2        0        12002   
ffff888806d6e800 0   2707076566 00000000 0        0        0 2        0        12784   
ffff888806d6a000 0   3780   00000551 0        0        0 2        0        12810   
ffff88885a980000 0   0      00000000 0        0        0 2        0        3       
ffff88880a1b6000 0   2825818928 00000111 0        0        0 2        0        20919   
ffff888806d6d800 0   3498   00000111 0        0        0 2        0        12783   
ffff88880c210000 0   3410172620 00000000 0        0        0 2        0        12811   
ffff88880b2cb800 0   2855   00000001 0        0        0 2        0        11851   
ffff88880a5bf800 15  10000038 00000000 33557184 0        0 27       0        1652  --问题socket
//省略部分无关socket

发现socket ffff88880a5bf800 存在大量积压，基本确认是积压导致。

根据Eth 15 和Pid 10000038 ，对照代码发现是发送和接收告警信息的socket，负责接收处理的进程是warnd。

查看warnd进程栈

/var/log# ps | grep warnd2849 root     2325m S    /bin/warnd
22135 root     16448 S    grep warnd
/var/log# cat /proc/2849/stack
[<ffffffff802bfe03>] futex_wait_queue_me+0xc3/0x120
[<ffffffff802c01e2>] futex_wait+0x102/0x230
[<ffffffff802c275e>] do_futex+0x14e/0xc30
[<ffffffff802c32ab>] SyS_futex+0x6b/0x140
[<ffffffff802016d5>] do_syscall_64+0x75/0x2c0
[<ffffffff80c0008d>] entry_SYSCALL_64_a

发现warnd在等待futex 锁，是那个操作导致的呢，这就需要查看用户态的调用栈了。

四、再接再厉

查看warnd 用户栈

用gdb attach上warnd进程，查看当前栈

/var/log# gdb
GNU gdb (GDB) 11.2
Copyright (C) 2022 Free Software Foundation, Inc.
//省略无关部分
For help, type "help".
Type "apropos word" to search for commands related to "word".
(gdb) attach 2849
Attaching to process 2849
[New LWP 2945]
[New LWP 2946]
[New LWP 2947]
//省略无关部分
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/libthread_db.so.1".
0x00007fcab97e4059 in ?? () from /lib/libc.so.6
(gdb) info threadId   Target Id                                 Frame 
* 1    Thread 0x7fcab8929800 (LWP 2849) "warnd" 0x00007fcab97e4059 in ?? () from /lib/libc.so.62    Thread 0x7fcab8924640 (LWP 2945) "warnd" 0x00007fcab97e4059 in ?? () from /lib/libc.so.63    Thread 0x7fcab8123640 (LWP 2946) "warnd" 0x00007fcab97e4059 in ?? () from /lib/libc.so.64    Thread 0x7fcab7922640 (LWP 2947) "warnd" 0x00007fcab97e4059 in ?? () from /lib/libc.so.6
//省略无关部分34   Thread 0x7fcaa802b640 (LWP 8217) "warnd" 0x00007fcab97e4059 in ?? () from /lib/libc.so.635   Thread 0x7fcaa782a640 (LWP 8238) "warnd" 0x00007fcab9868add in sendmsg () from /lib/libc.so.636   Thread 0x7fcaa7029640 (LWP 8245) "warnd" 0x00007fcab97e4059 in ?? () from /lib/libc.so.637   Thread 0x7fcaa611f640 (LWP 8260) "warnd" 0x00007fcab97e4059 in ?? () from /lib/libc.so.638   Thread 0x7fcaa590d640 (LWP 8267) "warnd" 0x00007fcab97e4059 in ?? () from /lib/libc.so.639   Thread 0x7fcaa510c640 (LWP 8268) "warnd" 0x00007fcab9867196 in epoll_wait () from /lib/libc.so.6

除了线程35和39外，其他线程全部卡在相同的位置。

查看线程1，可以知道系统调用线程读写锁的写锁时因为得不到调度进入了休眠。那么这个锁被那个线程占有了呢？

(gdb) thread 1
[Switching to thread 1 (Thread 0x7fcab8929800 (LWP 2849))]
#0  0x00007fcab97e4059 in ?? () from /lib/libc.so.6
(gdb) bt full
#0  0x00007fcab97e4059 in ?? () from /lib/libc.so.6
No symbol table info available.
#1  0x00007fcab97ed4f1 in pthread_rwlock_wrlock () from /lib/libc.so.6
No symbol table info available.
#2  0x000000000040d5d3 in ?? ()
No symbol table info available.
#3  0x0000000000404ad9 in ?? ()
No symbol table info available.
#4  0x00007fcab978b1f7 in ?? () from /lib/libc.so.6
No symbol table info available.
#5  0x00007fcab978b2ac in __libc_start_main () from /lib/libc.so.6
No symbol table info available.
#6  0x0000000000404b01 in ?? ()
No symbol table info available.

我们再查看看35线程。通过查看代码发现，在sendmsg之前，线程已经持通过pthread_rwlock_wrlock 持有了写锁。也就是其他线程都在等待35线程释放写锁。那么35线程为什么不释放写锁呢？

  (gdb) thread 35
[Switching to thread 35 (Thread 0x7fcaa782a640 (LWP 8238))]
#0  0x00007fcab9868add in sendmsg () from /lib/libc.so.6
(gdb) bt full
#0  0x00007fcab9868add in sendmsg () from /lib/libc.so.6
No symbol table info available.
#1  0x00007fcab967f81d in fun_nl_sendto0 () from /lib/libfun_nl_ipc.so
No symbol table info available.
#2  0x00007fcab9b2a61a in send_warn () from /lib/libwarnapi.so
No symbol table info available.
#3  0x00000000004159d0 in ?? ()
No symbol table info available.
#4  0x0000000000415dbc in ?? ()
No symbol table info available.
#5  0x000000000040c9c5 in ?? ()
No symbol table info available.
#6  0x00007fcab9b62067 in ?? () from /lib/libevent.so
No symbol table info available.
#7  0x00007fcab9b62314 in ?? () from /lib/libevent.so
No symbol table info available.
#8  0x00007fcab9b62568 in ?? () from /lib/libevent.so
No symbol table info available.
#9  0x000000000040ca8e in ?? ()
No symbol table info available.
#10 0x00007fcab97e731a in ?? () from /lib/libc.so.6
No symbol table info available.
#11 0x00007fcab9866db0 in clone () from /lib/libc.so.6

查代码发现35线程sendmsg就是向 已经积压的netlink socket 发送warn消息。因为netlink socket积压，导致35线程进入休眠等待。

分析到这里，基本逻辑差不多通顺了。

1. 压力测试导致netlink socket积压
2. 35线程获取写锁后，向netlink socket发送消息。因为积压导致休眠。
3. 其他线程包括netlink socket消息接受处理的线程因为获取不到写锁，导致休眠。
4. 此时：线程35发送消息持有写锁，等待netlink socket buffer空闲。处理netlink socket消息的线程，等待写锁。–根因
5. cli命令行进程会向warnd发送netlink消息，因为netlink socket消息积压(消息没有得到及时处理)，导致发送进程进入等待休眠。

后记

warnd进程主要处理其他进程发来的warn消息，自己也发送warn消息。在锁的处理上不够完善，导致压力测试下，socket接收队列打满后，形成了死锁。