Retained MutableEntityEntry leak in entity context causes application hang

whitingjr · April 18, 2018, 1:47pm

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

vlad · April 18, 2018, 1:59pm

Looking at the testsuite for EntityManager tests the EntityEntryContext will not be cleared after a Transaction.commit().

Why should the commit clear the EntityManager? There is a clear() method for that.

For instance, you can span an EntityManager over multiple successive JPA transactions.

Am I expected to re-open EntityManager occasionally to make this application stable?

Since you are running a batch processing task, the lifespan of an EnitityManager should span on one or more batches, but not for the entire duration of the batch processing task. You can either flush-clear-commit or just create a new EntityManager after processing every N items.

For more details about the best way to do batch processing with JPA and Hibernate, check out this article.

Sanne · April 18, 2018, 2:06pm

Hi Jeremy,

Vlad is right, a loop like the one in your code is not safe. You need to clear() the EntityManager if you want to ensure all state is removed.

Your expecation is reasonable but consider also that you might have a more complex domain model so you can’t trust such a pattern.

whitingjr · April 20, 2018, 11:28am

Hi,
Getting back just to say thanks for the suggestions.

Adding these two method calls did delay the exhaustion
.flush()
.clear()
but did not solve it. Only postponed the inevitable.

Only by implementing the second option of recycling the EntityManager did the live retained set remain small enough for FGCs to be productive.
The loader application is now stable.

vlad · April 20, 2018, 11:37am

If you think that clearing the EntityManager leaks entity objects, then you should open a Jira issue.

gsmet · May 3, 2018, 1:26pm

Hi @whitingjr

Any chance you could use the ORM test case template to show us your leak: https://github.com/hibernate/hibernate-test-case-templates/tree/master/orm/hibernate-orm-5 ?

That would be helpful.

whitingjr · May 15, 2018, 3:27pm

Further to my testing. I found this combination produced a stable bulk data loader application without needing to recycle EntityManager.

em.flush();
em.commit();
em.clear();

As far as I am concerned 5.2.16 does not need a JIRA.

whitingjr · May 15, 2018, 3:29pm

Thanks for pointing this out. In the situation of creating a reproducer needs to be provided it will be helpful.

Topic		Replies	Views
Java request taking 40-50MB memory Hibernate ORM	8	2741	March 30, 2018
Possible memory leak in Envers due to Narayana Transaction Reaper Hibernate ORM	5	997	April 17, 2018
Potential memory leak in Hibernate 6 ScrollableResultsConsumer Hibernate ORM	2	356	August 15, 2023
Excessive memory usage in org.hibernate.engine.internal.StatefulPersistenceContext Hibernate ORM	5	916	November 15, 2022
Queries appears in startup for each entity Hibernate Validator	0	640	April 26, 2021

Retained MutableEntityEntry leak in entity context causes application hang

Related Topics