docker内存和cpu调试
本地启动了一个sshd的容器服务，但该容器经常会被重启导致ssh连接失败，使用kubectl describe pod命令查看改命令发现有容器返回值为137，一般是系统环境原因，且一般为内存不足导致的，参见:Container exits with non-zero exit code 137
Started: Tue, 20 Nov 2018 12:14:42 +0800 Last State: Terminated Reason: Error Exit Code: 137 Started: Mon, 19 Nov 2018 14:18:22 +0800 Finished: Tue, 20 Nov 2018 12:14:16 +0800
- 登陆该容器的node节点，查看系统日志发现sshd申请内存严重超时，且看到normal ZONE中的free<min，这种情况下会触发内核杀死进程回收内存，可能会导致sshd容器或containerd进程重启。min的值由vm.min_free_kbytes设置，原理参见min_free_kbytes
Nov 20 04:02:36 ip-172-20-54-91 kernel: [91374.975004] sshd: page allocation stalls for 20388ms, order:0, mode:0x24200ca(GFP_HIGHUSER_MOVABLE) Nov 20 04:02:36 ip-172-20-54-91 kernel: [91374.984454] CPU: 3 PID: 1257 Comm: sshd Not tainted 4.9.0-7-amd64 #1 Debian 4.9.110-3+deb9u2 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91374.988477] Hardware name: Xen HVM domU, BIOS 4.2.amazon 08/24/2006 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91374.995081] 0000000000000000 ffffffff90d30694 ffffffff91401218 ffffb76e46b5fb60 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.004170] ffffffff90b89d0a 024200ca00000006 ffffffff91401218 ffffb76e46b5fb00 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.004170] ffff8b5300000010 ffffb76e46b5fb70 ffffb76e46b5fb20 286e078452d92816 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.004170] Call Trace: Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.004170] [<ffffffff90d30694>] ? dump_stack+0x5c/0x78 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff90b89d0a>] ? warn_alloc+0x13a/0x160 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff90b8a735>] ? __alloc_pages_slowpath+0x995/0xbf0 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff9100fee1>] ? __schedule+0x241/0x6f0 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff90a1bc81>] ? xen_clocksource_get_cycles+0x11/0x20 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff90aef21e>] ? ktime_get+0x3e/0xb0 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff90b8ab91>] ? __alloc_pages_nodemask+0x201/0x260 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff90bdd39e>] ? alloc_pages_vma+0xae/0x260 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff90bb43c9>] ? wp_page_copy+0x89/0x700 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff90bb56c1>] ? do_wp_page+0x161/0x7e0 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff90bc5261>] ? page_add_file_rmap+0x11/0x110 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff90bb7812>] ? alloc_set_pte+0x3c2/0x550 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff90bb8422>] ? handle_mm_fault+0x832/0x1280 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff90a61015>] ? __do_page_fault+0x255/0x4f0 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.026383] [<ffffffff91016018>] ? page_fault+0x28/0x30 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.110910] Mem-Info: Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.113701] active_anon:3868989 inactive_anon:1176 isolated_anon:0 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.113701] active_file:23607 inactive_file:21078 isolated_file:720 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.113701] unevictable:0 dirty:8 writeback:0 unstable:0 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.113701] slab_reclaimable:16746 slab_unreclaimable:57137 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.113701] mapped:38107 shmem:3568 pagetables:20708 bounce:0 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.113701] free:33020 free_pcp:370 free_cma:0 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.143413] Node 0 active_anon:15475956kB inactive_anon:4704kB active_file:94428kB inactive_file:84312kB unevictable:0kB isolated(anon):0kB isolated(file):2880kB mapped:152428kB dirty:32kB writeback:0kB shmem:14272kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 135168kB writeback_tmp:0kB unstable:0kB pages_scanned:50 all_unreclaimable? no Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.169765] Node 0 DMA free:15904kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15988kB managed:15904kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.195526] lowmem_reserve[]: 0 3741 16011 16011 16011 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.201354] Node 0 DMA32 free:64640kB min:15776kB low:19720kB high:23664kB active_anon:3624584kB inactive_anon:144kB active_file:17908kB inactive_file:15952kB unevictable:0kB writepending:0kB present:3915776kB managed:3850208kB mlocked:0kB slab_reclaimable:11200kB slab_unreclaimable:45456kB kernel_stack:12508kB pagetables:16536kB bounce:0kB free_pcp:508kB local_pcp:0kB free_cma:0kB Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.230119] lowmem_reserve[]: 0 0 12270 12270 12270 Nov 20 04:02:36 ip-172-20-54-91 kernel: [91375.235036] Node 0 Normal free:51536kB min:51740kB low:64672kB high:77604kB active_anon:11851568kB inactive_anon:4560kB active_file:76636kB inactive_file:68596kB unevictable:0kB writepending:32kB present:12845056kB managed:12569296kB mlocked:0kB slab_reclaimable:55784kB slab_unreclaimable:183092kB kernel_stack:47380kB pagetables:66296kB bounce:0kB free_pcp:1056kB local_pcp:0kB free_cma:0kB
- 同时可以参见/proc/meminfo中的MemTotal和SwapTotal，可以发现内存已经不足，也可以查看/proc/buddyinfo文件，查看剩余连续内存的分布，小内存比较多时说明内存碎片化比较严重
附：使用perf进行cpu占用率进行分析
- 如下代码中，函数AA死循环，预期会占用大量CPU资源
#include<stdio.h> #include<stdlib.h> void AA(){ int i=0; while(1){ i++; } } void BB(){ printf("BB\n"); } int main(){ BB(); AA(); }
- 首先使用top命令查看cpu占用率，可以看出用户空间cpu占用率达到了50%，而内核空间很低，可以看出cpu占用率主要在用户态，涉及系统调用比较少
%Cpu(s): 50.0 us, 8.3 sy, 0.0 ni, 41.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
- 使用perf top，部分结果如下，可以看到一个名为test的进程，同时可以看到一个名为AA的符号，该符号就是名为AA的函数
Samples: 699K of event 'cpu-clock', Event count (approx.): 8217702565 Overhead Shared Object Symbol 99.68% test [.] AA 0.12% [kernel] [k] _raw_spin_unlock_irqrestore 0.06% [kernel] [k] __do_softirq 0.02% [kernel] [k] e1000_xmit_frame 0.01% libc-2.17.so [.] _int_malloc 0.00% [kernel] [k] clear_page 0.00% libvmtools.so.0.0.0 [.] Backdoor_InOut 0.00% [kernel] [k] kstat_irqs
- 使用perf record记录下10s以内的cpu 处理器时钟使用情况，通过perf report可以看到占用率高的进程的调用栈
perf record -a -e cycles -o cycle.perf -g sleep 10
# perf report -i cycle.perf|more # To display the perf.data header info, please use --header/--header-only options. # # # Total Lost Samples: 0 # # Samples: 22K of event 'cpu-clock' # Event count (approx.): 5736750000 # # Children Self Command Shared Object Symbol # ........ ........ ............... ................... .......................................................................... # 88.97% 0.00% test libc-2.17.so [.] __libc_start_main | ---__libc_start_main main AA 88.97% 0.00% test test [.] main | ---main AA 88.97% 88.88% test test [.] AA | --88.88%--__libc_start_main main AA
TIPS:
- perf工具依赖ELF文件的debug段信息，如果调试到一个stripped binary时因为无法解析会打印16进制信息。
- perf工具无法兼容编译时解析被 -fomit-frame-pointer优化的程序，参见perf CPU Sampling
参见：
https://utcc.utoronto.ca/~cks/space/blog/linux/DecodingPageAllocFailures
https://www.cnblogs.com/004x/p/6651600.htm
http://tldp.org/LDP/Linux-Filesystem-Hierarchy/html/proc.html
https://utcc.utoronto.ca/~cks/space/blog/linux/KernelMemoryZones
https://blog.csdn.net/lickylin/article/details/50726847
http://www.10tiao.com/html/497/201606/2456160252/1.html
https://www.kernel.org/doc/Documentation/filesystems/proc.txt
本文来自博客园，作者：charlieroro，转载请注明原文链接：https://www.cnblogs.com/charlieroro/p/10064022.html
