注：最后就是升级到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