java程序员简单堆栈调试
新年到了,重新注册了一个账号,满打满算去年刚毕业,工作时间很短,工作中和继续学习中越来越觉得知识的匮乏,所以准备每周发一篇自己整理的知识点的贴子。
回到正题上,工作中一些生产环境总会触碰到稀奇古怪的问题让人头大,有时候调试半天也发现不了问题,然后人就傻了,或者说,有可能也会出现本地一点点问题都没有,然后上线后过几天就出现问题了,什么内存泄露过载,死锁都有可能不能及时发现,所以服务器的堆栈调试是必要学的一课。
操作流程
top命令
我用的是linux系统的服务器,首先可以使用top命令查看下进程信息,里面有
top - 10:37:36 up 109 days, 14:20, 5 users, load average: 0.11, 0.05, 0.01
Tasks: 785 total, 1 running, 783 sleeping, 1 stopped, 0 zombie
Cpu(s): 0.1%us, 0.1%sy, 0.0%ni, 99.8%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 132166720k total, 128446776k used, 3719944k free, 393164k buffers
Swap: 0k total, 0k used, 0k free, 62456412k cached
这样的信息,主要对应的是
第一行(top):
“00:11:04”为系统当前时刻;
“3:35”为系统启动后到现在的运作时间;
“2 users”为当前登录到系统的用户,更确切的说是登录到用户的终端数 -- 同一个用户同一时间对系统多个终端的连接将被视为多个用户连接到系统,这里的用户数也将表现为终端的数目;
“load average”为当前系统负载的平均值,后面的三个值分别为1分钟前、5分钟前、15分钟前进程的平均数,一般的可以认为这个数值超过 CPU 数目时,CPU 将比较吃力的负载当前系统所包含的进程;
第二行(Tasks):
“59 total”为当前系统进程总数;
“1 running”为当前运行中的进程数;
“58 sleeping”为当前处于等待状态中的进程数;
“0 stoped”为被停止的系统进程数;
“0 zombie”为被复原的进程数;
第三行(Cpus):
分别表示了 CPU 当前的使用率;
第四行(Mem):
分别表示了内存总量、当前使用量、空闲内存量、以及缓冲使用中的内存量;
第五行(Swap):
表示类别同第四行(Mem),但此处反映着交换分区(Swap)的使用情况。通常,交换分区(Swap)被频繁使用的情况,将被视作物理内存不足而造成的。
之后下面的就是进程信息,程序进程都会在这里面展示
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3025 root 20 0 2577164 246936 0 S 14.3 13.1 15900:24 java
12102 root 10 -10 142860 21320 4572 S 1.7 1.1 1010:11 AliYunDun
566 root 20 0 678932 21380 4736 S 0.7 1.1 1061:40 exe
6282 root 20 0 737648 13784 2384 S 0.3 0.7 756:25.31 BT-Task
11007 root 20 0 3053812 111824 0 S 0.3 5.9 378:59.75 java
15083 root 20 0 2670328 641752 0 S 0.3 34.1 2098:01 java
16687 redis 20 0 165120 2668 1084 S 0.3 0.1 820:16.93 redis-server
1 root 20 0 51904 2868 1340 S 0.0 0.2 85:27.68 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.15 kthreadd
4 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
6 root 20 0 0 0 0 S 0.0 0.0 30:40.01 ksoftirqd/0
7 root rt 0 0 0 0 S 0.0 0.0 0:00.00 migration/0
8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh
9 root 20 0 0 0 0 S 0.0 0.0 238:16.74 rcu_sched
10 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 lru-add-drain
11 root rt 0 0 0 0 S 0.0 0.0 2:30.12 watchdog/0
13 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kdevtmpfs
14 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 netns
15 root 20 0 0 0 0 S 0.0 0.0 0:32.37 khungtaskd
16 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 writeback
17 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kintegrityd
18 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 bioset
19 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 bioset
20 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 bioset
21 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kblockd
22 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 md
23 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 edac-poller
24 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 watchdogd
30 root 20 0 0 0 0 S 0.0 0.0 14:37.26 kswapd0
31 root 25 5 0 0 0 S 0.0 0.0 0:00.00 ksmd
32 root 39 19 0 0 0 S 0.0 0.0 0:53.50 khugepaged
33 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 crypto
41 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kthrotld
43 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kmpath_rdacd
44 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kaluad
根据前面的pid进程号和后面的command命令精准查看服务进程信息,比如java服务,后面的就是command就是java,不过启动多个Java服务就会分不清,通过TIME+信息可以看到进程使用cpu的时间,同一台机器可以通过这个启动前后顺序区分服务,但是并不精准。
top -Hp -pid命令
使用top -Hp -pid 查看进程下子线程信息
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
15085 root 20 0 2670328 641752 0 S 0.3 34.1 98:29.14 java
15083 root 20 0 2670328 641752 0 S 0.0 34.1 0:00.00 java
15084 root 20 0 2670328 641752 0 S 0.0 34.1 0:09.24 java
15086 root 20 0 2670328 641752 0 S 0.0 34.1 0:00.96 java
15087 root 20 0 2670328 641752 0 S 0.0 34.1 0:00.85 java
15088 root 20 0 2670328 641752 0 S 0.0 34.1 0:00.00 java
15089 root 20 0 2670328 641752 0 S 0.0 34.1 3:37.16 java
15090 root 20 0 2670328 641752 0 S 0.0 34.1 2:35.52 java
15091 root 20 0 2670328 641752 0 S 0.0 34.1 0:03.36 java
15092 root 20 0 2670328 641752 0 S 0.0 34.1 339:54.12 java
15098 root 20 0 2670328 641752 0 S 0.0 34.1 0:31.34 java
15100 root 20 0 2670328 641752 0 S 0.0 34.1 0:49.31 java
15101 root 20 0 2670328 641752 0 S 0.0 34.1 0:52.71 java
15102 root 20 0 2670328 641752 0 S 0.0 34.1 26:26.71 java
15103 root 20 0 2670328 641752 0 S 0.0 34.1 0:49.39 java
15104 root 20 0 2670328 641752 0 S 0.0 34.1 0:00.07 java
15105 root 20 0 2670328 641752 0 S 0.0 34.1 0:42.36 java
15106 root 20 0 2670328 641752 0 S 0.0 34.1 0:00.00 java
15107 root 20 0 2670328 641752 0 S 0.0 34.1 0:35.34 java
15108 root 20 0 2670328 641752 0 S 0.0 34.1 0:00.02 java
15109 root 20 0 2670328 641752 0 S 0.0 34.1 0:44.18 java
15110 root 20 0 2670328 641752 0 S 0.0 34.1 0:54.24 java
15125 root 20 0 2670328 641752 0 S 0.0 34.1 118:01.99 java
15126 root 20 0 2670328 641752 0 S 0.0 34.1 0:49.07 java
15127 root 20 0 2670328 641752 0 S 0.0 34.1 0:02.74 java
15129 root 20 0 2670328 641752 0 S 0.0 34.1 1:44.91 java
15130 root 20 0 2670328 641752 0 S 0.0 34.1 2:07.57 java
15131 root 20 0 2670328 641752 0 S 0.0 34.1 109:22.47 java
15134 root 20 0 2670328 641752 0 S 0.0 34.1 84:53.55 java
15135 root 20 0 2670328 641752 0 S 0.0 34.1 51:24.75 java
15136 root 20 0 2670328 641752 0 S 0.0 34.1 0:00.00 java
15137 root 20 0 2670328 641752 0 S 0.0 34.1 0:00.00 java
15138 root 20 0 2670328 641752 0 S 0.0 34.1 80:55.66 java
15139 root 20 0 2670328 641752 0 S 0.0 34.1 11:00.48 java
15140 root 20 0 2670328 641752 0 S 0.0 34.1 10:59.59 java
里面会出现该进程下子线程的各个信息,一般的排错方式就是查看占用CPU很高的线程信息,里面存放的都是栈信息。
printf “%x\n” -pid命令
printf “%x\n” -pid 查看子线程转化16进制后的nid,通过nid查看栈信息和它的状态,转换后的情况是这样的
printf “%x\n” 15134
“3b1en”
通过nid可以精准查看占用cpu和内存线程信息。
jstack -pid |grep nid命令
jstack -pid |grep nid -A 50 使用jstack查看50行后的程序运行信息,查看导致线程占用过高的原因
前面的pid是top下的进程pid,后面的nid是printf转换后的nid,nid前面一般加0x,即上面的nid应该写为jstack -pid |grep 0x3b1en -A 50,行数是可以自行调整的。
一般的waiting线程也会占用内存和cpu,但是占用量较少,内存泄露会占用大量内存,使服务缓存空间过载,最终挂掉,死锁会导致程序运行异常,cpu过大。
总结
jstack Dump 日志文件中的线程状态
dump 文件里,值得关注的线程状态有:
死锁,Deadlock(重点关注)
执行中,Runnable
等待资源,Waiting on condition(重点关注)
等待获取监视器,Waiting on monitor entry(重点关注)
暂停,Suspended
对象等待中,Object.wait() 或 TIMED_WAITING
阻塞,Blocked(重点关注)
停止,Parked
我用的堆栈排查就是这样的,比较简单,应对与一些简单问题是没问题的,学无止境,学的越多感觉自己越渺小,以后继续学习,如果有更好更精准的排查方式会继续分享的。