侧边栏壁纸
博主头像
沧海月明

解决了什么问题，做了什么优化

  • 累计撰写 149 篇文章
  • 累计创建 33 个标签
  • 累计收到 1 条评论

目 录CONTENT

文章目录
运维基础 技术实践

【实践】k8s问题排查和解决方案

FatFish1
FatFish1
2024-11-11 / 0 评论 / 0 点赞 / 68 阅读 / 0 字 / 正在检测是否收录...

问题1 Exit Code 1

首先明确Exit Code 1的含义：在创建容器时执行初始化命令失败，容器状态如下

Init:CrashLoopBackOff

对于exit(1)的容器，使用kubectl logs可能看不出来，因为容器初始化失败了

执行

kubectl describe pods -n <namespace>

可以看到执行失败的命令

Command:
   /bin/sh
   -c
   chown 1100:1100 /home/service/******; chmod 700 /home/service/******

原来是目录权限变更语句执行失败了。来到node节点上找日志

cd /var/log/containers
ls | grep <servicename>

找到当前服务启动对应日志，看到如下内容：

{"log":"chown: changing ownership of '/home/service/******': Operation not permitted\n","stream":"stderr","time":"2024-10-17T01:40:54.747865763Z"}

{"log":"chmod: changing permissions of '/home/service/******': Operation not permitted\n","stream":"stderr","time":"2024-10-17T01:40:54.751532166Z"}

可以看到是因为没有权限执行导致的

但是有其他服务部署也挂载了这个目录，那就进其他服务的pod里面看看

docker ps -a | grep <otherservice>
cd /home/service/******
cd ../
ll

发现这个目录的权限归属是root用户

再看失败服务的容器设置：

spec:
  ……
  securityContext:
    runAsUser: 1100   # pod进程用户id
    runAsGroup: 3000  # pod进程用户组id
    fsGroup: 2000     # 挂载卷文件组id

看到runAsUser指定的用户进程是1100，即service用户

  • runAsUser字段：指定Pod中的所有容器内的进程都使用指定用户ID来运行。

  • runAsGroup 字段：指定所有容器中的进程都以主组 ID来运行。 如果忽略此字段，则容器的主组 ID 将是 root（0）。

  • fsGroup字段：容器中挂载卷及在该卷中创建的任何文件的属主都会是指定组ID。

可知问题是用户组权限不对导致目录修改失败

问题2 k8s OOMKilled - 直接内存场景

myservice-75cb6665db-4z6ct 3/3 Running 1 2h

看到pod上产生1次重启，通过执行kubectl describe pods myservice-75cb6665db-4z6ct 可以看到详情：

Containers:
  myservice:
    Container ID:   docker://ed1f6757ce5d01a5cbf1de99eb789a4f1b6342c52650c89379857c184837f047
    Image:          ……
    Image ID:       ……
    Port:           ……
    State:          Running
      Started:      Sun, 10 Nov 2024 11:39:26 +0800
    Last State:     Terminated
      Reason:       OOMKilled
      Exit Code:    143
      Started:      Thu, 24 Oct 2024 17:40:14 +0800
      Finished:     Sun, 10 Nov 2024 11:39:26 +0800
    Ready:          True
    Restart Count:  1

可知是由于OOMKilled导致的pod被杀，去node节点上面找日志

先基于containerID找pod对应的docker containerid

docker ps -a | grep ed1f67

>> k8s_myservice_myservice-68f4494d45-6jhcw_default_ec1af12e-91eb-11ef-b2a4-fa163eaa4e5f_1

可以看到docker containerID是ec1af12e-91eb-11ef-b2a4-fa163eaa4e5f

执行

cd /var/log/pods/ec1af12e-91eb-11ef-b2a4-fa163eaa4e5f
ll

>>
lrwxrwxrwx 1 root root 166 Oct 24 17:40 myservice_0.log -> /mnt/paas/docker/containers/49bcb9e499e12004a7cc5db6e57f2df19b0aa8d93538d941eeada5e29f095dfe/49bcb9e499e12004a7cc5db6e57f2df19b0aa8d93538d941eeada5e29f095dfe-json.log
lrwxrwxrwx 1 root root 166 Nov 10 11:39 myservice_1.log -> /mnt/paas/docker/containers/ed1f6757ce5d01a5cbf1de99eb789a4f1b6342c52650c89379857c184837f047/ed1f6757ce5d01a5cbf1de99eb789a4f1b6342c52650c89379857c184837f047-json.log

可以看到该服务有两个日志，_0是之前出问题被kill的，_1是新的

基于这个k8s containerID找容器日志，执行

cd /var/log
grep 49bcb9e499e12004a7cc5db6e57f2df19b0aa8d93538d941eeada5e29f095dfe messages

>>
messages:Nov 10 11:37:42 myk8s kernel: [13611867.088189] [ pid ]   uid  tgid total_vm      rss nr_ptes swapents oom_score_adj name
messages:Nov 10 11:37:42 myk8s kernel: [13611867.088270] [14862]  1100 14862      287       14       4        0           873 tini
messages:Nov 10 11:37:42 myk8s kernel: [13611867.088272] [15150]  1100 15150      995      143       7        0           873 entrypoint.sh
messages:Nov 10 11:37:42 myk8s kernel: [13611867.088277] [18301]  1100 18301  6998963  4179660   10362        0           873 java
messages:Nov 10 11:37:42 myk8s kernel: [13611867.088296] [72910]  1100 72910      563       18       5        0           873 sleep
messages:Nov 10 11:37:42 myk8s kernel: [13611867.088299] Memory cgroup out of memory: Kill process 62995 (retry-pool-thre) score 1871 or sacrifice child
messages:Nov 10 11:37:42 myk8s kernel: [13611867.089747] Killed process 18301 (java) total-vm:27995852kB, anon-rss:16718640kB, file-rss:0kB, shmem-rss:0kB

可以看到是cgroup的memory超过阈值导致的，在这个日志中，默认的页大小是4kb，即uid 1100对应的数据是页数，后面要x4，即下面这段日志：

messages:Nov 10 11:37:42 myk8s kernel: [13611867.088189] [ pid ]   uid  tgid total_vm      rss nr_ptes swapents oom_score_adj name
……
messages:Nov 10 11:37:42 myk8s kernel: [13611867.088277] [18301]  1100 18301  6998963  4179660   10362        0           873 java

数据都要x4才能得到实际的kb

而再下面的kill日志中是实际的kb：

  • total-vm： 进程使用的虚拟内存大小，即程序要求申请的大小，在linux存在namespace、cgroup机制的场景下，所有pod的申请内存可能远超docker容器所在节点的物理内存

  • rss： resident set size，用人话说就是程序实际使用的大小，是一种衡量Linux中进程使用的内存量的方法。total-vm中的一部分内存实际上已经被映射到了系统RAM区来供其分配或使用（或已分配和使用）

  • anon-rss： 即匿名内存。分配在实际内存块中的那部分rss，例如调用malloc函数

  • file-rss： 映射到设备和文件得 rss内存块

根据这个日志可以看出来：JAVA进程18301的内存情况为：

  • 申请的内存大小为27995852kb（total_vm页数x4）

  • 实际使用的内存为16718640kb（rss页数x4），其中全部为anon-rss内存（malloc申请的）

基于此上情况分析：

  • 如果在vim中打开一个很大的文件，file-rss会变得很大

  • 如果使用malloc()、new来申请大量内存并使用，那么anon-rss将会变得很大

  • 如果使用malloc()、new分配了大量的空间却没有使用，那么total-vm将会变得更高，但是由于这样不会真正使用内存，所以 rss会很低

基本可以确定问题来源是内存分配不当，使用NMT追踪内存，增加配置

JAVA_OPTS="$JAVA_OPTS -XX:NativeMemoryTracking=detail"

定时执行以下命令，查看内存情况

./jcmd <pid> VM.native_memory detail > nmt.txt

通过查看NMT结果发现Internal区在增加，推测为直接内存有增长

-                  Internal (reserved=122600KB, committed=122600KB)
                            (malloc=122564KB #92403)
                            (mmap: reserved=36KB, committed=36KB)

通过arthas组件也可以印证这一点

./java -jar arthas-boot.jar <pid>

> memory
direct                                   78M                        78M                        -                 100.00%

看到drect区在不断增长

直接内存问题可以通过nio分析内存泄露，先通过jstack确认是哪里使用了nio

./jstack <pid>
"Connect thread xx.xx.xxx.xxx session" #1108 prio=5 os_prio=0 cpu=1732.18ms elapsed=80210.18s tid=0x00007fb544006160 nid=0xeed runnable  [0x00007fb19eced000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.Net.poll(java.base@17.0.8/Native Method)
        at sun.nio.ch.NioSocketImpl.park(java.base@17.0.8/Unknown Source)
        at sun.nio.ch.NioSocketImpl.timedRead(java.base@17.0.8/Unknown Source)
        at sun.nio.ch.NioSocketImpl.implRead(java.base@17.0.8/Unknown Source)
        at sun.nio.ch.NioSocketImpl.read(java.base@17.0.8/Unknown Source)
        at sun.nio.ch.NioSocketImpl$1.read(java.base@17.0.8/Unknown Source)
        at java.net.Socket$SocketInputStream.read(java.base@17.0.8/Unknown Source)
        at com.jcraft.jsch.IO.getByte(IO.java:83)
        at com.jcraft.jsch.Session.read(Session.java:1177)
        at com.jcraft.jsch.Session.run(Session.java:1723)
        at com.jcraft.jsch.Session$$Lambda$6096/0x00007fb5c529de30.run(Unknown Source)
        at java.lang.Thread.run(java.base@17.0.8/Unknown Source)

可以看到服务中使用了jsch组件使用nio，在timedRead方法中申请了直接内存

直接内存释放是通过System.gc()进行的，这里可以参考nio部分，检查服务的JVM参数，服务配置-XX:+DisableExplicitGC 但未配置--XX:MaxDirectMemorySize=512m ，这样导致服务无限制申请直接内存，且不进行回收，最终OOM

解决方案：增加-XX:+ExplicitGCInvokesConcurrent 、-XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses 、

-XX:MaxDirectMemorySize=512m ，去掉-XX:+DisableExplicitGC （待验证）

问题3 anon内存过多导致OOMKill的场景

大部分情况下，直接内存是很不容易找到其泄露点的，不是IO导致的直接内存泄露，还有一个考虑方向：Linux Arena内存池分配过量超过堆外内存限制

同样也是OOMKill场景，按照pmap+NMT的套路分析，发现没有什么明显的堆外内存泄露，使用pmap分析：

pmap -x <pid> | sort -n -k3 > pmap-sorted.txt

可以因为NMT工具有局限性，只能找到JVM相关的内存，如果是直接申请在Linux底层的内存，NMT是没法抓到的，这时候可以借助pmap拿到的内存块与NMT进行对比，找到pmap中存在但NMT中不存在的

结果发现了一些接近64M的anon块，但看上去也不是太多：

00007f9de0000000   65508   57780   57780 rw---   [ anon ]
……
……

这部分地址被标记为anon，一开始并不太了解这是些什么，那就使用gdb对其进行分析

gdb -pid 2071
dump memory mem.bin 0x7fa754000000 0x7f9de0000000
strings mem.bin

一般gdb分析可以看到里面是一些类字节码和一些字符串，大致可以推测是什么东西在消耗内存

但是在这个案例中，看到的只有一些短的字符，也没有什么字节码相关的内容，那这里到底是些啥呢

偶然发现一个参考文章：

https://cloud.tencent.com/developer/article/1054839

得知anon是Anonymous memory段的缩写，查资料才知道，有一个Arena内存池，它跟cpu核数是相关的

一般来说，

32-bit应用程序Arena的大小最大为1MB，64-bit应用程序最大为64MB，而1c对应8个Arena内存，每个为64M

那么4c=512M * 4，即2G的潜在占用，随着时间，这部分内存会逐渐填充

在docker环境下，这2G的堆外内存就变成了无形的消耗，因为docker环境相当于一个java进程，申请的线程大小是提前定好的，直接放在cgroup的限制中，在容器中java程序的jvm参数中，已经通过Xms、Xmx等参数设置好了堆内存，相应的剩下就给了堆外内存

如果这时候Arena内存不断增加，理论上限为2G，就会不断积压堆外内存，最终积压的还是cgroup到底内存总量，最终导致OOMKill

可以通过减少Arena区的形式减少堆外内存消耗：

根据Hadoop、Redis等产品的最佳实践建议，尝试设置MALLOC_ARENA_MAX环境变量值为4：

export MALLOC_ARENA_MAX=4

或者直接降低核数到3，本质上应该是类似的效用

事实发现确实有用，OOMKill情况没有再发生

但是相应的，减少Arena区内存可能让JVM进程的Native Memory分配、重用、回收等性能多多少少会受到一些影响，也可以使用Google的tcmalloc解决。

问题4 日志文件读写与OOMKill

这次的问题与之前类似，还是容器频繁出现的OOMKill，初步排查服务，发现并没有堆内存泄露

这次结合服务特性，将目光放在日志打印方面

进入pod后，进入cgroup目录查看：

cd /sys/fs/cgroup/memory/

cat memory.stat

看到如下输出：

cache 319287296
rss 9138176
total_cache 319287296
total_inactive_anon 4096
total_active_anon 9072640
total_inactive_file 114122752
total_active_file 205148160

其中rss就是anon-rss，可以理解为堆内存，cache是pageCache，查阅资料，了解为：除了通过MMap文件直接映射外，进程文件还可以通过系统调用Buffered I/O相关的Syscall将数据写入到PageCache，因此，PageCache也会占用一部分内存。

带total的相当于一个总量

而其中：

total_inactive_file 114122752
total_active_file 205148160

就是活跃和不活跃文件的总量，可以看到，二者之和即cache

而在做docker内存统计的时候，使用docker stat命令得到的MEM USAGE是memory.usage_in_bytes-memory.stat[total_cache]的结果

func calculateMemUsageUnixNoCache(mem types.MemoryStats) float64 {
    return float64(mem.Usage - mem.Stats["cache"])
}

发现这个服务堆内存使用并不高，但是文件缓存缺占据了很大一部分

尝试清空日志文件，发现cache得到极大缓解，这是为什么呢，是因为inactive_file这一部分代表的缓存是一种滞留的缓存，它的内存曾经被容器使用过，但现在不再被容器使用。因此，它被容器视为“可自由重用”，或者如果有内存压力，主机可以随时回收它（如果没有内存压力，主机将不会回收它）

而在k8s环境下，这一部分内存是不会计入容器使用的堆内存中，因此也是一个非常不容易发现的点

结合分析，可以得到一个解决方案：调整log4j压缩日志的大小，减轻io读写文件压力

0
docker 操作系统 kubernetes
版权归属： FatFish1
本文链接： http://localhost:8090/archives/k8squestion
许可协议： 本文使用《署名-非商业性使用-相同方式共享 4.0 国际 (CC BY-NC-SA 4.0)》协议授权

评论区