何が起こったか
Cloudwatchを見ているとインスタンス起動時にCPU負荷が高いので調べて欲しいといわれた
調べればやり方はいくらでもでてきますが、自分の備忘録用に。
環境
Red Hat Enterprise Linux Server release 7.5
(AWS EC2上)
本当にCPUが高負荷なのか
本当にCPUが高負荷になっているのか？CloudWatchのバグじゃないのか？
ということでsarコマンドで確認します。
もしsarコマンドが入っていない環境であればインストールします。
$ sudo yum install sysstat
ちなみに今回本番環境で発生したのですが、本番環境ではめったなことでは直接ログインできない為、本番のログをとってきてsaファイルを見ることもできます。
$sar -f <ファイルのパス>
09時10分02秒 CPU %user %nice %system %iowait %steal %idle
09時20分01秒 all 3.97 0.00 0.35 0.00 0.01 95.67
09時30分01秒 all 4.01 0.00 0.36 0.00 0.01 95.62
09時40分02秒 all 3.87 0.00 0.42 0.00 0.01 95.69
09時50分01秒 all 4.05 0.00 0.35 0.00 0.01 95.59
10時00分01秒 all 4.04 0.00 0.37 0.00 0.01 95.58
10時10分01秒 all 3.95 0.00 0.35 0.00 0.01 95.69
10時20分02秒 all 3.98 0.00 0.36 0.00 0.01 95.65
10時30分01秒 all 4.04 0.00 0.36 0.00 0.01 95.59
10時40分01秒 all 3.81 0.00 0.41 0.00 0.01 95.76
10時50分02秒 all 3.96 0.00 0.36 0.00 0.01 95.67
11時00分01秒 all 4.14 0.00 0.35 0.00 0.01 95.49
11時10分01秒 all 3.94 0.00 0.35 0.00 0.01 95.71
こんな感じで結果が見れます。
見てみると特に高負荷になっている様子が見えません。
cloudwatchを見ているとステージング環境でも同様の事象がみられるので、ステージング環境で再現させます。
また、10分単位というのは間隔が広すぎるので、1分単位にしてみます。
$ vi /etc/cron.d/sysstat
以下の*/10を*/1にします
# Run system activity accounting tool every 10 minutes
*/10 * * * * root /usr/lib64/sa/sa1 1 1
# 0 * * * * root /usr/lib64/sa/sa1 600 6 &
# Generate a daily summary of process accounting at 23:53
53 23 * * * root /usr/lib64/sa/sa2 -A
OSを再起動し、確認
19時53分01秒 CPU %user %nice %system %iowait %steal %idle
19時54分01秒 all 68.91 0.00 3.04 0.05 0.01 28.00
19時55分01秒 all 2.93 0.01 0.41 0.01 0.02 96.63
19時56分01秒 all 8.20 0.00 0.86 0.02 0.01 90.91
19時57分01秒 all 4.65 0.00 0.34 0.01 0.01 94.99
19時58分01秒 all 0.26 0.00 0.07 0.00 0.01 99.67
19時59分01秒 all 4.97 0.01 0.36 0.00 0.02 94.65
20時00分01秒 all 4.93 0.00 0.39 0.00 0.01 94.67
20時01分01秒 all 3.11 0.00 0.54 0.00 0.01 96.34
20時02分01秒 all 4.97 0.00 0.38 0.00 0.01 94.64
20時03分01秒 all 4.87 0.00 0.34 0.00 0.01 94.78
はい。CPUが高負荷になっていますね。
高負荷になっているスレッドの特定
まずはCPUが高負荷のプロセスの特定
$ ps -aux
%CPUの列を見るとCPUの消費率がわかります。
今回tomcatが140とかになっていました。
(topコマンドで確認する方法もありますが、今回見づらかったのでpsコマンドを使いました)
続いてどのスレッドが負荷かかっているのかを確認します。
$ ps -L aux
このコマンドを打つと以下のように出力されます（CPU負荷が落ち着いたときのを取りました）
USER PID LWP %CPU NLWP %MEM VSZ RSS TTY STAT START TIME COMMAND
test 1007 1016 0.4 56 16.8 6749028 1299196 ? Sl 16:52 0:01 /usr/bin/java -Djava.util.logging.config.file=/opt/test/tomcat/conf/logging.properties -Djava
test 1007 1029 2.2 56 16.8 6749028 1299196 ? Sl 16:52 0:05 /usr/bin/java -Djava.util.logging.config.file=/opt/test/tomcat/conf/logging.properties -Djava
test 1007 1032 1.6 56 16.8 6749028 1299196 ? Sl 16:52 0:04 /usr/bin/java -Djava.util.logging.config.file=/opt/test/tomcat/conf/logging.properties -Djava
test 1007 1053 1.9 56 16.8 6749028 1299196 ? Sl 16:52 0:04 /usr/bin/java -Djava.util.logging.config.file=/opt/test/tomcat/conf/logging.properties -Djava
test 1007 1057 0.0 56 16.8 6749028 1299196 ? Sl 16:52 0:00 /usr/bin/java -Djava.util.logging.config.file=/opt/test/tomcat/conf/logging.properties -Djava
ここで高負荷になっているPIDとLWPをメモします。
スレッドダンプの確認
わかっておりましたが、高負荷なプロセスはｼﾞｬﾊﾞ！です。
ということでスレッドダンプを確認していきます
sudo -u test jstack -l <高負荷だったPID> > /tmp/jstack
このようにしてスレッドダンプを取得します。
数分に一回とると変化がわかってよいそうです。
※実行するユーザーは実際にプロセスを起動しているユーザーと同一でないとエラーが出ます
/tmp/jstackのなかを見ると以下のように出力されています
"localhost-startStop-1" #17 daemon prio=5 os_prio=0 tid=0x00007f6fe0001db0 nid=0x5ee runnable [0x00007f700c062000]
java.lang.Thread.State: RUNNABLE
at org.springframework.asm.Type.getReturnType(Type.java:386)
at org.springframework.core.type.classreading.AnnotationMetadataReadingVisitor.visitMethod(AnnotationMetadataReadingVisitor.java:81)
at org.springframework.asm.ClassReader.readMethod(ClassReader.java:1061)
at org.springframework.asm.ClassReader.accept(ClassReader.java:729)
at org.springframework.asm.ClassReader.accept(ClassReader.java:527)
at org.springframework.core.type.classreading.SimpleMetadataReader.<init>(SimpleMetadataReader.java:64)
at org.springframework.core.type.classreading.SimpleMetadataReaderFactory.getMetadataReader(SimpleMetadataReaderFactory.java:102)
at org.springframework.core.type.classreading.CachingMetadataReaderFactory.getMetadataReader(CachingMetadataReaderFactory.java:102)
- locked <0x00000006f3a459d8> (a org.springframework.core.type.classreading.CachingMetadataReaderFactory$1)
at org.springframework.context.annotation.ClassPathScanningCandidateComponentProvider.findCandidateComponents(ClassPathScanningCandidateComponentProvider.java:287)
at org.springframework.context.annotation.ClassPathBeanDefinitionScanner.doScan(ClassPathBeanDefinitionScanner.java:272)
at org.springframework.context.annotation.ComponentScanAnnotationParser.parse(ComponentScanAnnotationParser.java:135)
at org.springframework.context.annotation.ConfigurationClassParser.doProcessConfigurationClass(ConfigurationClassParser.java:289)
at org.springframework.context.annotation.ConfigurationClassParser.processConfigurationClass(ConfigurationClassParser.java:247)
at org.springframework.context.annotation.ConfigurationClassParser.parse(ConfigurationClassParser.java:200)
at org.springframework.context.annotation.ConfigurationClassParser.parse(ConfigurationClassParser.java:169)
at org.springframework.context.annotation.ConfigurationClassPostProcessor.processConfigBeanDefinitions(ConfigurationClassPostProcessor.java:308)
at org.springframework.context.annotation.ConfigurationClassPostProcessor.postProcessBeanDefinitionRegistry(ConfigurationClassPostProcessor.java:228)
at org.springframework.context.support.PostProcessorRegistrationDelegate.invokeBeanDefinitionRegistryPostProcessors(PostProcessorRegistrationDelegate.java:272)
at org.springframework.context.support.PostProcessorRegistrationDelegate.invokeBeanFactoryPostProcessors(PostProcessorRegistrationDelegate.java:92)
at org.springframework.context.support.AbstractApplicationContext.invokeBeanFactoryPostProcessors(AbstractApplicationContext.java:687)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:525)
- locked <0x0000000708be6ac8> (a java.lang.Object)
（以下略）
このnid=0x5eeと書かれているところの0xのあとの数字が先ほどps -L auxでみたLIDを16進数になおした値です。
沢山書かれているスレッドダンプの中からLIDと一致するものを探します。
スレッドダンプの見方は以下のサイトを参考にします
https://yohei-a.hatenablog.jp/entry/20150101/1420112104
結論
スレッドダンプの中を見ても特に変なスレッドは見当たりませんでした。
そもそもtomcat起動するときにある程度CPU消費するよね、ということと、今回の環境ではtomcatを2台起動しているのでCPUの負荷が落ち着くには時間がかかるよね･･･という感じです。
異常なくてよかったですが、これを機にスレッドダンプの見方もわかったのでとても勉強になりました