我的程序哪里出错了? --本地没问题,怎么线上异常呢,深入程序堆栈看一看

129 阅读5分钟

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” 151343b1en”

通过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

我用的堆栈排查就是这样的,比较简单,应对与一些简单问题是没问题的,学无止境,学的越多感觉自己越渺小,以后继续学习,如果有更好更精准的排查方式会继续分享的。