Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
Hi,
I made the benchmarks with the files you provided. I have more or less the same magnitude: Version 504: 0:00:01:09.021 Version 1175: 0:00:02:37.507
However, by launching it in the time profiler (MooseModel new importFromMSEStream: (StandardFileStream readOnlyFileNamed: 'd:/ArgoUML-0-34.mse')), it takes 504: 1 min 55 1175: 4 min 25 Well there is a delta...
After investigation, the standard process has almost the same duration (120 secs for prespur and 140 secs for spur). But, there is a large difference in GC time:
504: not spur **Memory** old +144,822,000 bytes young -8,293,660 bytes used +136,528,340 bytes free -104,186,788 bytes
**GCs** full 1 totalling 965ms (1.0% uptime), avg 965.0ms incr 3264 totalling 42,279ms (33.0% uptime), avg 13.0ms tenures 2,497 (avg 1 GCs/tenure) root table 0 overflows
1175: spur **Memory** old +0 bytes young +340,048 bytes used +340,048 bytes free -340,048 bytes **GCs** full 7 totalling 145,003ms (66.0% uptime), avg 20715.0ms incr 3288 totalling 30,912ms (14.0% uptime), avg 9.0ms tenures 7,146,505 (avg 0 GCs/tenure) root table 0 overflows
Total GC time 504: 43 secs 1175: 176 secs
See the performance reports attached.
I let VM people take care of the issue ;)
Cheers, Vincent
-----Original Message----- From: moose-dev-bounces@list.inf.unibe.ch [mailto:moose-dev-bounces@list.inf.unibe.ch] On Behalf Of Tudor Girba Sent: dimanche 24 janvier 2016 09:08 To: Moose-related development Subject: [Moose-dev] Re: mse loading looks slower :(
Hi,
I am talking about the difference between Moose 6 images: - October 7: https://ci.inria.fr/moose/job/moose-6.0/504/artifact/moose-6.0.zip
- yesterday: https://ci.inria.fr/moose/job/moose-6.0/1175/artifact/moose-6.0.zip
Multiple things did change, but not in Moose. In the end, I would like to understand where the slowness comes. Maybe it comes from Spur itself, but maybe it comes from somewhere else.
Cheers, Doru
On Jan 24, 2016, at 1:41 AM, Mariano Martinez Peck marianopeck@gmail.com
wrote:
Doru...just to be sure it is not a Pharo (image change), when you said
before and after Spur, do you mean a Pharo 5.0 exactly (just before Spur) and a Pharo JUST after it? Otherwise, the slowness may come from the difference between the 2 Pharos you are running.
Cheers,
On Sat, Jan 23, 2016 at 5:55 PM, Tudor Girba tudor@tudorgirba.com wrote: Hi,
I am doing some performance testing of Moose with the Spur VM on Mac.
I tried to load an MSE file with ArgoUML 0.34 and on my machine it loads
twice as slow with Spur than before:
- PreSpur: 0:00:01:07.272
- Spur: 0:00:02:10.508
Here is the reference file: https://dl.dropboxusercontent.com/u/18323746/Tmp/ArgoUML-0-34.mse.zip
And here is the script: [ MooseModel new importFromMSEStream: (StandardFileStream
readOnlyFileNamed:
(FileSystem workingDirectory / 'src' /
'ArgoUML-0-34' / 'ArgoUML-0-34.mse') fullName).
] timeToRunDo you get the same?
Cheers, Doru
-- www.tudorgirba.com www.feenk.com
"Problem solving should be focused on describing the problem in a way that makes the solution obvious."
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- Mariano http://marianopeck.wordpress.com _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- www.tudorgirba.com www.feenk.com
"What is more important: To be happy, or to make happy?"
_______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
I can confirm more time taken [ MooseModel new importFromMSEStream: (StandardFileStream readOnlyFileNamed: (FileSystem workingDirectory / '../../src' / 'ArgoUML-0-34.mse') fullName). ] timeProfile
I wonder what happens if you block the UI while loading
1178 spur (50542 on vm 420) - 85216 tallies, 85302 msec.
**Tree** -------------------------------- Process: (40s) Morphic UI Process: nil -------------------------------- 32.7% {27886ms} MooseModel class>>importFrom: |32.7% {27860ms} MooseModel class>>importFrom:withMetamodel: | 32.7% {27854ms} MSEImporter(FMImporter)>>run | 32.7% {27854ms} FMMSEParser>>run | 32.6% {27850ms} FMMSEParser>>basicRun | 32.6% {27850ms} FMMSEParser>>Document | 32.4% {27648ms} FMMSEParser>>Element | 22.4% {19072ms} FMMSEParser>>Attribute | |8.5% {7209ms} MSEImporter(FMImporter)>>endAttribute: | | |8.4% {7169ms} FMFutureElement>>endAttribute: | | | 8.4% {7151ms} FMFutureAttribute>>endAttribute: | | | 8.4% {7129ms} FMFutureAttribute>>maybeEnd | | | 4.4% {3753ms} FM3PropertyDescription>>setOn:values: | | | |4.3% {3653ms} FAMIXMethod(Object)>>mmSetProperty:to: | | | | 4.3% {3633ms} FM3PropertyDescription>>setOn:rawValue: | | | | 1.3% {1079ms} FAMIXParameter(FAMIXStructuralEntity)>>declaredType: | | | | 1.3% {1067ms} FMMultivalueLink class>>on:update:from:to: | | | | 1.2% {1059ms} FMMultivalueLink>>unsafeAdd: | | | | 1.2% {1051ms} OrderedCollection(SequenceableCollection)>>includes: | | | | 1.2% {1051ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | 1.2% {1051ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | 1.2% {1051ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | | 1.1% {960ms} primitives | | | 3.9% {3308ms} FM3MetaDescription>>attributeNamed:ifAbsent: | | | 1.6% {1343ms} FMMultivalueLink(Collection)>>detect:ifNone: | | | 1.4% {1180ms} FM3MetaDescription>>attributeNamed:ifAbsent: | |5.9% {4996ms} FMMSEParser>>Value | | |3.7% {3166ms} FMMSEParser>>Reference | | | |2.3% {1945ms} FMMSEParser>>Identifier | | | | 1.4% {1232ms} Character>>isDigit | | | | 1.3% {1080ms} Character>>characterSet | | | | 1.2% {1062ms} EncodedCharSet class>>charsetAt: | | | | 1.2% {1034ms} Array(SequenceableCollection)>>at:ifAbsent: | | | | 1.2% {1024ms} primitives | | |1.7% {1425ms} FMMSEParser>>Primitive | | | 1.2% {1033ms} FMMSEParser>>Number | |5.2% {4420ms} FMMSEParser>>tNAME | | |4.1% {3503ms} Character>>isAlphaNumeric | | | 3.5% {2987ms} Character>>isLetter | | | 3.1% {2667ms} Character>>characterSet | | | 3.1% {2641ms} EncodedCharSet class>>charsetAt: | | | 3.0% {2585ms} Array(SequenceableCollection)>>at:ifAbsent: | | | 3.0% {2547ms} primitives | |2.2% {1876ms} MSEImporter(FMImporter)>>beginAttribute: | | 2.2% {1852ms} FMFutureElement>>beginAttribute: | | 1.8% {1558ms} PhexMatcher>>beTrue | | 1.7% {1487ms} PhexMatcher>>true | | 1.6% {1405ms} PhexMatcher>>expectedUnknownMessageToReturn: | 6.0% {5156ms} FMMSEParser>>Serial | |4.8% {4131ms} MSEImporter(FMImporter)>>serial: | | |4.8% {4125ms} FMFutureElement>>serial: | | | 4.8% {4121ms} MSEImporter(FMImporter)>>assign:to: | | | 4.1% {3524ms} FMDanglingReference>>resolve: | | | 3.4% {2859ms} FMFutureAttribute>>maybeEnd | | | 2.0% {1706ms} FM3PropertyDescription>>setOn:values: | | | |1.9% {1646ms} FAMIXMethod(Object)>>mmSetProperty:to: | | | | 1.9% {1624ms} FM3PropertyDescription>>setOn:rawValue: | | | 1.3% {1137ms} FM3MetaDescription>>attributeNamed:ifAbsent: | |1.1% {905ms} FMMSEParser>>Identifier | 2.0% {1680ms} FMMSEParser>>tFULLNAME | |1.6% {1325ms} Character>>isAlphaNumeric | | 1.3% {1075ms} Character>>isLetter | | 1.1% {969ms} Character>>characterSet | | 1.1% {953ms} EncodedCharSet class>>charsetAt: | | 1.1% {937ms} Array(SequenceableCollection)>>at:ifAbsent: | | 1.1% {917ms} primitives | 1.6% {1395ms} MSEImporter(FMImporter)>>beginElement: | 1.6% {1357ms} FMFutureElement class>>with:name: | 1.6% {1353ms} FMFutureElement>>with:name: | 1.4% {1195ms} FM3MetaDescription>>createInstance | 1.4% {1163ms} FAMIXImplicitVariable class(Behavior)>>new 1.4% {1183ms} MooseModel>>silentlyAddAll: 1.4% {1157ms} MooseModel>>silentlyAdd: -------------------------------- Process: other processes -------------------------------- 36.2% {30857ms} InputEventFetcher>>eventLoop 36.2% {30857ms} InputEventFetcher>>waitForInput 29.4% {25047ms} Semaphore>>waitTimeoutMSecs: 29.4% {25047ms} DelayWaitTimeout>>wait **Leaves** 36.2% {30857ms} InputEventFetcher>>waitForInput 29.4% {25047ms} DelayWaitTimeout>>wait 7.8% {6637ms} Array(SequenceableCollection)>>at:ifAbsent: 3.6% {3102ms} Array(SequenceableCollection)>>indexOf:startingAt:ifAbsent: 1.4% {1213ms} FMMultivalueLink(Collection)>>detect:ifNone: 1.3% {1125ms} ByteString(String)>>= 1.1% {914ms} PhexMatcher>>expect:describeShould:describeShouldNot:
**Memory** old +134,217,728 bytes young -134,644,032 bytes used -426,304 bytes free +134,644,032 bytes
**GCs** full 7 totalling 56,554ms (66.0% uptime), avg 8079.0ms incr 3309 totalling 13,509ms (16.0% uptime), avg 4.0ms tenures 7,140,590 (avg 0 GCs/tenure) root table 0 overflows
1178 Spur (50542 on vm 403) - 87658 tallies, 87744 msec.
**Tree** -------------------------------- Process: (40s) Morphic UI Process: nil -------------------------------- 34.1% {29962ms} MooseModel class>>importFrom: |34.1% {29954ms} MooseModel class>>importFrom:withMetamodel: | 34.1% {29952ms} MSEImporter(FMImporter)>>run | 34.1% {29952ms} FMMSEParser>>run | 34.1% {29948ms} FMMSEParser>>basicRun | 34.1% {29948ms} FMMSEParser>>Document | 33.9% {29764ms} FMMSEParser>>Element | 22.8% {19998ms} FMMSEParser>>Attribute | |9.1% {7992ms} MSEImporter(FMImporter)>>endAttribute: | | |9.1% {7972ms} FMFutureElement>>endAttribute: | | | 9.1% {7968ms} FMFutureAttribute>>endAttribute: | | | 9.1% {7964ms} FMFutureAttribute>>maybeEnd | | | 5.2% {4538ms} FM3PropertyDescription>>setOn:values: | | | |5.1% {4444ms} FAMIXMethod(Object)>>mmSetProperty:to: | | | | 5.0% {4386ms} FM3PropertyDescription>>setOn:rawValue: | | | | 1.5% {1287ms} FAMIXParameter(FAMIXStructuralEntity)>>declaredType: | | | | |1.5% {1283ms} FMMultivalueLink class>>on:update:from:to: | | | | | 1.4% {1255ms} FMMultivalueLink>>unsafeAdd: | | | | | 1.4% {1247ms} OrderedCollection(SequenceableCollection)>>includes: | | | | | 1.4% {1247ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | | 1.4% {1247ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | | 1.4% {1247ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | | | 1.3% {1177ms} primitives | | | | 1.1% {968ms} FAMIXMethod(FAMIXBehaviouralEntity)>>declaredType: | | | | |1.1% {968ms} FMMultivalueLink class>>on:update:from:to: | | | | | 1.1% {954ms} FMMultivalueLink>>unsafeAdd: | | | | | 1.1% {952ms} OrderedCollection(SequenceableCollection)>>includes: | | | | | 1.1% {952ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | | 1.1% {952ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | | 1.1% {952ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | | | 1.0% {888ms} primitives | | | | 1.1% {958ms} FAMIXInvocation>>receiver: | | | | 1.1% {954ms} FMMultivalueLink class>>on:update:from:to: | | | | 1.0% {910ms} FMMultivalueLink>>unsafeAdd: | | | | 1.0% {900ms} OrderedCollection(SequenceableCollection)>>includes: | | | | 1.0% {900ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | 1.0% {900ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | 1.0% {900ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | 3.8% {3367ms} FM3MetaDescription>>attributeNamed:ifAbsent: | | | 1.6% {1395ms} FM3MetaDescription>>attributeNamed:ifAbsent: | | | 1.1% {979ms} FMMultivalueLink(Collection)>>detect:ifNone: | |5.8% {5121ms} FMMSEParser>>Value | | |3.6% {3197ms} FMMSEParser>>Reference | | | |2.4% {2122ms} FMMSEParser>>Identifier | | | | 1.6% {1399ms} Character>>isDigit | | | | 1.4% {1243ms} Character>>characterSet | | | | 1.4% {1225ms} EncodedCharSet class>>charsetAt: | | | | 1.4% {1199ms} Array(SequenceableCollection)>>at:ifAbsent: | | | | 1.3% {1153ms} primitives | | |1.8% {1552ms} FMMSEParser>>Primitive | | | 1.3% {1169ms} FMMSEParser>>Number | |5.2% {4562ms} FMMSEParser>>tNAME | | |4.1% {3565ms} Character>>isAlphaNumeric | | | 3.5% {3068ms} Character>>isLetter | | | 3.2% {2816ms} Character>>characterSet | | | 3.2% {2782ms} EncodedCharSet class>>charsetAt: | | | 3.1% {2722ms} Array(SequenceableCollection)>>at:ifAbsent: | | | 3.0% {2658ms} primitives | |2.0% {1726ms} MSEImporter(FMImporter)>>beginAttribute: | | 1.9% {1684ms} FMFutureElement>>beginAttribute: | | 1.6% {1425ms} PhexMatcher>>beTrue | | 1.5% {1351ms} PhexMatcher>>true | | 1.4% {1243ms} PhexMatcher>>expectedUnknownMessageToReturn: | 6.1% {5343ms} FMMSEParser>>Serial | |5.0% {4374ms} MSEImporter(FMImporter)>>serial: | | 5.0% {4370ms} FMFutureElement>>serial: | | 5.0% {4370ms} MSEImporter(FMImporter)>>assign:to: | | 4.2% {3708ms} FMDanglingReference>>resolve: | | 3.4% {3027ms} FMFutureAttribute>>maybeEnd | | 2.1% {1864ms} FM3PropertyDescription>>setOn:values: | | |2.1% {1812ms} FAMIXInheritance(Object)>>mmSetProperty:to: | | | 2.0% {1790ms} FM3PropertyDescription>>setOn:rawValue: | | 1.3% {1131ms} FM3MetaDescription>>attributeNamed:ifAbsent: | 2.3% {2034ms} FMMSEParser>>tFULLNAME | |1.8% {1606ms} Character>>isAlphaNumeric | | 1.6% {1401ms} Character>>isLetter | | 1.5% {1305ms} Character>>characterSet | | 1.5% {1295ms} EncodedCharSet class>>charsetAt: | | 1.5% {1275ms} Array(SequenceableCollection)>>at:ifAbsent: | | 1.4% {1259ms} primitives | 2.3% {1998ms} MSEImporter(FMImporter)>>beginElement: | 2.2% {1948ms} FMFutureElement class>>with:name: | 2.2% {1948ms} FMFutureElement>>with:name: | 2.0% {1774ms} FM3MetaDescription>>createInstance | 2.0% {1740ms} FAMIXLocalVariable class(Behavior)>>new 1.4% {1207ms} MooseModel>>silentlyAddAll: 1.3% {1183ms} MooseModel>>silentlyAdd: -------------------------------- Process: other processes -------------------------------- 64.1% {56239ms} Semaphore>>waitTimeoutMSecs: 64.1% {56239ms} DelayWaitTimeout>>wait **Leaves** 64.1% {56239ms} DelayWaitTimeout>>wait 9.1% {7960ms} Array(SequenceableCollection)>>at:ifAbsent: 4.5% {3922ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: 1.6% {1431ms} ByteSymbol(String)>>=
**Memory** old +134,217,728 bytes young -133,875,776 bytes used +341,952 bytes free +133,875,776 bytes
**GCs** full 8 totalling 57,100ms (65.0% uptime), avg 7138.0ms incr 3317 totalling 14,673ms (17.0% uptime), avg 4.0ms tenures 7,133,411 (avg 0 GCs/tenure) root table 0 overflows
504 Non-spur (50370) - 42377 tallies, 42492 msec.
**Tree** -------------------------------- Process: other processes -------------------------------- 4.0% {1701ms} Semaphore>>waitTimeoutMSecs: 4.0% {1701ms} DelayWaitTimeout>>wait -------------------------------- Process: (40s) Morphic UI Process: nil -------------------------------- 92.3% {39219ms} MooseModel class>>importFrom: |92.2% {39179ms} MooseModel class>>importFrom:withMetamodel: | 92.2% {39175ms} MSEImporter(FMImporter)>>run | 92.2% {39175ms} FMMSEParser>>run | 92.2% {39163ms} FMMSEParser>>basicRun | 92.2% {39163ms} FMMSEParser>>Document | 84.4% {35866ms} FMMSEParser>>Element | |59.5% {25266ms} FMMSEParser>>Attribute | | |23.1% {9814ms} MSEImporter(FMImporter)>>endAttribute: | | | |23.0% {9777ms} FMFutureElement>>endAttribute: | | | | 23.0% {9767ms} FMFutureAttribute>>endAttribute: | | | | 23.0% {9753ms} FMFutureAttribute>>maybeEnd | | | | 12.9% {5465ms} FM3PropertyDescription>>setOn:values: | | | | |12.6% {5363ms} FAMIXInvocation(Object)>>mmSetProperty:to: | | | | | 12.6% {5344ms} FM3PropertyDescription>>setOn:rawValue: | | | | | 3.2% {1378ms} FAMIXLocalVariable(FAMIXStructuralEntity)>>declaredType: | | | | | |3.2% {1378ms} FMMultivalueLink class>>on:update:from:to: | | | | | | 3.2% {1372ms} FMMultivalueLink>>unsafeAdd: | | | | | | 3.2% {1364ms} OrderedCollection(SequenceableCollection)>>includes: | | | | | | 3.2% {1364ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | | | 3.2% {1364ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | | | 3.2% {1364ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | | | | 3.0% {1281ms} primitives | | | | | 2.9% {1219ms} FAMIXMethod(FAMIXBehaviouralEntity)>>declaredType: | | | | | |2.9% {1217ms} FMMultivalueLink class>>on:update:from:to: | | | | | | 2.9% {1217ms} FMMultivalueLink>>unsafeAdd: | | | | | | 2.9% {1217ms} OrderedCollection(SequenceableCollection)>>includes: | | | | | | 2.9% {1217ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | | | 2.9% {1217ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | | | 2.9% {1217ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | | | | 2.7% {1133ms} primitives | | | | | 2.8% {1189ms} FAMIXInvocation>>receiver: | | | | | |2.8% {1187ms} FMMultivalueLink class>>on:update:from:to: | | | | | | 2.8% {1179ms} FMMultivalueLink>>unsafeAdd: | | | | | | 2.8% {1175ms} OrderedCollection(SequenceableCollection)>>includes: | | | | | | 2.8% {1175ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | | | 2.8% {1175ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | | | 2.8% {1175ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | | | | 2.6% {1087ms} primitives | | | | | 1.7% {734ms} ByteSymbol(Symbol)>>asMutator | | | | | 1.6% {694ms} ByteString(String)>>asSymbol | | | | | 1.5% {628ms} Symbol class>>intern: | | | | | 1.5% {626ms} Symbol class>>lookup: | | | | | 1.5% {626ms} WeakSet>>like: | | | | | 1.5% {622ms} WeakSet>>scanFor: | | | | | 1.2% {495ms} ByteString(String)>>hash | | | | | 1.1% {481ms} primitives | | | | 9.9% {4216ms} FM3MetaDescription>>attributeNamed:ifAbsent: | | | | 4.0% {1705ms} FM3MetaDescription>>attributeNamed:ifAbsent: | | | | |1.6% {680ms} FM3MetaDescription>>attributeNamed:ifAbsent: | | | | | |1.2% {501ms} FM3MetaDescription>>attributeNamed:ifAbsent: | | | | |1.3% {574ms} FMMultivalueLink(Collection)>>detect:ifNone: | | | | 2.9% {1252ms} FMMultivalueLink(Collection)>>detect:ifNone: | | | | |2.1% {896ms} FMMultivalueLink(Collection)>>detect:ifFound:ifNone: | | | | | 1.0% {441ms} FMMultivalueLink>>do: | | | | 2.0% {852ms} ByteString(String)>>= | | | | 1.9% {828ms} primitives | | |15.4% {6526ms} FMMSEParser>>tNAME | | | |12.2% {5185ms} Character>>isAlphaNumeric | | | | |10.7% {4561ms} Character>>isLetter | | | | | |9.9% {4212ms} Character>>characterSet | | | | | | 9.8% {4166ms} EncodedCharSet class>>charsetAt: | | | | | | 9.7% {4112ms} Array(SequenceableCollection)>>at:ifAbsent: | | | | | | 9.5% {4052ms} primitives | | | | |1.2% {496ms} Character>>isDigit | | | |1.1% {486ms} Character>>isLetter | | | | 1.0% {444ms} Character>>characterSet | | | | 1.0% {442ms} EncodedCharSet class>>charsetAt: | | | | 1.0% {436ms} Array(SequenceableCollection)>>at:ifAbsent: | | | | 1.0% {426ms} primitives | | |13.2% {5616ms} FMMSEParser>>Value | | | |8.2% {3480ms} FMMSEParser>>Reference | | | | |5.1% {2187ms} FMMSEParser>>Identifier | | | | | |3.7% {1559ms} Character>>isDigit | | | | | | 3.4% {1429ms} Character>>characterSet | | | | | | 3.3% {1419ms} EncodedCharSet class>>charsetAt: | | | | | | 3.3% {1407ms} Array(SequenceableCollection)>>at:ifAbsent: | | | | | | 3.2% {1379ms} primitives | | | | |2.0% {860ms} MSEImporter(FMImporter)>>referenceNumber: | | | | | 2.0% {858ms} FMFutureAttribute>>referenceNumber: | | | |4.3% {1837ms} FMMSEParser>>Primitive | | | | 3.1% {1328ms} FMMSEParser>>Number | | | | 1.9% {794ms} Character>>isDigit | | | | 1.7% {738ms} Character>>characterSet | | | | 1.7% {738ms} EncodedCharSet class>>charsetAt: | | | | 1.7% {730ms} Array(SequenceableCollection)>>at:ifAbsent: | | | | 1.7% {722ms} primitives | | |6.3% {2687ms} MSEImporter(FMImporter)>>beginAttribute: | | | 6.2% {2645ms} FMFutureElement>>beginAttribute: | | | 4.3% {1825ms} PhexMatcher>>beTrue | | | |4.2% {1767ms} PhexMatcher>>true | | | | 3.9% {1675ms} PhexMatcher>>expectedUnknownMessageToReturn: | | | | 2.5% {1077ms} Array(Collection)>>copyWithout: | | | | |2.4% {1041ms} Array(SequenceableCollection)>>reject: | | | | | 1.3% {566ms} Array class(SequenceableCollection class)>>new:streamContents: | | | | | |1.0% {445ms} primitives | | | | | 1.1% {475ms} primitives | | | | 1.4% {578ms} PhexMatcher>>expect:describeShould:describeShouldNot: | | | | 1.2% {527ms} primitives | | | 1.9% {788ms} FMFutureAttribute class>>with:name: | | | 1.8% {778ms} FMFutureAttribute>>with:name: | | | 1.3% {543ms} primitives | |14.6% {6224ms} FMMSEParser>>Serial | | |12.1% {5136ms} MSEImporter(FMImporter)>>serial: | | | |12.1% {5124ms} FMFutureElement>>serial: | | | | 12.1% {5122ms} MSEImporter(FMImporter)>>assign:to: | | | | 9.9% {4215ms} FMDanglingReference>>resolve: | | | | |7.6% {3215ms} FMFutureAttribute>>maybeEnd | | | | | |4.1% {1737ms} FM3PropertyDescription>>setOn:values: | | | | | | |3.9% {1671ms} FAMIXAccess(Object)>>mmSetProperty:to: | | | | | | | 3.9% {1662ms} FM3PropertyDescription>>setOn:rawValue: | | | | | | | 2.1% {888ms} FAMIXParameter(FAMIXStructuralEntity)>>declaredType: | | | | | | | 2.1% {884ms} FMMultivalueLink class>>on:update:from:to: | | | | | | | 2.1% {882ms} FMMultivalueLink>>unsafeAdd: | | | | | | | 2.1% {882ms} OrderedCollection(SequenceableCollection)>>includes: | | | | | | | 2.1% {882ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | | | | 2.1% {882ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | | | | 2.1% {882ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | | | | | 1.8% {776ms} primitives | | | | | |3.4% {1452ms} FM3MetaDescription>>attributeNamed:ifAbsent: | | | | | | 1.5% {650ms} FMMultivalueLink(Collection)>>detect:ifNone: | | | | | | |1.2% {513ms} FMMultivalueLink(Collection)>>detect:ifFound:ifNone: | | | | | | 1.0% {443ms} FM3MetaDescription>>attributeNamed:ifAbsent: | | | | |2.2% {929ms} PhexMatcher>>beTrue | | | | | 2.2% {920ms} PhexMatcher>>true | | | | | 2.1% {874ms} PhexMatcher>>expectedUnknownMessageToReturn: | | | | | 1.4% {582ms} Array(Collection)>>copyWithout: | | | | | 1.3% {574ms} Array(SequenceableCollection)>>reject: | | | | | 1.1% {457ms} Array class(SequenceableCollection class)>>new:streamContents: | | | | 1.1% {481ms} PhexMatcher>>>= | | | | 1.1% {447ms} PhexMatcher>>expect:using: | | | | 1.0% {429ms} PhexMatcher>>expect:describeShould:describeShouldNot: | | |2.3% {962ms} FMMSEParser>>Identifier | | | 1.6% {665ms} Character>>isDigit | | | 1.4% {595ms} Character>>characterSet | | | 1.4% {583ms} EncodedCharSet class>>charsetAt: | | | 1.4% {575ms} Array(SequenceableCollection)>>at:ifAbsent: | | | 1.3% {569ms} primitives | |5.2% {2230ms} FMMSEParser>>tFULLNAME | | |4.1% {1737ms} Character>>isAlphaNumeric | | | 3.6% {1538ms} Character>>isLetter | | | 3.4% {1452ms} Character>>characterSet | | | 3.4% {1438ms} EncodedCharSet class>>charsetAt: | | | 3.3% {1418ms} Array(SequenceableCollection)>>at:ifAbsent: | | | 3.3% {1398ms} primitives | |4.3% {1813ms} MSEImporter(FMImporter)>>beginElement: | | 4.1% {1725ms} FMFutureElement class>>with:name: | | 4.0% {1715ms} FMFutureElement>>with:name: | | 3.7% {1560ms} FM3MetaDescription>>createInstance | | 3.6% {1532ms} FAMIXInvocation class(Behavior)>>new | | 1.3% {544ms} FAMIXMethod>>initialize | | 1.2% {528ms} FAMIXMethod(FAMIXBehaviouralEntity)>>initialize | 7.7% {3289ms} MSEImporter>>endDocument | 7.7% {3289ms} FMRepository>>addAll: | 7.7% {3281ms} FMRepository>>add: | 7.7% {3281ms} IdentitySet(Set)>>add: | 7.2% {3048ms} IdentitySet>>scanFor: | 7.1% {3028ms} primitives 2.9% {1243ms} MooseModel>>silentlyAddAll: 2.9% {1229ms} MooseModel>>silentlyAdd: 2.0% {838ms} MooseModel>>add: 1.6% {700ms} MooseModel(MooseAbstractGroup)>>add: 1.6% {678ms} MooseGroupRuntimeStorage>>add: 1.6% {670ms} MooseGroupRuntimeStorage>>updateCacheFor: **Leaves** 22.8% {9667ms} Array(SequenceableCollection)>>at:ifAbsent: 11.0% {4677ms} Array(SequenceableCollection)>>indexOf:startingAt:ifAbsent: 7.5% {3195ms} IdentitySet>>scanFor: 4.0% {1701ms} DelayWaitTimeout>>wait 3.8% {1624ms} ByteString(String)>>= 2.5% {1073ms} FMMultivalueLink(Collection)>>detect:ifFound:ifNone: 2.2% {935ms} PhexMatcher>>expect:describeShould:describeShouldNot: 2.1% {897ms} FMMultivalueLink(Collection)>>detect:ifNone: 2.1% {880ms} FMMultivalueLink>>do: 2.1% {876ms} WriteStream>>nextPut: 1.6% {670ms} FM3MetaDescription>>attributeNamed:ifAbsent: 1.4% {594ms} Array class(SequenceableCollection class)>>new:streamContents: 1.4% {592ms} Array(SequenceableCollection)>>reject: 1.3% {543ms} FMFutureAttribute>>with:name: 1.2% {523ms} SmallInteger(ProtoObject)>>~~ 1.2% {497ms} ByteString(String)>>hash
**Memory** old +110,336,532 bytes young +169,672 bytes used +110,506,204 bytes free -699,236 bytes
**GCs** full 10 totalling 3,122ms (7.0% uptime), avg 312.0ms incr 3216 totalling 17,586ms (41.0% uptime), avg 5.0ms tenures 2,480 (avg 1 GCs/tenure) root table 0 overflows
Producing less garbage speeds it up
MooseModel>addNoAnnounce: anElement self entityStorage add: anElement. self privateState flushGroups. anElement privateSetMooseModel: self. ^anElement
MooseModel>silentlyAddAll: entities entities do: [:each | self addNoAnnounce: each]. ^entities
- 66218 tallies, 66280 msec.
**Tree** -------------------------------- Process: (40s) Morphic UI Process: nil -------------------------------- 44.9% {29736ms} MooseModel class>>importFrom: |44.8% {29722ms} MooseModel class>>importFrom:withMetamodel: | 44.8% {29714ms} MSEImporter(FMImporter)>>run | 44.8% {29714ms} FMMSEParser>>run | 44.8% {29714ms} FMMSEParser>>basicRun | 44.8% {29714ms} FMMSEParser>>Document | 44.5% {29506ms} FMMSEParser>>Element | 31.3% {20727ms} FMMSEParser>>Attribute | |11.8% {7827ms} MSEImporter(FMImporter)>>endAttribute: | | |11.8% {7819ms} FMFutureElement>>endAttribute: | | | 11.8% {7811ms} FMFutureAttribute>>endAttribute: | | | 11.8% {7795ms} FMFutureAttribute>>maybeEnd | | | 6.4% {4250ms} FM3PropertyDescription>>setOn:values: | | | |6.3% {4154ms} FAMIXFileAnchor(Object)>>mmSetProperty:to: | | | | 6.2% {4130ms} FM3PropertyDescription>>setOn:rawValue: | | | | 1.8% {1175ms} FAMIXLocalVariable(FAMIXStructuralEntity)>>declaredType: | | | | |1.8% {1171ms} FMMultivalueLink class>>on:update:from:to: | | | | | 1.8% {1167ms} FMMultivalueLink>>unsafeAdd: | | | | | 1.7% {1159ms} OrderedCollection(SequenceableCollection)>>includes: | | | | | 1.7% {1159ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | | 1.7% {1159ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | | 1.7% {1159ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | | | 1.7% {1107ms} primitives | | | | 1.4% {951ms} FAMIXMethod(FAMIXBehaviouralEntity)>>declaredType: | | | | |1.4% {951ms} FMMultivalueLink class>>on:update:from:to: | | | | | 1.4% {945ms} FMMultivalueLink>>unsafeAdd: | | | | | 1.4% {939ms} OrderedCollection(SequenceableCollection)>>includes: | | | | | 1.4% {939ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | | 1.4% {939ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | | 1.4% {939ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | | | 1.3% {839ms} primitives | | | | 1.3% {879ms} FAMIXInvocation>>receiver: | | | | 1.3% {879ms} FMMultivalueLink class>>on:update:from:to: | | | | 1.3% {831ms} FMMultivalueLink>>unsafeAdd: | | | | 1.2% {817ms} OrderedCollection(SequenceableCollection)>>includes: | | | | 1.2% {811ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | 1.2% {811ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | 1.2% {811ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | | 1.1% {723ms} primitives | | | 5.3% {3489ms} FM3MetaDescription>>attributeNamed:ifAbsent: | | | 1.9% {1291ms} FMMultivalueLink(Collection)>>detect:ifNone: | | | |1.6% {1089ms} FMMultivalueLink(Collection)>>detect:ifFound:ifNone: | | | | 1.3% {861ms} FMMultivalueLink>>do: | | | | 1.1% {743ms} primitives | | | 1.9% {1289ms} FM3MetaDescription>>attributeNamed:ifAbsent: | |7.8% {5141ms} FMMSEParser>>tNAME | | |6.2% {4122ms} Character>>isAlphaNumeric | | | 4.8% {3201ms} Character>>isLetter | | | |4.4% {2913ms} Character>>characterSet | | | | 4.3% {2863ms} EncodedCharSet class>>charsetAt: | | | | 4.2% {2811ms} Array(SequenceableCollection)>>at:ifAbsent: | | | | 4.2% {2769ms} primitives | | | 1.3% {847ms} Character>>isDigit | | | 1.2% {763ms} Character>>characterSet | | | 1.1% {755ms} EncodedCharSet class>>charsetAt: | | | 1.1% {751ms} Array(SequenceableCollection)>>at:ifAbsent: | | | 1.1% {745ms} primitives | |7.6% {5043ms} FMMSEParser>>Value | | |4.7% {3107ms} FMMSEParser>>Reference | | | |3.0% {1958ms} FMMSEParser>>Identifier | | | | |1.9% {1275ms} Character>>isDigit | | | | | 1.7% {1127ms} Character>>characterSet | | | | | 1.7% {1111ms} EncodedCharSet class>>charsetAt: | | | | | 1.6% {1093ms} Array(SequenceableCollection)>>at:ifAbsent: | | | | | 1.6% {1071ms} primitives | | | |1.1% {721ms} MSEImporter(FMImporter)>>referenceNumber: | | | | 1.1% {715ms} FMFutureAttribute>>referenceNumber: | | |2.4% {1610ms} FMMSEParser>>Primitive | | | 1.9% {1233ms} FMMSEParser>>Number | | | 1.1% {741ms} Character>>isDigit | |3.2% {2150ms} MSEImporter(FMImporter)>>beginAttribute: | | 3.2% {2126ms} FMFutureElement>>beginAttribute: | | 2.7% {1806ms} PhexMatcher>>beTrue | | 2.6% {1756ms} PhexMatcher>>true | | 2.5% {1678ms} PhexMatcher>>expectedUnknownMessageToReturn: | | 1.4% {925ms} Array(Collection)>>copyWithout: | | |1.3% {891ms} Array(SequenceableCollection)>>reject: | | 1.1% {721ms} PhexMatcher>>expect:describeShould:describeShouldNot: | 7.9% {5213ms} FMMSEParser>>Serial | |6.4% {4236ms} MSEImporter(FMImporter)>>serial: | | |6.4% {4226ms} FMFutureElement>>serial: | | | 6.4% {4222ms} MSEImporter(FMImporter)>>assign:to: | | | 5.5% {3617ms} FMDanglingReference>>resolve: | | | 4.5% {2979ms} FMFutureAttribute>>maybeEnd | | | 2.7% {1760ms} FM3PropertyDescription>>setOn:values: | | | |2.5% {1688ms} FAMIXInvocation(Object)>>mmSetProperty:to: | | | | 2.5% {1656ms} FM3PropertyDescription>>setOn:rawValue: | | | | 1.1% {759ms} FAMIXLocalVariable(FAMIXStructuralEntity)>>declaredType: | | | | 1.1% {759ms} FMMultivalueLink class>>on:update:from:to: | | | | 1.1% {739ms} FMMultivalueLink>>unsafeAdd: | | | | 1.1% {739ms} OrderedCollection(SequenceableCollection)>>includes: | | | | 1.1% {739ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | 1.1% {739ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | 1.1% {739ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | 1.8% {1187ms} FM3MetaDescription>>attributeNamed:ifAbsent: | |1.2% {819ms} FMMSEParser>>Identifier | 2.5% {1672ms} FMMSEParser>>tFULLNAME | |1.9% {1275ms} Character>>isAlphaNumeric | | 1.7% {1105ms} Character>>isLetter | | 1.5% {991ms} Character>>characterSet | | 1.5% {977ms} EncodedCharSet class>>charsetAt: | | 1.4% {961ms} Array(SequenceableCollection)>>at:ifAbsent: | | 1.4% {937ms} primitives | 2.4% {1565ms} MSEImporter(FMImporter)>>beginElement: | 2.3% {1523ms} FMFutureElement class>>with:name: | 2.3% {1513ms} FMFutureElement>>with:name: | 2.1% {1361ms} FM3MetaDescription>>createInstance | 2.0% {1313ms} FAMIXInvocation class(Behavior)>>new 1.2% {763ms} MooseModel>>silentlyAddAll: 1.1% {749ms} MooseModel>>addNoAnnounce: -------------------------------- Process: other processes -------------------------------- 43.4% {28751ms} InputEventFetcher>>eventLoop 43.4% {28751ms} InputEventFetcher>>waitForInput 10.1% {6724ms} Semaphore>>waitTimeoutMSecs: 10.1% {6724ms} DelayWaitTimeout>>wait **Leaves** 43.4% {28751ms} InputEventFetcher>>waitForInput 11.3% {7489ms} Array(SequenceableCollection)>>at:ifAbsent: 10.1% {6724ms} DelayWaitTimeout>>wait 5.5% {3615ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: 1.9% {1273ms} ByteSymbol(String)>>= 1.8% {1175ms} FMMultivalueLink>>do: 1.6% {1073ms} PhexMatcher>>expect:describeShould:describeShouldNot: 1.2% {787ms} WriteStream>>nextPut: 1.0% {677ms} UndefinedObject(ProtoObject)>>~~ 1.0% {671ms} FMMultivalueLink(Collection)>>detect:ifFound:ifNone:
**Memory** old +167,772,160 bytes young -167,290,864 bytes used +481,296 bytes free +167,290,864 bytes
**GCs** full 9 totalling 36,946ms (56.0% uptime), avg 4105.0ms incr 3179 totalling 13,809ms (21.0% uptime), avg 4.0ms tenures 7,162,840 (avg 0 GCs/tenure) root table 0 overflows
this is interesting now I would be curious to understand why spur gc is more busy.
Stef
Le 24/1/16 15:40, Stephan Eggermont a écrit :
Producing less garbage speeds it up
MooseModel>addNoAnnounce: anElement self entityStorage add: anElement. self privateState flushGroups. anElement privateSetMooseModel: self. ^anElement
MooseModel>silentlyAddAll: entities
entities do: [:each | self addNoAnnounce: each]. ^entities
- 66218 tallies, 66280 msec.
**Tree**
Process: (40s) Morphic UI Process: nil
44.9% {29736ms} MooseModel class>>importFrom: |44.8% {29722ms} MooseModel class>>importFrom:withMetamodel: | 44.8% {29714ms} MSEImporter(FMImporter)>>run | 44.8% {29714ms} FMMSEParser>>run | 44.8% {29714ms} FMMSEParser>>basicRun | 44.8% {29714ms} FMMSEParser>>Document | 44.5% {29506ms} FMMSEParser>>Element | 31.3% {20727ms} FMMSEParser>>Attribute | |11.8% {7827ms} MSEImporter(FMImporter)>>endAttribute: | | |11.8% {7819ms} FMFutureElement>>endAttribute: | | | 11.8% {7811ms} FMFutureAttribute>>endAttribute: | | | 11.8% {7795ms} FMFutureAttribute>>maybeEnd | | | 6.4% {4250ms} FM3PropertyDescription>>setOn:values: | | | |6.3% {4154ms} FAMIXFileAnchor(Object)>>mmSetProperty:to: | | | | 6.2% {4130ms} FM3PropertyDescription>>setOn:rawValue: | | | | 1.8% {1175ms} FAMIXLocalVariable(FAMIXStructuralEntity)>>declaredType: | | | | |1.8% {1171ms} FMMultivalueLink class>>on:update:from:to: | | | | | 1.8% {1167ms} FMMultivalueLink>>unsafeAdd: | | | | | 1.7% {1159ms} OrderedCollection(SequenceableCollection)>>includes: | | | | | 1.7% {1159ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | | 1.7% {1159ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | | 1.7% {1159ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | | | 1.7% {1107ms} primitives | | | | 1.4% {951ms} FAMIXMethod(FAMIXBehaviouralEntity)>>declaredType: | | | | |1.4% {951ms} FMMultivalueLink class>>on:update:from:to: | | | | | 1.4% {945ms} FMMultivalueLink>>unsafeAdd: | | | | | 1.4% {939ms} OrderedCollection(SequenceableCollection)>>includes: | | | | | 1.4% {939ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | | 1.4% {939ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | | 1.4% {939ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | | | 1.3% {839ms} primitives | | | | 1.3% {879ms} FAMIXInvocation>>receiver: | | | | 1.3% {879ms} FMMultivalueLink class>>on:update:from:to: | | | | 1.3% {831ms} FMMultivalueLink>>unsafeAdd: | | | | 1.2% {817ms} OrderedCollection(SequenceableCollection)>>includes: | | | | 1.2% {811ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | 1.2% {811ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | 1.2% {811ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | | 1.1% {723ms} primitives | | | 5.3% {3489ms} FM3MetaDescription>>attributeNamed:ifAbsent: | | | 1.9% {1291ms} FMMultivalueLink(Collection)>>detect:ifNone: | | | |1.6% {1089ms} FMMultivalueLink(Collection)>>detect:ifFound:ifNone: | | | | 1.3% {861ms} FMMultivalueLink>>do: | | | | 1.1% {743ms} primitives | | | 1.9% {1289ms} FM3MetaDescription>>attributeNamed:ifAbsent: | |7.8% {5141ms} FMMSEParser>>tNAME | | |6.2% {4122ms} Character>>isAlphaNumeric | | | 4.8% {3201ms} Character>>isLetter | | | |4.4% {2913ms} Character>>characterSet | | | | 4.3% {2863ms} EncodedCharSet class>>charsetAt: | | | | 4.2% {2811ms} Array(SequenceableCollection)>>at:ifAbsent: | | | | 4.2% {2769ms} primitives | | | 1.3% {847ms} Character>>isDigit | | | 1.2% {763ms} Character>>characterSet | | | 1.1% {755ms} EncodedCharSet class>>charsetAt: | | | 1.1% {751ms} Array(SequenceableCollection)>>at:ifAbsent: | | | 1.1% {745ms} primitives | |7.6% {5043ms} FMMSEParser>>Value | | |4.7% {3107ms} FMMSEParser>>Reference | | | |3.0% {1958ms} FMMSEParser>>Identifier | | | | |1.9% {1275ms} Character>>isDigit | | | | | 1.7% {1127ms} Character>>characterSet | | | | | 1.7% {1111ms} EncodedCharSet class>>charsetAt: | | | | | 1.6% {1093ms} Array(SequenceableCollection)>>at:ifAbsent: | | | | | 1.6% {1071ms} primitives | | | |1.1% {721ms} MSEImporter(FMImporter)>>referenceNumber: | | | | 1.1% {715ms} FMFutureAttribute>>referenceNumber: | | |2.4% {1610ms} FMMSEParser>>Primitive | | | 1.9% {1233ms} FMMSEParser>>Number | | | 1.1% {741ms} Character>>isDigit | |3.2% {2150ms} MSEImporter(FMImporter)>>beginAttribute: | | 3.2% {2126ms} FMFutureElement>>beginAttribute: | | 2.7% {1806ms} PhexMatcher>>beTrue | | 2.6% {1756ms} PhexMatcher>>true | | 2.5% {1678ms} PhexMatcher>>expectedUnknownMessageToReturn: | | 1.4% {925ms} Array(Collection)>>copyWithout: | | |1.3% {891ms} Array(SequenceableCollection)>>reject: | | 1.1% {721ms} PhexMatcher>>expect:describeShould:describeShouldNot: | 7.9% {5213ms} FMMSEParser>>Serial | |6.4% {4236ms} MSEImporter(FMImporter)>>serial: | | |6.4% {4226ms} FMFutureElement>>serial: | | | 6.4% {4222ms} MSEImporter(FMImporter)>>assign:to: | | | 5.5% {3617ms} FMDanglingReference>>resolve: | | | 4.5% {2979ms} FMFutureAttribute>>maybeEnd | | | 2.7% {1760ms} FM3PropertyDescription>>setOn:values: | | | |2.5% {1688ms} FAMIXInvocation(Object)>>mmSetProperty:to: | | | | 2.5% {1656ms} FM3PropertyDescription>>setOn:rawValue: | | | | 1.1% {759ms} FAMIXLocalVariable(FAMIXStructuralEntity)>>declaredType: | | | | 1.1% {759ms} FMMultivalueLink class>>on:update:from:to: | | | | 1.1% {739ms} FMMultivalueLink>>unsafeAdd: | | | | 1.1% {739ms} OrderedCollection(SequenceableCollection)>>includes: | | | | 1.1% {739ms} OrderedCollection(SequenceableCollection)>>indexOf: | | | | 1.1% {739ms} OrderedCollection(SequenceableCollection)>>indexOf:ifAbsent: | | | | 1.1% {739ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: | | | 1.8% {1187ms} FM3MetaDescription>>attributeNamed:ifAbsent: | |1.2% {819ms} FMMSEParser>>Identifier | 2.5% {1672ms} FMMSEParser>>tFULLNAME | |1.9% {1275ms} Character>>isAlphaNumeric | | 1.7% {1105ms} Character>>isLetter | | 1.5% {991ms} Character>>characterSet | | 1.5% {977ms} EncodedCharSet class>>charsetAt: | | 1.4% {961ms} Array(SequenceableCollection)>>at:ifAbsent: | | 1.4% {937ms} primitives | 2.4% {1565ms} MSEImporter(FMImporter)>>beginElement: | 2.3% {1523ms} FMFutureElement class>>with:name: | 2.3% {1513ms} FMFutureElement>>with:name: | 2.1% {1361ms} FM3MetaDescription>>createInstance | 2.0% {1313ms} FAMIXInvocation class(Behavior)>>new 1.2% {763ms} MooseModel>>silentlyAddAll:
1.1% {749ms} MooseModel>>addNoAnnounce:
Process: other processes
43.4% {28751ms} InputEventFetcher>>eventLoop 43.4% {28751ms} InputEventFetcher>>waitForInput 10.1% {6724ms} Semaphore>>waitTimeoutMSecs: 10.1% {6724ms} DelayWaitTimeout>>wait **Leaves** 43.4% {28751ms} InputEventFetcher>>waitForInput 11.3% {7489ms} Array(SequenceableCollection)>>at:ifAbsent: 10.1% {6724ms} DelayWaitTimeout>>wait 5.5% {3615ms} OrderedCollection(SequenceableCollection)>>indexOf:startingAt:ifAbsent: 1.9% {1273ms} ByteSymbol(String)>>= 1.8% {1175ms} FMMultivalueLink>>do: 1.6% {1073ms} PhexMatcher>>expect:describeShould:describeShouldNot: 1.2% {787ms} WriteStream>>nextPut: 1.0% {677ms} UndefinedObject(ProtoObject)>>~~ 1.0% {671ms} FMMultivalueLink(Collection)>>detect:ifFound:ifNone:
**Memory** old +167,772,160 bytes young -167,290,864 bytes used +481,296 bytes free +167,290,864 bytes
**GCs** full 9 totalling 36,946ms (56.0% uptime), avg 4105.0ms incr 3179 totalling 13,809ms (21.0% uptime), avg 4.0ms tenures 7,162,840 (avg 0 GCs/tenure) root table 0 overflows
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
On 24-01-16 15:40, Stephan Eggermont wrote:
Producing less garbage speeds it up
- 66218 tallies, 66280 msec.
Hmm, can't reproduce it. It is now again just about as slow as it was.
Stephan
Hi Vincent,
I'll take a look early this week. There's clearly a bug; the Spur GC is /not/ collecting those dictionaries :-( (thanks Stephan!). Assuming the bug is fixed times should come down (see below). It may be that the bug in Slang that I introduced in December has broken things because I don't see these symptoms in my daily work (but I use the most up-to-date VM version possible ;-) ). But I'm not in denial and look forward to using MOOSE as a good stress case.
I do want to say that the GC is not complete. Right now we have a scavenger that works well, and a global GC that has a slow compaction algorithm, and hence there are significant pauses. For example here's what I see as typical in using SPur for VMMaker work:
memory 160,432,128 bytes old 153,658,624 bytes (95.8%) young 4,838,224 bytes (3%) used 127,009,928 bytes (79.2%) free 28,126,456 bytes (17.5%) GCs 7,265 (?? ms between GCs) full 36 totalling 13,229 ms (0% uptime), avg 367.5 ms incr 7,229 totalling 6,546 ms (0% uptime), avg 0.9 ms tenures 3,589,063 (avg 0 GCs/tenure)
(There's no uptime in the above stats because we're still transitioning Squeak to the 64-bit clock and there are consequently bugs in computing uptime).
The plan is to add an incremental global GC so this work is broken up into much smaller pieces. I don't want to see 700ms pauses in global GC; one can't do game animation with that. So an incremental mark-sweep is needed. There are two nice papers we're considering, one from Lua and one for a truly concurrent collector. But time is pressing, so if anyone out there knows GC and is interested in helping this is a nicely self-contained project for which we'd love to have volunteers.
_,,,^..^,,,_ (phone)
On Jan 24, 2016, at 3:43 AM, Vincent BLONDEAU vincent.blondeau@polytech-lille.net wrote:
Hi,
I made the benchmarks with the files you provided. I have more or less the same magnitude: Version 504: 0:00:01:09.021 Version 1175: 0:00:02:37.507
However, by launching it in the time profiler (MooseModel new importFromMSEStream: (StandardFileStream readOnlyFileNamed: 'd:/ArgoUML-0-34.mse')), it takes 504: 1 min 55 1175: 4 min 25 Well there is a delta...
After investigation, the standard process has almost the same duration (120 secs for prespur and 140 secs for spur). But, there is a large difference in GC time:
504: not spur **Memory** old +144,822,000 bytes young -8,293,660 bytes used +136,528,340 bytes free -104,186,788 bytes
**GCs** full 1 totalling 965ms (1.0% uptime), avg 965.0ms incr 3264 totalling 42,279ms (33.0% uptime), avg 13.0ms tenures 2,497 (avg 1 GCs/tenure) root table 0 overflows
1175: spur **Memory** old +0 bytes young +340,048 bytes used +340,048 bytes free -340,048 bytes **GCs** full 7 totalling 145,003ms (66.0% uptime), avg 20715.0ms incr 3288 totalling 30,912ms (14.0% uptime), avg 9.0ms tenures 7,146,505 (avg 0 GCs/tenure) root table 0 overflows
Total GC time 504: 43 secs 1175: 176 secs
See the performance reports attached.
I let VM people take care of the issue ;)
Cheers, Vincent
-----Original Message----- From: moose-dev-bounces@list.inf.unibe.ch [mailto:moose-dev-bounces@list.inf.unibe.ch] On Behalf Of Tudor Girba Sent: dimanche 24 janvier 2016 09:08 To: Moose-related development Subject: [Moose-dev] Re: mse loading looks slower :(
Hi,
I am talking about the difference between Moose 6 images:
- October 7:
https://ci.inria.fr/moose/job/moose-6.0/504/artifact/moose-6.0.zip
- yesterday:
https://ci.inria.fr/moose/job/moose-6.0/1175/artifact/moose-6.0.zip
Multiple things did change, but not in Moose. In the end, I would like to understand where the slowness comes. Maybe it comes from Spur itself, but maybe it comes from somewhere else.
Cheers, Doru
On Jan 24, 2016, at 1:41 AM, Mariano Martinez Peck marianopeck@gmail.com
wrote:
Doru...just to be sure it is not a Pharo (image change), when you said
before and after Spur, do you mean a Pharo 5.0 exactly (just before Spur) and a Pharo JUST after it? Otherwise, the slowness may come from the difference between the 2 Pharos you are running.
Cheers,
On Sat, Jan 23, 2016 at 5:55 PM, Tudor Girba tudor@tudorgirba.com wrote: Hi,
I am doing some performance testing of Moose with the Spur VM on Mac.
I tried to load an MSE file with ArgoUML 0.34 and on my machine it loads
twice as slow with Spur than before:
- PreSpur: 0:00:01:07.272
- Spur: 0:00:02:10.508
Here is the reference file: https://dl.dropboxusercontent.com/u/18323746/Tmp/ArgoUML-0-34.mse.zip
And here is the script: [ MooseModel new importFromMSEStream: (StandardFileStream
readOnlyFileNamed:
(FileSystem workingDirectory / 'src' /'ArgoUML-0-34' / 'ArgoUML-0-34.mse') fullName).
] timeToRunDo you get the same?
Cheers, Doru
-- www.tudorgirba.com www.feenk.com
"Problem solving should be focused on describing the problem in a way that makes the solution obvious."
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- Mariano http://marianopeck.wordpress.com _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- www.tudorgirba.com www.feenk.com
"What is more important: To be happy, or to make happy?"
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev <report504.txt> <report1175.txt>
Hi Eliot,
Thanks for looking at this.
Please let us know what support you need, or what kind of experiments we can do on our side.
Cheers, Doru
On Jan 24, 2016, at 9:20 PM, Eliot Miranda eliot.miranda@gmail.com wrote:
Hi Vincent,
I'll take a look early this week. There's clearly a bug; the Spur GC is /not/ collecting those dictionaries :-( (thanks Stephan!). Assuming the bug is fixed times should come down (see below). It may be that the bug in Slang that I introduced in December has broken things because I don't see these symptoms in my daily work (but I use the most up-to-date VM version possible ;-) ). But I'm not in denial and look forward to using MOOSE as a good stress case.
I do want to say that the GC is not complete. Right now we have a scavenger that works well, and a global GC that has a slow compaction algorithm, and hence there are significant pauses. For example here's what I see as typical in using SPur for VMMaker work:
memory 160,432,128 bytes old 153,658,624 bytes (95.8%) young 4,838,224 bytes (3%) used 127,009,928 bytes (79.2%) free 28,126,456 bytes (17.5%) GCs 7,265 (?? ms between GCs) full 36 totalling 13,229 ms (0% uptime), avg 367.5 ms incr 7,229 totalling 6,546 ms (0% uptime), avg 0.9 ms tenures 3,589,063 (avg 0 GCs/tenure)
(There's no uptime in the above stats because we're still transitioning Squeak to the 64-bit clock and there are consequently bugs in computing uptime).
The plan is to add an incremental global GC so this work is broken up into much smaller pieces. I don't want to see 700ms pauses in global GC; one can't do game animation with that. So an incremental mark-sweep is needed. There are two nice papers we're considering, one from Lua and one for a truly concurrent collector. But time is pressing, so if anyone out there knows GC and is interested in helping this is a nicely self-contained project for which we'd love to have volunteers.
_,,,^..^,,,_ (phone)
On Jan 24, 2016, at 3:43 AM, Vincent BLONDEAU vincent.blondeau@polytech-lille.net wrote:
Hi,
I made the benchmarks with the files you provided. I have more or less the same magnitude: Version 504: 0:00:01:09.021 Version 1175: 0:00:02:37.507
However, by launching it in the time profiler (MooseModel new importFromMSEStream: (StandardFileStream readOnlyFileNamed: 'd:/ArgoUML-0-34.mse')), it takes 504: 1 min 55 1175: 4 min 25 Well there is a delta...
After investigation, the standard process has almost the same duration (120 secs for prespur and 140 secs for spur). But, there is a large difference in GC time:
504: not spur **Memory** old +144,822,000 bytes young -8,293,660 bytes used +136,528,340 bytes free -104,186,788 bytes
**GCs** full 1 totalling 965ms (1.0% uptime), avg 965.0ms incr 3264 totalling 42,279ms (33.0% uptime), avg 13.0ms tenures 2,497 (avg 1 GCs/tenure) root table 0 overflows
1175: spur **Memory** old +0 bytes young +340,048 bytes used +340,048 bytes free -340,048 bytes **GCs** full 7 totalling 145,003ms (66.0% uptime), avg 20715.0ms incr 3288 totalling 30,912ms (14.0% uptime), avg 9.0ms tenures 7,146,505 (avg 0 GCs/tenure) root table 0 overflows
Total GC time 504: 43 secs 1175: 176 secs
See the performance reports attached.
I let VM people take care of the issue ;)
Cheers, Vincent
-----Original Message----- From: moose-dev-bounces@list.inf.unibe.ch [mailto:moose-dev-bounces@list.inf.unibe.ch] On Behalf Of Tudor Girba Sent: dimanche 24 janvier 2016 09:08 To: Moose-related development Subject: [Moose-dev] Re: mse loading looks slower :(
Hi,
I am talking about the difference between Moose 6 images:
- October 7:
https://ci.inria.fr/moose/job/moose-6.0/504/artifact/moose-6.0.zip
- yesterday:
https://ci.inria.fr/moose/job/moose-6.0/1175/artifact/moose-6.0.zip
Multiple things did change, but not in Moose. In the end, I would like to understand where the slowness comes. Maybe it comes from Spur itself, but maybe it comes from somewhere else.
Cheers, Doru
On Jan 24, 2016, at 1:41 AM, Mariano Martinez Peck marianopeck@gmail.com
wrote:
Doru...just to be sure it is not a Pharo (image change), when you said
before and after Spur, do you mean a Pharo 5.0 exactly (just before Spur) and a Pharo JUST after it? Otherwise, the slowness may come from the difference between the 2 Pharos you are running.
Cheers,
On Sat, Jan 23, 2016 at 5:55 PM, Tudor Girba tudor@tudorgirba.com wrote: Hi,
I am doing some performance testing of Moose with the Spur VM on Mac.
I tried to load an MSE file with ArgoUML 0.34 and on my machine it loads
twice as slow with Spur than before:
- PreSpur: 0:00:01:07.272
- Spur: 0:00:02:10.508
Here is the reference file: https://dl.dropboxusercontent.com/u/18323746/Tmp/ArgoUML-0-34.mse.zip
And here is the script: [ MooseModel new importFromMSEStream: (StandardFileStream
readOnlyFileNamed:
(FileSystem workingDirectory / 'src' /'ArgoUML-0-34' / 'ArgoUML-0-34.mse') fullName).
] timeToRunDo you get the same?
Cheers, Doru
-- www.tudorgirba.com www.feenk.com
"Problem solving should be focused on describing the problem in a way that makes the solution obvious."
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- Mariano http://marianopeck.wordpress.com _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- www.tudorgirba.com www.feenk.com
"What is more important: To be happy, or to make happy?"
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev <report504.txt> <report1175.txt>
Hi Doru,
On Sun, Jan 24, 2016 at 12:26 PM, Tudor Girba tudor@tudorgirba.com wrote:
Hi Eliot,
Thanks for looking at this.
Please let us know what support you need, or what kind of experiments we can do on our side.
What I want most of all is a test case that I can run on Mac. I'm assuming that I can just copy the job that Vincent mentioned in his email and use that as a test case. Do you see any issues with that? If so, how do I get a really bug MOOSE test case to run on Mac?
Cheers, Doru
On Jan 24, 2016, at 9:20 PM, Eliot Miranda eliot.miranda@gmail.com
wrote:
Hi Vincent,
I'll take a look early this week. There's clearly a bug; the Spur GC is /not/ collecting those dictionaries :-( (thanks Stephan!). Assuming the bug is fixed times should come down (see below). It may be that the bug in Slang that I introduced in December has broken things because I don't see these symptoms in my daily work (but I use the most up-to-date VM version possible ;-) ). But I'm not in denial and look forward to using MOOSE as a good stress case.
I do want to say that the GC is not complete. Right now we have a scavenger that works well, and a global GC that has a slow compaction algorithm, and hence there are significant pauses. For example here's what I see as typical in using SPur for VMMaker work:
memory 160,432,128 bytes old 153,658,624 bytes (95.8%) young 4,838,224 bytes (3%) used 127,009,928 bytes (79.2%) free 28,126,456 bytes (17.5%) GCs 7,265 (?? ms between GCs) full 36 totalling 13,229 ms (0% uptime), avg 367.5 ms incr 7,229 totalling 6,546 ms (0% uptime), avg 0.9 ms tenures 3,589,063 (avg 0 GCs/tenure)
(There's no uptime in the above stats because we're still transitioning Squeak to the 64-bit clock and there are consequently bugs in computing uptime).
The plan is to add an incremental global GC so this work is broken up into much smaller pieces. I don't want to see 700ms pauses in global GC; one can't do game animation with that. So an incremental mark-sweep is needed. There are two nice papers we're considering, one from Lua and one for a truly concurrent collector. But time is pressing, so if anyone out there knows GC and is interested in helping this is a nicely self-contained project for which we'd love to have volunteers.
_,,,^..^,,,_ (phone)
On Jan 24, 2016, at 3:43 AM, Vincent BLONDEAU <
vincent.blondeau@polytech-lille.net> wrote:
Hi,
I made the benchmarks with the files you provided. I have more or less
the
same magnitude: Version 504: 0:00:01:09.021 Version 1175: 0:00:02:37.507
However, by launching it in the time profiler (MooseModel new importFromMSEStream: (StandardFileStream readOnlyFileNamed: 'd:/ArgoUML-0-34.mse')), it takes 504: 1 min 55 1175: 4 min 25 Well there is a delta...
After investigation, the standard process has almost the same duration
(120
secs for prespur and 140 secs for spur). But, there is a large difference in GC time:
504: not spur **Memory** old +144,822,000 bytes young -8,293,660 bytes used +136,528,340 bytes free -104,186,788 bytes
**GCs** full 1 totalling 965ms (1.0% uptime), avg 965.0ms incr 3264 totalling 42,279ms (33.0% uptime), avg 13.0ms tenures 2,497 (avg 1 GCs/tenure) root table 0 overflows
1175: spur **Memory** old +0 bytes young +340,048 bytes used +340,048 bytes free -340,048 bytes **GCs** full 7 totalling 145,003ms (66.0% uptime), avg 20715.0ms incr 3288 totalling 30,912ms (14.0% uptime), avg 9.0ms tenures 7,146,505 (avg 0 GCs/tenure) root table 0 overflows
Total GC time 504: 43 secs 1175: 176 secs
See the performance reports attached.
I let VM people take care of the issue ;)
Cheers, Vincent
-----Original Message----- From: moose-dev-bounces@list.inf.unibe.ch [mailto:moose-dev-bounces@list.inf.unibe.ch] On Behalf Of Tudor Girba Sent: dimanche 24 janvier 2016 09:08 To: Moose-related development Subject: [Moose-dev] Re: mse loading looks slower :(
Hi,
I am talking about the difference between Moose 6 images:
- October 7:
https://ci.inria.fr/moose/job/moose-6.0/504/artifact/moose-6.0.zip
- yesterday:
https://ci.inria.fr/moose/job/moose-6.0/1175/artifact/moose-6.0.zip
Multiple things did change, but not in Moose. In the end, I would like
to
understand where the slowness comes. Maybe it comes from Spur itself,
but
maybe it comes from somewhere else.
Cheers, Doru
On Jan 24, 2016, at 1:41 AM, Mariano Martinez Peck <
marianopeck@gmail.com>
wrote:
Doru...just to be sure it is not a Pharo (image change), when you said
before and after Spur, do you mean a Pharo 5.0 exactly (just before
Spur)
and a Pharo JUST after it? Otherwise, the slowness may come from the difference between the 2 Pharos you are running.
Cheers,
On Sat, Jan 23, 2016 at 5:55 PM, Tudor Girba tudor@tudorgirba.com
wrote:
Hi,
I am doing some performance testing of Moose with the Spur VM on Mac.
I tried to load an MSE file with ArgoUML 0.34 and on my machine it
loads
twice as slow with Spur than before:
- PreSpur: 0:00:01:07.272
- Spur: 0:00:02:10.508
Here is the reference file: https://dl.dropboxusercontent.com/u/18323746/Tmp/ArgoUML-0-34.mse.zip
And here is the script: [ MooseModel new importFromMSEStream: (StandardFileStream
readOnlyFileNamed:
(FileSystem workingDirectory / 'src' /'ArgoUML-0-34' / 'ArgoUML-0-34.mse') fullName).
] timeToRunDo you get the same?
Cheers, Doru
-- www.tudorgirba.com www.feenk.com
"Problem solving should be focused on describing the problem in a way that makes the solution obvious."
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- Mariano http://marianopeck.wordpress.com _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- www.tudorgirba.com www.feenk.com
"What is more important: To be happy, or to make happy?"
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev <report504.txt> <report1175.txt>
Hi Eliot,
I created a package to easily reproduce the problem: https://dl.dropboxusercontent.com/u/18323746/Tmp/moose-6-for-GC-bug.zip
In there you will get: - an image, - the MSE file to be loaded, and - a Playground script that loads that file.
On my Mac, this takes some 3 minutes, while before it took about 1 minute.
Let me know if you need anything else.
Cheers, Doru
On Jan 24, 2016, at 9:33 PM, Eliot Miranda eliot.miranda@gmail.com wrote:
Hi Doru,
On Sun, Jan 24, 2016 at 12:26 PM, Tudor Girba tudor@tudorgirba.com wrote: Hi Eliot,
Thanks for looking at this.
Please let us know what support you need, or what kind of experiments we can do on our side.
What I want most of all is a test case that I can run on Mac. I'm assuming that I can just copy the job that Vincent mentioned in his email and use that as a test case. Do you see any issues with that? If so, how do I get a really bug MOOSE test case to run on Mac?
Cheers, Doru
On Jan 24, 2016, at 9:20 PM, Eliot Miranda eliot.miranda@gmail.com wrote:
Hi Vincent,
I'll take a look early this week. There's clearly a bug; the Spur GC is /not/ collecting those dictionaries :-( (thanks Stephan!). Assuming the bug is fixed times should come down (see below). It may be that the bug in Slang that I introduced in December has broken things because I don't see these symptoms in my daily work (but I use the most up-to-date VM version possible ;-) ). But I'm not in denial and look forward to using MOOSE as a good stress case.
I do want to say that the GC is not complete. Right now we have a scavenger that works well, and a global GC that has a slow compaction algorithm, and hence there are significant pauses. For example here's what I see as typical in using SPur for VMMaker work:
memory 160,432,128 bytes old 153,658,624 bytes (95.8%) young 4,838,224 bytes (3%) used 127,009,928 bytes (79.2%) free 28,126,456 bytes (17.5%) GCs 7,265 (?? ms between GCs) full 36 totalling 13,229 ms (0% uptime), avg 367.5 ms incr 7,229 totalling 6,546 ms (0% uptime), avg 0.9 ms tenures 3,589,063 (avg 0 GCs/tenure)
(There's no uptime in the above stats because we're still transitioning Squeak to the 64-bit clock and there are consequently bugs in computing uptime).
The plan is to add an incremental global GC so this work is broken up into much smaller pieces. I don't want to see 700ms pauses in global GC; one can't do game animation with that. So an incremental mark-sweep is needed. There are two nice papers we're considering, one from Lua and one for a truly concurrent collector. But time is pressing, so if anyone out there knows GC and is interested in helping this is a nicely self-contained project for which we'd love to have volunteers.
_,,,^..^,,,_ (phone)
On Jan 24, 2016, at 3:43 AM, Vincent BLONDEAU vincent.blondeau@polytech-lille.net wrote:
Hi,
I made the benchmarks with the files you provided. I have more or less the same magnitude: Version 504: 0:00:01:09.021 Version 1175: 0:00:02:37.507
However, by launching it in the time profiler (MooseModel new importFromMSEStream: (StandardFileStream readOnlyFileNamed: 'd:/ArgoUML-0-34.mse')), it takes 504: 1 min 55 1175: 4 min 25 Well there is a delta...
After investigation, the standard process has almost the same duration (120 secs for prespur and 140 secs for spur). But, there is a large difference in GC time:
504: not spur **Memory** old +144,822,000 bytes young -8,293,660 bytes used +136,528,340 bytes free -104,186,788 bytes
**GCs** full 1 totalling 965ms (1.0% uptime), avg 965.0ms incr 3264 totalling 42,279ms (33.0% uptime), avg 13.0ms tenures 2,497 (avg 1 GCs/tenure) root table 0 overflows
1175: spur **Memory** old +0 bytes young +340,048 bytes used +340,048 bytes free -340,048 bytes **GCs** full 7 totalling 145,003ms (66.0% uptime), avg 20715.0ms incr 3288 totalling 30,912ms (14.0% uptime), avg 9.0ms tenures 7,146,505 (avg 0 GCs/tenure) root table 0 overflows
Total GC time 504: 43 secs 1175: 176 secs
See the performance reports attached.
I let VM people take care of the issue ;)
Cheers, Vincent
-----Original Message----- From: moose-dev-bounces@list.inf.unibe.ch [mailto:moose-dev-bounces@list.inf.unibe.ch] On Behalf Of Tudor Girba Sent: dimanche 24 janvier 2016 09:08 To: Moose-related development Subject: [Moose-dev] Re: mse loading looks slower :(
Hi,
I am talking about the difference between Moose 6 images:
- October 7:
https://ci.inria.fr/moose/job/moose-6.0/504/artifact/moose-6.0.zip
- yesterday:
https://ci.inria.fr/moose/job/moose-6.0/1175/artifact/moose-6.0.zip
Multiple things did change, but not in Moose. In the end, I would like to understand where the slowness comes. Maybe it comes from Spur itself, but maybe it comes from somewhere else.
Cheers, Doru
On Jan 24, 2016, at 1:41 AM, Mariano Martinez Peck marianopeck@gmail.com
wrote:
Doru...just to be sure it is not a Pharo (image change), when you said
before and after Spur, do you mean a Pharo 5.0 exactly (just before Spur) and a Pharo JUST after it? Otherwise, the slowness may come from the difference between the 2 Pharos you are running.
Cheers,
On Sat, Jan 23, 2016 at 5:55 PM, Tudor Girba tudor@tudorgirba.com wrote: Hi,
I am doing some performance testing of Moose with the Spur VM on Mac.
I tried to load an MSE file with ArgoUML 0.34 and on my machine it loads
twice as slow with Spur than before:
- PreSpur: 0:00:01:07.272
- Spur: 0:00:02:10.508
Here is the reference file: https://dl.dropboxusercontent.com/u/18323746/Tmp/ArgoUML-0-34.mse.zip
And here is the script: [ MooseModel new importFromMSEStream: (StandardFileStream
readOnlyFileNamed:
(FileSystem workingDirectory / 'src' /'ArgoUML-0-34' / 'ArgoUML-0-34.mse') fullName).
] timeToRunDo you get the same?
Cheers, Doru
-- www.tudorgirba.com www.feenk.com
"Problem solving should be focused on describing the problem in a way that makes the solution obvious."
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- Mariano http://marianopeck.wordpress.com _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- www.tudorgirba.com www.feenk.com
"What is more important: To be happy, or to make happy?"
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev <report504.txt> <report1175.txt>
-- _,,,^..^,,,_ best, Eliot _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
On Sun, Jan 24, 2016 at 12:42 PM, Tudor Girba tudor@tudorgirba.com wrote:
Hi Eliot,
I created a package to easily reproduce the problem: https://dl.dropboxusercontent.com/u/18323746/Tmp/moose-6-for-GC-bug.zip
In there you will get:
- an image,
- the MSE file to be loaded, and
- a Playground script that loads that file.
That sounds perfect.
On my Mac, this takes some 3 minutes, while before it took about 1 minute.
What's the system info on your Mac? Mine is "*Version* 10.9.5 *Processor* 2.2GHz Intel Core i7 *Memory* 16Gb 1333 MHz DDR3"
Let me know if you need anything else.
Cheers, Doru
On Jan 24, 2016, at 9:33 PM, Eliot Miranda eliot.miranda@gmail.com
wrote:
Hi Doru,
On Sun, Jan 24, 2016 at 12:26 PM, Tudor Girba tudor@tudorgirba.com
wrote:
Hi Eliot,
Thanks for looking at this.
Please let us know what support you need, or what kind of experiments we
can do on our side.
What I want most of all is a test case that I can run on Mac. I'm
assuming that I can just copy the job that Vincent mentioned in his email and use that as a test case. Do you see any issues with that? If so, how do I get a really bug MOOSE test case to run on Mac?
Cheers, Doru
On Jan 24, 2016, at 9:20 PM, Eliot Miranda eliot.miranda@gmail.com
wrote:
Hi Vincent,
I'll take a look early this week. There's clearly a bug; the Spur GC is /not/ collecting those dictionaries :-( (thanks Stephan!). Assuming the bug is fixed times should come down (see below). It may be that the bug in Slang that I introduced in December has broken things because I don't see these symptoms in my daily work (but I use the most up-to-date VM version possible ;-) ). But I'm not in denial and look forward to using MOOSE as a good stress case.
I do want to say that the GC is not complete. Right now we have a scavenger that works well, and a global GC that has a slow compaction algorithm, and hence there are significant pauses. For example here's what I see as typical in using SPur for VMMaker work:
memory 160,432,128 bytes old 153,658,624 bytes (95.8%) young 4,838,224 bytes (3%) used 127,009,928 bytes (79.2%) free 28,126,456 bytes (17.5%) GCs 7,265 (?? ms between GCs) full 36 totalling 13,229 ms (0% uptime), avg 367.5 ms incr 7,229 totalling 6,546 ms (0% uptime), avg 0.9 ms tenures 3,589,063 (avg 0 GCs/tenure)
(There's no uptime in the above stats because we're still transitioning Squeak to the 64-bit clock and there are consequently bugs in computing uptime).
The plan is to add an incremental global GC so this work is broken up into much smaller pieces. I don't want to see 700ms pauses in global GC; one can't do game animation with that. So an incremental mark-sweep is needed. There are two nice papers we're considering, one from Lua and one for a truly concurrent collector. But time is pressing, so if anyone out there knows GC and is interested in helping this is a nicely self-contained project for which we'd love to have volunteers.
_,,,^..^,,,_ (phone)
On Jan 24, 2016, at 3:43 AM, Vincent BLONDEAU <
vincent.blondeau@polytech-lille.net> wrote:
Hi,
I made the benchmarks with the files you provided. I have more or
less the
same magnitude: Version 504: 0:00:01:09.021 Version 1175: 0:00:02:37.507
However, by launching it in the time profiler (MooseModel new importFromMSEStream: (StandardFileStream readOnlyFileNamed: 'd:/ArgoUML-0-34.mse')), it takes 504: 1 min 55 1175: 4 min 25 Well there is a delta...
After investigation, the standard process has almost the same
duration (120
secs for prespur and 140 secs for spur). But, there is a large difference in GC time:
504: not spur **Memory** old +144,822,000 bytes young -8,293,660 bytes used +136,528,340 bytes free -104,186,788 bytes
**GCs** full 1 totalling 965ms (1.0% uptime), avg 965.0ms incr 3264 totalling 42,279ms (33.0% uptime), avg 13.0ms tenures 2,497 (avg 1 GCs/tenure) root table 0 overflows
1175: spur **Memory** old +0 bytes young +340,048 bytes used +340,048 bytes free -340,048 bytes **GCs** full 7 totalling 145,003ms (66.0% uptime), avg 20715.0ms incr 3288 totalling 30,912ms (14.0% uptime), avg 9.0ms tenures 7,146,505 (avg 0 GCs/tenure) root table 0 overflows
Total GC time 504: 43 secs 1175: 176 secs
See the performance reports attached.
I let VM people take care of the issue ;)
Cheers, Vincent
-----Original Message----- From: moose-dev-bounces@list.inf.unibe.ch [mailto:moose-dev-bounces@list.inf.unibe.ch] On Behalf Of Tudor Girba Sent: dimanche 24 janvier 2016 09:08 To: Moose-related development Subject: [Moose-dev] Re: mse loading looks slower :(
Hi,
I am talking about the difference between Moose 6 images:
- October 7:
https://ci.inria.fr/moose/job/moose-6.0/504/artifact/moose-6.0.zip
- yesterday:
https://ci.inria.fr/moose/job/moose-6.0/1175/artifact/moose-6.0.zip
Multiple things did change, but not in Moose. In the end, I would
like to
understand where the slowness comes. Maybe it comes from Spur itself,
but
maybe it comes from somewhere else.
Cheers, Doru
On Jan 24, 2016, at 1:41 AM, Mariano Martinez Peck <
marianopeck@gmail.com>
wrote:
Doru...just to be sure it is not a Pharo (image change), when you
said
before and after Spur, do you mean a Pharo 5.0 exactly (just before
Spur)
and a Pharo JUST after it? Otherwise, the slowness may come from the difference between the 2 Pharos you are running.
Cheers,
On Sat, Jan 23, 2016 at 5:55 PM, Tudor Girba tudor@tudorgirba.com
wrote:
Hi,
I am doing some performance testing of Moose with the Spur VM on Mac.
I tried to load an MSE file with ArgoUML 0.34 and on my machine it
loads
twice as slow with Spur than before:
- PreSpur: 0:00:01:07.272
- Spur: 0:00:02:10.508
Here is the reference file:
https://dl.dropboxusercontent.com/u/18323746/Tmp/ArgoUML-0-34.mse.zip
And here is the script: [ MooseModel new importFromMSEStream: (StandardFileStream
readOnlyFileNamed:
(FileSystem workingDirectory / 'src' /'ArgoUML-0-34' / 'ArgoUML-0-34.mse') fullName).
] timeToRunDo you get the same?
Cheers, Doru
-- www.tudorgirba.com www.feenk.com
"Problem solving should be focused on describing the problem in a way that makes the solution obvious."
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- Mariano http://marianopeck.wordpress.com _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- www.tudorgirba.com www.feenk.com
"What is more important: To be happy, or to make happy?"
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev <report504.txt> <report1175.txt>
-- _,,,^..^,,,_ best, Eliot _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
Hi,
On Jan 24, 2016, at 9:51 PM, Eliot Miranda eliot.miranda@gmail.com wrote:
On Sun, Jan 24, 2016 at 12:42 PM, Tudor Girba tudor@tudorgirba.com wrote: Hi Eliot,
I created a package to easily reproduce the problem: https://dl.dropboxusercontent.com/u/18323746/Tmp/moose-6-for-GC-bug.zip
In there you will get:
- an image,
- the MSE file to be loaded, and
- a Playground script that loads that file.
That sounds perfect.
On my Mac, this takes some 3 minutes, while before it took about 1 minute.
What's the system info on your Mac? Mine is "Version 10.9.5 Processor 2.2GHz Intel Core i7 Memory 16Gb 1333 MHz DDR3”
Model Name: MacBook Pro Model Identifier: MacBookPro10,1 Processor Name: Intel Core i7 Processor Speed: 2.6 GHz Number of Processors: 1 Total Number of Cores: 4 L2 Cache (per Core): 256 KB L3 Cache: 6 MB Memory: 16 GB Boot ROM Version: MBP101.00EE.B0A SMC Version (system): 2.3f36 Serial Number (system): C02JG3T5DKQ5 Hardware UUID: 1FF116A4-5040-53B2-A133-F95256DE6C94
Cheers, Doru
Let me know if you need anything else.
Cheers, Doru
On Jan 24, 2016, at 9:33 PM, Eliot Miranda eliot.miranda@gmail.com wrote:
Hi Doru,
On Sun, Jan 24, 2016 at 12:26 PM, Tudor Girba tudor@tudorgirba.com wrote: Hi Eliot,
Thanks for looking at this.
Please let us know what support you need, or what kind of experiments we can do on our side.
What I want most of all is a test case that I can run on Mac. I'm assuming that I can just copy the job that Vincent mentioned in his email and use that as a test case. Do you see any issues with that? If so, how do I get a really bug MOOSE test case to run on Mac?
Cheers, Doru
On Jan 24, 2016, at 9:20 PM, Eliot Miranda eliot.miranda@gmail.com wrote:
Hi Vincent,
I'll take a look early this week. There's clearly a bug; the Spur GC is /not/ collecting those dictionaries :-( (thanks Stephan!). Assuming the bug is fixed times should come down (see below). It may be that the bug in Slang that I introduced in December has broken things because I don't see these symptoms in my daily work (but I use the most up-to-date VM version possible ;-) ). But I'm not in denial and look forward to using MOOSE as a good stress case.
I do want to say that the GC is not complete. Right now we have a scavenger that works well, and a global GC that has a slow compaction algorithm, and hence there are significant pauses. For example here's what I see as typical in using SPur for VMMaker work:
memory 160,432,128 bytes old 153,658,624 bytes (95.8%) young 4,838,224 bytes (3%) used 127,009,928 bytes (79.2%) free 28,126,456 bytes (17.5%) GCs 7,265 (?? ms between GCs) full 36 totalling 13,229 ms (0% uptime), avg 367.5 ms incr 7,229 totalling 6,546 ms (0% uptime), avg 0.9 ms tenures 3,589,063 (avg 0 GCs/tenure)
(There's no uptime in the above stats because we're still transitioning Squeak to the 64-bit clock and there are consequently bugs in computing uptime).
The plan is to add an incremental global GC so this work is broken up into much smaller pieces. I don't want to see 700ms pauses in global GC; one can't do game animation with that. So an incremental mark-sweep is needed. There are two nice papers we're considering, one from Lua and one for a truly concurrent collector. But time is pressing, so if anyone out there knows GC and is interested in helping this is a nicely self-contained project for which we'd love to have volunteers.
_,,,^..^,,,_ (phone)
On Jan 24, 2016, at 3:43 AM, Vincent BLONDEAU vincent.blondeau@polytech-lille.net wrote:
Hi,
I made the benchmarks with the files you provided. I have more or less the same magnitude: Version 504: 0:00:01:09.021 Version 1175: 0:00:02:37.507
However, by launching it in the time profiler (MooseModel new importFromMSEStream: (StandardFileStream readOnlyFileNamed: 'd:/ArgoUML-0-34.mse')), it takes 504: 1 min 55 1175: 4 min 25 Well there is a delta...
After investigation, the standard process has almost the same duration (120 secs for prespur and 140 secs for spur). But, there is a large difference in GC time:
504: not spur **Memory** old +144,822,000 bytes young -8,293,660 bytes used +136,528,340 bytes free -104,186,788 bytes
**GCs** full 1 totalling 965ms (1.0% uptime), avg 965.0ms incr 3264 totalling 42,279ms (33.0% uptime), avg 13.0ms tenures 2,497 (avg 1 GCs/tenure) root table 0 overflows
1175: spur **Memory** old +0 bytes young +340,048 bytes used +340,048 bytes free -340,048 bytes **GCs** full 7 totalling 145,003ms (66.0% uptime), avg 20715.0ms incr 3288 totalling 30,912ms (14.0% uptime), avg 9.0ms tenures 7,146,505 (avg 0 GCs/tenure) root table 0 overflows
Total GC time 504: 43 secs 1175: 176 secs
See the performance reports attached.
I let VM people take care of the issue ;)
Cheers, Vincent
-----Original Message----- From: moose-dev-bounces@list.inf.unibe.ch [mailto:moose-dev-bounces@list.inf.unibe.ch] On Behalf Of Tudor Girba Sent: dimanche 24 janvier 2016 09:08 To: Moose-related development Subject: [Moose-dev] Re: mse loading looks slower :(
Hi,
I am talking about the difference between Moose 6 images:
- October 7:
https://ci.inria.fr/moose/job/moose-6.0/504/artifact/moose-6.0.zip
- yesterday:
https://ci.inria.fr/moose/job/moose-6.0/1175/artifact/moose-6.0.zip
Multiple things did change, but not in Moose. In the end, I would like to understand where the slowness comes. Maybe it comes from Spur itself, but maybe it comes from somewhere else.
Cheers, Doru
On Jan 24, 2016, at 1:41 AM, Mariano Martinez Peck marianopeck@gmail.com
wrote:
Doru...just to be sure it is not a Pharo (image change), when you said
before and after Spur, do you mean a Pharo 5.0 exactly (just before Spur) and a Pharo JUST after it? Otherwise, the slowness may come from the difference between the 2 Pharos you are running.
Cheers,
On Sat, Jan 23, 2016 at 5:55 PM, Tudor Girba tudor@tudorgirba.com wrote: Hi,
I am doing some performance testing of Moose with the Spur VM on Mac.
I tried to load an MSE file with ArgoUML 0.34 and on my machine it loads
twice as slow with Spur than before:
- PreSpur: 0:00:01:07.272
- Spur: 0:00:02:10.508
Here is the reference file: https://dl.dropboxusercontent.com/u/18323746/Tmp/ArgoUML-0-34.mse.zip
And here is the script: [ MooseModel new importFromMSEStream: (StandardFileStream
readOnlyFileNamed:
(FileSystem workingDirectory / 'src' /'ArgoUML-0-34' / 'ArgoUML-0-34.mse') fullName).
] timeToRunDo you get the same?
Cheers, Doru
-- www.tudorgirba.com www.feenk.com
"Problem solving should be focused on describing the problem in a way that makes the solution obvious."
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- Mariano http://marianopeck.wordpress.com _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- www.tudorgirba.com www.feenk.com
"What is more important: To be happy, or to make happy?"
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev <report504.txt> <report1175.txt>
-- _,,,^..^,,,_ best, Eliot _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- _,,,^..^,,,_ best, Eliot _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
Hi Doru,
On Sun, Jan 24, 2016 at 12:42 PM, Tudor Girba tudor@tudorgirba.com wrote:
Hi Eliot,
I created a package to easily reproduce the problem: https://dl.dropboxusercontent.com/u/18323746/Tmp/moose-6-for-GC-bug.zip
In there you will get:
- an image,
- the MSE file to be loaded, and
- a Playground script that loads that file.
I take it that this is a Spur image. t would be great to have both a Spur and a V3 mage to compare, as similar as is easily achievable. But as long as there's both a V3 and a Spur image...
On my Mac, this takes some 3 minutes, while before it took about 1 minute.
Let me know if you need anything else.
Cheers, Doru
On Jan 24, 2016, at 9:33 PM, Eliot Miranda eliot.miranda@gmail.com
wrote:
Hi Doru,
On Sun, Jan 24, 2016 at 12:26 PM, Tudor Girba tudor@tudorgirba.com
wrote:
Hi Eliot,
Thanks for looking at this.
Please let us know what support you need, or what kind of experiments we
can do on our side.
What I want most of all is a test case that I can run on Mac. I'm
assuming that I can just copy the job that Vincent mentioned in his email and use that as a test case. Do you see any issues with that? If so, how do I get a really bug MOOSE test case to run on Mac?
Cheers, Doru
On Jan 24, 2016, at 9:20 PM, Eliot Miranda eliot.miranda@gmail.com
wrote:
Hi Vincent,
I'll take a look early this week. There's clearly a bug; the Spur GC is /not/ collecting those dictionaries :-( (thanks Stephan!). Assuming the bug is fixed times should come down (see below). It may be that the bug in Slang that I introduced in December has broken things because I don't see these symptoms in my daily work (but I use the most up-to-date VM version possible ;-) ). But I'm not in denial and look forward to using MOOSE as a good stress case.
I do want to say that the GC is not complete. Right now we have a scavenger that works well, and a global GC that has a slow compaction algorithm, and hence there are significant pauses. For example here's what I see as typical in using SPur for VMMaker work:
memory 160,432,128 bytes old 153,658,624 bytes (95.8%) young 4,838,224 bytes (3%) used 127,009,928 bytes (79.2%) free 28,126,456 bytes (17.5%) GCs 7,265 (?? ms between GCs) full 36 totalling 13,229 ms (0% uptime), avg 367.5 ms incr 7,229 totalling 6,546 ms (0% uptime), avg 0.9 ms tenures 3,589,063 (avg 0 GCs/tenure)
(There's no uptime in the above stats because we're still transitioning Squeak to the 64-bit clock and there are consequently bugs in computing uptime).
The plan is to add an incremental global GC so this work is broken up into much smaller pieces. I don't want to see 700ms pauses in global GC; one can't do game animation with that. So an incremental mark-sweep is needed. There are two nice papers we're considering, one from Lua and one for a truly concurrent collector. But time is pressing, so if anyone out there knows GC and is interested in helping this is a nicely self-contained project for which we'd love to have volunteers.
_,,,^..^,,,_ (phone)
On Jan 24, 2016, at 3:43 AM, Vincent BLONDEAU <
vincent.blondeau@polytech-lille.net> wrote:
Hi,
I made the benchmarks with the files you provided. I have more or
less the
same magnitude: Version 504: 0:00:01:09.021 Version 1175: 0:00:02:37.507
However, by launching it in the time profiler (MooseModel new importFromMSEStream: (StandardFileStream readOnlyFileNamed: 'd:/ArgoUML-0-34.mse')), it takes 504: 1 min 55 1175: 4 min 25 Well there is a delta...
After investigation, the standard process has almost the same
duration (120
secs for prespur and 140 secs for spur). But, there is a large difference in GC time:
504: not spur **Memory** old +144,822,000 bytes young -8,293,660 bytes used +136,528,340 bytes free -104,186,788 bytes
**GCs** full 1 totalling 965ms (1.0% uptime), avg 965.0ms incr 3264 totalling 42,279ms (33.0% uptime), avg 13.0ms tenures 2,497 (avg 1 GCs/tenure) root table 0 overflows
1175: spur **Memory** old +0 bytes young +340,048 bytes used +340,048 bytes free -340,048 bytes **GCs** full 7 totalling 145,003ms (66.0% uptime), avg 20715.0ms incr 3288 totalling 30,912ms (14.0% uptime), avg 9.0ms tenures 7,146,505 (avg 0 GCs/tenure) root table 0 overflows
Total GC time 504: 43 secs 1175: 176 secs
See the performance reports attached.
I let VM people take care of the issue ;)
Cheers, Vincent
-----Original Message----- From: moose-dev-bounces@list.inf.unibe.ch [mailto:moose-dev-bounces@list.inf.unibe.ch] On Behalf Of Tudor Girba Sent: dimanche 24 janvier 2016 09:08 To: Moose-related development Subject: [Moose-dev] Re: mse loading looks slower :(
Hi,
I am talking about the difference between Moose 6 images:
- October 7:
https://ci.inria.fr/moose/job/moose-6.0/504/artifact/moose-6.0.zip
- yesterday:
https://ci.inria.fr/moose/job/moose-6.0/1175/artifact/moose-6.0.zip
Multiple things did change, but not in Moose. In the end, I would
like to
understand where the slowness comes. Maybe it comes from Spur itself,
but
maybe it comes from somewhere else.
Cheers, Doru
On Jan 24, 2016, at 1:41 AM, Mariano Martinez Peck <
marianopeck@gmail.com>
wrote:
Doru...just to be sure it is not a Pharo (image change), when you
said
before and after Spur, do you mean a Pharo 5.0 exactly (just before
Spur)
and a Pharo JUST after it? Otherwise, the slowness may come from the difference between the 2 Pharos you are running.
Cheers,
On Sat, Jan 23, 2016 at 5:55 PM, Tudor Girba tudor@tudorgirba.com
wrote:
Hi,
I am doing some performance testing of Moose with the Spur VM on Mac.
I tried to load an MSE file with ArgoUML 0.34 and on my machine it
loads
twice as slow with Spur than before:
- PreSpur: 0:00:01:07.272
- Spur: 0:00:02:10.508
Here is the reference file:
https://dl.dropboxusercontent.com/u/18323746/Tmp/ArgoUML-0-34.mse.zip
And here is the script: [ MooseModel new importFromMSEStream: (StandardFileStream
readOnlyFileNamed:
(FileSystem workingDirectory / 'src' /'ArgoUML-0-34' / 'ArgoUML-0-34.mse') fullName).
] timeToRunDo you get the same?
Cheers, Doru
-- www.tudorgirba.com www.feenk.com
"Problem solving should be focused on describing the problem in a way that makes the solution obvious."
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- Mariano http://marianopeck.wordpress.com _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- www.tudorgirba.com www.feenk.com
"What is more important: To be happy, or to make happy?"
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev <report504.txt> <report1175.txt>
-- _,,,^..^,,,_ best, Eliot _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
Hi Eliot,
Indeed, this was a Spur image. I will put together the same setup with a pre-Spur image and get back to you.
Cheers, Doru
On Jan 24, 2016, at 11:35 PM, Eliot Miranda eliot.miranda@gmail.com wrote:
Hi Doru,
On Sun, Jan 24, 2016 at 12:42 PM, Tudor Girba tudor@tudorgirba.com wrote: Hi Eliot,
I created a package to easily reproduce the problem: https://dl.dropboxusercontent.com/u/18323746/Tmp/moose-6-for-GC-bug.zip
In there you will get:
- an image,
- the MSE file to be loaded, and
- a Playground script that loads that file.
I take it that this is a Spur image. t would be great to have both a Spur and a V3 mage to compare, as similar as is easily achievable. But as long as there's both a V3 and a Spur image...
On my Mac, this takes some 3 minutes, while before it took about 1 minute.
Let me know if you need anything else.
Cheers, Doru
On Jan 24, 2016, at 9:33 PM, Eliot Miranda eliot.miranda@gmail.com wrote:
Hi Doru,
On Sun, Jan 24, 2016 at 12:26 PM, Tudor Girba tudor@tudorgirba.com wrote: Hi Eliot,
Thanks for looking at this.
Please let us know what support you need, or what kind of experiments we can do on our side.
What I want most of all is a test case that I can run on Mac. I'm assuming that I can just copy the job that Vincent mentioned in his email and use that as a test case. Do you see any issues with that? If so, how do I get a really bug MOOSE test case to run on Mac?
Cheers, Doru
On Jan 24, 2016, at 9:20 PM, Eliot Miranda eliot.miranda@gmail.com wrote:
Hi Vincent,
I'll take a look early this week. There's clearly a bug; the Spur GC is /not/ collecting those dictionaries :-( (thanks Stephan!). Assuming the bug is fixed times should come down (see below). It may be that the bug in Slang that I introduced in December has broken things because I don't see these symptoms in my daily work (but I use the most up-to-date VM version possible ;-) ). But I'm not in denial and look forward to using MOOSE as a good stress case.
I do want to say that the GC is not complete. Right now we have a scavenger that works well, and a global GC that has a slow compaction algorithm, and hence there are significant pauses. For example here's what I see as typical in using SPur for VMMaker work:
memory 160,432,128 bytes old 153,658,624 bytes (95.8%) young 4,838,224 bytes (3%) used 127,009,928 bytes (79.2%) free 28,126,456 bytes (17.5%) GCs 7,265 (?? ms between GCs) full 36 totalling 13,229 ms (0% uptime), avg 367.5 ms incr 7,229 totalling 6,546 ms (0% uptime), avg 0.9 ms tenures 3,589,063 (avg 0 GCs/tenure)
(There's no uptime in the above stats because we're still transitioning Squeak to the 64-bit clock and there are consequently bugs in computing uptime).
The plan is to add an incremental global GC so this work is broken up into much smaller pieces. I don't want to see 700ms pauses in global GC; one can't do game animation with that. So an incremental mark-sweep is needed. There are two nice papers we're considering, one from Lua and one for a truly concurrent collector. But time is pressing, so if anyone out there knows GC and is interested in helping this is a nicely self-contained project for which we'd love to have volunteers.
_,,,^..^,,,_ (phone)
On Jan 24, 2016, at 3:43 AM, Vincent BLONDEAU vincent.blondeau@polytech-lille.net wrote:
Hi,
I made the benchmarks with the files you provided. I have more or less the same magnitude: Version 504: 0:00:01:09.021 Version 1175: 0:00:02:37.507
However, by launching it in the time profiler (MooseModel new importFromMSEStream: (StandardFileStream readOnlyFileNamed: 'd:/ArgoUML-0-34.mse')), it takes 504: 1 min 55 1175: 4 min 25 Well there is a delta...
After investigation, the standard process has almost the same duration (120 secs for prespur and 140 secs for spur). But, there is a large difference in GC time:
504: not spur **Memory** old +144,822,000 bytes young -8,293,660 bytes used +136,528,340 bytes free -104,186,788 bytes
**GCs** full 1 totalling 965ms (1.0% uptime), avg 965.0ms incr 3264 totalling 42,279ms (33.0% uptime), avg 13.0ms tenures 2,497 (avg 1 GCs/tenure) root table 0 overflows
1175: spur **Memory** old +0 bytes young +340,048 bytes used +340,048 bytes free -340,048 bytes **GCs** full 7 totalling 145,003ms (66.0% uptime), avg 20715.0ms incr 3288 totalling 30,912ms (14.0% uptime), avg 9.0ms tenures 7,146,505 (avg 0 GCs/tenure) root table 0 overflows
Total GC time 504: 43 secs 1175: 176 secs
See the performance reports attached.
I let VM people take care of the issue ;)
Cheers, Vincent
-----Original Message----- From: moose-dev-bounces@list.inf.unibe.ch [mailto:moose-dev-bounces@list.inf.unibe.ch] On Behalf Of Tudor Girba Sent: dimanche 24 janvier 2016 09:08 To: Moose-related development Subject: [Moose-dev] Re: mse loading looks slower :(
Hi,
I am talking about the difference between Moose 6 images:
- October 7:
https://ci.inria.fr/moose/job/moose-6.0/504/artifact/moose-6.0.zip
- yesterday:
https://ci.inria.fr/moose/job/moose-6.0/1175/artifact/moose-6.0.zip
Multiple things did change, but not in Moose. In the end, I would like to understand where the slowness comes. Maybe it comes from Spur itself, but maybe it comes from somewhere else.
Cheers, Doru
On Jan 24, 2016, at 1:41 AM, Mariano Martinez Peck marianopeck@gmail.com
wrote:
Doru...just to be sure it is not a Pharo (image change), when you said
before and after Spur, do you mean a Pharo 5.0 exactly (just before Spur) and a Pharo JUST after it? Otherwise, the slowness may come from the difference between the 2 Pharos you are running.
Cheers,
On Sat, Jan 23, 2016 at 5:55 PM, Tudor Girba tudor@tudorgirba.com wrote: Hi,
I am doing some performance testing of Moose with the Spur VM on Mac.
I tried to load an MSE file with ArgoUML 0.34 and on my machine it loads
twice as slow with Spur than before:
- PreSpur: 0:00:01:07.272
- Spur: 0:00:02:10.508
Here is the reference file: https://dl.dropboxusercontent.com/u/18323746/Tmp/ArgoUML-0-34.mse.zip
And here is the script: [ MooseModel new importFromMSEStream: (StandardFileStream
readOnlyFileNamed:
(FileSystem workingDirectory / 'src' /'ArgoUML-0-34' / 'ArgoUML-0-34.mse') fullName).
] timeToRunDo you get the same?
Cheers, Doru
-- www.tudorgirba.com www.feenk.com
"Problem solving should be focused on describing the problem in a way that makes the solution obvious."
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- Mariano http://marianopeck.wordpress.com _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- www.tudorgirba.com www.feenk.com
"What is more important: To be happy, or to make happy?"
Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev <report504.txt> <report1175.txt>
-- _,,,^..^,,,_ best, Eliot _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-- _,,,^..^,,,_ best, Eliot _______________________________________________ Moose-dev mailing list Moose-dev@list.inf.unibe.ch https://www.list.inf.unibe.ch/listinfo/moose-dev
-
Eliot Miranda -
Stephan Eggermont -
stepharo -
Tudor Girba -
Vincent BLONDEAU