Hi,
I using hibernate-core 5.2.25.Final as part of a bulk data loading application.
The application uses a local transaction to package each unit of work. The backend is a Postgresql database.
I am finding everything works well for a while. Using jstat I am seeing Full Garbage Collection (FGC) is reclaiming a decreasing percentage of tenured space.
Continued running of the application shows typical effects of a memory leak. See jstat output.
Timestamp S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
24.8 0.00 99.68 12.43 5.81 96.78 94.30 19 0.198 1 0.023 0.221
32.9 0.00 99.14 13.90 8.18 96.78 94.30 23 0.257 1 0.023 0.280
40.9 0.00 99.38 22.35 10.69 96.78 94.30 27 0.320 1 0.023 0.343
48.8 0.00 62.53 32.34 13.64 96.78 94.30 31 0.373 1 0.023 0.396
56.8 0.00 59.24 41.80 16.28 96.78 94.30 35 0.430 1 0.023 0.453
64.8 0.00 66.18 49.69 18.28 96.78 94.30 39 0.483 1 0.023 0.506
72.9 0.00 99.92 63.06 20.03 96.78 94.30 43 0.535 1 0.023 0.558
80.9 99.99 0.00 34.31 30.85 97.28 95.50 46 0.625 1 0.023 0.648
88.8 99.99 0.00 39.17 30.85 97.28 95.50 46 0.625 1 0.023 0.648
96.8 99.99 0.00 39.96 30.85 97.28 95.50 46 0.625 1 0.023 0.648
104.9 99.99 0.00 40.74 30.85 97.28 95.50 46 0.625 1 0.023 0.648
112.9 99.99 0.00 40.74 30.85 97.28 95.50 46 0.625 1 0.023 0.648
Timestamp S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
120.9 99.99 0.00 40.74 30.85 97.28 95.50 46 0.625 1 0.023 0.648
128.9 99.99 0.00 40.74 30.85 97.28 95.50 46 0.625 1 0.023 0.648
136.8 99.99 0.00 41.53 30.85 97.28 95.50 46 0.625 1 0.023 0.648
144.8 99.99 0.00 41.53 30.85 97.28 95.50 46 0.625 1 0.023 0.648
152.9 0.00 99.98 73.59 52.38 97.40 94.12 49 0.805 1 0.023 0.829
160.9 0.00 0.00 84.08 34.09 97.29 93.91 55 1.253 2 0.498 1.751
168.9 15.93 0.00 66.12 42.85 97.29 93.91 62 1.433 2 0.498 1.931
176.8 22.89 0.00 99.00 50.22 97.29 93.91 69 1.595 2 0.498 2.093
184.8 35.88 0.00 88.76 58.61 97.29 93.91 74 1.759 2 0.498 2.256
192.9 46.36 0.00 57.72 65.71 97.29 93.91 80 1.922 2 0.498 2.420
200.8 61.24 0.00 7.66 71.67 97.29 93.91 86 2.093 2 0.498 2.590
208.9 0.00 73.89 43.00 76.41 97.29 93.91 91 2.243 2 0.498 2.741
Timestamp S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
216.9 74.15 0.00 79.40 80.97 97.29 93.91 96 2.392 2 0.498 2.890
224.9 83.59 0.00 0.00 86.14 97.29 93.91 102 2.586 2 0.498 3.084
232.9 0.00 99.52 34.66 90.26 97.29 93.91 107 2.758 2 0.498 3.255
240.8 85.90 0.00 64.04 94.18 97.29 93.91 112 2.921 2 0.498 3.419
248.9 0.00 89.15 96.02 97.92 97.29 93.91 117 3.086 2 0.498 3.584
256.9 84.88 0.00 0.00 60.54 97.29 93.91 122 3.337 3 2.449 5.786
264.9 0.00 83.72 48.05 62.51 97.29 93.91 127 3.555 3 2.449 6.005
272.9 93.42 0.00 83.69 64.43 97.29 93.91 132 3.774 3 2.449 6.223
280.8 89.15 0.00 40.15 67.51 97.29 93.91 138 4.044 3 2.449 6.493
288.9 96.60 0.00 26.17 69.53 97.29 93.91 144 4.314 3 2.449 6.763
296.9 89.54 0.00 1.98 71.69 97.29 93.91 150 4.592 3 2.449 7.042
304.9 0.00 91.57 76.08 73.28 97.29 93.91 155 4.846 3 2.449 7.295
Timestamp S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
312.8 0.00 86.60 43.70 75.17 97.29 93.91 161 5.134 3 2.449 7.584
320.9 0.00 94.11 12.24 77.50 97.29 93.91 167 5.445 3 2.449 7.895
328.9 90.72 0.00 94.35 78.97 97.29 93.91 172 5.694 3 2.449 8.143
336.9 94.18 0.00 63.94 80.74 97.29 93.91 178 5.997 3 2.449 8.446
344.9 88.49 0.00 38.40 82.43 97.29 93.91 184 6.304 3 2.449 8.753
352.9 86.70 0.00 7.64 84.10 97.30 93.91 190 6.623 3 2.449 9.072
360.9 0.00 87.41 91.45 85.47 97.30 93.91 195 6.913 3 2.449 9.362
368.9 0.00 90.81 66.10 87.09 97.30 93.91 201 7.237 3 2.449 9.686
376.9 0.00 93.77 37.87 88.67 97.30 93.91 207 7.568 3 2.449 10.017
384.9 0.00 99.99 20.21 90.32 97.30 93.91 213 7.894 3 2.449 10.343
392.9 86.32 0.00 95.51 91.60 97.30 93.91 218 8.178 3 2.449 10.627
400.9 98.09 0.00 78.80 93.07 97.30 93.91 224 8.523 3 2.449 10.972
Timestamp S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
408.9 92.18 0.00 61.13 94.56 97.30 93.91 230 8.885 3 2.449 11.334
416.9 94.38 0.00 33.09 96.03 97.30 93.91 236 9.236 3 2.449 11.685
....
711.3 90.58 0.00 12.28 98.41 97.30 93.91 460 23.209 4 3.981 27.189
719.3 96.84 0.00 66.12 99.02 97.30 93.91 466 23.635 4 3.981 27.616
727.3 0.00 88.94 3.84 99.73 97.30 93.91 473 24.131 4 3.981 28.111
735.4 86.97 0.00 16.87 78.06 97.31 93.91 478 24.508 5 5.860 30.367
743.4 88.30 0.00 83.99 78.52 97.31 93.91 484 24.961 5 5.860 30.821
751.3 0.00 84.06 46.05 79.06 97.31 93.91 491 25.468 5 5.860 31.327
759.3 87.71 0.00 15.13 79.59 97.31 93.91 498 25.990 5 5.860 31.850
......
Timestamp S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
893.1 98.70 0.00 95.41 88.00 97.32 93.91 610 34.626 5 5.860 40.486
901.1 0.00 99.77 65.29 88.47 97.32 93.91 617 35.174 5 5.860 41.033
909.2 93.52 0.00 60.25 89.19 97.32 93.91 624 35.731 5 5.860 41.590
917.2 0.00 99.65 47.17 90.31 97.32 93.91 631 36.305 5 5.860 42.165
925.2 98.68 0.00 20.60 91.42 97.32 93.91 638 36.871 5 5.860 42.731
933.2 0.00 89.89 14.71 91.92 97.32 93.91 645 37.416 5 5.860 43.276
941.1 94.92 0.00 0.00 92.39 97.32 93.91 652 37.987 5 5.860 43.847
949.2 93.65 0.00 85.70 93.03 97.32 93.91 658 38.442 5 5.860 44.302
957.2 0.00 96.36 84.10 93.52 97.32 93.91 665 39.033 5 5.860 44.893
965.2 91.57 0.00 82.30 94.27 97.32 93.91 672 39.607 5 5.860 45.467
973.2 0.00 90.31 88.39 94.76 97.32 93.91 679 40.188 5 5.860 46.048
981.2 92.77 0.00 87.06 95.22 97.32 93.91 686 40.778 5 5.860 46.638
Timestamp S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
989.2 88.66 0.00 0.00 96.02 97.32 93.91 694 41.448 5 5.860 47.308
997.2 0.00 92.22 10.00 96.62 97.32 93.91 701 42.035 5 5.860 47.895
1005.2 96.38 0.00 12.09 97.77 97.32 93.91 708 42.649 5 5.860 48.509
1013.2 0.00 93.78 33.09 98.58 97.32 93.91 715 43.208 5 5.860 49.067
1021.2 86.65 0.00 56.03 99.44 97.32 93.91 722 43.773 5 5.860 49.633
1029.2 89.95 0.00 40.97 95.02 97.32 93.91 728 44.268 6 7.350 51.617
1037.2 0.00 82.45 58.45 96.58 97.33 93.91 735 44.864 6 7.350 52.214
1045.2 90.65 0.00 57.84 97.42 97.33 93.91 742 45.445 6 7.350 52.794
1053.2 0.00 93.06 72.82 98.29 97.33 93.91 749 46.039 6 7.350 53.389
1061.2 88.80 0.00 67.87 99.22 97.33 93.91 756 46.686 6 7.350 54.036
1069.2 93.97 0.00 41.35 96.86 97.33 93.91 762 47.198 7 8.767 55.964
1077.2 0.00 95.17 36.01 97.47 97.33 93.91 769 47.759 7 8.767 56.525
Timestamp S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
1085.2 98.42 0.00 42.41 98.28 97.33 93.91 776 48.371 7 8.767 57.137
1093.2 0.00 0.00 7.00 97.28 97.33 93.91 782 49.146 8 10.087 59.233
1101.2 85.44 0.00 14.95 98.82 97.33 93.91 789 49.738 8 10.087 59.825
1109.2 51.54 99.99 100.00 99.05 97.33 93.91 795 50.197 9 11.435 61.633
1117.2 0.00 99.79 87.98 98.29 97.33 93.91 800 50.776 10 12.717 63.493
1125.2 0.00 99.73 26.11 98.29 97.33 93.91 808 51.500 10 12.717 64.217
1133.2 94.55 0.00 96.25 99.02 97.33 93.91 815 52.133 10 12.717 64.851
1141.2 90.83 0.00 44.60 99.46 97.33 93.91 823 52.865 10 12.717 65.582
1149.2 0.00 89.42 0.00 99.85 97.33 93.91 830 53.520 11 12.717 66.237
1157.2 0.00 3.65 100.00 99.99 97.33 93.91 830 53.520 12 17.720 71.240
1165.2 0.00 0.00 100.00 99.98 97.33 93.91 830 53.520 13 23.742 77.261
1173.2 0.00 0.00 100.00 99.98 97.33 93.91 830 53.520 14 29.597 83.116
Timestamp S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
1181.2 0.00 0.00 100.00 100.00 97.33 93.91 830 53.520 16 39.848 93.368
1189.2 0.00 0.00 69.53 99.99 97.33 93.91 830 53.520 16 47.771 101.291
Seeing FGC increasing in frequency towards the end of the sample.
After that point the loading ceases to operate. The application needed killing.
I took a heap dump. Before the process became un-servicable.
Whith the heap dump I used the Heap Analyzer in Eclipse IDE.
The Leak Suspects Report showed MutableEntityEntry being a leak suspect.
Finding the way to the GC root shows this simplified stack of references:
StatefulPerstenceContext.entityEntryContext
EntityEntryContext.nonEnhancedEntityXref
IdentityHashMap.table
EntityEntryContext$ManagedEntityImpl
.entityEntry MutableEntityEntry
.entityInstance VehicleDescription
.next EntityEntryContext$ManagedEntityImpl
.previous EntityEntryContext$ManagedEntityImpl
Looking at the testsuite for EntityManager tests the EntityEntryContext will not be cleared after a Transaction.commit(). Test EntityManagerTest.testEntityManager() checks that.
This is a very simplified example of the code
EntityManager em = .....
for (....){
Transaction t = em.getTransaction();
t.begin()
Person p = new ....
p.set()
p.addChild(Child);
em.persist(p);
t.commit()
}
em.close();
The application has a mixture of Entities. Some having associations. Uni or Bi directional.
I am expecting Entities no longer used to be removed/expired, eventually. It is true that most are removed from the context after a commit. But I am seeing some remain. Over time the number increases. Eventually causing the program to hang.
Is this what’s expected to happen ?
Am I expected to re-open EntityManager occasionally to make this application stable ?
Regards,
Jeremy