Winse Blog

走走停停, 熙熙攘攘, 忙忙碌碌, 不知何畏.

追生产的一次优化

注:最后就是升级到JDK8(哭笑)…

最近闲得慌啊,本来不是自己职能范围内的。但是看着一台机器每天负载50+的跑,不舒服,就想去折腾折腾把负载降下来。

进程图:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
top - 08:01:24 up 1203 days,  9:06,  4 users,  load average: 31.41, 32.97, 32.38
Tasks: 569 total,  11 running, 558 sleeping,   0 stopped,   0 zombie
Cpu(s): 20.1%us, 68.1%sy,  0.0%ni,  6.0%id,  0.1%wa,  0.0%hi,  5.7%si,  0.0%st
Mem:  49420852k total, 31831356k used, 17589496k free,   358748k buffers
Swap: 33791992k total,   519332k used, 33272660k free, 18614472k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                   
 2340 omc       20   0 29.2g 8.5g  11m S 598.1 18.1   3436:40 java                     
31349 omc       20   0 8071m 563m  11m S 348.4  1.2   1735:33 java                     
28147 omc       20   0 15.5g 1.5g  14m S 341.9  3.2   1959:42 java                     
   61 root      20   0     0    0    0 S 48.9  0.0  83728:05 ksoftirqd/14              
   73 root      20   0     0    0    0 S 48.2  0.0  82342:12 ksoftirqd/17              
    9 root      20   0     0    0    0 S 46.9  0.0  85312:03 ksoftirqd/1               
   13 root      20   0     0    0    0 S 46.6  0.0  84297:57 ksoftirqd/2               
   25 root      20   0     0    0    0 S 45.3  0.0  82811:49 ksoftirqd/5               
   89 root      20   0     0    0    0 S 45.3  0.0  84608:31 ksoftirqd/21              
   65 root      20   0     0    0    0 S 44.9  0.0  83475:48 ksoftirqd/15              
   17 root      20   0     0    0    0 R 44.6  0.0  83990:21 ksoftirqd/3               
   57 root      20   0     0    0    0 S 44.6  0.0  84625:38 ksoftirqd/13              
   33 root      20   0     0    0    0 R 44.0  0.0  80537:34 ksoftirqd/7               
    4 root      20   0     0    0    0 R 43.3  0.0  81489:54 ksoftirqd/0               
   41 root      20   0     0    0    0 R 42.0  0.0  82651:17 ksoftirqd/9               
   37 root      20   0     0    0    0 S 40.0  0.0  82636:26 ksoftirqd/8               
   85 root      20   0     0    0    0 S 39.7  0.0  84557:49 ksoftirqd/20              
   21 root      20   0     0    0    0 S 38.7  0.0  83271:24 ksoftirqd/4               
   53 root      20   0     0    0    0 R 36.1  0.0  82083:15 ksoftirqd/12              
   45 root      20   0     0    0    0 R 35.8  0.0  86230:39 ksoftirqd/10              
   93 root      20   0     0    0    0 R 35.4  0.0  86416:12 ksoftirqd/22              
   69 root      20   0     0    0    0 R 35.1  0.0  82726:46 ksoftirqd/16              
   29 root      20   0     0    0    0 S 34.8  0.0  78415:22 ksoftirqd/6               
   77 root      20   0     0    0    0 R 33.1  0.0  82419:34 ksoftirqd/18              
   81 root      20   0     0    0    0 S 30.2  0.0  80141:58 ksoftirqd/19              
   97 root      20   0     0    0    0 R 21.3  0.0  85993:03 ksoftirqd/23              
   49 root      20   0     0    0    0 S 21.0  0.0  86742:13 ksoftirqd/11              
28418 nobody    20   0  855m  32m 1144 S 20.7  0.1  72:23.66 gmetad

线程图:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
top - 08:03:20 up 1203 days,  9:08,  4 users,  load average: 31.07, 32.36, 32.23
Tasks: 940 total,  31 running, 909 sleeping,   0 stopped,   0 zombie
Cpu(s): 20.0%us, 70.0%sy,  0.0%ni,  4.6%id,  0.0%wa,  0.0%hi,  5.4%si,  0.0%st
Mem:  49420852k total, 31845576k used, 17575276k free,   358776k buffers
Swap: 33791992k total,   519332k used, 33272660k free, 18615376k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND             
28174 omc       20   0 15.5g 1.5g  14m R 59.9  3.2 307:28.86 java                
28203 omc       20   0 15.5g 1.5g  14m S 55.7  3.2 272:43.21 java                
 2416 omc       20   0 29.2g 8.5g  11m R 55.4 18.1 274:31.07 java                
31384 omc       20   0 8071m 563m  11m R 53.7  1.2 240:45.47 java                
 2409 omc       20   0 29.2g 8.5g  11m S 53.1 18.1 245:56.03 java                
28197 omc       20   0 15.5g 1.5g  14m S 52.4  3.2 279:04.35 java                
 2406 omc       20   0 29.2g 8.5g  11m R 51.8 18.1 249:00.25 java                
28208 omc       20   0 15.5g 1.5g  14m R 51.8  3.2 300:50.49 java                
 2412 omc       20   0 29.2g 8.5g  11m S 51.5 18.1 232:11.81 java                
 2415 omc       20   0 29.2g 8.5g  11m R 51.5 18.1 234:57.25 java                
 2391 omc       20   0 29.2g 8.5g  11m R 51.1 18.1 301:52.48 java                
28175 omc       20   0 15.5g 1.5g  14m R 51.1  3.2 299:18.11 java                
31383 omc       20   0 8071m 563m  11m R 50.8  1.2 242:23.43 java                
16662 omc       20   0 29.2g 8.5g  11m R 49.5 18.1   3:26.22 java                
31381 omc       20   0 8071m 563m  11m R 49.5  1.2 237:05.25 java                
   41 root      20   0     0    0    0 S 48.9  0.0  82652:00 ksoftirqd/9         
   17 root      20   0     0    0    0 S 47.9  0.0  83990:59 ksoftirqd/3         
   65 root      20   0     0    0    0 S 47.9  0.0  83476:26 ksoftirqd/15        
 2408 omc       20   0 29.2g 8.5g  11m R 47.9 18.1 249:43.27 java                
31382 omc       20   0 8071m 563m  11m R 47.9  1.2 237:07.76 java                
   49 root      20   0     0    0    0 S 47.3  0.0  86743:04 ksoftirqd/11        
   89 root      20   0     0    0    0 R 46.6  0.0  84609:14 ksoftirqd/21        
   81 root      20   0     0    0    0 S 46.3  0.0  80142:39 ksoftirqd/19        
   61 root      20   0     0    0    0 R 46.0  0.0  83728:50 ksoftirqd/14        
31376 omc       20   0 8071m 563m  11m R 45.3  1.2 306:00.66 java                
   33 root      20   0     0    0    0 R 45.0  0.0  80538:15 ksoftirqd/7         
31385 omc       20   0 8071m 563m  11m R 45.0  1.2 272:52.36 java                
   13 root      20   0     0    0    0 S 44.7  0.0  84298:42 ksoftirqd/2         
   73 root      20   0     0    0    0 S 43.7  0.0  82342:53 ksoftirqd/17        
   53 root      20   0     0    0    0 R 43.4  0.0  82083:54 ksoftirqd/12        
   97 root      20   0     0    0    0 S 43.4  0.0  85993:53 ksoftirqd/23        
   45 root      20   0     0    0    0 R 42.4  0.0  86231:24 ksoftirqd/10        
   77 root      20   0     0    0    0 S 42.1  0.0  82420:20 ksoftirqd/18        
 2407 omc       20   0 29.2g 8.5g  11m R 41.1 18.1 240:01.88 java                
 2410 omc       20   0 29.2g 8.5g  11m R 40.8 18.1 227:49.76 java                
   85 root      20   0     0    0    0 R 40.5  0.0  84558:37 ksoftirqd/20        
28196 omc       20   0 15.5g 1.5g  14m R 38.2  3.2 276:56.00 java                
   29 root      20   0     0    0    0 S 37.9  0.0  78416:08 ksoftirqd/6         
   37 root      20   0     0    0    0 S 37.9  0.0  82637:15 ksoftirqd/8         
 2411 omc       20   0 29.2g 8.5g  11m R 37.9 18.1 247:22.02 java                
 2360 omc       20   0 29.2g 8.5g  11m S 37.6 18.1 179:49.10 java                
 2413 omc       20   0 29.2g 8.5g  11m S 36.9 18.1 233:48.03 java                
   69 root      20   0     0    0    0 R 36.3  0.0  82727:24 ksoftirqd/16        
    4 root      20   0     0    0    0 R 35.6  0.0  81490:34 ksoftirqd/0         
31369 omc       20   0 8071m 563m  11m R 35.6  1.2 192:32.42 java                
   21 root      20   0     0    0    0 S 35.0  0.0  83272:02 ksoftirqd/4         
28167 omc       20   0 15.5g 1.5g  14m R 33.7  3.2 197:02.78 java                
   25 root      20   0     0    0    0 S 27.2  0.0  82812:29 ksoftirqd/5         
   93 root      20   0     0    0    0 R 25.9  0.0  86416:55 ksoftirqd/22

按照网络上的文档,查cpu时间很长的、占用很高的线程,然后拿着ID转成16进程到jstack里面去对:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
[omc@cu-omc1 ~]$ jstack 28147
2017-06-01 08:07:13
Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.7-b01 mixed mode):
...
"Timer-0" daemon prio=10 tid=0x00007fbd84850000 nid=0x6e27 in Object.wait() [0x00007fbe31f98000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.util.TimerThread.mainLoop(Timer.java:552)
        - locked <0x0000000767760360> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:505)

"schedulerFactory_QuartzSchedulerThread" prio=10 tid=0x00007fbd843f6000 nid=0x6e26 in Object.wait() [0x00007fbe32099000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:311)
        - locked <0x0000000767770098> (a java.lang.Object)

"schedulerFactory_Worker-2" prio=10 tid=0x00007fbd848cd000 nid=0x6e25 in Object.wait() [0x00007fbe3219a000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)
        - locked <0x00000007677ebb38> (a java.lang.Object)

"schedulerFactory_Worker-1" prio=10 tid=0x00007fbd848b3000 nid=0x6e24 in Object.wait() [0x00007fbe3229b000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568)
        - locked <0x00000007677ec710> (a java.lang.Object)
...
"GC task thread#17 (ParallelGC)" prio=10 tid=0x00007fbe64035000 nid=0x6e06 runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007fbe6411f800 nid=0x6e0e waiting on condition 

JNI global references: 321

[omc@cu-omc1 ~]$ echo "obase=16;28203" | bc
6E2B
[omc@cu-omc1 ~]$ cat | while read id ; do echo "obase=16;$id" | bc ; done <<EOF
28174
28203
28197
28208
28175
28196
28167
EOF

6E0E
6E2B
6E25
6E30
6E0F
6E24
6E07

基本都是sleep,wait的线程占用cpu很大。并且导致了系统cpu软中断处理进程ksoftirqd占用了大部分系统资源。系统不停的在处理上下文,负载奇高:

ksoftirqd 不知道干嘛的,/proc/interrupts 看不懂,查了sleep和wait的区别,strace、iostat、jmap、jstack、jstat、vmstat、pidstat、还有看到内存补齐的一些文章,反正就是找不到北。

一开始以为是quartz的问题,对比了其他机器的quartz应用,有怀疑过版本问题(quartz-1.8.6, 2.2.0);有试着去减少simplethreadpool的默认线程数(org.quartz.threadPool.threadCount),CPU占用是会少一点点,但是ksoftirqd还是压力很大,系统还是很大部分消耗在上下文切换,路子不对。

问题环境:

  • Red Hat Enterprise Linux Server release 6.3 (Santiago)/2.6.32-279.el6.x86_64
  • Spring + quartz-2.2.½
  • jdk1.7.0_17

完全没辙,不是功能代码的问题啊。搞到12点,困死了,回去睡个觉。今天一早起来,想想,不如换个 JDK8 试试吧(按照部署要求jdk放local目录下,要ROOT密码的昨晚就没动)。我勒个去,重启了感觉世界都变亮了。上下文切换cs 1w不到,us、sy基本忽略不计啊。

1
2
3
4
5
6
7
8
9
10
11
$ vmstat -a 1
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free  inact active   si   so    bi    bo   in   cs us sy id wa st
 0  0 517160 25052176 12486824 10402340    0    0     2    31    0    0  4  9 86  0  0
 0  0 517160 25052732 12486972 10401996    0    0     0  4676 4548 4806  0  0 99  0  0
 1  0 517160 25052468 12486972 10402356    0    0     0     0 4044 4419  0  0 99  0  0
 0  1 517160 25053664 12486852 10401992    0    0     0  8100 7608 5311  0  0 95  4  0
 0  1 517160 25054800 12486852 10402084    0    0     0  8228 7847 5408  1  1 95  4  0
 0  1 517160 25054924 12486852 10402380    0    0     0  8200 8075 4929  0  0 95  4  0
 1  1 517160 25054868 12486852 10402112    0    0     0  7484 7898 5754  1  1 94  4  0
 2  1 517160 25055544 12486848 10402148    0    0     0  8224 7537 4428  0  0 95  4  0

好吧,以后优化的第一步就是换JDK .__. 。就像优化数据库第一步就建索引 V.V 。应该是JDK8对object.wait调用linux系统调用进行了优化。

有点意思

us过高 当us值过高时,表示运行的应用消耗了大部分的cpu。在这种情况下,对于java应用而言,最重要的是找到具体消耗cpu的线程所执行的代码,可以采用如下方法。

首先通过linux命令top命令查看us过高的pid值

通过top -Hp pid查看该pid进程下的线程的cpu消耗状况,得到具体pid值

将pid值转化为16进制,这个转化后的值对应nid值的线程

通过jstack pid grep -C 20 “16进制的值” 命令查看运行程序的线程信息

该线程就是消耗cpu的线程,在采样时须多执行几次上述的过程,以确保找到真实的消耗cpu的线程。

java应用造成us过高的原因主要是线程一直处于可运行的状态Runnable,通常是这些线程在执行无阻塞、循环、正则或纯粹的计算等动作造成。 另外一个可能会造成us过高的原因是频繁的gc。如每次请求都需要分配较多内存,当访问量高时就导致不断的进行gc,系统响应速度下降, 进而造成堆积的请求更多,消耗的内存严重不足,最严重的时候会导致系统不断进行FullGC,对于频繁的gc需要通过分析jvm内存的消耗来查找原因。

sy过高 当sy值过高时,表示linux花费了更多的时间在进行线程切换。java应用造成这种现象的主要原因是启动的线程比较多, 且这些线程多处于不断的阻塞(例如锁等待,io等待)和执行状态的变化过程中,这就导致了操作系统要不断的切换执行的线程, 产生大量的上下文切换。在这种情况下,对java应用而言,最重要的是找出不断切换状态的原因, 可采用的方法为通过kill -3 pid 或jstack -l pid的方法dump出java应用程序的线程信息,查看线程的状态信息以及锁信息, 找出等待状态或锁竞争过多的线程。

strace -T -r -c -p pid pstack pid trace -p tid

–END

Comments