【银河麒麟高级服务器操作系统】系统日志Call trace现象分析及处理全流程

了解更多银河麒麟操作系统全新产品，请点击访问

麒麟软件产品专区：https://product.kylinos.cn

开发者专区：https://developer.kylinos.cn

文档中心：https://document.kylinos.cn

服务器环境以及配置

系统环境	物理机/虚拟机/云/容器	虚拟机
网络环境	外网/私有网络/无网络	私有网络
硬件环境	处理器：	Hygon C86 7285 32-core Processor
	内存：	32 GiB
	BIOS版本：	SeaBIOS
软件环境	具体操作系统版本	银河麒麟高级服务器操作系统 V10 SP1
软件环境	内核版本	4.19.90-23.15.v2101.ky10.x86_64

现象描述

早6点左右虚拟机hang了好几分钟，出问题后把节点摘了，没在当前虚拟机跑了。在7点2分messages才有日志记录有大量Call trace： list_del函数试图从链表中删除一个节点，但在检查该节点的next和prev指针时发现了不一致性请排查虚拟机hang的原因以及分析排查Call trace情况。

现象分析

分析messages日志

Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.831889] list_del corruption. next->prev should be ffffd05b18a41ec8, but was ffffd05b11576848
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.833504] WARNING: CPU: 1 PID: 743 at lib/list_debug.c:56 __list_del_entry_valid+0x8a/0x90
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.835050] Modules linked in: nls_utf8 isofs binfmt_misc tcp_diag inet_diag sunrpc ext4 mbcache jbd2 kvm_amd ccp kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel sg joydev virtio_balloon i2c_piix4 pcspkr psmouse ip_tables xfs libcrc32c sr_mod cdrom sd_mod ata_generic crc32c_intel cirrus drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops ttm drm virtio_net ata_piix net_failover virtio_console libata serio_raw virtio_scsi failover floppy dm_mirror dm_region_hash dm_log dm_mod
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.842887] CPU: 1 PID: 743 Comm: systemd-journal Kdump: loaded Tainted: G W 4.19.90-23.15.v2101.ky10.x86_64 #1
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.845961] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.13.0-0-gf21b5a4aeb02-prebuilt.qemu.org 04/01/2014
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.849036] RIP: 0010:__list_del_entry_valid+0x8a/0x90
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.850562] Code: c4 ff 0f 0b 31 c0 c3 48 89 f2 48 89 fe 48 c7 c7 b8 59 0e bc e8 67 56 c4 ff 0f 0b 31 c0 c3 48 c7 c7 f8 59 0e bc e8 56 56 c4 ff <0f> 0b 31 c0 c3 90 48 85 d2 41 55 41 54 55 53 74 5f 48 85 f6 74 64
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.853639] RSP: 0018:ffff9f66040cf8d8 EFLAGS: 00010082
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.855156] RAX: 0000000000000000 RBX: ffffd05b18a41ec0 RCX: 0000000000000006
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.856664] RDX: 0000000000000007 RSI: 0000000000000092 RDI: ffff94329c856890
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.858167] RBP: ffff943296a72000 R08: 0000000000063462 R09: 0000000000000018
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.859649] R10: ffff94321509e6d0 R11: ffff9432964aec70 R12: ffff9f66040cfbc8
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.861146] R13: 0000000000000000 R14: 0000000000000000 R15: ffffffffbc463908
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.862637] FS: 00007fab73427940(0000) GS:ffff94329c840000(0000) knlGS:0000000000000000
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.864170] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.865697] CR2: 00007fc4e2ee4000 CR3: 00000007dbb70000 CR4: 00000000003406e0
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.867242] Call Trace:
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.868728] release_pages+0x17f/0x5a0
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.870214] __pagevec_release+0x2b/0x30
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.871671] shmem_undo_range+0x370/0x870
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.873265] shmem_truncate_range+0x16/0x40
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.874725] shmem_fallocate+0x175/0x4c0
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.876181] vfs_fallocate+0x13f/0x270
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.877651] ksys_fallocate+0x3c/0x70
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.879105] __x64_sys_fallocate+0x1a/0x20
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.880563] do_syscall_64+0x5b/0x1d0
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.882037] entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.883509] RIP: 0033:0x7fab74467f45
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.884979] Code: 54 49 89 cd 55 53 49 89 d4 89 f5 89 fb 48 83 ec 18 e8 2f 76 01 00 4d 89 ea 41 89 c0 4c 89 e2 89 ee 89 df b8 1d 01 00 00 0f 05 <48> 3d 00 f0 ff ff 77 35 44 89 c7 89 44 24 0c e8 67 76 01 00 8b 44
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.888160] RSP: 002b:00007fff2d018c40 EFLAGS: 00000293 ORIG_RAX: 000000000000011d
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.889715] RAX: ffffffffffffffda RBX: 0000000000000021 RCX: 00007fab74467f45
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.891259] RDX: 0000000000000000 RSI: 0000000000000003 RDI: 0000000000000021
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.892752] RBP: 0000000000000003 R08: 0000000000000000 R09: 0000000000000000
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.894235] R10: 0000000008000000 R11: 0000000000000293 R12: 0000000000000000
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.895694] R13: 0000000008000000 R14: 0000000000000011 R15: 00007fff2d018e38
Jul 8 07:02:34 PLPSAPP1 kernel: [23274630.897180] ---[ end trace 101918ae875052b5 ]---

do_syscall_64+0x5b/0x1d0
  __x64_sys_fallocate+0x1a/0x20 用户空间程序调用 fallocate，开始处理文件空间预分配
   ksys_fallocate+0x3c/0x70 虚拟文件系统的 fallocate 实现
    vfs_fallocate+0x13f/0x270
     shmem_fallocate+0x175/0x4c0 tmpfs文件系统的fallocate实现，处理共享内存文件系统的空间预分配
      shmem_truncate_range+0x16/0x40 在shmem_fallocate过程中，如果需要释放一些页面，会调用这个函数来执行截断操作
       shmem_undo_range+0x370/0x870 tmpfs 中撤销分配的函数，负责删除指定范围内的页面
        __pagevec_release+0x2b/0x30 在撤销或释放页面时，内核使用页面向量来批量操作，以提高效率。
         release_pages+0x17f/0x5a0 释放多个页面的核心函数，遍历页面列表并释放每个页面。

systemd-journald 服务在重启过程中失败，原因是日志文件已满（1.5G），没有剩余空间。收到 SIGTERM 信号后，systemd-journald 关闭，但在重新启动时，因日志文件已满，未能成功启动，导致超时。

Jul 8 07:02:49 PLPSAPP1 rsyslogd[38846]: imjournal: journal reloaded... [v8.1907.0 try https://www.rsyslog.com/e/0 ]
Jul 8 07:02:49 PLPSAPP1 rsyslogd[38846]: imjournal: journal reloaded... [v8.1907.0 try https://www.rsyslog.com/e/0 ]
Jul 8 07:02:49 PLPSAPP1 systemd-journald[36836]: Journal stopped
Jul 8 07:02:50 PLPSAPP1 systemd-journald[37081]: Journal started
Jul 8 07:02:50 PLPSAPP1 systemd-journald[37081]: Runtime Journal (/run/log/journal/aba8e21d9dc64b2193542d4b2caccc95) is 1.5G, max 1.5G, 0B free.
Jul 8 07:02:51 PLPSAPP1 systemd-journald[36836]: [23274690.936680] Received SIGTERM from PID 1 (systemd).
Jul 8 07:02:51 PLPSAPP1 systemd[1]: [23274690.958033] systemd-journald.service: Failed with result 'timeout'.
Jul 8 07:02:51 PLPSAPP1 systemd[1]: [23274690.960028] Failed to start Journal Service.
Jul 8 07:02:51 PLPSAPP1 systemd[1]: [23274690.961478] Dependency failed for Flush Journal to Persistent Storage.
Jul 8 07:02:51 PLPSAPP1 systemd[1]: [23274690.973694] systemd-journal-flush.service: Job systemd-journal-flush.service/start failed with result 'dependency'.
Jul 8 07:02:51 PLPSAPP1 systemd[1]: [23274690.977363] systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart.
Jul 8 07:02:51 PLPSAPP1 systemd[1]: [23274690.980372] systemd-journald.service: Scheduled restart job, restart counter is at 3.
Jul 8 07:02:51 PLPSAPP1 systemd[1]: [23274690.982920] Stopped Journal Service.
Jul 8 07:02:51 PLPSAPP1 systemd[1]: [23274690.987932] Starting Journal Service...
Jul 8 07:02:51 PLPSAPP1 systemd[1]: [23274691.022359] titanagent_check_exception.service: Succeeded.
Jul 8 07:02:51 PLPSAPP1 systemd[1]: [23274691.024182] Started titanagent check exception.

systemd-joural(PID 743)一直存在警告，而后systemd-journal（PID 743）进程由于超时被kill，后续拉起来的systemd-journal（PID 37081）继续报警告。

sa日志分析

sar -rh -f sa08，查看内存使用情况，空闲内存还有很多。

sar -u -f sa08，查看CPU使用情况，问题发生时，用户态使用55%，内核态使用32%。

sar -P ALL -f sa08，查看CPU使用情况，6核CPU，用户态和内核态都使用较高。

sar -q -f sa08，问题发生时系统负载较高。

sar -d -f sa08，查看磁盘读写情况，发现在磁盘读写较低的情况下，await较高。设备sda和sdc的 %util 超过 20%，await 值都超过了 1000ms，表示 I/O 请求在队列中等待的时间很长，可能会导致系统性能下降。

分析小结

分析messages日志，从空间调用 fallocate 系统调用开始，经过多个层次的函数调用，最终到达具体文件系统（tmpfs）的实现。日志中出现的问题表明在这个过程中，内存链表操作发生了损坏，导致内核警告,且伴随提示丢失了40多万行的内核日志信息，记录的情况也已经不是问题的第一现场，出现链表检测错误告警后并不会进行修复，在接下来使用到问题链表时，依旧会出发告警情况。

日志系统进行预分配，需要在tmpfs中进行，且伴随内存页的迁移情况，其中伴随page->lru链表的告警的信息输出，由于日志系统存储在tmpfs中，也造成一定的hang住情况，丢失了不少内核信息，也丢失了问题第一现场

分析sa日志，磁盘读写延迟非常高。长时间的I/O等待会导致内存中的数据迟迟不能写入磁盘，可能影响内存的释放和管理，可能会影响文件系统的元数据操作，如链表操作和页表管理。

从目前的日志情况没有直接的原因说明系统hang住的情况，可能存在其他进程依赖日志输出，日志又被卡住，造成这种依赖的应用系统hang情况