本来这是一个纪实系列,但写了才发现饼画太大,要累似了,就先写成这样吧,一来是经验帖,二来是cache thrashing livelock的样本展示
我也不想多磨叽,这次主要通过两个命令获取linux日志然后与时间节点一一比对

指标

屏幕截图 2026-07-17 115943.png
屏幕截图 2026-07-17 120101.png
屏幕截图 2026-07-17 120209.png

操作记录:
重启实例 操作成功 2026年7月16日 22:40:22 2026年7月16日 22:49:20
重启实例 操作成功 2026年7月16日 17:27:55 2026年7月16日 17:36:55

描述

我们可以看到有三处典型的cache thrashing livelock,分别记为alpha,beta,gamma

我把关键时间节点找出来了:
Alpha
Up:Jul 16 12:22:00-12:24:00
Down:Jul 16 12:38:00-12:42:00

Beta
Up:Jul 16 17:12:00-17:14:00
Down:Jul 16 17:38:00-17:42:00

Gamma
Up:Jul 16 22:16:00-22:18:00
Down:Jul 16 22:50:00-22:52:00

beta和gamma没什么稀奇的,就是我用V2ray下hf数据集,然后触发了cache thrashing ,在图中我们可以看到beta和gamma都是两次带宽流量峰后紧跟着磁盘IO的读"高原"。但alpha,从我们已有的指标看,毫无征兆地触发了cache thrashing livelock,非常奇妙。

日志取证

使用的命令

Beta

Jul 16 17:10:19.499489 iZj6cco0jle1j1w2wuan03Z systemd[1]: Starting sysstat-collect.service - system activity accounting tool...
Jul 16 17:10:19.621041 iZj6cco0jle1j1w2wuan03Z systemd[1]: sysstat-collect.service: Deactivated successfully.
Jul 16 17:10:19.621294 iZj6cco0jle1j1w2wuan03Z systemd[1]: Finished sysstat-collect.service - system activity accounting tool.
Jul 16 17:12:47.160905 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 17:13:09.933748 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 17:30:10.361107 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 17:32:52.531359 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
-- Boot b5407e04347942568040183a33d5eaa6 --

平平无奇
sysstat-collect.service 非常普通的系统级性能采集(我打算单独再写一篇)
然后17:12的时候就是我人为引发的问题
后面的boot就是服务器重启了

写完文章后注:其实写的时候我也是边查边写的,对日志理解不是很到位,对于systemd,CORN,systemd-journald我会重新写一篇来研究

Gamma

Jul 16 22:10:20.707059 iZj6cco0jle1j1w2wuan03Z systemd[1]: Starting sysstat-collect.service - system activity accounting tool...
Jul 16 22:10:20.750663 iZj6cco0jle1j1w2wuan03Z systemd[1]: sysstat-collect.service: Deactivated successfully.
Jul 16 22:10:20.750943 iZj6cco0jle1j1w2wuan03Z systemd[1]: Finished sysstat-collect.service - system activity accounting tool.
Jul 16 22:15:01.995398 iZj6cco0jle1j1w2wuan03Z CRON[52475]: pam_unix(cron:session): session opened for user root(uid=0) by root(uid=0)
Jul 16 22:15:01.998159 iZj6cco0jle1j1w2wuan03Z CRON[52476]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jul 16 22:15:02.006170 iZj6cco0jle1j1w2wuan03Z CRON[52475]: pam_unix(cron:session): session closed for user root
Jul 16 22:17:31.915362 iZj6cco0jle1j1w2wuan03Z CRON[52487]: pam_unix(cron:session): session opened for user root(uid=0) by root(uid=0)
Jul 16 22:17:45.163445 iZj6cco0jle1j1w2wuan03Z systemd-journald[300]: Under memory pressure, flushing caches.
Jul 16 22:17:51.702362 iZj6cco0jle1j1w2wuan03Z systemd-journald[300]: Under memory pressure, flushing caches.
Jul 16 22:17:56.261407 iZj6cco0jle1j1w2wuan03Z systemd-journald[300]: Under memory pressure, flushing caches.
Jul 16 22:18:00.500860 iZj6cco0jle1j1w2wuan03Z systemd-journald[300]: Under memory pressure, flushing caches.
Jul 16 22:18:06.604445 iZj6cco0jle1j1w2wuan03Z systemd-journald[300]: Under memory pressure, flushing caches.
Jul 16 22:18:23.707356 iZj6cco0jle1j1w2wuan03Z systemd-journald[300]: Under memory pressure, flushing caches.
Jul 16 22:23:34.211973 iZj6cco0jle1j1w2wuan03Z systemd-journald[300]: Under memory pressure, flushing caches.
Jul 16 22:35:39.646501 iZj6cco0jle1j1w2wuan03Z systemd-journald[300]: Under memory pressure, flushing caches.
-- Boot 9749fa72de964dcfba7e5ef433fb864e --

依旧是路人甲 sysstat-collect.service

command -v debian-sa1 > /dev/null && debian-sa1 1 1 也是普通的系统任务,和前面那个作用一模一样
人为引发的Under memory pressure, flushing caches.
服务器重启

意外之喜x2

alpha的出现是出乎意料的,那时我还不懂,不以为意,直到知道了cache thrashing livelock的存在。而且在审查alpha的日志时还买一送一。整个过程非常非常长,按我注意到的顺序来排

Jul 16 12:13:36.970612 iZj6cco0jle1j1w2wuan03Z sshd[276650]: Invalid user ubuntu from 120.48.8.4 port 41736
Jul 16 12:13:37.012681 iZj6cco0jle1j1w2wuan03Z sshd[276650]: pam_unix(sshd:auth): check pass; user unknown
Jul 16 12:13:37.012704 iZj6cco0jle1j1w2wuan03Z sshd[276650]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=120.48.8.4
Jul 16 12:13:38.912121 iZj6cco0jle1j1w2wuan03Z sshd[276650]: Failed password for invalid user ubuntu from 120.48.8.4 port 41736 ssh2
Jul 16 12:13:39.268121 iZj6cco0jle1j1w2wuan03Z sshd[276650]: Connection closed by invalid user ubuntu 120.48.8.4 port 41736 [preauth]
Jul 16 12:13:47.617808 iZj6cco0jle1j1w2wuan03Z sshd[276658]: Invalid user dev from 120.48.8.4 port 41744
Jul 16 12:13:49.882777 iZj6cco0jle1j1w2wuan03Z sshd[276658]: pam_unix(sshd:auth): check pass; user unknown
Jul 16 12:13:49.882803 iZj6cco0jle1j1w2wuan03Z sshd[276658]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=120.48.8.4
Jul 16 12:13:51.762009 iZj6cco0jle1j1w2wuan03Z sshd[276658]: Failed password for invalid user dev from 120.48.8.4 port 41744 ssh2
Jul 16 12:13:51.888248 iZj6cco0jle1j1w2wuan03Z sshd[276658]: Connection closed by invalid user dev 120.48.8.4 port 41744 [preauth]
Jul 16 12:13:55.675498 iZj6cco0jle1j1w2wuan03Z sshd[276670]: Invalid user kali from 120.48.8.4 port 36502
Jul 16 12:13:55.720109 iZj6cco0jle1j1w2wuan03Z sshd[276670]: pam_unix(sshd:auth): check pass; user unknown
Jul 16 12:13:55.720135 iZj6cco0jle1j1w2wuan03Z sshd[276670]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=120.48.8.4
Jul 16 12:13:57.756694 iZj6cco0jle1j1w2wuan03Z sshd[276670]: Failed password for invalid user kali from 120.48.8.4 port 36502 ssh2
Jul 16 12:14:01.343462 iZj6cco0jle1j1w2wuan03Z sshd[276680]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=120.48.8.4  user=root
Jul 16 12:14:01.650470 iZj6cco0jle1j1w2wuan03Z sshd[276670]: Connection closed by invalid user kali 120.48.8.4 port 36502 [preauth]
Jul 16 12:14:03.204338 iZj6cco0jle1j1w2wuan03Z sshd[276680]: Failed password for root from 120.48.8.4 port 36518 ssh2
Jul 16 12:14:05.103079 iZj6cco0jle1j1w2wuan03Z sshd[276680]: Connection closed by authenticating user root 120.48.8.4 port 36518 [preauth]
Jul 16 12:15:01.713382 iZj6cco0jle1j1w2wuan03Z CRON[276743]: pam_unix(cron:session): session opened for user root(uid=0) by root(uid=0)
Jul 16 12:15:01.714367 iZj6cco0jle1j1w2wuan03Z CRON[276744]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jul 16 12:15:01.723570 iZj6cco0jle1j1w2wuan03Z CRON[276743]: pam_unix(cron:session): session closed for user root
Jul 16 12:17:01.743314 iZj6cco0jle1j1w2wuan03Z CRON[276867]: pam_unix(cron:session): session opened for user root(uid=0) by root(uid=0)
Jul 16 12:17:01.744487 iZj6cco0jle1j1w2wuan03Z CRON[276868]: (root) CMD (cd / && run-parts --report /etc/cron.hourly)
Jul 16 12:17:01.758400 iZj6cco0jle1j1w2wuan03Z CRON[276867]: pam_unix(cron:session): session closed for user root
Jul 16 12:20:19.465133 iZj6cco0jle1j1w2wuan03Z systemd[1]: Starting sysstat-collect.service - system activity accounting tool...
Jul 16 12:20:19.541853 iZj6cco0jle1j1w2wuan03Z systemd[1]: sysstat-collect.service: Deactivated successfully.
Jul 16 12:20:19.542097 iZj6cco0jle1j1w2wuan03Z systemd[1]: Finished sysstat-collect.service - system activity accounting tool.

为了避免信息量过大消化不良,中间强行划分一下,上面是第二个惊喜,下面是第一个惊喜。到这里没有什么和cache thrashing livelock相关的日志。

我们可以看到清一色的sshd和CRON以及systemd
sshd的Invalid user pam_unix(sshd:auth) 这两条都是ssh登陆的日志,如果再往前翻,就会翻出相当相当多的"登陆失败"。在后面我们会分析,这就是ssh爆破。

其实大概是个人都看得出来,也没什么可分性的吧,各位给我"走个面儿"就假装是小白让我分析一下吧

CRON和systemd在前面已经分析过,是系统任务用于获取性能指标,不再赘述。

继续:

Jul 16 12:21:19.471085 iZj6cco0jle1j1w2wuan03Z systemd[1]: Starting apt-daily.service - Daily apt download activities...
Jul 16 12:21:20.086200 iZj6cco0jle1j1w2wuan03Z systemd[1]: Starting apt-news.service - Update APT News...
Jul 16 12:21:20.092856 iZj6cco0jle1j1w2wuan03Z systemd[1]: Starting esm-cache.service - Update the local ESM caches...
Jul 16 12:21:21.340125 iZj6cco0jle1j1w2wuan03Z systemd[1]: apt-news.service: Deactivated successfully.
Jul 16 12:21:21.340401 iZj6cco0jle1j1w2wuan03Z systemd[1]: Finished apt-news.service - Update APT News.
Jul 16 12:21:21.477159 iZj6cco0jle1j1w2wuan03Z dbus-daemon[796]: [system] Activating via systemd: service name='org.freedesktop.PackageKit' unit='packagekit.service' requested by ':1.2091' (uid=0 pid=277508 comm="/usr/bin/gdbus call --system --dest org.freedeskto" label="unconfined")
Jul 16 12:21:21.487198 iZj6cco0jle1j1w2wuan03Z systemd[1]: Starting packagekit.service - PackageKit Daemon...
Jul 16 12:21:21.519278 iZj6cco0jle1j1w2wuan03Z PackageKit[277512]: daemon start
Jul 16 12:21:21.568889 iZj6cco0jle1j1w2wuan03Z systemd[1]: esm-cache.service: Deactivated successfully.
Jul 16 12:21:21.569123 iZj6cco0jle1j1w2wuan03Z systemd[1]: Finished esm-cache.service - Update the local ESM caches.
Jul 16 12:21:21.595938 iZj6cco0jle1j1w2wuan03Z dbus-daemon[796]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Jul 16 12:21:21.596156 iZj6cco0jle1j1w2wuan03Z systemd[1]: Started packagekit.service - PackageKit Daemon.
Jul 16 12:25:45.352023 iZj6cco0jle1j1w2wuan03Z CRON[277654]: pam_unix(cron:session): session opened for user root(uid=0) by root(uid=0)
Jul 16 12:26:27.034190 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:25:47.195151 iZj6cco0jle1j1w2wuan03Z CRON[277656]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jul 16 12:26:48.031640 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:26:56.438783 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:27:04.464041 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:27:11.013522 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.

这是cache thrashing livelock发生时的日志逐条看:
Starting apt-daily.service - Daily apt download activities... apt日常更新

Starting apt-news.service - Update APT News... apt-news更新 ->
apt-news.service: Deactivated successfully. apt-news更新成功 ->
Finished apt-news.service - Update APT News. apt-news更新进程退出(这么表述对吗,我不确定)

Starting esm-cache.service - Update the local ESM caches... ESM更新 ->
esm-cache.service: Deactivated successfully. apt-news更新成功 ->
Finished esm-cache.service - Update the local ESM caches. ESM更新进程退出

Activating via systemd: service name='org.freedesktop.PackageKit' unit='packagekit.service' requested by ':1.2091' 应该是PackageKit更新 ->
Starting packagekit.service - PackageKit Daemon... ??? ->
daemon start ??? ->
Successfully activated service 'org.freedesktop.PackageKit' ??? ->
Started packagekit.service - PackageKit Daemon.' ???

CRON 和前面一样

Under memory pressure, flushing caches. cache thrashing livelock发生

更奇妙的是

Jul 16 12:36:01.583778 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:36:19.618150 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:36:25.671401 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:27:16.596282 iZj6cco0jle1j1w2wuan03Z systemd[1]: packagekit.service: Deactivated successfully.
Jul 16 12:36:39.209589 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:36:41.204423 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:26:27.372918 iZj6cco0jle1j1w2wuan03Z PackageKit[277512]: daemon quit
Jul 16 12:26:37.647922 iZj6cco0jle1j1w2wuan03Z sshd[277653]: ssh_dispatch_run_fatal: Connection from 51.68.34.131 port 45490: Broken pipe [preauth]
Jul 16 12:36:50.273945 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:36:53.637128 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:36:49.652203 iZj6cco0jle1j1w2wuan03Z systemd[1]: Starting fwupd-refresh.service - Refresh fwupd metadata and update motd...
Jul 16 12:36:56.837291 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:26:37.648546 iZj6cco0jle1j1w2wuan03Z sshd[277652]: ssh_dispatch_run_fatal: Connection from 182.61.35.204 port 55954: Broken pipe [preauth]
Jul 16 12:36:59.477417 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:36:55.528393 iZj6cco0jle1j1w2wuan03Z systemd[1]: Starting sysstat-collect.service - system activity accounting tool...
Jul 16 12:27:31.541801 iZj6cco0jle1j1w2wuan03Z sshd[277655]: ssh_dispatch_run_fatal: Connection from 45.91.171.156 port 40386: Broken pipe [preauth]snapd.service: Watchdog timeout (limit 5min)
Jul 16 12:36:57.129750 iZj6cco0jle1j1w2wuan03Z systemd[1]: !
Jul 16 12:37:05.427429 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:28:51.717203 iZj6cco0jle1j1w2wuan03Z sshd[277664]: banner exchange: Connection from 58.59.233.169 port 37379: invalid format
Jul 16 12:37:07.337219 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:37:07.337370 iZj6cco0jle1j1w2wuan03Z snapd[810]: SIGABRT: abort
Jul 16 12:36:57.207318 iZj6cco0jle1j1w2wuan03Z systemd[1]: snapd.service: Killing process 810 (snapd) with signal SIGABRT.
Jul 16 12:35:49.176654 iZj6cco0jle1j1w2wuan03Z CRON[277710]: pam_unix(cron:session): session opened for user root(uid=0) by root(uid=0)
Jul 16 12:37:08.296684 iZj6cco0jle1j1w2wuan03Z snapd[810]: PC=0x609e11440601 m=0 sigcode=0
Jul 16 12:37:08.296684 iZj6cco0jle1j1w2wuan03Z snapd[810]: goroutine 8 gp=0xc0000a16c0 m=0 mp=0x609e131efd80 [syscall, 5577 minutes]:
Jul 16 12:37:06.468343 iZj6cco0jle1j1w2wuan03Z systemd[1]: sysstat-collect.service: Deactivated successfully.
Jul 16 12:35:52.115753 iZj6cco0jle1j1w2wuan03Z CRON[277713]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Jul 16 12:37:08.982884 iZj6cco0jle1j1w2wuan03Z systemd-journald[295]: Under memory pressure, flushing caches.
Jul 16 12:37:08.997105 iZj6cco0jle1j1w2wuan03Z snapd[810]: runtime.notetsleepg(0x609e13210b00, 0xffffffffffffffff)
Jul 16 12:37:08.997105 iZj6cco0jle1j1w2wuan03Z snapd[810]:         /snap/go/10937/src/runtime/lock_futex.go:246 +0x29 fp=0xc000069fa0 sp=0xc000069f78 pc=0x609e113d0f69
Jul 16 12:37:08.997105 iZj6cco0jle1j1w2wuan03Z snapd[810]: os/signal.signal_recv()
Jul 16 12:37:08.997105 iZj6cco0jle1j1w2wuan03Z snapd[810]:         /snap/go/10937/src/runtime/sigqueue.go:152 +0x29 fp=0xc000069fc0 sp=0xc000069fa0 pc=0x609e11438389
Jul 16 12:37:07.336999 iZj6cco0jle1j1w2wuan03Z systemd[1]: Finished sysstat-collect.service - system activity accounting tool.
Jul 16 12:36:04.232233 iZj6cco0jle1j1w2wuan03Z CRON[277710]: pam_unix(cron:session): session closed for user root
Jul 16 12:37:09.159000 iZj6cco0jle1j1w2wuan03Z snapd[810]: os/signal.loop()

这里就不逐句分析了,因为核心很明显,就是这句:
snapd.service: Watchdog timeout (limit 5min) 由于磁盘IO打满,snap被卡死,来不及喂狗,就被
snapd[810]: SIGABRT: abort
systemd[1]: snapd.service: Killing process 810 (snapd) with signal SIGABRT.
直接kill了。然后释放了内存,跳出了cache thrashing livelock的状态。

分析

Beta&Gamma

bata和gamma两次都是我人为诱发的。我服务器上没有留足冗余内存,然后Xray把内存吃满了,(这里还漏了一个逻辑环节,我们会从alpha中看到),所以触发了cache thrashing livelock。后面磁盘IO下降单纯就是我把服务器重启了。

Alpha

alpha的情况非常好玩,也具有一定的普遍性:这种情况会发生在任何一台冗余内存不足的尚未仔细配置的小服务器上。
从前面的日志我们可以发现,基本上cache thrashing livelock是由apt的定时更新任务吃掉了服务器剩下本就不多的内存引起的。
具体分析详见 http://readfrog.ltd/index.php/archives/66/

ssh爆破

在alpha段的日志里有大量的ssh信息,而且全部都来源于120.48.8.4这个ip,pwd我们看不到,但username确定是从kali到dev到ubuntu试了个遍。我们也不用详细去分析每一条日志了,几乎都是重复的。也没有可以学习借鉴(?)的地方,全部都是来自同一个ip,也不用代理伪装一下,可能是脚本小子吧。
ssh爆破阿里云盾居然没检测出来,阿里控制台一派祥和,不知道是粉饰太平还是我没花钱,也有可能两个都是。不愧是 全球生成式 AI “领导者” ,这让那些deepseek api套皮ai应用情何以堪。说什么"计算是为了无法计算的价值",我懂了,价值是阿里的股价吧?红筹架构确实无法计算。
image.png

阴阳怪气就到这里,更详细的技术讨论见 http://readfrog.ltd/index.php/archives/60/

结语

轻量服务器服务器要留足40%的冗余内存
有一说一,我感觉有点理解医生看心电图是什么感觉了。
那么,这篇到这里也算差不多了吧??我写到这里其实已经是自我怀疑的状态了。