当前位置： 首页 > article >正文

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

article 2025/2/7 11:14:40

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

麒麟软件产品专区：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情况  

下一步计划

建议日志系统存储到/var/log中，不存储在内存文件系统中，这样避免复现问题丢失日志情况，进一步有助于问题分析。

#创建目录  /var/log/journal    

mkdir -p /var/log/journal     

#修改/etc/systemd/journald.conf文件

[Journal]
SystemMaxUse=2G
SystemMaxFileSize=128M

而后执行systemctl restart systemd-journald

问题出现后，在未重系统启前，可以echo c > /proc/sysrq-trigger手动触发vmcore，收集vmcore进行进一步分析。


http://www.kler.cn/a/534962.html

相关文章：

  • 音频录制一般在什么情况下会选择保存为PCM？什么情况会选择保存为WAV？
  • 《深度洞察ICA：人工智能信号处理降维的独特利器》
  • Deepseek本地部署（ollama+open-webui）
  • PHP Composer：高效依赖管理工具详解
  • 走向基于大语言模型的新一代推荐系统：综述与展望
  • 四川正熠法律咨询有限公司正规吗可信吗？
  • Redis持久化-秒杀系统设计
  • flappy-bird-gymnasium
  • 【Linux系统】线程：线程的优点 / 缺点 / 超线程技术 / 异常 / 用途
  • 深入理解 Unix Shell 管道 Pipes：基础和高级用法 xargs tee awk sed等（中英双语）
  • 第二节 程序设计的基本结构
  • 无人机在铁路隧道检查应用技术详解
  • DeepSeek之python实现API应用
  • 【LLM运用】在Ubuntu上Cosyvoice的部署
  • java异常分类，异常处理，面试中常见异常问题！
  • Java并发面试题（题目来源JavaGuide）
  • 算法设计与分析三级项目--管道铺设系统
  • css-根据不同后端返回值返回渲染不同的div样式以及公共组件设定
  • Spring JDBC模块解析 -深入SqlParameterSource
  • 论文解读 | NeurIPS'24 Spotlight ChronoMagic-Bench 评估文本到视频生成的质变幅度评估基准...
  • B站自研的第二代视频连麦系统（上）
  • 拧紧“安全阀”，AORO-P300 Ultra防爆平板畅通新型工业化通信“大动脉”
  • .net的一些知识点3
  • Windows本地部署DeepSeek-R1大模型并使用web界面远程交互
  • 网络面试题（第一部分）
  • 7.攻防世界 wzsc_文件上传