java - 卡住 Tomcat 线程。 EclipseLink 乐观锁定

Question

我在 Ubuntu 服务器上使用 EclipseLink v2.7.2 和 Mysql 数据库(innodb 表)运行 Java 应用程序。由于某些线程需要越来越长的时间才能完成，该应用程序最近失败了。最后，我开始收到错误:

WARNING: Connection has been abandoned PooledConnection[com.mysql.jdbc.JDBC4Connection@19e0dcec]:java.lang.Exception

如果我不重启服务器，它最终会崩溃。

UBUNTU 中的“top”命令显示 100% CPU 使用率:

top screenshot

另外，我查看了mysql，得到了下一个信息:

mysql> SHOW ENGINE INNODB STATUS\G
*************************** 1. row ***************************
 Type: InnoDB
  Name:
Status:
=====================================
2018-11-09 11:38:56 0x7f81cc1a9700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 37 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 216408 srv_active, 0 srv_shutdown, 437923 srv_idle
srv_master_thread log flush and writes: 654230
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 338439
OS WAIT ARRAY INFO: signal count 382398
RW-shared spins 0, rounds 598829, OS waits 248958
RW-excl spins 0, rounds 2260413, OS waits 18158
RW-sx spins 9817, rounds 216149, OS waits 2550
Spin rounds per wait: 598829.00 RW-shared, 2260413.00 RW-excl, 22.02 RW-sx
------------------------
LATEST FOREIGN KEY ERROR
------------------------
2018-11-07 15:51:31 0x7f81cc331700 Transaction:
TRANSACTION 38673943, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
22 lock struct(s), heap size 1136, 10 row lock(s), undo log entries 9
MySQL thread id 280, OS thread handle 140195453409024, query id 16450494 localhost 127.0.0.1 user_php update
INSERT INTO eventos_faccion (id, cantidad, fecha, param, tipo, faccion, objeto, tecnologia) VALUES (370684, 1, 1541602291871, 'id=233962, tipo=LANCE_S en [Base] id: 6026, nombre: City prime', 'LIBERAR_TRABAJO', 10, null, null)
Foreign key constraint fails for table `db`.`eventos_faccion`:
,
  CONSTRAINT `fk_eventos_faccion_facciones2` FOREIGN KEY (`tipo`) REFERENCES `tipos_eventos_faccion` (`id_alpha`) ON DELETE CASCADE ON UPDATE CASCADE
Trying to add in child table, in index fk_eventos_faccion_facciones2_idx tuple:
DATA TUPLE: 2 fields;
 0: len 15; hex 4c4942455241525f54524142414a4f; asc WORK;;
 1: len 8; hex 800000000005a7fc; asc         ;;

But in parent table `db`.`tipos_eventos_faccion`, in index PRIMARY,
the closest match we can find is record:
PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 13; hex 50414e54414c4c415f42415345; asc PANTALLA_BASE;;
 1: len 6; hex 0000020c2669; asc     &i;;
 2: len 7; hex fd00000150050d; asc     P  ;;

------------
TRANSACTIONS
------------
Trx id counter 38832116
Purge done for trx's n:o < 38831849 undo n:o < 0 state: running but idle
History list length 13
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421670725406944, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421670725399584, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421670725394064, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421670725411544, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421670725410624, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421670725408784, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421670725403264, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421670725392224, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421670725402344, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421670725404184, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421670725393144, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421670725397744, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421670725394984, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 38831881, ACTIVE 6498 sec
3 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 415, OS thread handle 140195452004096, query id 21620015 localhost 127.0.0.1 user_php
Trx read view will not see trx with id >= 38831882, sees < 38831819
---TRANSACTION 38831871, ACTIVE 7058 sec
3 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 404, OS thread handle 140195450599168, query id 21619851 localhost 127.0.0.1 user_php
Trx read view will not see trx with id >= 38831872, sees < 38831819
---TRANSACTION 38831861, ACTIVE 7430 sec
3 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 412, OS thread handle 140195080742656, query id 21620173 localhost 127.0.0.1 user_php
Trx read view will not see trx with id >= 38831862, sees < 38831819
---TRANSACTION 38831858, ACTIVE 7454 sec
3 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 410, OS thread handle 140195452204800, query id 21620222 localhost 127.0.0.1 user_php
Trx read view will not see trx with id >= 38831859, sees < 38831819
---TRANSACTION 38831847, ACTIVE 7501 sec
3 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 401, OS thread handle 140195453007616, query id 21620390 localhost 127.0.0.1 user_php
Trx read view will not see trx with id >= 38831848, sees < 38831819
---TRANSACTION 38831845, ACTIVE 7505 sec
3 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 416, OS thread handle 140195317356288, query id 21620557 localhost 127.0.0.1 user_php
Trx read view will not see trx with id >= 38831846, sees < 38831819
---TRANSACTION 38831838, ACTIVE 7595 sec
3 lock struct(s), heap size 1136, 1 row lock(s), undo log entries 1
MySQL thread id 417, OS thread handle 140195080541952, query id 21620018 localhost 127.0.0.1 user_php
Trx read view will not see trx with id >= 38831839, sees < 38831819
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 0
237906 OS file reads, 4750976 OS file writes, 2006899 OS fsyncs
0.08 reads/s, 16384 avg bytes/read, 0.54 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 2468, seg size 2470, 34751 merges
merged operations:
 insert 108525, delete mark 42752, delete 24784
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 34673, node heap has 91 buffer(s)
Hash table size 34673, node heap has 53 buffer(s)
Hash table size 34673, node heap has 309 buffer(s)
Hash table size 34673, node heap has 77 buffer(s)
Hash table size 34673, node heap has 102 buffer(s)
Hash table size 34673, node heap has 74 buffer(s)
Hash table size 34673, node heap has 21 buffer(s)
Hash table size 34673, node heap has 60 buffer(s)
9.41 hash searches/s, 2.97 non-hash searches/s
---
LOG
---
Log sequence number 64961000248
Log flushed up to   64961000248
Pages flushed up to 64961000248
Last checkpoint at  64961000239
0 pending log flushes, 0 pending chkp writes
979206 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 137428992
Dictionary memory allocated 2634757
Buffer pool size   8191
Free buffers       1024
Database pages     6380
Old database pages 2335
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1401959, not young 19003541
0.41 youngs/s, 145.54 non-youngs/s
Pages read 237568, created 12099, written 3517421
0.08 reads/s, 0.41 creates/s, 0.54 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 519 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 6380, unzip_LRU len: 0
I/O sum[23]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
7 read views open inside InnoDB
Process ID=26906, Main thread ID=140195374556928, state: sleeping
Number of rows inserted 2906426, updated 4070202, deleted 2302355, read 1113088516
52.35 inserts/s, 0.00 updates/s, 0.00 deletes/s, 52.38 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set (0,00 sec)

这是tomcat配置数据源

<Resource 
          name="ds/mysql" 
          auth="Container" 
          type="javax.sql.DataSource" 
          maxActive="100" 
          maxIdle="30" 
          maxWait="100"
          removeAbandoned="true" 
          removeAbandonedTimeout="90" 
          logAbandoned="true" 
          validationQuery="select 1"
          testOnBorrow="true"
          username="user" 
          password="pass"
          jdbcInterceptors="ConnectionState;StatementFinalizer;ResetAbandonedTimer"       
          driverClassName="com.mysql.jdbc.Driver" 
          factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
          url="jdbc:mysql://127.0.0.1:3306/db?useSSL=false"/>

检查 Tomcat 管理器我发现了这些数据:

JVM
Free memory: 191.90 MB Total memory: 2014.75 MB Max memory: 2014.75 MB

Memory Pool Type    Initial Total   Maximum Used
CMS Old Gen Heap memory 1715.25 MB  1715.25 MB  1715.25 MB  1715.24 MB (99%)
Par Eden Space  Heap memory 266.25 MB   266.25 MB   266.25 MB   107.59 MB (40%)
Par Survivor Space  Heap memory 33.25 MB    33.25 MB    33.25 MB    0.00 MB (0%)
Code Cache  Non-heap memory 2.43 MB 95.06 MB    240.00 MB   92.42 MB (38%)
Compressed Class Space  Non-heap memory 0.00 MB 9.01 MB 1024.00 MB  7.65 MB (0%)
Metaspace   Non-heap memory 0.00 MB 99.24 MB    -0.00 MB    88.30 MB

我读到这个 ​​99% 的内存使用率可能与内存泄漏有关

Answer 1

首先我意识到内存有问题。如果您查看显示“top”程序的屏幕截图，内存使用率为 99%。

一开始我以为可能是分配给堆的内存太少了，于是尝试增加，但很快我就意识到是“内存泄漏”。一旦 tomcat 服务器开始耗尽内存，线程之间的锁就会变得越来越普遍。锁定那里的症状，内存是原因。

在使用 VisualVM 程序并在“堆转储”中生成后，我使用 MAT 内存分析程序 来查看问题所在。我发现系统在缓冲区中存储 JSP 页面时使用了非常多的内存。

在StackOverflow和google里潜了好几天，发现在Tomcat中可以修改一些系统变量来限制buffer的使用。此代码必须放在 catalina.properties 文件中。

org.apache.jasper.runtime.BodyContentImpl.LIMIT_BUFFER=true

此外，更多指令帮助Tomcat 控制jsp 页面。我在 web.xml 文件中将其添加到我的生产服务器。

<servlet>   
    <init-param>
        <param-name>development</param-name>
        <param-value>false</param-value>
    </init-param>
    <init-param>
        <param-name>modificationTestInterval</param-name>
        <param-value>60</param-value>
    </init-param>
    <init-param>
        <param-name>genStringAsCharArray</param-name>
        <param-value>true</param-value>
    </init-param>
    <init-param>
        <param-name>trimSpaces</param-name>
        <param-value>true</param-value>
    </init-param>       
    <init-param>
        <param-name>enablePooling</param-name>
        <param-value>false</param-value>
    </init-param>   
<servlet>

我花了几天时间才找到解决方案，希望这对其他人有帮助。