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 最大连接数和最大并发数是多少
服务假死