Magma on 3.7 report

[Bert Freudenberg]

Am 25.03.2006 um 21:12 schrieb Chris Muller:

> Now that the performance regression is restored, let me try  
> responding properly.
>
>> In the attached tally, Magma spends 97.3% (!) of the time in
>> removeGarbageCollectedObjectEntries.
>
>  Magma maintains a two-way map, object->oid (a.k.a. "oids") and oid- 
> >object (a.k.a. "objects").  It currently handles this with a  
> WeakIdentityKeyDictionary and a MaWeakValueDictionary,  
> respectively.  WeakKey dictionaries automatically remove their (key- 
> >value) entries when objects are collected/finalized, but WeakValue  
> dictionaries entries remain, and simply reference nil (i.e., oid- 
> >nil).

Shouldn't then objects and oids usually have the same size?

>  So, as the client moves to explore a other parts of a huge domain  
> model, the WeakKey dictionary is fine but the WeakValue never  
> shrinks unless Magma cleans it up manually.  This is what  
> removeGarbageCollectedObjectEntries does.  It simply rebuilds the  
> entire MaWeakValueDictionary by enumerating all and only keeping  
> the non-nil values.
>
>  The best strategy for when to rebuild is difficult to generalize.   
> Time-based could cause unnecessary rebuilds or not rebuild soon  
> enough, so I made based on conditions.  Whenever the 'objects' size  
> is twice that of the 'oids' size, the next oid assignment will take  
> a detour rebuild the "objects" collection (oid->object), removing  
> all the nil entries.

The problem for me is that in one of the three MagmaOidManager  
instances, objects size is 17516 and oids size is 6587 even after a  
full GC. Thus, removeGarbageCollectedObjectEntries is called on each- 
and-every access, explaining the huge time this takes.

What I did is adding a quick test to  
removeGarbageCollectedObjectEntries to check if there are indeed  
garbage collected entries (there are non in my initial load). This  
reduced the time spent in there from 97% to 12%, which is bearable.  
Raising the check threshold to  "objects size > (oids size * 3)" made  
it go away alltogether - see attached MessageTally for bringing in 1K  
SSVersions.

I put my modified Magma packages at http://source.impara.de/ss.html

I also fixed the use of instVarNames instead of allInstVarNames in  
the MaReadStrategy, you could not name an inst var of a superclass  
otherwise.

- Bert -

89444 tallies, 90098 msec.

**Tree**
100.0% {90098ms} SSProject>>versions
   96.0% {86494ms} SSVersion>>propertyAt:ifAbsent:
     |96.0% {86494ms} MagmaMutatingProxy(MaMutatingProxy) 
 >>doesNotUnderstand:
     |  96.0% {86494ms} MagmaMutatingProxy(MaMutatingProxy) 
 >>mutateAndSend:
     |    96.0% {86494ms} MagmaMutatingProxy>>mutant
     |      96.0% {86494ms} MagmaSession>>realObjectFor:
     |        93.1% {83881ms} MagmaSession>>materializeObject:
     |          |92.9% {83701ms}  
MaObjectSerializer>>materializeGraph:do:
     |          |  92.9% {83701ms}  
MaObjectSerializer>>materializeGraphDo:
     |          |    91.3% {82259ms}  
MaObjectSerializer>>newSkeletonFor:fromProxy:
     |          |      90.6% {81629ms} MaVariableObjectBuffer 
(MaObjectBuffer)>>oid
     |          |        90.6% {81629ms} primitives
     |        2.9% {2613ms} MagmaSession>>read:
     |          2.9% {2613ms} MagmaSession>>submit:
     |            2.8% {2523ms} MaLocalServerLink>>submit:
     |              2.8% {2523ms} MaLocalRequestServer 
(MaRequestServer)>>processRequest:
     |                2.8% {2523ms} MagmaRepositoryController>>value:
     |                  2.8% {2523ms}  
MagmaRepositoryController>>processRequest:
     |                    2.8% {2523ms} MaReadRequest>>process
     |                      2.8% {2523ms}  
MaObjectRepository>>read:for:using:
     |                        2.8% {2523ms}  
MaObjectRepository>>byteArrayAt:using:
     |                          2.7% {2433ms}  
MaObjectRepository>>graphBufferAt:using:
     |                            2.5% {2252ms} MaVariableObjectBuffer 
(MaObjectBuffer)>>appendGraphUsing:into:...:minDepth:with:filer:
   4.0% {3604ms} MagmaMutatingProxy(MaMutatingProxy)>>doesNotUnderstand:
     4.0% {3604ms} MagmaMutatingProxy(MaMutatingProxy)>>mutateAndSend:
       4.0% {3604ms} MagmaMutatingProxy>>mutant
         4.0% {3604ms} MagmaSession>>realObjectFor:
           2.4% {2162ms} MagmaSession>>materializeObject:
             2.4% {2162ms} MaObjectSerializer>>materializeGraph:do:
               2.4% {2162ms} MaObjectSerializer>>materializeGraphDo:
**Leaves**
90.7% {81719ms} MaVariableObjectBuffer(MaObjectBuffer)>>oid
3.1% {2793ms} Dictionary>>scanFor:

**Memory**
	old			+2,303,788 bytes
	young		+113,468 bytes
	used		+2,417,256 bytes
	free		-2,417,256 bytes

**GCs**
	full			0 totalling 0ms (0.0% uptime)
	incr		370 totalling 1,624ms (2.0% uptime), avg 4.0ms
	tenures		32 (avg 11 GCs/tenure)
	root table	0 overflows