charleschchen
作者charleschchen2022-10-28 19:23
系统架构师, 浪潮商用机器有限公司

案例分析:AIX环境根目录读过高引起的性能问题

字数 9900阅读 1458评论 0赞 1

问题现象

客户反馈在AIX环境性能测试中,给应用进一步加压时,/根目录读访问异常飙升,达到600MBps,同时应用TPS也出现了明显下降。

工具介绍

IO热点可以使用filemon工具来分析定位,filemon是一个基于trace实现的IO活动监控工具,使用也相对简单,例如如下示例,设置100MB的trace buffer对系统IO活动进行5秒的跟踪:

#filemon -o /tmp/filemon.out -T 100000000 -u -O all,detailed 
#sleep 5
#trcstop

完成跟踪后生成的报告保存在/tmp/filemon.out文本文件中,可以直接阅读。需要注意文件内容,如果有“XXXXX events were lost. Reported data may have inconsistencies or errors.”类似的字样,则说明监控设置的trace buffer不足,监控时间过长,生成报告可能不准确。需要调整-T参数增加buffer大小,或者缩短监控时间。
filemon也能直接由trace文件生成;通常我们可以结合perfpmr的trace数据来生成filemon.

问题分析

filemon报告里含有最活跃文件、段、逻辑卷、物理卷等等信息:
Most Active Files
Most Active Segments
Most Active Logical Volumes
Most Active Physical Volumes
Most Active Files Process-Wise
Most Active Files Thread-Wise
因为本例中是根目录读异常,因此可以直接查看Most Active Files:

Most Active Files  
------------------------------------------------------------------------  
#MBs #opns #rds #wrs file volume:inode  
------------------------------------------------------------------------  
90.0 272 23039 0 services  
2.4 373 608 0 hosts  
...

可以得知根目录读异常高来源于/etc/services文件访问。

/etc/services文件存放的是网络端口与服务名的对应关系,因此可以确定根目录读访问异常高来源于应用程序对网络服务映射的查询。

进一步跟踪分析涉及/etc/services访问的应用进程可知,应用程序对/etc/services的每一次访问都遵循同样的模式,如下:


15B testproc 57 56295876 112263537 kopen 0.005394 open /etc/services fd=12 RDONLY  
163 testproc 57 56295876 112263537 kread 0.005400 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005430 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005456 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005482 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005511 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005538 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005571 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005598 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005630 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005664 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005698 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005746 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005798 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005850 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005895 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005926 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005960 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.005994 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006027 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006055 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006081 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006125 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006171 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006220 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006254 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006285 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006317 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006351 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006384 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006421 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006481 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006535 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006588 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006638 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006685 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006736 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006786 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006838 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006891 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006945 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.006998 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007035 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007068 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007102 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007150 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007203 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007256 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007302 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007354 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007389 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007418 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007445 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007475 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007520 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007583 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007641 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007693 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007740 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007787 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007832 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007876 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007922 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007956 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.007993 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008026 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008056 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008087 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008117 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008145 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008175 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008206 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008233 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008261 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008287 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008315 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008344 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008373 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008402 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008430 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008465 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008493 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008521 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008549 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008578 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008603 read(12,0000000020104E80,1000) /etc/services  
163 testproc 57 56295876 112263537 kread 0.008612 read(12,0000000020104E80,1000) /etc/services  
12E testproc 57 56295876 112263537 close 0.008615 close /etc/services fd=12  

即每次查询都读取了整个/etc/services文件,一共86页。这导致了大量的CPU消耗。

解决方法

经过确认,应用自己实现了查询/etc/services文件获取缓存服务端口号功能。由于新增的缓存服务映射放在/etc/services文件的最后,因此导致每次查询都需要遍历整个文件。
因此,最简单的修改方法是将该缓存服务映射放置在/etc/services文件的开头。经过该调整,根目录读访问从600MBps降低到10MBps以下。

如果觉得我的文章对您有用,请点赞。您的支持将鼓励我继续创作!

1

添加新评论0 条评论

Ctrl+Enter 发表

作者其他文章

相关文章

相关问题

相关资料

X社区推广