RHEL6环境下透明大页和Hadoop高CPU sys
同学反馈hadoop运行在虚拟机中，出现非常异常的负载过高问题。一旦任务开始运行，系统立即卡得无法操作。
登录检查top，发现任务运行时，CPU主要消耗在system而不是计算的use，这说明存在什么程序异常，导致不断在内核态消耗系统资源，并没有正常在工作计算。
top - 15:52:28 up 1 day, 5:05, 7 users, load average: 16.69, 5.96, 2.19
Tasks: 181 total, 16 running, 165 sleeping, 0 stopped, 0 zombie
Cpu0 : 5.9%us, 93.8%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.3%hi, 0.0%si, 0.0%st
Cpu1 : 3.6%us, 96.4%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu2 : 4.6%us, 95.4%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu3 : 0.3%us, 99.7%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 8058056k total, 7476536k used, 581520k free, 37996k buffers
Swap: 0k total, 0k used, 0k free, 3225056k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ GROUP P TIME COMMAND
2570 hadoop 20 0 4453m 648m 25m S 0.3 8.2 53:12.97 hadoop 2 53:12 java
1843 hdfs 20 0 2767m 435m 28m S 0.0 5.5 16:52.01 hadoop 0 16:52 java
2514 hadoop 20 0 2357m 424m 51m S 0.0 5.4 2:08.02 hadoop 3 2:08 java
1748 hdfs 20 0 3899m 421m 28m S 18.7 5.4 89:12.91 hadoop 0 89:12 java
2707 root 20 0 4603m 398m 52m S 0.6 5.1 2:51.18 root 1 2:51 java
2490 hadoop 20 0 2261m 359m 50m S 0.0 4.6 2:37.18 hadoop 3 2:37 java
1942 hadoop 20 0 4141m 344m 28m S 0.6 4.4 14:30.26 hadoop 3 14:30 java
2940 hadoop 20 0 2819m 282m 28m S 0.3 3.6 7:10.89 hadoop 3 7:10 java
4966 root 20 0 3686m 219m 14m S 14.1 2.8 0:51.95 root 1 0:51 java
19706 root 20 0 3027m 164m 13m S 0.3 2.1 2:09.46 root 1 2:09 java
3097 hadoop 20 0 2746m 156m 27m S 0.0 2.0 1:27.23 hadoop 3 1:27 java
5830 hadoop 20 0 2198m 107m 27m S 33.7 1.4 1:09.69 hadoop 0 1:09 java
27060 root 20 0 303m 75m 5200 S 18.4 1.0 7:05.99 root 3 7:05 ilogtail
3043 hue 20 0 2710m 73m 5664 S 0.0 0.9 0:14.46 hue 1 0:14 hue
26082 ganglia 20 0 286m 37m 2556 R 17.8 0.5 68:19.41 ganglia 2 68:19 gmond
1364 mysql 20 0 626m 28m 4344 S 0.0 0.4 0:31.21 mysql 3 0:31 mysqld
2688 root 20 0 352m 14m 3440 S 0.3 0.2 0:51.18 root 0 0:51 supervisor
3268 root 20 0 276m 9716 4940 S 0.0 0.1 0:03.76 root 3 0:03 httpd
3170 ganglia 20 0 227m 9260 1348 S 19.3 0.1 41:04.32 ganglia 2 41:04 gmetad
1438 root 20 0 81940 8952 5288 S 0.3 0.1 7:22.85 root 0 7:22 AliHids
27105 root 20 0 172m 7052 3084 S 0.0 0.1 5:01.65 root 0 5:01 python上述任务运行起来时候，发现系统执行任何检查内存状态命令都很缓慢。例如vmstat时候，卡了好一会才开始有输出。但是vmstat输出可以看到，并没有很高的上下文切换
[root@emr-header-1 ~]# vmstat 1 10
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
13 0 0 587056 37908 3225036 0 0 30 36 57 7 2 25 73 0 0
12 0 0 587056 37908 3225036 0 0 0 0 6229 2902 4 96 0 0 0
12 0 0 586932 37908 3225036 0 0 0 0 4666 2147 5 95 0 0 0
14 0 0 587064 37916 3225028 0 0 0 32 4696 2225 4 96 0 0 0
13 0 0 587064 37916 3225036 0 0 0 92 4700 2252 4 96 0 0 0
13 0 0 586940 37916 3225036 0 0 0 0 4639 2158 4 97 0 0 0
14 0 0 586924 37916 3225036 0 0 0 0 4656 2221 2 99 0 0 0
17 0 0 586924 37916 3225036 0 0 0 0 4578 2216 4 96 0 0 0
18 0 0 586800 37916 3225036 0 0 0 4 4592 2229 4 96 0 0 0
18 0 0 586800 37920 3225036 0 0 0 40 4621 2237 5 95 0 0 0尝试用ps抓运行在队列中任务也不行，卡住没有任何输出。检查发现ps命令无法使用
[root@emr-header-1 ~]# ps -o comm,pid,ppid,user,time,etime,start,pcpu,state --sort=comm aH | grep '^COMMAND\|R$'原因是procfs无法访问，尝试cd到proc中检查进程状态，发现也不能进入，长时间无输出。
[root@emr-header-1 ~]# cd /proc/2570google了一下，原来这个问题是RedHat Enterprise Linux 6的透明大页的bug Performance Issues with Transparent Huge Pages (THP) 。详细的排查方法，可以参考 Linux 6 Transparent Huge Pages and Hadoop Workloads
尝试关闭透明大页
检查当前THP状态，可以看到是始终打开的，我们现在关闭掉
[root@emr-header-1 proc]# cat /sys/kernel/mm/redhat_transparent_hugepage/enabled
[always] madvise never
[root@emr-header-1 proc]# echo never > /sys/kernel/mm/redhat_transparent_hugepage/enabled
[root@emr-header-1 proc]# cat /sys/kernel/mm/redhat_transparent_hugepage/enabled
always madvise [never][root@emr-header-1 2570]# cat /sys/kernel/mm/redhat_transparent_hugepage/defrag
[always] madvise never关闭
[root@emr-header-1 2570]# echo never > /sys/kernel/mm/redhat_transparent_hugepage/defrag
[root@emr-header-1 2570]# cat /sys/kernel/mm/redhat_transparent_hugepage/defrag
always madvise [never]然后重启emr-agent
[root@emr-header-1 2570]# service emr-agent restart
Stopping emr-agent: [ OK ]
Starting emr-agent: [ OK ]此时再次观察，发现任务的还是没有解决问题
top - 17:47:40 up 1 day, 7:01, 8 users, load average: 14.30, 12.24, 8.06
Tasks: 170 total, 8 running, 162 sleeping, 0 stopped, 0 zombie
Cpu0 : 0.7%us, 99.0%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.3%si, 0.0%st
Cpu1 : 0.7%us, 99.3%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu2 : 0.3%us, 99.7%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu3 : 2.0%us, 98.0%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 8058056k total, 7686156k used, 371900k free, 41568k buffers
Swap: 0k total, 0k used, 0k free, 3420192k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
26082 ganglia 20 0 288m 39m 2556 R 55.1 0.5 81:53.35 gmond
15053 hadoop 20 0 4553m 121m 24m S 53.4 1.5 6:36.45 java
20001 root 20 0 297m 70m 5184 S 31.5 0.9 6:56.79 ilogtail
15788 root 20 0 56796 520 364 R 30.9 0.0 0:09.23 rrdtool
18497 root 20 0 3695m 266m 15m S 28.9 3.4 8:45.15 java
15798 root 20 0 112 4 0 R 28.5 0.0 0:01.03 env
15768 root 20 0 15036 1176 840 R 25.6 0.0 0:23.93 top
15787 root 20 0 16924 1228 848 R 25.6 0.0 0:09.62 sampler.py
15797 root 20 0 1180 92 72 R 25.6 0.0 0:01.56 sh
15775 root 20 0 103m 1564 1120 S 21.6 0.0 0:11.87 service
1748 hdfs 20 0 3899m 383m 28m S 20.6 4.9 96:18.13 java
11108 root 20 0 312m 4216 1660 S 6.0 0.1 20:09.36 aegis_quartz
13983 root 20 0 98328 4160 3156 S 6.0 0.1 3:57.80 sshd
283 root 20 0 0 0 0 S 3.3 0.0 8:37.16 jbd2/xvda1-8
2424 root 20 0 98324 4164 3156 S 3.3 0.1 1:37.10 sshd
3170 ganglia 20 0 227m 9032 1348 S 3.0 0.1 46:59.56 gmetad这个问题想尝试通过扩容内存和CPU来排查，采用XEN guest操作系统动态添加／移除内存或CPU为虚拟机扩容内存，从原先8G扩容到16G
不过，这个方法还没有做，先看看是哪个占用了sys
查找sys占用较高的进程
使用了一个比较土的方法，先把系统中所有正在运行的进程找出来
ps aux | awk '{print $2}' | tee run_pid然后对每个进程使用pidstat命令，这样就可以看出是使用多少system
for i in `cat run_pid`;do pidstat -p $i;done | tee run_pid_cpu此时能够得到的信息类似
Linux 2.6.32-431.23.3.el6.x86_64 (emr-header-1.cluster-25364) 12/19/2016 _x86_64_ (4 CPU)
04:41:59 PM PID %usr %system %guest %CPU CPU Command
04:41:59 PM 14541 0.66 1.87 0.00 2.53 1 java
Linux 2.6.32-431.23.3.el6.x86_64 (emr-header-1.cluster-25364) 12/19/2016 _x86_64_ (4 CPU)
04:41:59 PM PID %usr %system %guest %CPU CPU Command
04:41:59 PM 17981 0.15 13.68 0.00 13.83 1 gmond现在按照第5列（%system）排序进程
cat run_pid_cpu | grep -v PID | grep -v 2.6.32-431.23.3.el6 | grep -v "^$" | sort -k 5需要按照第4列（
%system）排序就可以知道是哪个进程异常 (参考 Sort file according to the second column?)
-k, --key=POS1[,POS2]
start a key at POS1, end it at POS2 (origin 1)
POS is F[.C][OPTS], where F is the field number and C the character position in the field. OPTS is one or more single-letter ordering options, which override global ordering options for that key. If no key is given, use the entire line as the key.
-t, --field-separator=SEP
use SEP instead of non-blank to blank transition可以看到占用处理器资源的情况主要集中在如下进程（第5列最大的值在最下面），其中异常的是gmond，占用了大量的system，但是缺没有us
04:41:59 PM 1629 0.01 1.27 0.00 1.28 3 bash
04:41:59 PM 10114 0.03 1.31 0.00 1.34 0 aegis_quartz
04:41:59 PM 1846 0.16 1.84 0.00 2.01 0 java
04:41:59 PM 14541 0.66 1.87 0.00 2.53 1 java
04:41:59 PM 1456 0.19 3.11 0.00 3.30 2 AliYunDun
04:41:59 PM 2599 17.73 3.67 0.00 21.40 3 java
04:41:59 PM 4953 0.25 3.70 0.00 3.95 1 java
04:41:59 PM 5883 0.02 3.89 0.00 3.92 1 ilogtail
04:41:59 PM 6644 0.12 8.08 0.00 8.20 2 java
04:41:59 PM 17981 0.15 13.68 0.00 13.83 1 gmondgmond是集群监控系统ganglia的监控服务，google到 gmond occupying 100% of the CPU 在非多播环境中，gmond进程可能会导致系统CPU百分百占用掉。这种情况下，检查节点是否设置deaf（也就是节点是否接收任何节点的消息），设置
deaf = yesgmond occupying 100% of the CPU 文档提到 CentOS 6.5有这个现象，ubuntu也有
这个设置貌似有效，虽然还是没有完全解决问题，因为我设置以后再采用上述方法排查
05:26:58 PM 1629 0.01 1.06 0.00 1.06 1 bash
05:26:58 PM 10938 0.01 1.10 0.00 1.11 2 gmond
05:26:58 PM 10114 0.03 1.31 0.00 1.34 0 aegis_quartz
05:26:58 PM 13746 0.01 1.46 0.00 1.47 3 ilogtail
05:26:58 PM 14541 0.60 1.59 0.00 2.19 1 java
05:26:58 PM 1846 0.15 1.68 0.00 1.84 0 java
05:26:58 PM 12909 0.20 2.00 0.00 2.20 1 java
05:26:58 PM 1456 0.19 3.11 0.00 3.30 0 AliYunDun
05:26:58 PM 2599 14.11 3.47 0.00 17.58 3 java
05:26:58 PM 15105 0.08 4.21 0.00 4.29 2 java看上去至少进程gmond已经不再大量消耗sys
strace
对
gmond进行 strace查看系统调用
strace -c -p 10938显示输出
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
99.99 13.704919 39157 350 read
0.01 0.001210 2 628 fstat
0.00 0.000211 1 326 1 open
0.00 0.000192 1 314 munmap
0.00 0.000147 0 327 close
0.00 0.000147 0 315 mmap
0.00 0.000087 0 274 137 write
0.00 0.000024 0 137 sendto
0.00 0.000000 0 6 stat
0.00 0.000000 0 325 lstat
0.00 0.000000 0 3 3 ioctl
0.00 0.000000 0 1 select
0.00 0.000000 0 3 socket
0.00 0.000000 0 4 getdents
0.00 0.000000 0 4 statfs
------ ----------- ----------- --------- --------- ----------------
100.00 13.706937 3017 141 total检查堆栈
[root@emr-header-1 ~]# cat /proc/10938/stack
[<ffffffff811a06d9>] poll_schedule_timeout+0x39/0x60
[<ffffffff811a179c>] do_select+0x57c/0x6c0
[<ffffffff811a1a6a>] core_sys_select+0x18a/0x2c0
[<ffffffff811a1df7>] sys_select+0x47/0x110
[<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xfffffffffffffffffor i in `ps -AL |grep gmond |cut -c 7-12`; do \
echo === $i ===; \
gdb --q --n --ex bt --batch --pid $i; \
done 2>&1 |tee /tmp/stacks.txt显示输出
=== 10938 ===
[Thread debugging using libthread_db enabled]
0x0000003bfb4e1353 in __select_nocancel () from /lib64/libc.so.6
#0 0x0000003bfb4e1353 in __select_nocancel () from /lib64/libc.so.6
#1 0x0000003c03023125 in apr_sleep () from /usr/lib64/libapr-1.so.0
#2 0x00000000004088f8 in main ()看上去
AliYunDun1456 似乎也是一个问题
在没有运行java程序对时候显示如下
[root@emr-header-1 ~]# strace -c -p 1456
Process 1456 attached - interrupt to quit
^CProcess 1456 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00 0.033997 103 331 nanosleep
0.00 0.000000 0 1 restart_syscall
------ ----------- ----------- --------- --------- ----------------
100.00 0.033997 332 total
[root@emr-header-1 ~]# strace -c -p 1456
Process 1456 attached - interrupt to quit
^CProcess 1456 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00 0.021996 89 248 nanosleep
0.00 0.000000 0 1 restart_syscall
------ ----------- ----------- --------- --------- ----------------
100.00 0.021996 249 total开始运行任务以后尝试strace云盾进程，发现这个进程不允许跟踪
[root@emr-header-1 2]# strace -c -p 1456
attach: ptrace(PTRACE_ATTACH, ...): Operation not permitted开始运行任务以后显示
for i in `ps -AL |grep AliYunDun |cut -c 7-12`; do \
echo === $i ===; \
gdb --q --n --ex bt --batch --pid $i; \
done 2>&1 |tee /tmp/stacks.txt显示输出
=== 1109 ===
[New LWP 1137]
[New LWP 1111]
[New LWP 1110]
[Thread debugging using libthread_db enabled]
0x0000003bfb4aca3d in nanosleep () from /lib64/libc.so.6
#0 0x0000003bfb4aca3d in nanosleep () from /lib64/libc.so.6
#1 0x0000003bfb4ac8b0 in sleep () from /lib64/libc.so.6
#2 0x0000000000441333 in ?? ()
#3 0x000000000041a7dd in ?? ()
#4 0x000000000041ada4 in ?? ()
#5 0x00000000004199ab in ?? ()
#6 0x0000000000409767 in ?? ()
#7 0x0000003bfb41ed5d in __libc_start_main () from /lib64/libc.so.6
#8 0x0000000000409629 in ?? ()
#9 0x00007fff8726fd48 in ?? ()
#10 0x000000000000001c in ?? ()
#11 0x0000000000000001 in ?? ()
#12 0x00007fff87270e99 in ?? ()
#13 0x0000000000000000 in ?? ()
=== 1110 ===
warning: process 1110 is a cloned process
[Thread debugging using libthread_db enabled]
0x0000003bfb4aca3d in nanosleep () from /lib64/libc.so.6
#0 0x0000003bfb4aca3d in nanosleep () from /lib64/libc.so.6
#1 0x0000003bfb4e1be4 in usleep () from /lib64/libc.so.6
#2 0x000000000044131a in ?? ()
#3 0x000000000043e650 in ?? ()
#4 0x000000000043d84f in aqs::CThreadUtil::ThreadFunc(void*) ()
#5 0x0000003bfbc079d1 in start_thread () from /lib64/libpthread.so.0
#6 0x0000003bfb4e88fd in clone () from /lib64/libc.so.6
=== 1111 ===
warning: process 1111 is a cloned process
[Thread debugging using libthread_db enabled]
0x0000003bfb4aca3d in nanosleep () from /lib64/libc.so.6
#0 0x0000003bfb4aca3d in nanosleep () from /lib64/libc.so.6
#1 0x0000003bfb4e1be4 in usleep () from /lib64/libc.so.6
#2 0x000000000044131a in ?? ()
#3 0x0000000000422628 in ?? ()
#4 0x000000000043d84f in aqs::CThreadUtil::ThreadFunc(void*) ()
#5 0x0000003bfbc079d1 in start_thread () from /lib64/libpthread.so.0
#6 0x0000003bfb4e88fd in clone () from /lib64/libc.so.6
=== 1137 ===
warning: process 1137 is a cloned process
[Thread debugging using libthread_db enabled]
0x0000003bfb4aca3d in nanosleep () from /lib64/libc.so.6
#0 0x0000003bfb4aca3d in nanosleep () from /lib64/libc.so.6
#1 0x0000003bfb4ac8b0 in sleep () from /lib64/libc.so.6
#2 0x0000000000441333 in ?? ()
#3 0x0000000000417c43 in ?? ()
#4 0x0000000000417e80 in ?? ()
#5 0x000000000043d84f in aqs::CThreadUtil::ThreadFunc(void*) ()
#6 0x0000003bfbc079d1 in start_thread () from /lib64/libpthread.so.0
#7 0x0000003bfb4e88fd in clone () from /lib64/libc.so.6
=== 1456 ===对java进程
strace对于java无效
[root@emr-header-1 ~]# strace -c -p 22345
Process 22345 attached - interrupt to quit
^CProcess 22345 detachedjava
[root@emr-header-1 ~]# cat /proc/22345/stack
[<ffffffff810ae569>] futex_wait_queue_me+0xb9/0xf0
[<ffffffff810af678>] futex_wait+0x1f8/0x380
[<ffffffff810b0f91>] do_futex+0x121/0xb50
[<ffffffff810b1a3b>] sys_futex+0x7b/0x170
[<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffffjps
[root@emr-header-1 ganglia]# cat /proc/22437/stack
[<ffffffff810ae569>] futex_wait_queue_me+0xb9/0xf0
[<ffffffff810af678>] futex_wait+0x1f8/0x380
[<ffffffff810b0f91>] do_futex+0x121/0xb50
[<ffffffff810b1a3b>] sys_futex+0x7b/0x170
[<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffff发现多个java进程都是等待在futex_wait_queue_me，搜索到[App hangs on futex_wait_queue_me() every a couple of minutes](App hangs on futex_wait_queue_me() every a couple of minutes) 说明：
CentOS 6的内核在运行java和多线程的程序会存在bug，升级到 2.6.32-504.16.2.el6.x86_64 后可以解决，具体的bug报告在 https://bugs.centos.org/view.php?id=8703 ，详细的问题解释在 futex: Ensure get_futex_key_refs() always implies a barrier
Commit b0c29f7 (futexes: Avoid taking the hb->lock if there's
nothing to wake up) changes the futex code to avoid taking a lock when
there are no waiters. This code has been subsequently fixed in commit
11d4616 (futex: revert back to the explicit waiter counting code).
Both the original commit and the fix-up rely on get_futex_key_refs() to
always imply a barrier.
However, for private futexes, none of the cases in the switch statement
of get_futex_key_refs() would be hit and the function completes without
a memory barrier as required before checking the "waiters" in
futex_wake() -> hb_waiters_pending(). The consequence is a race with a
thread waiting on a futex on another CPU, allowing the waker thread to
read "waiters == 0" while the waiter thread to have read "futex_val ==
locked" (in kernel).
Without this fix, the problem (user space deadlocks) can be seen with
Android bionic's mutex implementation on an arm64 multi-cluster system.升级CentOS 6内核 2.6.32-642.11.1.el6 升级以后同样的任务调度不再出现异常的sys使用率。
观察 java 进程的stack，依然是相同的函数，但是没有任何阻塞
# cat /proc/30964/stack
[<ffffffff810ba4ea>] futex_wait_queue_me+0xba/0xf0
[<ffffffff810bb660>] futex_wait+0x1c0/0x310
[<ffffffff810bcf61>] do_futex+0x121/0xae0
[<ffffffff810bd99b>] sys_futex+0x7b/0x170
[<ffffffff8100b0d2>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffff
# cat /proc/30964/stack
[<ffffffff810ba4ea>] futex_wait_queue_me+0xba/0xf0
[<ffffffff810bb660>] futex_wait+0x1c0/0x310
[<ffffffff810bcf61>] do_futex+0x121/0xae0
[<ffffffff810bd99b>] sys_futex+0x7b/0x170
[<ffffffff8100b0d2>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffff参考
Last updated