Hi Chris,
Thank you for the quick answer - very much appreciated.
I have made some further discoveries and actually see the degradation on the Magma server (vs in my client image). I am doing some tests with SSD disk, commit sizes and will update this thread more about this as I progress and write it up on a blog. I think this is key to the performance: 68.9% {11294ms} [] MaHashIndex>>add:at: 25.1% {4112ms} MaHashIndexRecord>>canAdd: ... 24.2% {3968ms} MaHashIndex>>selectRecord: 24.0% {3931ms} MaHashIndex>>readRecord:at: ... 17.2% {2814ms} MaHashIndex>>writeRecord: 17.1% {2799ms} MaFileRecordBroker>>writeFrom:at:
But this has to wait since I have run into something very annoying (and I cannot understand how my image became corrupted): Basically, I have a MagmaSession disconnect hanging on (this time I tried primDisconnect, the stack is almost the same on disconnect):
Mutex>>critical: MaNetworkServerLink>>submit: [] in [] in [] in MagmaSession>>submit:to: [] in [] in BlockClosure>>maOn:do:on:do:on:do: BlockClosure>>on:do: [] in BlockClosure>>maOn:do:on:do:on:do: [] in [] in BlockClosure>>maOn:do:on:do: BlockClosure>>on:do: [] in BlockClosure>>maOn:do:on:do: BlockClosure>>on:do: BlockClosure>>maOn:do:on:do: BlockClosure>>maOn:do:on:do:on:do: [] in [] in MagmaSession>>submit:to: BlockClosure>>ensure: CursorWithMask(Cursor)>>showWhile: [] in MagmaSession>>submit:to: Mutex>>critical: MagmaSession>>submit:to: [] in [] in MagmaSession>>primDisconnect MagmaSession>>linksDo:
The mutex is held by a suspended Process in Debugger class>>morphicOpenOn:context:label:contents:fullView:
I've tried to resume the process but MethodContext>>cannotReturn: is coming back to me and some poking around tells me that the title of the debugger was: "'MaObjectSerializationUserError: No createProxyBlock specified. See MaObjectSerializer>>toCreateProxies:'" Now, how can I break this Mutex to clean up the MagmaSession?
If I try to terminate the process - it simply goes into suspend. Since I am doing changes, testing and ALT-. to break long commits or other vicious cycles - it would be good to know how to drop all Magma tracked objects from memory (i.e. all "Magma state", oids etc) and reset the database? What is the best strategy to do this?
Cheers, Tim
Den 22 maj 2018 kl. 15:06 skrev Chris Muller asqueaker@gmail.com:
Hi!
First, thanks for the great email, the detail and for your deep exploration and usage of the tools provided by Magma in the first place, I'm very impressed!
To cut to the chase about WriteBarrier: yes. WriteBarrier is meant for stable bulk-load's you want to perform faster. The trade-off of using it is, if you need to do debugging, it's harder to access the instances via, i.e., TKEntry allInstances select: [ : each | .... ], because they're not instances of TKEntry, but of TKEntry*.
Is this database shared with other real-time users? If not, I would experiment committing at least 500 or 1000 or 2500 or 5000 or 10000 per commit.
There is a logarithmic rate of degradation to adding new objects proportional to the number of unique objects already in a MagmaCollection or MagmaCollectionIndex. The rate of degradation of duplicate objects is *linear*, but it doesn't sound like your model is affected by that.
You were very smart to override #isImmutableInMagma on your TEEntry's, given how many would be clogging up the readSet unnecessarily due to their archival nature (unchanging).
Those big Dictionary's of the MaSharedObjectsBroker will still slow down the changed-detection of your commits whenever you didn't add something. Because that means their size won't have changed, and nor will their contents, but the only way Magma could know that is by enumerating them. And, if they DID change, then they have to be committed. So, there is a trade-off there, but this is something I would like to think about further -- a few years ago a made an advanced feature that could help with this, but I need to research it.
Besides the sizes of those Dictionary caches, you'd want to ensure those objects IN them are not in the readSet, if possible. WriteBarrier can definitely help with that for objects which are not #isImmutableInMagma. Some of the lower level objects don't can't take advantage of the WriteBarrier (see #maAllowsWriteBarrier), but normal objects like the ones from your domain can.
WbDictionary, et al. no longer apply after Closures were redone a few years ago which disallowed Array's from being made uncompact, something required for the WriteBarrier to be able to swap its class via #primitiveChangeClassTo:.
I can help you optimize further if you include a MessageTally profile dump next time.
Cheers! Chris
On Tue, May 22, 2018 at 8:28 AM, Tim Käck timkack@icloud.com wrote: Hi all,
First let me explain how my application works (and excuse this lengthy post):
It processes a log file and create TKEntry’s (i.e. smalltalk objects representing the log entry). Since several entries contains the same values for several fields (example: paths, userIds etc) I have LRUCache infront of a MaSharedObject broker (Thanks Chris for this!). The reasons are two fold: 1) The LRUCache makes it faster to lookup keys when I have a lot of log data on the heap 2) The MaSharedObject broker prevents having the same value stored many times and by that use up valuable heap usage. Lets call this TKMaLRU<mumble>Cache - and there are several of these depending on their scope and content. The <mumble> part is because they have some specialities to what they store (literals, dates, times etc). These TKEntry’s are stored in an OrderedCollection but now when I am “magma:fying” the application, I have decided to use a MagmaCollection (because we talk about 4-5 million entries). Let call this a TKLog. The TKLog is stored in a TKProject, which in turn is stored in my root of my Magma database - in my grand TKProjects singleton object.
So, to summarise the architecture somewhat:
TKProjects contain TKProject’s, that contain TKLog’s, where each contains a collection of TKEntry’s. The TKProjects contain some TKMaLRU<mumble>Caches that are global and shared between projects. The TKProject contain some TKMaLRU<mumble>Caches that are shared across all TKLogs The TKLog contains some TKMaLRU<mumble>Caches that are only relevant for that specific log.
Here is how the commit mechanism work: 1) MagmaSession begin 2) Read and process log entry into a TKLog entry (i.e. also lookup or add values to above mentioned MaSharedObject brokered caches) 3) repeat step 2) X times 4) MagmaSession commitAndBegin. 5) Repeat 2 - 4 until all log has been processed.
Now, in step 3 - I have tested to commit every TKEntry, every 50 TKEntry and every 150 TKEntry - but the results are somewhat disappointing. Looking at the client side report - it seems to suggest that "Time to Download Full Response” is taking longer and longer:
Time to Download Full Response
End Time Name Count min max sum mean last -------- ---- ----- --- --- --- ---- ---- 2018-05-08T21:24:56.756581+02:00 Time to Download Full Response 98 1439.0 4269.0 197938.0 2019.77551 1703 2018-05-08T21:29:56.756864+02:00 Time to Download Full Response 97 1575.0 3388.0 200137.0 2063.26804 1817 2018-05-08T21:34:56.759649+02:00 Time to Download Full Response 96 1325.0 3533.0 197440.0 2056.66666 2039 2018-05-08T21:39:56.761206+02:00 Time to Download Full Response 95 1134.0 3539.0 193899.0 2041.04210 2061 2018-05-08T21:44:56.764136+02:00 Time to Download Full Response 92 1537.0 4060.0 193165.0 2099.61956 1994 2018-05-08T21:49:56.772738+02:00 Time to Download Full Response 91 1672.0 4183.0 192310.0 2113.29670 1998 <…snip…> 2018-05-09T07:29:57.823266+02:00 Time to Download Full Response 71 2388.0 5202.0 213569.0 3008.01408 3175 2018-05-09T07:34:57.825258+02:00 Time to Download Full Response 61 2829.0 5700.0 211781.0 3471.81967 3197 2018-05-09T07:39:57.825924+02:00 Time to Download Full Response 55 2385.0 6392.0 193054.0 3510.07272 2965 2018-05-09T07:44:57.828316+02:00 Time to Download Full Response 56 2839.0 6606.0 201693.0 3601.66071 3249 2018-05-09T07:49:57.830572+02:00 Time to Download Full Response 62 1870.0 6230.0 207707.0 3350.11290 3543 2018-05-09T07:54:57.832358+02:00 Time to Download Full Response 58 2790.0 6422.0 199911.0 3446.74137 3215 2018-05-09T07:59:57.834803+02:00 Time to Download Full Response 61 2658.0 5832.0 208315.0 3415.0 3839 2018-05-09T08:04:57.841518+02:00 Time to Download Full Response 60 2266.0 4742.0 199554.0 3325.9 3122 2018-05-09T08:09:57.842645+02:00 Time to Download Full Response 57 2439.0 5669.0 190848.0 3348.21052 3782 2018-05-09T08:14:57.843325+02:00 Time to Download Full Response 56 2183.0 5850.0 191640.0 3422.14285 3040 2018-05-09T08:19:57.845536+02:00 Time to Download Full Response 56 2803.0 5767.0 196116.0 3502.07142 3225 2018-05-09T08:24:57.846522+02:00 Time to Download Full Response 61 2653.0 5717.0 211016.0 3459.27868 3406 2018-05-09T08:29:57.9646+02:00 Time to Download Full Response 54 2765.0 5772.0 186693.0 3457.27777 3277 2018-05-09T08:34:57.967164+02:00 Time to Download Full Response 54 2970.0 5636.0 193700.0 3587.03703 3401 2018-05-09T08:39:57.981221+02:00 Time to Download Full Response 55 2583.0 5411.0 197685.0 3594.27272 3607 2018-05-09T08:44:57.981925+02:00 Time to Download Full Response 56 2664.0 5661.0 196917.0 3516.375 3829 2018-05-09T08:49:57.982564+02:00 Time to Download Full Response 57 2854.0 6889.0 202831.0 3558.43859 3014 2018-05-09T08:54:57.983894+02:00 Time to Download Full Response 63 2761.0 6190.0 214199.0 3399.98412 3226 2018-05-09T08:59:57.990957+02:00 Time to Download Full Response 63 2796.0 5130.0 216577.0 3437.73015 3066 2018-05-09T09:04:57.992464+02:00 Time to Download Full Response 55 2894.0 6478.0 200221.0 3640.38181 3300 2018-05-09T09:09:57.994927+02:00 Time to Download Full Response 51 3173.0 5203.0 194755.0 3818.72549 3276 2018-05-09T09:14:57.995991+02:00 Time to Download Full Response 55 3167.0 6066.0 205586.0 3737.92727 3432 2018-05-09T09:19:57.998695+02:00 Time to Download Full Response 57 2840.0 6339.0 212726.0 3732.03508 3445 2018-05-09T09:24:58.010041+02:00 Time to Download Full Response 53 2737.0 5854.0 203695.0 3843.30188 3212 2018-05-09T09:29:58.011472+02:00 Time to Download Full Response 55 1893.0 5003.0 193155.0 3511.90909 3311 2018-05-09T09:34:58.013342+02:00 Time to Download Full Response 53 2573.0 6791.0 194739.0 3674.32075 3588 2018-05-09T09:39:58.016082+02:00 Time to Download Full Response 55 2810.0 5476.0 195984.0 3563.34545 3254
I also see a degradation over time on "Time waiting for MaCommitRequest requests"
End Time Name Count min max sum mean last -------- ---- ----- --- --- --- ---- ---- 2018-05-08T21:24:56.756627+02:00 Time waiting for MaCommitRequest requ... 98 1443.0 4291.0 199387.0 2034.56122 1706 2018-05-08T21:29:56.756915+02:00 Time waiting for MaCommitRequest requ... 97 1583.0 3399.0 201187.0 2074.09278 1821 2018-05-08T21:34:56.759692+02:00 Time waiting for MaCommitRequest requ... 96 1333.0 3538.0 199918.0 2082.47916 2047 2018-05-08T21:39:56.761261+02:00 Time waiting for MaCommitRequest requ... 95 1143.0 3547.0 196105.0 2064.26315 2070 2018-05-08T21:44:56.764175+02:00 Time waiting for MaCommitRequest requ... 92 1540.0 4449.0 195004.0 2119.60869 1999 2018-05-08T21:49:56.77278+02:00 Time waiting for MaCommitRequest requ... 91 1678.0 4190.0 194502.0 2137.38461 2008 2018-05-08T21:54:56.774304+02:00 Time waiting for MaCommitRequest requ... 89 1389.0 4015.0 190014.0 2134.98876 1858 2018-05-08T21:59:56.777215+02:00 Time waiting for MaCommitRequest requ... 88 1731.0 4576.0 191360.0 2174.54545 2020 2018-05-08T22:04:56.779026+02:00 Time waiting for MaCommitRequest requ... 88 1705.0 3551.0 191334.0 2174.25 1859 <…snip…> 2018-05-09T09:09:57.99499+02:00 Time waiting for MaCommitRequest requ... 51 3185.0 5210.0 195250.0 3828.43137 3286 2018-05-09T09:14:57.996035+02:00 Time waiting for MaCommitRequest requ... 55 3174.0 6073.0 206588.0 3756.14545 3898 2018-05-09T09:19:57.998772+02:00 Time waiting for MaCommitRequest requ... 57 2849.0 6346.0 213850.0 3751.75438 3455 2018-05-09T09:24:58.010092+02:00 Time waiting for MaCommitRequest requ... 53 2740.0 5856.0 205350.0 3874.52830 3216 2018-05-09T09:29:58.011514+02:00 Time waiting for MaCommitRequest requ... 55 1896.0 5259.0 196371.0 3570.38181 3315 2018-05-09T09:34:58.013386+02:00 Time waiting for MaCommitRequest requ... 53 2582.0 6796.0 196473.0 3707.03773 3593 2018-05-09T09:39:58.016132+02:00 Time waiting for MaCommitRequest requ... 55 2818.0 5485.0 196926.0 3580.47272 3268 nil Time waiting for MaCommitRequest requ... 10 3125.0 4748.0 37967.0 3796.7 3511
This has led me to implement isImmutableInMagma on the TKEntry to keep the readSet low, but now I have run into a problem: The caches are based on Dictionaries and they can grow to 20000-30000 (or more) entries.
After all of this, my question is simple: Should I use a WriteBarrier capable object instead (I could not find a WbDictionary unfortunately)? In fact - how does WriteBarrier work in the context of Magma? I have set allowWriteBarrier: true when connecting to the Magma DB.
Cheers, Tim
_______________________________________________ Magma mailing list Magma@lists.squeakfoundation.org http://lists.squeakfoundation.org/mailman/listinfo/magma