Java线上问题排查总结

如果遇到线上问题,需要从几个方面排查问题。接口成功率,响应时间,CPU、内存占用率,IO性能
①如果是接口成功率为低甚至为0,可以考虑是不是出现了Java或者Mysql死锁问题。
②如果是接口响应时间长,可以考虑是不是文件IO频繁或者IO性能低,或者是慢SQL问题。
③如果接口响应一段时间后,接口响应失败,判断是否出现OOM异常。
④如果Java程序占用CPU过高是否存在空转,频繁gc,频繁上下文切换;如果内存占用率高是否存在堆外内存泄露问题。

Java死锁

测试代码:

public static void main(String[] args) {
   ReentrantLock lock1 = new ReentrantLock();
   ReentrantLock lock2 = new ReentrantLock();

   Thread t1 = new Thread(()->{
       lock1.lock();
       try {
           TimeUnit.SECONDS.sleep(10);
       } catch (InterruptedException e) {
            e.printStackTrace();
       }
       lock2.lock();
       lock2.unlock();
       lock1.unlock();
   });
   Thread t2 = new Thread(()->{
       lock2.lock();
       try {
           TimeUnit.SECONDS.sleep(5);
       } catch (InterruptedException e) {
           e.printStackTrace();
       }
       lock1.lock();
       lock1.unlock();
       lock2.unlock();
       });

   t1.start();
   t2.start();
}

查看方式
使用jstack pid直接查看最下面有没有Found 1 deadlock,如果有,查看下面代码指代行数就可以发现出问题的代码了

Java死锁测试

Mysql死锁

测试死锁

test.user 表设置id主键索引
连接1,2的查询顺序为id=1,id=2;id=2,id=1,造成死锁
//连接1 
set autocommit=0;
select * from user where id=1 for update;
select * from user where id=2 for update;

//连接2
set autocommit=0;
select * from user where id=2 for update;

执行上述语句之后,其中一个连接会阻塞,而另一个连接将会提示死锁信息:

mm12.PNG

Mysql死锁可以使用show engine innodb status命令查看Mysql死锁的情况,前提是Mysql开启了死锁检查
Mysql死锁状态信息

解决方法:当出现死锁以后,有下面三种解决方法
1)开启系统死锁检测,发现死锁后,会主动回滚死锁中的某一个事务,让其他事务得以继续执行。执行set global innodb_deadlock_detect=on;表示开启这个逻辑。Mysql默认开启。show variables like 'innodb_deadlock_detect';命名查看此系统值。不过在高并发系统上,死锁检测可能导致SQL执行速度减慢,可能会关闭死锁检测。

2)设置锁超时时间。如果关闭死锁检查,Mysql线程还可以通过设置innodb_lock_wait_timeout来限制SQL的锁等待时间。 关于MySQL死锁检测机制参数innodb_deadlock_detect设置的一点思考
①如果发生死锁,等待加锁的线程会在超时会退出并回滚,其他事务则可以继续执行。
命令 set global innodb_lock_wait_timeout=60 来设置锁等待过期时间。默认值是50s。通过show variables like 'innodb_lock_wait_timeout';查看此系统值。
②但是innodb_lock_wait_timeout只会回滚最后的造成锁等待超时的语句,并不会回滚整个事务。此时线程2还是持有id=1的锁并没有释放,线程1中的事务依然存在,死锁问题还可能存在。所以还需要设置innodb_rollback_on_timeout=on,这样一旦出现锁超时的SQL整个事务都会回滚,可以很好地解决死锁问题。innodb_rollback_on_timeout属于只读变量,需要修改my.conf或者my.ini文件的内容并重启Mysql才生效。
Java程序可以通过设置 @Transactional(rollbackFor = Exception.class)起到回滚整个事务的效果
③可以执行select * from information_schema.innodb_trx;查看回滚前后的事务数量变化。

锁超时提示

锁超时前后事务变化

3)如果线上设置了比较长的锁等待时间,或者想尽快处理问题,可以执行kill mysql_thread_id手动杀死其中mysql线程。
①执行select * from performance_schema.data_lock_waits;查看当前锁等待信息。或者执行show status like 'InnoDB_row_lock%';

data_lock_waits表信息

  • REQUESTING_THREAD_ID:请求执行的mysql线程id
  • BLOCKING_THREAD_ID:造成请求线程锁等待的线程id
  • REQUESTING_ENGINE_TRANSACTION_ID:请求执行的事务id
  • BLOCKING_ENGINE_TRANSACTION_ID:造成请求线程锁等待的事务id
    此外该表还可以关联performance_schema.events_statements_current查看请求事务正在等待执行的sql以及阻塞事务正在执行的sql。performance_schema.events_statements_current表记录了当前事务的执行执行语句。
 SELECT dlw.REQUESTING_THREAD_ID ,dlw.BLOCKING_THREAD_ID, dlw.REQUESTING_ENGINE_TRANSACTION_ID  ,dlw.BLOCKING_ENGINE_TRANSACTION_ID,
 esc.SQL_TEXT, esc2.SQL_TEXT FROM performance_schema.data_lock_waits dlw 
inner join performance_schema.events_statements_current esc 
 on dlw.REQUESTING_THREAD_ID = esc.THREAD_ID 
inner join performance_schema.events_statements_current esc2
 on dlw.BLOCKING_THREAD_ID  = esc2.THREAD_ID 

②执行select trx_mysql_thread_id from information_schema.innodb_trx where trx_id in (select REQUESTING_ENGINE_TRANSACTION_ID from performance_schema.data_lock_waits)查询所有锁等待mysql_thread_id
使用kill mysql_thread_id;杀死其中的线程。

kill mysql_thread_id效果

③此外还可以通过show engine innodb status语句查看锁等待情况,找到存在死锁的线程并kill

存在死锁的线程

以上需要用到的表描述
performance_schema.data_locks 当前事务持有的锁信息表
performance_schema.data_lock_waits 事务锁等待信息表
performance_schema.events_statements_current 当前事务执行SQL信息表
information_schema.innodb_trx 当前所有的事务信息表

Mysql锁等待超时导致查询失败
可以使用方法3)中的步骤查询performance_schema.data_lock_waits表和show engine innodb status查询造成锁等待超时的SQL。

JAVA服务突然无故挂掉

服务运行过程中突然死掉。需要重启才能运行。虽然设置了 -XX:HeapDumpPath 参数但是日志里面并没有错误信息,也没有出现OOM异常。执行jps出现process information unavailable,说明可能是系统重启或者服务突然挂掉。
这种情况可以查看系统日志文件/var/log/message, 或者 dmesg 命令。
如果出现以下信息,而且pid与JAVA进程相同,那大概率是由于系统内存不足,导致JAVA服务被系统杀死的缘故。
linux java 进程被kill 如何排查原因 linux java进程自动退出

[15219579.748115] Out of memory: Kill process 30891 (java) score 112 or sacrifice child
[15219579.749110] Killed process 30891 (java), UID 997, total-vm:5716160kB, anon-rss:872648kB, file-rss:0kB, shmem-rss:0kB

OOM Killer:Linux操作系统内存不足时,会先触发内存回收机制释放内存,并将这部分被释放的内存分配给其他进程。如果内存回收机制不能处理系统内存不足的情况,则系统会触发OOM Killer(Out of Memory Killer)强制释放进程占用的内存,达到给系统解压的目的。对于系统关键进程(如init进程、内核线程等)是不能被杀死的,其它进程则通过oom_badness进行打分(0~1000),分数最高者被选中,一般占用系统内存最高的进程会被杀死。

原因:这种情况一般是设置了不合理的JVM参数,而且机器本身启动了较多的服务导致的。因为JVM默认初始内存是系统1/64 ,默认最大内存是系统1/4,默认当堆内存大于40%时,就会增大内存至最大内存。
如果在增大内存的过程中,操作系统就会找出需要杀死的进程,释放内存空间。这种情况下JAVA服务就有可能会被系统杀死而无故挂掉。

解决方法:为每个JVM服务设置合理的启动参数,最好将-Xms,-Xmx这两个参数设置一致。同时避免一台机器中启动多个JAVA服务。

JAVA假死问题

可能出现的原因:
①频繁Full GC导致STW,或者发生了内存泄露
②发生死循环,CPU占用率过高
③线程长时间阻塞,导致请求长时间无法响应

频繁Full GC
使用jstat -gcutil <pid>或者jstat -gc<pid>查看GC次数和时间

jstat命令

  • YGC:从应用程序启动到采样时年轻代中gc次数
  • YGCT:从应用程序启动到采样时年轻代中gc所用时间(s)
  • FGC:从应用程序启动到采样时old代(全gc)gc次数
  • FGCT:从应用程序启动到采样时old代(全gc)gc所用时间(s)
  • GCT:从应用程序启动到采样时gc用的总时间(s)

如果YGC,FGC,GCT的值比较大,这可能是由于发生JVM频繁GC而导致的STW问题
①获取GC日志:添加启动参数java -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCCause -Xloggc:/logs/gc.log
②查看堆内存使用情况:使用jmap -dump:live,format=b,file=/dump.hprof pid命令生成多次dump文件。使用visualVM,jConsole,MAT等工具对比堆内存使用情况,分析是否有不合理对象或者大量生成的对象,例如Spring Bean大对象或者类静态变量。
③优化JVM配置,调整JVM堆内存参数或者使用更适合的垃圾收集器

JAVA发生死循环
如果JAVA服务CPU占用率接近100%,说明程序可能出现死循环。
①使用top命令查看CPU异常的PID

top命令

②使用 top -Hp PID查询进程中所有的线程CPU占用率
top -H PID

③使用jstack PID |grep ThreadID的十六进程查看是哪个方法
mm22.PNG

如果jstack pid命令出现这种结果,可能是由于使用此命令的用户与启动java的命令不是同一个,也可能是由于执行jstack时执行FULL GC导致无法连接。可以添加打印GC参数nohup java -XX:+PrintGC DemoTest > output.txt 2>&1 &,然后到output.txt文件中查看jstack线程信息。

6393: Unable to open socket file: target process not responding or HotSpot VM not loaded
The -F option can be used when the target process is not responding

线程长时间阻塞
如果发现线上请求过程非常漫长,几分钟都没有返回结果,但是测试一次请求只花费了5s左右,这时候需要查看代码是否发生了阻塞逻辑,导致并发访问下线程被阻塞了。
测试代码,模拟接口调用或者数据库加锁请求:

@RequestMapping("/block")
public String block2() throws InterruptedException {
   synchronized ("aaa") {
       TimeUnit.SECONDS.sleep(5);
   }
   return "--block--";
}

使用arthas工具thread命令查看所有http线程的执行情况,发现所有http请求都处于BLOCKED状态,说明它们都在等在锁释放。尤其是接口并发请求比较多,但是tomcat处理线程比较少的情况,等待时间会更长。使用thread ID查看线程被阻塞的原因

所有线程状态

线程详情

Java线程状态图

Connection refused

tomcat请求流程图

①用户发送http请求,客户机先于服务器进行三次握手,
②握手成功,从半连接队列进入全连接队列
③tomcat获取指定端口的全连接队列中的socket数据
④Acceptor采用NIO方式,将socket数据交给工作线程处理

其中Springboot关于tomcat响应配置的参数包括:

server:
 tomcat:
   # 表示工作线程的最大数量,默认200
   max-threads: 200
   # 表示工作线程的最小数量,初始创建的线程数,默认10
   min-spare-threads: 10
   # 表示该tomcat服务最大连接数,一旦达到限制,操作系统仍然可以接受基于“acceptCount”属性的连接,默认8192
   max-connections: 8192
   # 表示连接如果大于最大连接数,还能接受的最大任务数,默认100
   accept-count: 100
   # 连接器在接受连接后等待显示请求 URI 行的时间。
   connection-timeout: 20000

当连接数达到最大值max-connections后,系统会继续接收连接,进行排队,但不会超过accept-count的值。
Tomcat最大并发数取决于max-connections+accept-count。SpringBoot可以同时处理多少请求?
如果出现Connection refused错误,可以查看以上配置是否合理。同时
使用ss -nlt|grep "port"查看指定端口全连接队列容量

  • Recv-Q表示(acceptCount)全连接队列目前长度
  • Send-Q表示(acceptCount)全连接队列的容量。

使用netstat -nat | grep -i "port" | grep ESTAB | wc -l查看指定端口成功建立的连接数

通过上述两个命令可以推算出请求是否是由于并发量过大导致的。
如果是因为某一时刻并发量过大导致无法访问,可以通过限流或者扩容来实现

Java OOM异常

常见的OOM异常详情说明: 10种常见OOM分析——手把手教你写bug

本文主要讲解Java heap space异常,这个是OOM遇到比较多的异常
添加JVM启动参数,接收OOM文件-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/logs/dump.hprof
示例程序:

public String test() throws InterruptedException {
       List<Integer[]> integers = new ArrayList<>();

       int size = 10 * 1024 * 1024;
       while (true) {
           Integer[] ints = new Integer[size];
           integers.add(ints);
       }
   }

提示如下:
java.lang.OutOfMemoryError: Java heap space
Dumping heap to /home/user/dump.hprof ...
Heap dump file created [1862040155 bytes in 38.078 secs]

MAT工具查看
找到hprof文件,使用MAT工具 => Leak Suspects 查看可能存在的内存泄露

MAT概念图

histogram图

histogram展示了Objects(类对象数量),Shallow Heap(浅堆大小),Retained Heap(深堆大小),从图中可以看出系统产生的Integer[]对象占用了大量内存,通过右键点击List Objects=>with incoming reference可以查看对象的引用链信息。利用MAT工具分析内存泄漏
Shallow Heap:表示对象本身占有的内存大小
Retained Heap:也叫保留集,表示释放对象占有的内存大小,说明如下;
深堆和浅堆说明

如上图:SH表示浅堆,RH表示深堆,上图假设每个对象自身所占的内存都是10,也即所有对象浅堆都是10。

  • 如果对象没有引用其他对象,那么它的深堆大小和浅堆相同,比如D,E,F,G;
  • 如果单独引用了其他对象,则深堆大小等于自身和引用链中所有对象的大小之和,例如B,C的深堆大小是30;
  • 如果和其他对象一起引用了其他其他对象,则深堆大小等于它单独引用对象大小之和,例如A虽然引用了B和C,但是释放A并不释放B的空间,只会释放C的空间,所以A的深堆大小等于A自身和C深堆之和。
zzz3.png

dominator_tree展示了对象树信息,包括对象引用链中所有对象深堆和浅堆大小,从图中可以看出0xe37211e8这个ArrayList占用了99.27%的内存,但其本身占用内存比较小,点开查看引用对象信息,直到发现Integer[]对象深堆和浅堆大小都比较大,说明产生了很多Integer[]大对象。

Leaks展示图

支配树中的累积对象

堆栈信息

Leaks可以直接展示存在内存泄漏的线程和大小,点击Details 查看造成内存泄漏的大对象信息和具体代码信息。

VisualVM查看
使用visualVM也可以查看内存泄露的信息,导入dump文件,点击选中的信息查看引起OOM线程,方法,变量信息

visualVM主页

追踪到的OOM异常方法,线程,变量

可能出现内存泄露的场景:GC日志分析 与 内存泄漏 与 OOM案例
①静态集合类,如将HashMap和ArrayList等申请成静态变量。那么容器中的所有对象都跟着不能被释放,从而导致内存的泄漏。
②资源未释放,如数据库连接,网络连接,IO连接等,如果没有显示的调用关闭函数,那么会导致大量的对象无法被回收,从而引起内存的泄漏。
③缓存泄漏,当对象被引入缓存的时候忘记清除。例如ThreadLocal
④内部非静态类,内部非静态类默认持有外部类的强引用,因此当内部类被长期饮用的时候,外部类对象将无法回收。

优化方案:
①尽早释放无用对象(置为null),提高GC回收效率。
②避免在循环中创建对象。
③获取数据库数据或者接口数据时尽量减少不必要字段的返回,占用内存空间。

参照:mysql死锁问题排查
这几种常见的 JVM 调优场景,你知道吗?
太坑了!Spring Boot 导致堆外内存泄露了!
数据库死锁排查思路
SQL优化经历
干货 | 阿里大神总结的JAVA 线上故障排查完整套路
JVM常用启动参数
Spring Boot 最大连接数和最大并发数是多少
服务假死

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 202,905评论 5 476
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,140评论 2 379
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 149,791评论 0 335
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,483评论 1 273
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,476评论 5 364
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,516评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,905评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,560评论 0 256
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,778评论 1 296
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,557评论 2 319
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,635评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,338评论 4 318
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,925评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,898评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,142评论 1 259
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 42,818评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,347评论 2 342

推荐阅读更多精彩内容

  • java中static关键字的作用 在Java中static表示“全局”或者“静态”的意思,用来修饰成员变量和成员...
    Lutecium阅读 1,004评论 1 5
  • Linux命令类 tail grep find top netstat btrace & greys 系统异常排查...
    simple_mind阅读 894评论 0 1
  • 前言线上定位问题时,主要靠监控和日志。一旦超出监控的范围,则排查思路很重要,按照流程化的思路来定位问题,能够让我们...
    立0911阅读 374评论 0 1
  • 1.spring对mybatis的事务管理是怎么支持的 一、事务的基本原理 Spring事务的本质其实就是数据库对...
    __游离__阅读 1,146评论 6 7
  • 在网上看到一篇专门汇总面试题的文章,于是一时兴起,就把其内容整理了一番,因为原文问题和答案不完整,且混在一起,于是...
    帅可儿妞阅读 811评论 0 1