Bug #2569
memory leaks of procedure, buffer, handle resources
100%
tt_buffer_gc_shortest_paths.txt 
(14 KB)
ca_upd20150503a.zip (98.5 KB)
ca_upd20150503b.zip (99.2 KB)
ca_upd20150504a.zip (125 KB)
ecf_upd20150517a.zip (409 KB)
ecf_upd20150518a.zip (409 KB)
ecf_upd20150518b.zip (408 KB)
History
#1 Updated by Eric Faulhaber about 9 years ago
See #2555 for the beginning of this discussion, which diverged from the original focus of that issue.
#2 Updated by Eric Faulhaber about 9 years ago
A related matter is that since all dynamically defined temp-tables are created at global scope, we have additional, strong references to ExternalProgramWrapper instances which have lived beyond their intended lifespan, via this reference chain:
Class Name | Ref. Objects | Shallow Heap | Ref. Shallow Heap | Retained Heap
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| | | |
java.lang.Thread @ 0x71e2801b8 Conversation [00000003:customer_appserver] Native Stack, Thread | 17,790 | 104 | 4,838,880 | 30,352
'- <Java Local> com.goldencode.p2j.net.DirectSession @ 0x71e280918 | 17,790 | 32 | 4,838,880 | 128
'- context com.goldencode.p2j.security.SecurityContext @ 0x646dd7d68 | 17,790 | 72 | 4,838,880 | 86,258,152
'- tokenMap java.util.HashMap @ 0x646dd7e40 | 17,790 | 48 | 4,838,880 | 86,257,896
'- table java.util.HashMap$Entry[128] @ 0x73e4c0208 | 17,790 | 528 | 4,838,880 | 86,257,848
|- [74] java.util.HashMap$Entry @ 0x646dda068 | 16,425 | 32 | 4,467,600 | 83,240
| '- value com.goldencode.p2j.security.ContextLocal$Wrapper @ 0x646dda088 | 16,425 | 24 | 4,467,600 | 83,208
| '- contents com.goldencode.p2j.util.TransactionManager$WorkArea @ 0x646dda0a0 | 16,425 | 104 | 4,467,600 | 83,184
| '- globalBlock com.goldencode.p2j.util.BlockDefinition @ 0x646dda400 | 16,425 | 80 | 4,467,600 | 81,144
| '- finalizables java.util.ArrayList @ 0x646dda468 | 16,425 | 24 | 4,467,600 | 81,040
| '- elementData java.lang.Object[6246] @ 0x72c43c128 | 16,425 | 25,000 | 4,467,600 | 81,016
| |- [109] com.goldencode.p2j.persist.TemporaryBuffer @ 0x60c3b9bb8 | 13 | 272 | 3,536 | 2,840
| | '- tempTableRef com.goldencode.p2j.persist.TempTableBuilder @ 0x60c3b1138 | 12 | 80 | 3,264 | 6,624
| | '- instProc com.goldencode.p2j.util.handle @ 0x60c3b1188 | 12 | 16 | 3,264 | 6,040
| | '- value com.goldencode.p2j.util.ExternalProgramWrapper @ 0x60c3b1198 | 12 | 24 | 3,264 | 6,024
| | '- referent com.something.server.common.Apictrl0 @ 0x60c3b11b0| 12 | 320 | 3,264 | 5,976
| | |- ttmap com.goldencode.p2j.persist.$__Proxy18 @ 0x60c3b1990 | 1 | 64 | 272 | 200
| | |- bufttxmltrans com.goldencode.p2j.persist.$__Proxy21 @ 0x60c3b32f8 | 1 | 64 | 272 | 200
| | |- bufsubTtsearch com.goldencode.p2j.persist.$__Proxy20 @ 0x60c3b52c0 | 1 | 64 | 272 | 200
| | |- ttapiprocs com.goldencode.p2j.persist.$__Proxy17 @ 0x60c3b1640 | 1 | 64 | 272 | 200
| | |- ttsearchBuf2 com.goldencode.p2j.persist.$__Proxy20 @ 0x60c3b4e28 | 1 | 64 | 272 | 200
| | |- bufTtxmltrans com.goldencode.p2j.persist.$__Proxy21 @ 0x60c3b4ad8 | 1 | 64 | 272 | 200
| | |- ttsearch com.goldencode.p2j.persist.$__Proxy20 @ 0x60c3b2030 | 1 | 64 | 272 | 200
| | |- ttorder com.goldencode.p2j.persist.$__Proxy16 @ 0x60c3b12f0 | 1 | 64 | 272 | 200
| | |- ttxmltrans com.goldencode.p2j.persist.$__Proxy21 @ 0x60c3b2420 | 1 | 64 | 272 | 200
| | |- ttfiltercriteria com.goldencode.p2j.persist.$__Proxy30 @ 0x60c3b2920 | 1 | 64 | 272 | 200
| | |- ttfilter com.goldencode.p2j.persist.$__Proxy19 @ 0x60c3b1ce0 | 1 | 64 | 272 | 200
| | |- bufparentttsearch com.goldencode.p2j.persist.$__Proxy20 @ 0x60c3b2fa8 | 1 | 64 | 272 | 200
| | '- Total: 12 entries | | | |
| |- [145] com.goldencode.p2j.persist.TemporaryBuffer @ 0x60c391fd0 | 13 | 272 | 3,536 | 2,840
| |- [91] com.goldencode.p2j.persist.TemporaryBuffer @ 0x74effcb88 | 13 | 272 | 3,536 | 2,840
| |- [127] com.goldencode.p2j.persist.TemporaryBuffer @ 0x74ef8e5e0 | 13 | 272 | 3,536 | 2,840
| |- [37] com.goldencode.p2j.persist.TemporaryBuffer @ 0x75723fd08 | 13 | 272 | 3,536 | 2,840
| |- [28] com.goldencode.p2j.persist.TemporaryBuffer @ 0x757242698 | 13 | 272 | 3,536 | 2,840
| |- [19] com.goldencode.p2j.persist.TemporaryBuffer @ 0x757245028 | 13 | 272 | 3,536 | 2,840
| |- [82] com.goldencode.p2j.persist.TemporaryBuffer @ 0x7572484f0 | 13 | 272 | 3,536 | 2,840
| |- [73] com.goldencode.p2j.persist.TemporaryBuffer @ 0x75724ae70 | 13 | 272 | 3,536 | 2,840
| |- [64] com.goldencode.p2j.persist.TemporaryBuffer @ 0x75724d800 | 13 | 272 | 3,536 | 2,840
| |- [55] com.goldencode.p2j.persist.TemporaryBuffer @ 0x757250190 | 13 | 272 | 3,536 | 2,840
| |- [118] com.goldencode.p2j.persist.TemporaryBuffer @ 0x60c3ba7c0 | 13 | 272 | 3,536 | 2,840
| |- [46] com.goldencode.p2j.persist.TemporaryBuffer @ 0x75723d378 | 13 | 272 | 3,536 | 2,840
| |- [154] com.goldencode.p2j.persist.TemporaryBuffer @ 0x60c3bc7c8 | 13 | 272 | 3,536 | 2,840
| |- [100] com.goldencode.p2j.persist.TemporaryBuffer @ 0x60b68aa70 | 13 | 272 | 3,536 | 2,840
| |- [136] com.goldencode.p2j.persist.TemporaryBuffer @ 0x60c365c70 | 13 | 272 | 3,536 | 2,840
| |- [5287] com.goldencode.p2j.persist.TemporaryBuffer @ 0x6b4a2d620 | 12 | 272 | 3,264 | 1,688
| |- [2038] com.goldencode.p2j.persist.TemporaryBuffer @ 0x5dc4c4dc8 | 12 | 272 | 3,264 | 1,752
| |- [588] com.goldencode.p2j.persist.TemporaryBuffer @ 0x61d36a378 | 12 | 272 | 3,264 | 1,736
| |- [5593] com.goldencode.p2j.persist.TemporaryBuffer @ 0x5c243d968 | 12 | 272 | 3,264 | 2,072
| |- [2418] com.goldencode.p2j.persist.TemporaryBuffer @ 0x612a52630 | 12 | 272 | 3,264 | 1,544
| |- [3154] com.goldencode.p2j.persist.TemporaryBuffer @ 0x72e46c738 | 12 | 272 | 3,264 | 1,496
| |- [4530] com.goldencode.p2j.persist.TemporaryBuffer @ 0x6cf6c9118 | 12 | 272 | 3,264 | 1,688
| |- [4920] com.goldencode.p2j.persist.TemporaryBuffer @ 0x69adb0030 | 12 | 272 | 3,264 | 1,608
| |- [5703] com.goldencode.p2j.persist.TemporaryBuffer @ 0x69eb99720 | 12 | 272 | 3,264 | 1,544
| '- Total: 25 of 2,533 entries; 2,508 more | | | |
|- [33] java.util.HashMap$Entry @ 0x754ac0510 | 1,331 | 32 | 362,032 | 14,133,648
|- [68] java.util.HashMap$Entry @ 0x6473a36f8 | 34 | 32 | 9,248 | 53,568
'- Total: 3 entries | | | |
com.goldencode.p2j.persist.TemporaryBuffer @ 0x69a79cf88 Native Stack | 25 | 272 | 6,800 | 1,576
com.goldencode.p2j.util.ExternalProgramWrapper @ 0x74136b038 Native Stack | 13 | 24 | 3,536 | 24
com.goldencode.p2j.persist.$__Proxy20 @ 0x74136abd8 Native Stack | 12 | 64 | 3,264 | 200
java.util.HashMap$Entry @ 0x5c12d5f00 Native Stack | 3 | 32 | 816 | 32
com.goldencode.p2j.persist.$__Proxy21 @ 0x74136b188 Native Stack | 2 | 64 | 544 | 200
java.util.HashMap$Entry @ 0x6d425e450 Native Stack | 1 | 32 | 272 | 32
com.goldencode.p2j.persist.$__Proxy928 @ 0x74136b050 Native Stack | 1 | 64 | 272 | 272
java.util.HashMap$Entry @ 0x5c12d6010 Native Stack | 1 | 32 | 272 | 32
com.goldencode.p2j.persist.$__Proxy928 @ 0x74136b2c0 Native Stack | 1 | 64 | 272 | 200
com.goldencode.p2j.persist.$__Proxy926 @ 0x74136ad88 Native Stack | 1 | 64 | 272 | 200
java.util.HashMap$Entry @ 0x5c12d6928 Native Stack | 1 | 32 | 272 | 32
com.goldencode.p2j.persist.$__Proxy30 @ 0x74136ae88 Native Stack | 1 | 64 | 272 | 200
com.goldencode.p2j.persist.$__Proxy20 @ 0x74136ab50 Native Stack | 1 | 64 | 272 | 200
com.goldencode.p2j.persist.$__Proxy926 @ 0x74136aee0 Native Stack | 1 | 64 | 272 | 200
com.goldencode.p2j.persist.QueryWrapper @ 0x74136b228 Native Stack | 1 | 80 | 272 | 344
Total: 16 entries | 17,855 | 1,120 | 4,856,560 |
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
This occurs because of our TM finalizable design, regardless of whether the temp-table buffers are part of a persistent procedure, so we get many more temp-table buffers surviving an external procedure than actually need to be persistent.
We don't necessarily need to make this part of the current discussion, but I wanted to document it so I don't lose track.
#3 Updated by Eric Faulhaber about 9 years ago
- File tt_buffer_gc_shortest_paths.txt added
For better readability of the content in the last last post, please see attached file.
#4 Updated by Constantin Asofiei about 9 years ago
Eric Faulhaber wrote:
A related matter is that since all dynamically defined temp-tables are created at global scope, we have additional, strong references to
ExternalProgramWrapperinstances which have lived beyond their intended lifespan, via this reference chain:
I don't understand something: aren't the TemporaryBuffer and TempTableBuilder instances you mention supposed to be cleaned up at some point? Are they dynamic or static?
The reference you mention is for the INSTANTIATING-PROCEDURE attribute - all resources know their creator. But I think you are correct, and there is a problem: as a dynamic resource can survive its creator, the INSTANTIATING-PROCEDURE for these resources gets set to unknown when the persistent proc which created it gets deleted.
The fix for this is a little more complicated, as it looks like each external program needs to track ALL resources created within it, not just static ones - so their INSTANTIATING-PROCEDURE attr can be set to unknown, when the external program gets deleted.
#5 Updated by Constantin Asofiei about 9 years ago
Eric Faulhaber wrote in #2555 note 53:
I tried a few tests and spent a lot of time in the debugger tonight. We still have otherwise unreachable instances of
ExternalProgramWrappercollecting inidResourcesandresourceIds. The problem is that everywhere we call theExternalProgramWrapperc'tor, we potentially add an entry into these maps. SinceTransparentWrapperforwardshashCodeandequalscalls to the referent, we are at least not creating new entries if another instance has the same referent. However, the problem is we don't ever callhandle.removeResourcefor most of these instances. Most of the handles which reference them eventually go out of scope and are no longer referenced by application code, but the strong references to their values remain in the context-local maps.
I'll add some logging to track cases when the handle.resourceId is called for an invalid resource... maybe we can find exactly who/when re-attaches these.
I did turn on FINE logging for
ProcedureManager(I changed the LOG initializer to useProcedureManager.class.getName(), btw). The only lines it logged were:[05/03/2015 03:42:47 EDT] (com.goldencode.p2j.util.ProcedureManager:FINE) Postponing deletion of procedure common/aapsvpr0.p [05/03/2015 03:42:47 EDT] (com.goldencode.p2j.util.ProcedureManager$WorkArea:FINE) Processing postponed delete for procedure common/aapsvpr0.p has failed
That should have bee has passed, I've got the texts backwards somehow.
BTW, this is a general problem which affects other
WrappedResourceimplementors as well, e.g.,BufferFieldImpl,StaticTempTable,TempTableBuilder, etc. These are not huge memory consumers, but there are many of them in the context-local maps. I didn't notice them there before; I think it is a side effect of this update.
Do you mean the handle$WorkArea context-local maps or something else?
#6 Updated by Eric Faulhaber about 9 years ago
Constantin Asofiei wrote:
I don't understand something: aren't the
TemporaryBufferandTempTableBuilderinstances you mention supposed to be cleaned up at some point? Are they dynamic or static?
The resources being held at the ends of these GC chains are static temp-table buffers which are held by the converted program instances wrapped in ExternalProgramWrapper objects. These seem to be held in place by dynamic temp table buffers, which have the strong reference chain: TM@WorkArea.finalizables -> TemporaryBuffer.tempTableRef -> TempTableBuilder.instProc -> handle.value -> ExternalProgramWrapper.referent -> converted business logic -> proxies to static temp-tables.
What I don't yet understand is why these dynamic temp-table buffers are still in TM$WorkArea.finalizables. Perhaps the code I wrote (not yet checked in) to remove them from the global finalizables list via BufferImpl.resourceDelete is never invoked. This might be the case if the corresponding, dynamic 4GL objects are not being deleted properly by business logic, which would represent leaks in the original code, too...
#7 Updated by Constantin Asofiei about 9 years ago
- File ca_upd20150503a.zip added
Eric Faulhaber wrote:
Constantin Asofiei wrote:
I don't understand something: aren't the
TemporaryBufferandTempTableBuilderinstances you mention supposed to be cleaned up at some point? Are they dynamic or static?The resources being held at the ends of these GC chains are static temp-table buffers which are held by the converted program instances wrapped in
ExternalProgramWrapperobjects. These seem to be held in place by dynamic temp table buffers, which have the strong reference chain:TM@WorkArea.finalizables -> TemporaryBuffer.tempTableRef -> TempTableBuilder.instProc -> handle.value -> ExternalProgramWrapper.referent -> converted business logic -> proxies to static temp-tables.
OK, but what is relevant for me is that the instProc is referencing a (I think) deleted procedure. Keeping all the procedure's resources (static or not) with it is just a side-effect.
Are there any other references to the proxies to static temp-tables (the end of the chain)? If not, then the attached update should solve this problem... and allow the external programs to be GC'ed, once they are deleted (as they will no longer be referenced by the instProc field).
Well, I think you are correct, there is a problem there. When adding things to the global scope, you need to manually remove it from there. I see these cases which might be problematic:What I don't yet understand is why these dynamic temp-table buffers are still in
TM$WorkArea.finalizables. Perhaps the code I wrote (not yet checked in) to remove them from the global finalizables list viaBufferImpl.resourceDeleteis never invoked. This might be the case if the corresponding, dynamic 4GL objects are not being deleted properly by business logic, which would represent leaks in the original code, too...
TemporaryBuffer.openScope:2849// A global temp table buffer is cleaned up when the context ends. TransactionManager.registerFinalizable(multiplexer, true);
RecordBuffer.openScopeAt:5825// Register this buffer as a Finalizable with the TM, so that its // finished method is called when this buffer scope is about to close. TransactionManager.registerFinalizableAt(blockDepth, this);TemporaryBuffer.openScopeAt:2891// register for temp table cleanup Multiplexer multiplexer = new Multiplexer(); TransactionManager.registerFinalizableAt(blockDepth, multiplexer); // register for no-undo validation if outside an application transaction if (!isUndoable() && !TransactionManager.isTransaction()) { TransactionManager.registerFinalizableAt(blockDepth, new NoUndoValidator()); }
All of these need to be cleaned up when the buffer gets deleted. And I don't think the right place is in BufferImpl.resourceDelete - the proper place should be in the RecordBuffer.finishedImpl and TemporaryBuffer.finishedImpl, so that all Finalizable instances get removed from the global scope...
#8 Updated by Constantin Asofiei about 9 years ago
I've just noticed the handle's logging for invalid resources is too noisy, it gets logged for valid cases (as when a resource is just created, before it gets valid)... please remove this before starting testing:
if (!resource.valid())
{
if (LOG.isLoggable(Level.WARNING))
{
LOG.log(Level.WARNING,
"You are creating a new ID for an invalid resource " +
resource.getClass().getName() + "!",
new Exception());
}
}
#9 Updated by Eric Faulhaber about 9 years ago
Constantin Asofiei wrote:
Are there any other references to the
proxies to static temp-tables(the end of the chain)? If not, then the attached update should solve this problem... and allow the external programs to be GC'ed, once they are deleted (as they will no longer be referenced by the instProc field).
Yes (speaking before your 0503a update, which I am testing now): besides the reference chain from TM$WorkArea.finalizables, the ExternalProgramWrapper references in idResources and resourceIds are still all there, and thus keep all these same static DMO proxies alive. I may have misunderstood your changes, but it didn't seem from my review that 0503a addresses this. Anyway, I'll let you know how the test goes...
[...] And I don't think the right place is in
BufferImpl.resourceDelete- the proper place should be in theRecordBuffer.finishedImplandTemporaryBuffer.finishedImpl, so that all Finalizable instances get removed from the global scope...
Yes, that's actually how I did it, but clearly there's a problem with my implementation, as the MAT output shows.
#10 Updated by Eric Faulhaber about 9 years ago
The 0503a appears to be working as designed with respect to cleaning up the reference chain previously pinned by TempTableBuilder.instProc, in that the handle instances stored in that field are cleared, AFAICT.
However, we are still holding lots of objects in the idResources and resourceIds maps (more than before, because now every WrappedResource instance is stored in there upon construction). I think we need to reconsider the approach introduced with 0502b.
#11 Updated by Constantin Asofiei about 9 years ago
Eric Faulhaber wrote:
The 0503a appears to be working as designed with respect to cleaning up the reference chain previously pinned by
TempTableBuilder.instProc, in that thehandleinstances stored in that field are cleared, AFAICT.However, we are still holding lots of objects in the
idResourcesandresourceIdsmaps (more than before, because now everyWrappedResourceinstance is stored in there upon construction). I think we need to reconsider the approach introduced with 0502b.
Is this from an intermediate state or final state, when everything should have cleaned up? I'll look for a lazy approach of setting the ID, only when the resource ID gets called explicitly.
#12 Updated by Constantin Asofiei about 9 years ago
- File ca_upd20150503b.zip added
Eric Faulhaber wrote:
[...] And I don't think the right place is in
BufferImpl.resourceDelete- the proper place should be in theRecordBuffer.finishedImplandTemporaryBuffer.finishedImpl, so that all Finalizable instances get removed from the global scope...Yes, that's actually how I did it, but clearly there's a problem with my implementation, as the MAT output shows.
Please try this version. I think it might solve your problem: previously the postponed procedure delete was being done too early, and static resources were not being deleted properly.
I've also added lazy setting of the resource's ID, so the handle's resource-related maps should not explode. The warning is now OK to be used - handle.resourceID should never be called for an invalid resource and with no ID previously set.
#13 Updated by Eric Faulhaber about 9 years ago
Constantin Asofiei wrote:
Is this from an intermediate state or final state, when everything should have cleaned up?
I take the heap dumps before disconnecting the BPM (so the app server connection is still up), but after all the tests have completed and the test harness has stopped running. So, it is from a final state.
#14 Updated by Eric Faulhaber about 9 years ago
Constantin Asofiei wrote:
Please try this version. I think it might solve your problem: previously the postponed procedure delete was being done too early, and static resources were not being deleted properly.
I've also added lazy setting of the resource's ID, so the handle's resource-related maps should not explode. The warning is now OK to be used - handle.resourceID should never be called for an invalid resource and with no ID previously set.
This looks promising on review; will let you know how testing goes. Thanks!
#15 Updated by Eric Faulhaber about 9 years ago
[05/03/2015 17:08:55 EDT] (com.goldencode.p2j.util.handle:WARNING) You are creating a new ID for an invalid resource com.goldencode.p2j.util.ExternalProgramWrapper!
java.lang.Exception
at com.goldencode.p2j.util.handle.resourceId(handle.java:515)
at com.goldencode.p2j.util.handle.toString(handle.java:2280)
at com.goldencode.p2j.util.handle.toString(handle.java:2257)
at com.goldencode.p2j.util.handle.toStringMessage(handle.java:2294)
at com.goldencode.p2j.persist.type.AbstractWrapperUserType.toString(AbstractWrapperUserType.java:295)
at com.goldencode.p2j.persist.type.HandleUserType.bindNonNull(HandleUserType.java:141)
at com.goldencode.p2j.persist.type.AbstractWrapperUserType.nullSafeSet(AbstractWrapperUserType.java:278)
at com.goldencode.p2j.persist.type.HandleUserType.nullSafeSet(HandleUserType.java:27)
at org.hibernate.type.CustomType.nullSafeSet(CustomType.java:155)
at org.hibernate.persister.entity.AbstractEntityPersister.dehydrate(AbstractEntityPersister.java:2747)
at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3152)
at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3087)
at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3416)
at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:140)
at org.hibernate.engine.spi.ActionQueue.execute(ActionQueue.java:362)
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:354)
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:276)
at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:326)
at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:52)
at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1213)
at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:402)
at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.beforeTransactionCommit(JdbcTransaction.java:101)
at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:175)
at com.goldencode.p2j.persist.Persistence$Context.commit(Persistence.java:4184)
at com.goldencode.p2j.persist.Persistence.commit(Persistence.java:3083)
at com.goldencode.p2j.persist.RecordBuffer$Handler.invoke(RecordBuffer.java:10741)
at com.goldencode.p2j.persist.$__Proxy34.setCrudhandle(Unknown Source)
at sun.reflect.GeneratedMethodAccessor1328.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.goldencode.p2j.persist.FieldReference.set(FieldReference.java:787)
at com.goldencode.p2j.persist.FieldReference.set(FieldReference.java:723)
at com.goldencode.p2j.persist.type.HandleFieldRef.set(HandleFieldRef.java:76)
at com.goldencode.p2j.util.ControlFlowOps.invokeExternalProcedure(ControlFlowOps.java:3368)
at com.goldencode.p2j.util.ControlFlowOps.invokePersistentImpl(ControlFlowOps.java:4309)
at com.goldencode.p2j.util.ControlFlowOps.invokePersistentImpl(ControlFlowOps.java:4209)
at com.goldencode.p2j.util.ControlFlowOps.invokePersistentSet(ControlFlowOps.java:1335)
at com.goldencode.p2j.util.ControlFlowOps.invokePersistentSet(ControlFlowOps.java:1314)
at com.something.server.common.Aapicrd0$15.body(Aapicrd0.java:1351)
...
There is only one log entry from
ProcedureManager:[05/03/2015 16:54:43 EDT] (com.goldencode.p2j.util.ProcedureManager:FINE) Postponing deletion of procedure common/aapsvpr0.p
There are still 3,339
ExternalProgramWrapper instances pinned by the following:
- 2,277 by
handle$WorkArea.idResources(Conversation thread); - 450 by
handle$WorkArea.resourceIds(Conversation thread); - 608 by
BufferManager.inUseRecords(Conversation thread); and - 4 by
LogicalTerminal.survivingScopes(Writer thread).
I don't really understand why the numbers for idResources and resourceIds are not the same.
There are 1,063 distinct EPW referent types.
The BufferManager.inUseRecords references are all handles stored in the TempRecord143Impl.crudhandle field. Those DMOs should have been released and evicted from the Hibernate session when that static temp-table buffer went out of scope; I'll have to look into what went wrong there.
I haven't finished my analysis, but I wanted to post some preliminary feedback (especially the handle warning, since that's new). I'll pick it up again tomorrow. Let me take it a little further before you spend more time on this; I know you have other time-critical tasks.
#16 Updated by Constantin Asofiei almost 9 years ago
- File ca_upd20150504a.zip added
Eric Faulhaber wrote:
Test runs with the last few updates have been noticeably slower (~2.5x).
Are there regressions in the failed tests (except the duration)?
I haven't profiled yet to determine the cause, but the log from the last run using 0503b is full of these, which probably contributes:
[...]
Well, this one is a real issue. The handle is assigned too early, when the procedure is ran persistent. It needs to be assigned only if the procedure is executed (and not ended with an error). Attached solves this issue.
There is only one log entry from
ProcedureManager:
[...]
Hm... you mean there is only one entry?
There are still 3,339ExternalProgramWrapperinstances pinned by the following:
- 2,277 by
handle$WorkArea.idResources(Conversation thread);- 450 by
handle$WorkArea.resourceIds(Conversation thread);- 608 by
BufferManager.inUseRecords(Conversation thread); and- 4 by
LogicalTerminal.survivingScopes(Writer thread).I don't really understand why the numbers for
idResourcesandresourceIdsare not the same.There are 1,063 distinct EPW referent types.
The
BufferManager.inUseRecordsreferences are all handles stored in theTempRecord143Impl.crudhandlefield. Those DMOs should have been released and evicted from the Hibernate session when that static temp-table buffer went out of scope; I'll have to look into what went wrong there.I haven't finished my analysis, but I wanted to post some preliminary feedback (especially the handle warning, since that's new). I'll pick it up again tomorrow. Let me take it a little further before you spend more time on this; I know you have other time-critical tasks.
Yes, I'm not using this task as my primary, I'm using it as a "get out of the box" task :).
#17 Updated by Eric Faulhaber almost 9 years ago
Constantin Asofiei wrote:
Eric Faulhaber wrote:
Test runs with the last few updates have been noticeably slower (~2.5x).
Are there regressions in the failed tests (except the duration)?
No, the same number of tests pass as before.
[...]
Well, this one is a real issue. The handle is assigned too early, when the procedure is ran persistent. It needs to be assigned only if the procedure is executed (and not ended with an error). Attached solves this issue.
Thanks.
There is only one log entry from
ProcedureManager:
[...]Hm... you mean there is only one entry?
Yes, with FINE-level logging enabled, that is the only line in the server log from ProcedureManager. Did you expect a lot more?
#18 Updated by Eric Faulhaber almost 9 years ago
Constantin Asofiei wrote:
[...]
Attached solves this issue.
Confirmed, no more warnings in the log. Performance is still a problem, though; I'll profile the next test run. I've made some changes, too, so it could be something I introduced.
#19 Updated by Eric Faulhaber almost 9 years ago
I had to step away for a few days to chase down a related task. Now I've had a chance to do some more debugging.
The ExternalProgramWrapper instances that are being left behind in the resource maps are getting added with calls like this:
ControlFlowOps.invokeWithMode("ip-create-licence", "III", new character("L01000"), new character("Common Module"), new character("commondb01"));
They are added to the maps by side effect of a
CompareOps.isEqual call at ControlFlowOps:4025:if (callerHandle != null && !CompareOps._isEqual(callerHandle, h))
These programs are never added to
ProcedureManager.deleteOnExit (in fact, nothing is -- it's always empty when ProcedureManager$WorkArea.scopeFinished is invoked). So, when one is popped off the thisProcedures deque, the code at line 2291:// check if we have a postponed delete Boolean delete = deleteOnExit.remove(referent);
always returns null. Since
delete is always null, we never reach line 3338 where these would be cleaned up:handle.removeResource(new ExternalProgramWrapper(referent));
I still think the core of this problem is that we are creating strong references to resources by side effect of a comparison operation. These resources should only be collected deliberately, not incidentally. I don't understand the overall mechanism well enough to propose an approach, but we seem to be calling
handle.resourceId all over the place without registering a cleanup mechanism. Are all the places that call an asHandle method (which in turn calls handle.resourceId) meant to be matched with calls to handle.removeResource via 4GL business logic statements like DELETE OBJECT?
I've only been looking at the ExternalProgramWrapper instances, because they are pinning record buffers, but I'm beginning to suspect we may be leaking other kinds of WrappedResource objects as well.
#20 Updated by Constantin Asofiei almost 9 years ago
Eric, don't know how I didn't notice this until now. handle.removeResource should be called for every kind of resource (dynamic or static), when that resource gets deleted. HandleChain.delete does this. But external programs are a special kind and don't extend from HandleChain... and I was calling handle.removeResource only in ExternalProgramWrapper.delete (called only when persistent procedures get deleted). This call should happen in ProcedureManager.delete, which is called for both static and dynamic procedures.
So if you add a handle.removeResource at the end of ProcedureManager.delete might solve the issue:
handle.removeResource(pdata.phandle.getResource());
#21 Updated by Eric Faulhaber almost 9 years ago
- File ecf_upd20150517a.zip added
Constantin, I included the suggested handle.removeResource fix, and it did indeed solve that problem. Thank you!
The attached update addresses this and a number of other memory leaks. These were accumulating to somewhere between 1.5-2GB of wasted heap in the largest set of customer unit tests. With the fix, the server remains in what appears to be a stable memory state throughout that test set. This gives us a nice performance boost as well, as the server previously would become progressively slower as more tests were run and more resources leaked in various data structures. We still seem to collect more dynamic temp-table buffer instances than I would like in TM global finalizables, but that's a relatively small leak compared to some of the others that were fixed, and I want to get those in sooner rather than later, so I'll defer fixing that for now.
Please note that the latest versions of the various updates you provided over the course of this discussion have been rolled into this update, and I fixed what appeared to be issues in several of them. In particular, where you added the id field to various classes, you used the idiom new WorkArea() in a number of places where I think the intention was work.obtain() or work.get(), or whatever flavor of retrieving a context local variable was appropriate for that particular class. Feel free to review those if you think I've misunderstood your intent. Anyway, bottom line is: you don't need to worry about testing and committing those files.
I am regression testing the update with Majic now. Thanks for all your help!
#22 Updated by Constantin Asofiei almost 9 years ago
Eric Faulhaber wrote:
Constantin, I included the suggested
handle.removeResourcefix, and it did indeed solve that problem. Thank you!
In particular, where you added theidfield to various classes, you used the idiomnew WorkArea()in a number of places where I think the intention waswork.obtain()orwork.get(), or whatever flavor of retrieving a context local variable was appropriate for that particular class. Feel free to review those if you think I've misunderstood your intent. Anyway, bottom line is: you don't need to worry about testing and committing those files.
There's one more place with a new WorkArea() in ColorTable.asHandle. Please fix this too.
Otherwise, I'm a worried about the unsynchronized access to the DatabaseManager.schemaByDMOClass map - this is populated by registerDatabase which has a lock on configLock, but the normalizeDMOClass does not sync on it. The other usage - getSchemaByClass - does sync on it.
#23 Updated by Eric Faulhaber almost 9 years ago
- File ecf_upd20150518a.zip added
Constantin Asofiei wrote:
There's one more place with a
new WorkArea()inColorTable.asHandle. Please fix this too.
Done.
Otherwise, I'm a worried about the unsynchronized access to the
DatabaseManager.schemaByDMOClassmap - this is populated byregisterDatabasewhich has a lock onconfigLock, but thenormalizeDMOClassdoes not sync on it. The other usage -getSchemaByClass- does sync on it.
Fixed, thank you.
I've restarted regression testing with the attached. First run got hung up in Ctrl-C testing anyway.
#24 Updated by Eric Faulhaber almost 9 years ago
- Assignee set to Eric Faulhaber
- File ecf_upd20150518b.zip added
- % Done changed from 0 to 90
The attached update is essentially the same as ecf_upd20150518a, but with the original error logging in TM.abnormalEnd reverted back to its original, FINE setting (my temporary change in 0518a to WARNING is good for debugging, but too verbose for production).
This update has passed regression testing and is committed to bzr rev. 10866.
#25 Updated by Eric Faulhaber over 8 years ago
- % Done changed from 90 to 100
- Status changed from WIP to Closed
#26 Updated by Greg Shah over 7 years ago
- Target version changed from Milestone 11 to Cleanup and Stablization for Server Features