JAVA程序导致cpu标高排查
1.使用top命令查看占用排名进程
top - 03:26:12 up 2:11, 8 users, load average: 3.87, 3.83, 3.68
Tasks: 240 total, 3 running, 237 sleeping, 0 stopped, 0 zombie
%Cpu(s): 49.3 us, 24.3 sy, 0.0 ni, 25.7 id, 0.0 wa, 0.0 hi, 0.7 si, 0.0 st
MiB Mem : 3889.8 total, 113.2 free, 540.3 used, 3236.2 buff/cache
MiB Swap: 3891.0 total, 3890.5 free, 0.5 used. 3058.3 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 19222 root 20 0 2520620 168192 14540 S 123.7 4.2 130:06.39 java 10443 root 20 0 17848 11476 8452 S 3.0 0.3 3:17.35 sshd 27665 root 20 0 17844 11520 8460 R 2.3 0.3 1:32.64 sshd 1290 root 20 0 17840 11680 8656 S 1.6 0.3 1:55.42 sshd 119440 root 20 0 17716 11792 8792 S 1.6 0.3 0:51.61 sshd 10592 root 20 0 11320 4344 2956 S 0.7 0.1 0:22.44 top
2.通过top -Hp pid 产看进程内线程的占用情况
Threads: 36 total, 3 running, 33 sleeping, 0 stopped, 0 zombie
%Cpu(s): 56.5 us, 23.6 sy, 0.0 ni, 19.9 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
MiB Mem : 3889.8 total, 149.9 free, 557.5 used, 3182.4 buff/cache
MiB Swap: 3891.0 total, 3890.5 free, 0.5 used. 3040.3 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 19247 root 20 0 2520620 168192 14540 S 42.2 4.2 44:26.65 VM Thread 19243 root 20 0 2520620 168192 14540 S 18.9 4.2 20:41.11 Concurrent Mark 34686 root 20 0 2520620 168192 14540 R 13.3 4.2 13:30.05 t_shiguiwu2 34684 root 20 0 2520620 168192 14540 R 12.3 4.2 13:13.34 t_shiguiwu0 34687 root 20 0 2520620 168192 14540 S 12.3 4.2 13:10.61 t_shiguiwu3 34685 root 20 0 2520620 168192 14540 R 12.0 4.2 13:17.44 t_shiguiwu1 19232 root 20 0 2520620 168192 14540 S 3.3 4.2 3:23.49 Gang worker#0 (
3.将罪魁祸首的线程号转成16进制
root@shiguiwu:/usr/local/wechat# printf '%x \n' 34686
877e
root@shiguiwu:/usr/local/wechat#
4.导出线程的执行路径定位问题
jstack 进程ID |grep tid(16进制的线程id英文小写) -A60 >> aa.txt
结果如下
"t_shiguiwu2" #39 daemon prio=5 os_prio=0 tid=0x00007fcf14084000 nid=0x877e runnable [0x00007fcee3cfe000]java.lang.Thread.State: RUNNABLEat org.apache.logging.log4j.core.util.datetime.FixedDateFormat.formatInstant(FixedDateFormat.java:575)at org.apache.logging.log4j.core.pattern.DatePatternConverter$FixedFormatter.format(DatePatternConverter.java:100)at org.apache.logging.log4j.core.pattern.DatePatternConverter$CachedTime.<init>(DatePatternConverter.java:155)at org.apache.logging.log4j.core.pattern.DatePatternConverter.formatWithoutThreadLocals(DatePatternConverter.java:310)at org.apache.logging.log4j.core.pattern.DatePatternConverter.format(DatePatternConverter.java:290)at org.apache.logging.log4j.core.pattern.DatePatternConverter.format(DatePatternConverter.java:265)at org.apache.logging.log4j.core.pattern.PatternFormatter.format(PatternFormatter.java:38)at org.apache.logging.log4j.core.layout.PatternLayout$PatternSerializer.toSerializable(PatternLayout.java:345)at org.apache.logging.log4j.core.layout.PatternLayout.toText(PatternLayout.java:244)at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:229)at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:59)at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:197)at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:190)at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:181)at org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:312)at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:543)at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:502)at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485)at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:460)at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)at org.apache.logging.log4j.core.Logger.log(Logger.java:161)at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2198)at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2152)at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2135)at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2034)at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1907)at org.apache.logging.slf4j.Log4jLogger.error(Log4jLogger.java:309)at com.wechat.server.mp.controller.TestController.lambda$testCpu$0(TestController.java:60)at com.wechat.server.mp.controller.TestController$$Lambda$689/1190122558.run(Unknown Source)at java.lang.Thread.run(Thread.java:750)
"aaa.txt" 61L, 5501B
线程上下文切换
cpu上下文切换太频繁也会让cpu标高，这个时候我们可以vmstat
root@shiguiwu:/usr/local/wechat# vmstat 1 40
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----r b swpd free buff cache si so bi bo in cs us sy id wa st0 0 0 950232 46248 912592 0 0 64 6 205 385 2 5 92 1 00 0 0 950232 46248 912592 0 0 0 0 350 544 1 5 95 0 00 0 0 950232 46248 912592 0 0 0 0 654 2039 4 10 86 0 00 0 0 950432 46248 912592 0 0 0 0 332 500 1 2 98 0 00 0 0 951240 46248 912592 0 0 0 0 384 584 1 3 97 0 00 0 0 950484 46248 912592 0 0 0 0 640 823 4 10 87 0 00 0 0 950736 46248 912592 0 0 0 8 298 443 1 4 96 0 00 0 0 950736 46248 912592 0 0 0 0 323 1019 1 3 97 0 00 0 0 949984 46248 912592 0 0 0 0 613 986 5 10 85 0 00 0 0 950744 46248 912592 0 0 0 0 294 459 1 2 98 0 00 0 0 950996 46248 912592 0 0 0 0 326 1039 2 5 94 0 00 0 0 950260 46256 912592 0 0 0 20 567 952 4 9 87 0 0