何が起こったか

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の負荷が落ち着くには時間がかかるよね･･･という感じです。
異常なくてよかったですが、これを機にスレッドダンプの見方もわかったのでとても勉強になりました