追踪CPU跑满

最近测试一个应用遇到问题:一旦压力略涨,应用的CPU就顶满。由于是多线程应用,直接就把系统的CPU耗完了。
本来想用gdb來调试的,结果gdb不给力,就在attach那里卡死,半天不动。后来想到了用perf来调试,果然找到了一处性能热点。修复热点以后,CPU顶满的问题缓解了一些,不太容易出现了,但是,多跑一会儿,还是会有。而且现在出现CPU顶满时,不仅gdb不返回,连perf record -a -g都无法用Ctrl+c来停止了,仔细top命令看了一下,原来系统的sys是100%,usr几乎为0%,也就是说,是卡在内核里了,难怪perf不好使。
perf这样的神器都用不了了,还能怎么办?最后@coly提醒我:用 echo t > /proc/sysrq-trigger 把内核栈整个打出来。好办法,我试了一下,dmesg里一堆信息:

Apr 25 22:37:57 v3 kernel: sheep         R  running task        0 19157      1 0x10000080
Apr 25 22:37:57 v3 kernel: ffff8802b41c5418 0000000000000086 ffff88028761ecc0 ffffea0008b0f478
Apr 25 22:37:57 v3 kernel: ffffffff814ef33e ffff88046ff9b588 ffffea0008b0f478 ffffea0008b0f478
Apr 25 22:37:57 v3 kernel: ffff8803ec6ab0f8 ffff8802b41c5fd8 000000000000f4e8 ffff8803ec6ab100
Apr 25 22:37:57 v3 kernel: Call Trace:
Apr 25 22:37:57 v3 kernel: [] ? _spin_lock+0x1e/0x30
Apr 25 22:37:57 v3 kernel: [] ? __lru_cache_add+0x40/0x90
Apr 25 22:37:57 v3 kernel: [] __cond_resched+0x2a/0x40
Apr 25 22:37:57 v3 kernel: [] _cond_resched+0x30/0x40
Apr 25 22:37:57 v3 kernel: [] migrate_pages+0x9d/0x4b0
Apr 25 22:37:57 v3 kernel: [] ? compaction_alloc+0x0/0x3e0
Apr 25 22:37:57 v3 kernel: [] compact_zone+0x4f4/0x770
Apr 25 22:37:57 v3 kernel: [] compact_zone_order+0xa1/0xe0
Apr 25 22:37:57 v3 kernel: [] try_to_compact_pages+0x11c/0x190
Apr 25 22:37:57 v3 kernel: [] ? native_sched_clock+0x13/0x60
Apr 25 22:37:57 v3 kernel: [] __alloc_pages_nodemask+0x5f5/0x940
Apr 25 22:37:57 v3 kernel: [] alloc_pages_vma+0x9a/0x150
Apr 25 22:37:57 v3 kernel: [] do_huge_pmd_anonymous_page+0x145/0x370
Apr 25 22:37:57 v3 kernel: [] handle_mm_fault+0x25a/0x2b0
Apr 25 22:37:57 v3 kernel: [] ? mempool_alloc+0x63/0x140
Apr 25 22:37:57 v3 kernel: [] __get_user_pages+0x12a/0x430
Apr 25 22:37:57 v3 kernel: [] ? rwsem_down_read_failed+0x26/0x30
Apr 25 22:37:57 v3 kernel: [] get_user_pages+0x49/0x50
Apr 25 22:37:57 v3 kernel: [] get_user_pages_fast+0x157/0x1c0
......
Apr 25 22:37:57 v3 kernel: sheep         D ffff88047fc24900     0 19158      1 0x10000080
Apr 25 22:37:57 v3 kernel: ffff880357da9890 0000000000000086 0000000000000000 0000000000000003
Apr 25 22:37:57 v3 kernel: ffff8804700e6ea0 ffff880357da9878 ffffffff812518e2 ffff880357da0000
Apr 25 22:37:57 v3 kernel: ffff8803ec6aa6b8 ffff880357da9fd8 000000000000f4e8 ffff8803ec6aa6b8
Apr 25 22:37:57 v3 kernel: Call Trace:
Apr 25 22:37:57 v3 kernel: [] ? __make_request+0x122/0x5a0
Apr 25 22:37:57 v3 kernel: [] rwsem_down_failed_common+0x95/0x1d0
Apr 25 22:37:57 v3 kernel: [] ? mempool_alloc_slab+0x15/0x20
Apr 25 22:37:57 v3 kernel: [] ? mempool_alloc+0x63/0x140
Apr 25 22:37:57 v3 kernel: [] rwsem_down_read_failed+0x26/0x30
Apr 25 22:37:57 v3 kernel: [] call_rwsem_down_read_failed+0x14/0x30
Apr 25 22:37:57 v3 kernel: [] ? down_read+0x24/0x30
Apr 25 22:37:57 v3 kernel: [] get_user_pages_fast+0x124/0x1c0
......

看到了"lock"、“mutex”这些字眼,果然是内核里面卡住了,@coly一看到compact_zone()就明确告诉我,是hugepages的问题,把它关掉试试。用

echo never > /sys/kernel/mm/redhat_transparent_hugepage/enabled
echo never > /sys/kernel/mm/redhat_transparent_hugepage/defrag
echo no > /sys/kernel/mm/redhat_transparent_hugepage/khugepaged/defrag

关掉,应用果然一切正常了。原来以前在hadoop集群上也遇到过类似的问题(所以现在alikernel是默认关掉transparent hugepaes的),不过当时只是CPU略涨,不像现在这个,干脆锁死了。
原来除了gdb,valgrind,perf,还有“echo t > /proc/sysrq-trigger"这样更犀利的办法,@coly告诉我,还有更犀利的,就是连sysrq-trigger都不好使了,可以看
/proc/{pid}/wchan,里面是该进程阻塞位置的内核函数名,在所有办法都没戏的时候可以看它。
学习了。

小记备份遭遇

今天备份机器上的一个目录,用“du -sh .”看这个目录只占用了1.5G空间。但是,我一用tar打包,就半天停不下来,tar包都涨到十几G了还没有打包完。奇怪,哪多出来这么多东西。
查了半天,后来发现目录里有个101G的大文件,而du -sh 对这个大文件的返回结果却是”1.1M“,喔,原来这是个空洞文件,tar却只能老老实实的读数据,所以出来的tar包巨大无比。看来,备份目录前光"du -sh .“是不够的,至少还得类似"find . -size +100M"全部检查一遍大小才行。

debuginfo的rpm包

之前rpmbuild -ba xxx.spec能自动打出binary包和对应的debuginfo包,但是我不想分成两个包,希望binary包里就是带调试符号的,在网上找了一堆,最简单的办法就是在spec文件里(头部)加一句

%global debug_package %{nil}

那些说在~/.rpmmacros里加东西的办法似乎都不好使。

但是,几天后,我在另一台机器上又遇到了相反的问题:rpmbuild -ba xxx.spec默认就不打debuginfo包。估计是机器的环境问题,不过谁知道又是哪个文件闹的环境问题呢?于是又检查了一圈,哦,原来是没有装redhat-rpm-config包,所以没有bsp-compress这个工具,故而打不出debuginfo包来。
机器上的软件环境,是个头疼的事,看来,docker也许真有搞头。

神器valgrind

其实早在2006年我就用过valgrind,但当时valgrind不能观测daemon的内存泄漏问题,所以后来渐渐用得少了。

今天又遇到一个内存泄漏问题,程序颇大,手工调试不太现实了,所以又想到了valgrind,毕竟在这7年间,valgrind又强大了不少。查了一下,它已经可以检测daemon进程了,方法在 这里 对应的官方文档在 这里 其中"monitor leak_check full reachable any"相当于设置gdb的breakpoint。

不过,我要调试的这个程序,一运行就fork了,然后子进程负责主要的逻辑,父进程只是等待子进程返回用的,而且,只在运行某个特殊逻辑时出现内存泄漏,平时的逻辑没有问题。怎么弄?折腾了一下,发现可以搞定:首先,在gdb里运行“set follow-fork-mode child”来自动跟踪子进程,然后,一开始不要急着用”monitor leak_check full reachable any"来检测,先"continue“运行一阵子,当开始跑造成内存泄漏的逻辑时,再ctrl+c打断,再”monitor leak_check full reachable any“设上断点,自然会吐出valgrind的memleak信息。

用这两招,果然找到内存泄漏的点了,隐藏颇深,如果不是用工具,真不知何年何月才能发现。感谢valgrind神器,支持vgdb支持daemon检测,真是杀手级的新特性。(我用的是最新的valgrind-3.9.0,老的valgrind估计不支持)

另外说明一下,我是gdb的小白,以上招数和解释不见得正确或最优,如有行家肯指点,感激不尽。

小问题汇总

最近遇到一些开发部署等方面的几个小问题,留个笔记。

第一个 编程问题

#include 
#include 
#include 

int main(int argc, char *argv[])
{
	int ret;

	pthread_mutex_t mt;
	ret = pthread_mutex_init(&mt, NULL);
	if (ret != 0) {
		printf("failed to init (ret: %d)\n", ret);
		goto fail;
	}
	ret = pthread_mutex_unlock(&mt);
	if (ret != 0) {
		printf("failed to unlock (ret: %d)\n", ret);
		goto fail;
	}
	ret = pthread_mutex_destroy(&mt);
	if (ret != 0) {
		printf("failed to destroy (ret: %d)\n", ret);
		goto fail;
	}

	printf("complete\n");
	return 0;
fail:
	printf("fail\n");
	return -1;
}
#编译
gcc test.c -o test -lpthread
#运行
./test
#结果
failed to destroy (ret: 16)
fail

pthread_mutex_destroy返回了EBUSY(16)错误,看来pthread的限制还挺严格的,只做了unlock的mutex不能正常destroy, 为什么?最后找到了 这个链接 看这意思,maintainer死活不肯改,觉得这个行为是正确的。既然maintainer不肯,那我也只好在程序里用pthread_cond代替了mutex,免得pthread_mutex_destroy老报错。

第二个 编程问题

#include 
#include 

int main(int argc, char **argv[])
{
	char test[ARG_MAX];
	memset(test, 0, ARG_MAX);
}

这段代码编译正常。但是如果我们在第一行再加一个"#include ",在debian下还能正常编译,但在centos6上编译就报错:

/root/a.c: In function ‘main’:
/root/a.c:7: error: ‘ARG_MAX’ undeclared (first use in this function)
/root/a.c:7: error: (Each undeclared identifier is reported only once
/root/a.c:7: error: for each function it appears in.)

原因是/usr/include/bits/local_lim.h里有一堆宏定义,最后把ARG_MAX又给undef了,颇为诡异。难道在centos6上就不应该limits.h和linux/limits.h一起用?实际代码如果多了,难免两个头文件都要include的。这里 给了一个标准的解决办法,就是用sysconf(_SC_ARG_MAX)代替ARG_MAX。

第三个 ssh通道打通

ssh通道打通是常见操作,但是我在机器上发现虽然按照步骤打通了,但是本机ssh还是需要密码,最后coly帮忙找到了原因:selinux。还要在/etc/selinux/config中将selinux设置成disabled,然后 setenforce 0,ssh通道才真“通”了。
感谢coly的发现,我不用继续输密码了。

1 2 3 4