JPA项目优化实战、死锁、填坑

棘手问题

最近接手一个棘手的项目，棘手的原因当然不是新项目业务逻辑复杂了。项目的成员关系较为混乱，接手的时候缺少很多原始的项目文档，交接的时候听到最多的回答就是“不知道”，由于客观原因又不得不接手，只好慢慢的交接。

项目交接

整个交接花了3天时间，每天早起晚睡的状态，出差比在公司还累。

从乙方SVN上将代码和文档拷贝下来，发现项目有三个，暂且称为ABC三个项目，还有部分原型图片和第三方服务配置信息。
项目刚开始以为是springboot+jpa+angularjs项目，AB两个项目虽然都是maven项目并且功能点类似，对接的三方服务不同而已，C项目是提供的额外的API项目，可以理解为只有springMVC的接口没有页面的项目。
启动项目的时候发现AB虽然代码有90%类似，但是并未复用代码，这就为今后的维护带来很大的隐患了，没办法保证两个项目的公共部分同步，每次都依靠手工去修改。
C项目是一个普通的JavaEE项目，没用maven做jar包依赖管理，而且编译的时候还不通过，后来检查发现，在项目build中依赖了target（target原本为项目编译目标文件夹，而此文件夹目前除了项目编译的class文件等还有一个额外的文件夹可以理解为是部分的main文件夹里的java）目录下的一个文件夹，这种配置方式让我无比头疼，最终为了项目好交接和维护，给改成maven项目。

普通JavaEE项目改成maven项目
（1）需要找到依赖得各种jar包；
（2）若有不在仓库中的jar包，需要将jar包手动添加到私服中；
（3）没用公司内部私服服务器的需要在maven项目中新建一个lib文件夹；
（4）在pom文件中添加lib文件夹中的jar包
（5）并利用resource打包时将手动添加的jar文件拷贝到target的lib目录下。

项目启动

代码交接完成后，准备将编译后的代码放到测试环境运行，保证代码可用，并且功能与线上保持一致（不验证没办法保证svn上代码与线上是否一致，因为看到svn没有做版本管理的时候心里就清楚了，大概率是不一致的）

项目传到测试环境，首先就是无法启动了，或者启动的环境配置不对。

(1) 项目SVN没用做倒版本管理，在多次上线后完全依靠手动修改配置的文件和代码，会带来失误；
(2) 环境变量没用做到分离，每次上线需要手动修改测试环境和手动环境配置，作为一个老程序员这种错误着实不应该了，本来想偷懒的问题可能会带来严重的生产事故。
(3) 一项项改完之后，对照功能清单发现，启动的测试环境与线上出现了不一致的地方，特别是页面很明显就能看出来
(4) 项目启动后需要紧盯日志，生怕错过什么信息，果然日志有报错信息，提示:

Exception in thread "main" java.lang.UnsupportedClassVersionError: picard/cmdline/PicardCommandLine : Unsupported major.minor version 52.0

这种报错信息是提示JDK版本不一致，检查环境变量得知，本地是JDK1.8无错误信息，测试环境JDK1.7有错误，生产环境JDK1.8无错误信息；很明显需要将测试环境变量更改为JDK1.8；乙方测试环境的上线流程是将报错的代码注释掉然后上测试，上生产后再去掉注释，这种操作也就胆子肥的可以试试。

项目版本及上线

询问乙方开发人员得知，他们也无法保证每次上线的代码和SVN一致，因为他们每次都是去线上替换class或者手动修改配置文件然后重启项目，这样的操作让自己还怎么对自己的项目有信心。
需要处理方案：
(1) 静态页面从生产上直接拷贝同步到svn代码中，保持起码页面的一致性；
(2) 备份线上项目，若遇到功能不一致情况，反编译class与java代码做对比；

再来说说项目中静态文件的问题（灰色敏感信息，你懂的）

project.png

问题相信大家一眼能看出来
(1) springboot项目页面模板文件要求放到templates文件夹中，但这不是绝对的，也可以忽略整个文件夹
(2) 页面文件放到webapp下是不安全的，很明显需要放到WEB-INF（在webapp下新建）目录下，防止整个静态页面被未授权访问
(3) 询问得知，Admin 和App作为前后端分离的两个前端页面项目，完全不用放到tomcat中，直接用apache或者nginx挂载，做倒真正的前后端分离；项目目前出现了超出tomcat承受能力的并发，更需要做前后端分离了，而不是将原本就是前后端分离的项目无脑的整合到一起（据说是为了解决跨域的问题，此时心里有1w+只羊驼在奔腾）

线上问题

在项目交接过程中就听客户反馈，线上项目经常无法访问，项目虽已上线但是并未作大规模推广，此时用户量应该在预测范围内，乙方团队反馈说是服务器问题，这样的反馈与我们没用实质性的帮助；首先只能去跟踪日志，发现日志未打开DEBUG级别，容易遗漏信息，需要将DEBUG级别打开定位问题

日志首先暴露了一个"Broken pipe"的问题，乙方解答是打开的文件说超过服务器的默认值1024，修改服务器设置，增加进程可打开的文件句柄数量。问题仍然存在。

此时最好的办法是review代码，发现多种读写文件，一类是上传文件到硬盘，另一类读写properties配置文件；
此时发现两个问题：
(1) 上传文件到服务器硬盘后生产的临时文件没有在使用后自动清理，导致临时文件暂用磁盘，但不至于导致异常；
(2) 读取properties文件是在一个万能的BaseController中，有个每次读取request参数的方法initJsonParam(),每次controller方法调用都会去读取properties文件，导致进程每次都要读取配置文件，此处大可不必要，只需读取一次放入类成员变量中即可，或者使用spring的配置文件注解自动注入文件。

文件的事情发现了原因，但是项目运行半天后又发生了连接被拒绝的问题，log提示线程池队列已满，拒绝入队请求。

线上的tomcat配置经过优化处理，配置了线程池，NIO2的方式；最大线程800，等待队列100个；
(1) " netstat -ant | grep 80 | wc -l "命令查看80端口的占用情况，发现一直在930以上
(2) " netstat -ant | grep 80 |awk '{++s[$NF]} END {for(i in s) print i,s[i]}' " 查看80端口的tcp连接情况，发现有450+的CLOSE_WAIT线程，此时肯定是不正常的
(3) " ps -ef | grep java " 定位到项目的PID
(4) " lsof -p PID " 查看出现CLOSE_WAIT的详细信息，发现是服务器端响应客户端时候在等待，并且应用程序没用及时检测到客户端已关闭连接，出现这种情况是服务器未返回信息，进程仍在等待业务处理。
(5) 程序中并没用复杂SQL查询，因为使用的JAP，基本都是单表操作较多，判断可能是数据库除了瓶颈。
(6) 检查服务器连接数都是正常的，未超过配置的最大连接数，但是进mysqld后，查看正在执行的事务发现有很多正在等待的进程，有900+之多，即使项目重启后很快也增加到三位数，此时疑惑中，因为并未发现大量的select操作，都是insert与update之间的互相等待。

寻找JPA连接数据库死锁原因,使用如下语句查找数据库死锁的源头

SELECT DISTINCT b.trx_id blocking_trx_id,
                     b.trx_mysql_thread_id 源头锁thread_id,
                     SUBSTRING(p. HOST, 1, INSTR(p. HOST, ':') - 1) blocking_host,
                     SUBSTRING(p. HOST, INSTR(p. HOST, ':') + 1) blocking_port,
                     IF(p.COMMAND = 'Sleep', p.TIME, 0) idel_in_trx,
                     b.trx_query blocking_query,
                     r.trx_id waiting_trx_id,
                     r.trx_mysql_thread_id waiting_thread,
                     TIMESTAMPDIFF(SECOND, r.trx_wait_started, CURRENT_TIMESTAMP) wait_time,
                     r.trx_query waiting_query,
                     l.lock_table waiting_table_lock
       FROM information_schema.INNODB_LOCKS l
       LEFT JOIN information_schema.INNODB_LOCK_WAITS w
         ON w.requested_lock_id = l.lock_id
       LEFT JOIN information_schema.INNODB_TRX b
         ON b.trx_id = w.blocking_trx_id
       LEFT JOIN information_schema.INNODB_TRX r
         ON r.trx_id = w.requesting_trx_id
       LEFT JOIN information_schema. PROCESSLIST p
         ON p.ID = b.trx_mysql_thread_id
     JOIN (SELECT blocking_trx_id -- 查找最源头的trx_id
           FROM information_schema.INNODB_LOCK_WAITS ilw
          WHERE blocking_trx_id NOT IN
                (SELECT requesting_trx_id
                   FROM information_schema.INNODB_LOCK_WAITS)) c
     ON c.blocking_trx_id = b.trx_id 
     ORDER BY wait_time DESC;

(1) waiting_query 一列发现很多等待的update语句，并且都是根据主键update，本身不应该出现死锁，都是走索引的SQL，不存在表锁。
(2) " SHOW STATUS LIKE '%lock%'; " sql查询所得等待时间，都是Innodb_row_lock,未发现表锁等信息，更疑惑；
(3) 查询应用程序的事务配置，都是在service层注解在类上配置了事务，都已经提交了，不存在程序失误得未提交事务。
(4) " SHOW ENGINE INNODB STATUS; " 查看锁发生的详细日志，此处节选部分日志

=====================================
2018-04-26 18:34:07 7f8ac91fb700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 17 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 13501269 srv_active, 0 srv_shutdown, 15670842 srv_idle
srv_master_thread log flush and writes: 29170711
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 7603696
OS WAIT ARRAY INFO: signal count 16033072
Mutex spin waits 117932426, rounds 141446289, OS waits 979385
RW-shared spins 8219797, rounds 187794144, OS waits 5726533
RW-excl spins 1287414, rounds 41555159, OS waits 839372
Spin rounds per wait: 1.20 mutex, 22.85 RW-shared, 32.28 RW-excl
------------------------
LATEST FOREIGN KEY ERROR
------------------------
2018-04-25 21:26:22 7f8aa8ae7700 Transaction:
TRANSACTION 71107923, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
9 lock struct(s), heap size 2936, 5 row lock(s), undo log entries 1
MySQL thread id 1700944, OS thread handle 0x7f8aa8ae7700, query id 1293657675 111.230.128.98 cdb_outerroot updating
delete from TUser where id=1875151
Foreign key constraint fails for table `dawanka`.`Event`:
,
  CONSTRAINT `FK6wrxw84b767pp74tpxwjy8ky7` FOREIGN KEY (`user_id`) REFERENCES `TUser` (`id`)
Trying to delete or update in parent table, in index `PRIMARY` tuple:
DATA TUPLE: 45 fields;
 0: len 8; hex 80000000001c9ccf; asc         ;;
 1: len 6; hex 0000043d0553; asc    = S;;
 2: len 7; hex 2b00001295110d; asc +      ;;
 3: len 1; hex 00; asc  ;;
 4: len 1; hex 00; asc  ;;
 5: len 1; hex 01; asc  ;;
 6: len 1; hex 00; asc  ;;
 7: len 4; hex 80000000; asc     ;;
 8: len 11; hex 41204d616e2773204d616e; asc A Man's Man;;
 9: SQL NULL;
 10: len 1; hex 00; asc  ;;
 11: SQL NULL;
 12: SQL NULL;
 13: SQL NULL;
 14: len 11; hex 3135363139383031333536; asc 15619801356;;
 15: SQL NULL;
 16: SQL NULL;
 17: SQL NULL;
 18: len 1; hex 00; asc  ;;
 19: len 5; hex 999ef480dd; asc      ;;
 20: len 1; hex 00; asc  ;;
 21: len 1; hex 01; asc  ;;
 22: len 39; hex 77785f35303838616665632d323234642d343635612d616634342d333636663436333531353865; asc wx_5088afec-224d-465a-af44-366f4635158e;;
 23: len 131; hex 687474703a2f2f77782e716c6f676f2e636e2f6d6d6f70656e2f58654f4c516e55374b74545637674e744970704e335269636c38415744774673307431666b32534d7242445456476963503577496c71616b63543264726172744f61527178584a5a696264397170547569615a6963666a6b354f724959315655365945484a2f313332; asc http://wx.qlogo.cn/mmopen/XeOLQnU7KtTV7gNtIppN3Ricl8AWDwFs0t1fk2SMrBDTVGicP5wIlqakcT2drartOaRqxXJZibd9qpTuiaZicfjk5OrIY1VU6YEHJ/132;;
 24: len 0; hex ; asc ;;
 25: SQL NULL;
 26: SQL NULL;
 27: SQL NULL;
 28: SQL NULL;
 29: SQL NULL;
 30: len 8; hex 8000000000000000; asc         ;;
 31: len 9; hex 800000000000000000; asc          ;;
 32: SQL NULL;
 33: SQL NULL;
 34: SQL NULL;
 35: SQL NULL;
 36: SQL NULL;
 37: SQL NULL;
 38: SQL NULL;
 39: SQL NULL;
 40: SQL NULL;
 41: SQL NULL;
 42: SQL NULL;
 43: SQL NULL;
 44: SQL NULL;

(5) 看到了"FOREIGN KEY (user_id)"，项目中使用了外键，对于多年不用外键设计数据库得我，瞬间就敏感了起来，查看表结构才恍然大悟，数据库中每张表都有hibernate自动生成得外键FK***，这是导致单表得增删改查出现死锁的重要原因。
(6) 但此时得外键导致得死锁并非是由于外键未加索引导致的扫描发生的表锁，mysql中的hibernate外键关联已自动加上了外键索引，看下面这段日志

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 1043 page no 76968 n bits 128 index `PRIMARY` of table `dawanka`.`TUser` trx id 71385898 lock_mode X locks rec but not gap waiting
Record lock, heap no 45 PHYSICAL RECORD: n_fields 45; compact format; info bits 0

发现TUser表记录被加上了X锁，也称排他锁，看第二段日志

*** (2) TRANSACTION:
TRANSACTION 71385898, ACTIVE 6838 sec starting index read
mysql tables in use 1, locked 1
10 lock struct(s), heap size 2936, 9 row lock(s), undo log entries 2
MySQL thread id 1707165, OS thread handle 0x7f8aa2196700, query id 1295789031 111.230.128.98 cdb_outerroot updating
update TUser set ***(隐私信息) where id=2128399
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 1043 page no 76968 n bits 120 index `PRIMARY` of table `dawanka`.`TUser` trx id 71385898 lock mode S locks rec but not gap
Record lock, heap no 45 PHYSICAL RECORD: n_fields 45; compact format; info bits 0

发现TUser表记录被加上了S锁，也称虽是共享锁，但是只允许其他读操作，不允许写，因为是主键，虽然只锁定了行记录数；但是整个数据库中核心业务都有外键，平凡的更新和读写的锁冲突，最终导致了雪崩式的锁等待，锁等待的时间大于应用程序的响应时间，导致应用程序中线程等待，占用资源，最终呈现给用户的就是应用不可访问，一片白茫茫的页面。

优化方案：
(1) 删掉数据库所有外键，并由程序控制数据逻辑
(2) 修改hibernate配置文件，防止项目启动，自动被加外键" spring.jpa.hibernate.ddl-auto=disable "

总结问题

代码交接不全面，文档未整理，存在较多的滞后信息和遗漏信息；
项目代码SVN版本管理未做；
各环境变量分离未做到；
各环境的环境变量保持一致未做到；
前后端分离的项目硬生生的合并到tomcat中，未研究讨论前者的设计用途擅自更改架构设计；
并发问题根本原因在于数据库死锁，而需要将外键删除，并修改hibernate配置文件，不适用外键的数据库设计；

PS:其实我们团队是这整个项目中的丙方，替乙方填坑的团队。
后续问题，还在排查中... ...