记一次tomcat假死问题排查

发现问题是因为tomcat http接口都访问不了了,但是tomcat进程还在,并且日志不再滚动了。

  1. 首先怀疑是内存泄漏,查看errorlog看有没有OutOfMemoryException 异常

vim biz.error.log发现没有OutOfMemoryException异常

  1. 那么应该是tomcat的线程出了问题,需要查看一下当前进程下线程执行状态

jstack pid > jstack_pid.log输出线程的执行状态到日志文件

把jstack_pid.log文件下载下来用记事本打开,发现基本上所有的线程都是WAITING状态,只有GC线程是RUNNABLE

Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.171-b11 mixed mode):

"Attach Listener" #1023 daemon prio=9 os_prio=0 tid=0x00007f8bfc014800 nid=0x2042 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"NettyClientPublicExecutor_4" #1020 daemon prio=5 os_prio=0 tid=0x0000000002363000 nid=0x1d3a waiting on condition [0x00007f8bc883d000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000ee136860> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

....

"VM Thread" os_prio=0 tid=0x00007f8c4010b800 nid=0x15f4 runnable 

"Gang worker#0 (Parallel GC Threads)" os_prio=0 tid=0x00007f8c4001b800 nid=0x15ef runnable 

"Gang worker#1 (Parallel GC Threads)" os_prio=0 tid=0x00007f8c4001d800 nid=0x15f0 runnable 

"Gang worker#2 (Parallel GC Threads)" os_prio=0 tid=0x00007f8c4001f000 nid=0x15f1 runnable 

"Gang worker#3 (Parallel GC Threads)" os_prio=0 tid=0x00007f8c40021000 nid=0x15f2 runnable 

"Concurrent Mark-Sweep GC Thread" os_prio=0 tid=0x00007f8c40064000 nid=0x15f3 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007f8c40165800 nid=0x15fe waiting on condition 

那么可以推测原因应该是GC回收不了大对象照成的

  1. 查看GC运行状态

jstat -gcutil pid 1000打印出GC运行状态(每秒刷新一次)

  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
  0.00   0.00  91.34 100.00  85.94  82.35   7830   32.715 43582 25846.169 25878.884
  0.00   0.00  91.34 100.00  85.94  82.35   7830   32.715 43582 25846.169 25878.884
  0.00   0.00  92.98 100.00  85.94  82.35   7830   32.715 43582 25846.169 25878.884
  0.00   0.00  94.03 100.00  85.94  82.35   7830   32.715 43582 25846.169 25878.884
  0.00   0.00  94.87 100.00  85.94  82.35   7830   32.715 43582 25846.169 25878.884
  0.00   0.00  95.50 100.00  85.94  82.35   7830   32.715 43582 25846.169 25878.884

果然O(老年代)已经满了,GC把所有线程资源都占了导致其他线程无法运行照成了假死状态

  1. 分析heap内存状态,找出具体代码问题
    jmap -dump:format=b,file=./heap.hprof [pid]生成heap文件

使用Memory Analyzer来分析


5dd4ba3fc91af.png

分析出来是订单的定时任务造成GC的问题


Inked5dd4babe7e7d1_LI.jpg

接下来去改代码就可以了。主要的方法就是先去看日志,日志找不到原因就去线程的堆栈信息里面找原因。


当然除了以上的办法还有几个有用的命令能更快地定位到线程问题

top -Hp pid 查看进程下线程的cpu和内存状态


 PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND        
25246 tomcat    20   0 4435752 986.7m   7368 S  70.3 40.6   0:21.32 java      //这个线程占了很高的cpu和内存                                                                                                                                                                                                                                                                                                                                                            
25243 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   0:00.00 java                                                                                                                                                                                     
25244 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   0:00.88 java                                                                                                                                                                                     
25245 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   0:20.04 java                                                                                                                                                                                                                                                                                                                                                             
25247 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   0:19.99 java                                                                                                                                                                                     
25248 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   0:19.98 java                                                                                                                                                                                     
25249 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   1:36.60 java                                                                                                                                                                                     
25250 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   1:47.24 java                                                                                                                                                                                     
25251 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   0:00.04 java                                                                                                                                                                                     
25252 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   0:00.04 java                                                                                                                                                                                     
25253 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   0:00.00 java                                                                                                                                                                                     
25254 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   0:00.00 java                                                                                                                                                                                     
25255 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   0:00.44 java                                                                                                                                                                                     
25256 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   0:00.07 java                                                                                                                                                                                     
25258 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   0:00.59 java                                                                                                                                                                                     
25259 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   1:05.06 java                                                                                                                                                                                     
25260 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   0:59.96 java                                                                                                                                                                                     
25261 tomcat    20   0 4435752 986.7m   7368 S  0.0 12.6   1:06.67 java
25336 tomcat    20   0 4435752 986.7m   7368 S  0.7 12.6   0:42.12 java 

ps -mp pid -o THREAD,tid,time查看当前进程下所有线程的耗时

USER     %CPU PRI SCNT WCHAN  USER SYSTEM   TID     TIME
tomcat    9.6   -    - -         -      -     - 00:28:07
tomcat    0.0  19    - futex_    -      - 25243 00:00:00
tomcat    0.0  19    - poll_s    -      - 25244 00:00:00
tomcat    0.1  19    - futex_    -      - 25245 00:00:20
tomcat    0.1  19    - futex_    -      - 25246 01:00:21   //这个线程执行了一个多小时,很可能有问题
tomcat    0.1  19    - futex_    -      - 25247 00:00:19
tomcat    0.1  19    - futex_    -      - 25248 00:00:19
tomcat    0.5  19    - futex_    -      - 25249 00:01:36
tomcat    0.6  19    - futex_    -      - 25250 00:01:47
tomcat    0.0  19    - futex_    -      - 25251 00:00:00
tomcat    0.0  19    - futex_    -      - 25252 00:00:00
tomcat    0.0  19    - futex_    -      - 25253 00:00:00
tomcat    0.0  19    - futex_    -      - 25254 00:00:00
tomcat    0.0  19    - futex_    -      - 25255 00:00:00
tomcat    0.0  19    - futex_    -      - 25256 00:00:00
tomcat    0.0  19    - ep_pol    -      - 25258 00:00:00
tomcat    0.3  19    - futex_    -      - 25259 00:01:05
tomcat    0.3  19    - futex_    -      - 25260 00:00:59

printf “%x\n” 25246转换线程id为16进制格式 629en
jstack pid |grep 629en -A 30 输出该线程的30行堆栈信息

"http-nio2-8089-exec-195" #344 daemon prio=5 os_prio=0 tid=0x00007fa8980de000 nid=0x6265 runnable [0x00007fa85e6d4000]
   java.lang.Thread.State: RUNNABLE
        at java.util.Arrays.copyOf(Arrays.java:3332)
        at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:124)
        at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:448)
        at java.lang.StringBuilder.append(StringBuilder.java:136)
        at org.apache.shiro.web.util.WebUtils.normalize(WebUtils.java:194)
        at org.apache.shiro.web.util.WebUtils.normalize(WebUtils.java:155)
        at org.apache.shiro.web.util.WebUtils.getRequestUri(WebUtils.java:140)
        at org.apache.shiro.web.util.WebUtils.getPathWithinApplication(WebUtils.java:112)
        at org.apache.shiro.web.filter.mgt.PathMatchingFilterChainResolver.getPathWithinApplication(PathMatchingFilterChainResolver.java:147)
        at org.apache.shiro.web.filter.mgt.PathMatchingFilterChainResolver.getChain(PathMatchingFilterChainResolver.java:99)
        at org.apache.shiro.web.servlet.AbstractShiroFilter.getExecutionChain(AbstractShiroFilter.java:415)
        at org.apache.shiro.web.servlet.AbstractShiroFilter.executeChain(AbstractShiroFilter.java:448)
        at org.apache.shiro.web.servlet.AbstractShiroFilter$1.call(AbstractShiroFilter.java:365)
        at org.apache.shiro.subject.support.SubjectCallable.doCall(SubjectCallable.java:90)
        at org.apache.shiro.subject.support.SubjectCallable.call(SubjectCallable.java:83)
        at org.apache.shiro.subject.support.DelegatingSubject.execute(DelegatingSubject.java:387)
        at org.apache.shiro.web.servlet.AbstractShiroFilter.doFilterInternal(AbstractShiroFilter.java:362)
        at org.apache.shiro.web.servlet.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:125)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at com.github.common.component.biz.Biz.doBizMethod(Biz.java:30)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:111)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
...
最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 162,408评论 4 371
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 68,690评论 2 307
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 112,036评论 0 255
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 44,726评论 0 221
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 53,123评论 3 296
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 41,037评论 1 225
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 32,178评论 2 318
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 30,964评论 0 213
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 34,703评论 1 250
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,863评论 2 254
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 32,333评论 1 265
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 28,658评论 3 263
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 33,374评论 3 244
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,195评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,988评论 0 201
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 36,167评论 2 285
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 35,970评论 2 279