Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
18 messages Options
Reply | Threaded
Open this post in threaded view
|

Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Vincent Blondeau
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: [hidden email]
[mailto:[hidden email]] 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 <[hidden email]>
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 <[hidden email]> 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).

>         ] timeToRun
>
> Do 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
> [hidden email]
> https://www.list.inf.unibe.ch/listinfo/moose-dev
>
>
>
> --
> Mariano
> http://marianopeck.wordpress.com
> _______________________________________________
> Moose-dev mailing list
> [hidden email]
> 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
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev

_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev

report504.txt (13K) Download Attachment
report1175.txt (7K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Stephan Eggermont-3


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


_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Stephan Eggermont-3
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
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

stepharo
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
> [hidden email]
> https://www.list.inf.unibe.ch/listinfo/moose-dev
>

_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Stephan Eggermont-3
In reply to this post by Vincent Blondeau
On 24-01-16 15:34, Vincent BLONDEAU wrote:
> Yes, and we have to do several passes to construct the model with references
> (so we store a mapping table).
> Maybe a collection or two are GCed.

Probably a bit more. Before loading, there were 172 instances of
SmallDictionary. After loading, 558293, of which 30194 contain something.

Stephan




_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Stephan Eggermont-3
In reply to this post by Stephan Eggermont-3
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

_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: [Pharo-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Tudor Girba-2
In reply to this post by Stephan Eggermont-3
What should we use instead? Array? nil when it’s empty? How about introducing some sort of a NilDictionary?

Would anyone like to experiment?

Cheers,
Doru


> On Jan 24, 2016, at 8:49 PM, Stephan Eggermont <[hidden email]> wrote:
>
> I think the use of SmallDictionaries for storing Famix state is not such a good idea. After loading the model:
>
> bag := Bag new .
> SmallDictionary allInstances do: [ :each | bag add: each size ].
> bag sortedCounts
>
> "{530387->0. 19253->3. 18292->1. 20->2. 2->4. 2->11. 1->12}"
>
> bag := Bag new .
> SmallDictionary allInstances do: [ :each | bag add: (each keys) ].
> bag sortedCounts
>
> an Array(530387->#() 19253->#(#cyclomaticComplexity #numberOfStatements #mooseName) 9311->#(#binding) 8707->#(#mooseName) 426->#(#comments) 20->#(#comments #ir) 13->#(#ir) 4->#(#comments #binding) 3->#(#binding #semanticWarning) 2->#('charset') 1->#(1 2 3 4 5 6 7 8 9 10 11 12) 1->#(14 15 16 17 18 19 20 21 22 23 24) 1->#(9 10 11 12 13 14 15 16) 1->an Array('-source-' #'`@method:' RBPatternVariableNode(`@args) '-pragmas-') 1->#(1 2 3 4 5 6 7 8 9 10 11) 1->{MooseModel} 1->{FAMIXAnnotationType. FAMIXClass. FAMIXNamespace. FAMIXMethod} 1->#(1 2))
>
>

_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: [Pharo-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Eliot Miranda-2
In reply to this post by Vincent Blondeau
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 <[hidden email]> 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: [hidden email]
> [mailto:[hidden email]] 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 <[hidden email]>
>> 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 <[hidden email]> 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).
>>       ] timeToRun
>>
>> Do 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
>> [hidden email]
>> https://www.list.inf.unibe.ch/listinfo/moose-dev
>>
>>
>>
>> --
>> Mariano
>> http://marianopeck.wordpress.com
>> _______________________________________________
>> Moose-dev mailing list
>> [hidden email]
>> 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
> [hidden email]
> https://www.list.inf.unibe.ch/listinfo/moose-dev
> <report504.txt>
> <report1175.txt>
_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: [Pharo-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Tudor Girba-2
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 <[hidden email]> 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 <[hidden email]> 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: [hidden email]
>> [mailto:[hidden email]] 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 <[hidden email]>
>>> 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 <[hidden email]> 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).
>>>      ] timeToRun
>>>
>>> Do 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
>>> [hidden email]
>>> https://www.list.inf.unibe.ch/listinfo/moose-dev
>>>
>>>
>>>
>>> --
>>> Mariano
>>> http://marianopeck.wordpress.com
>>> _______________________________________________
>>> Moose-dev mailing list
>>> [hidden email]
>>> 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
>> [hidden email]
>> https://www.list.inf.unibe.ch/listinfo/moose-dev
>> <report504.txt>
>> <report1175.txt>
>

_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: [Pharo-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Eliot Miranda-2
Hi Doru,

On Sun, Jan 24, 2016 at 12:26 PM, Tudor Girba <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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: [hidden email]
>> [mailto:[hidden email]] 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 <[hidden email]>
>>> 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 <[hidden email]> 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).
>>>      ] timeToRun
>>>
>>> Do 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
>>> [hidden email]
>>> https://www.list.inf.unibe.ch/listinfo/moose-dev
>>>
>>>
>>>
>>> --
>>> Mariano
>>> http://marianopeck.wordpress.com
>>> _______________________________________________
>>> Moose-dev mailing list
>>> [hidden email]
>>> 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
>> [hidden email]
>> https://www.list.inf.unibe.ch/listinfo/moose-dev
>> <report504.txt>
>> <report1175.txt>
>





--
_,,,^..^,,,_
best, Eliot

_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: [Pharo-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Tudor Girba-2
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 <[hidden email]> wrote:
>
> Hi Doru,
>
> On Sun, Jan 24, 2016 at 12:26 PM, Tudor Girba <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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: [hidden email]
> >> [mailto:[hidden email]] 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 <[hidden email]>
> >>> 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 <[hidden email]> 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).
> >>>      ] timeToRun
> >>>
> >>> Do 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
> >>> [hidden email]
> >>> https://www.list.inf.unibe.ch/listinfo/moose-dev
> >>>
> >>>
> >>>
> >>> --
> >>> Mariano
> >>> http://marianopeck.wordpress.com
> >>> _______________________________________________
> >>> Moose-dev mailing list
> >>> [hidden email]
> >>> 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
> >> [hidden email]
> >> https://www.list.inf.unibe.ch/listinfo/moose-dev
> >> <report504.txt>
> >> <report1175.txt>
> >
>
>
>
>
>
> --
> _,,,^..^,,,_
> best, Eliot
> _______________________________________________
> Moose-dev mailing list
> [hidden email]
> https://www.list.inf.unibe.ch/listinfo/moose-dev

_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: [Pharo-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Eliot Miranda-2


On Sun, Jan 24, 2016 at 12:42 PM, Tudor Girba <[hidden email]> 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 <[hidden email]> wrote:
>
> Hi Doru,
>
> On Sun, Jan 24, 2016 at 12:26 PM, Tudor Girba <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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: [hidden email]
> >> [mailto:[hidden email]] 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 <[hidden email]>
> >>> 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 <[hidden email]> 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).
> >>>      ] timeToRun
> >>>
> >>> Do 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
> >>> [hidden email]
> >>> https://www.list.inf.unibe.ch/listinfo/moose-dev
> >>>
> >>>
> >>>
> >>> --
> >>> Mariano
> >>> http://marianopeck.wordpress.com
> >>> _______________________________________________
> >>> Moose-dev mailing list
> >>> [hidden email]
> >>> 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
> >> [hidden email]
> >> https://www.list.inf.unibe.ch/listinfo/moose-dev
> >> <report504.txt>
> >> <report1175.txt>
> >
>
>
>
>
>
> --
> _,,,^..^,,,_
> best, Eliot
> _______________________________________________
> Moose-dev mailing list
> [hidden email]
> https://www.list.inf.unibe.ch/listinfo/moose-dev





--
_,,,^..^,,,_
best, Eliot

_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: [Pharo-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Stephan Eggermont-3
In reply to this post by Tudor Girba-2
On 24-01-16 21:19, Tudor Girba wrote:
> What should we use instead? Array? nil when it’s empty? How about introducing some sort of a NilDictionary?
>
> Would anyone like to experiment?

With the fast become the NullDictionary should work even better than
before. Storing all the keys when we have only so little variants is
wasteful, generating value classes would be much faster

Stephan


_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: [Pharo-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Tudor Girba-2
In reply to this post by Eliot Miranda-2
Hi,

> On Jan 24, 2016, at 9:51 PM, Eliot Miranda <[hidden email]> wrote:
>
>
>
> On Sun, Jan 24, 2016 at 12:42 PM, Tudor Girba <[hidden email]> 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 <[hidden email]> wrote:
> >
> > Hi Doru,
> >
> > On Sun, Jan 24, 2016 at 12:26 PM, Tudor Girba <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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: [hidden email]
> > >> [mailto:[hidden email]] 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 <[hidden email]>
> > >>> 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 <[hidden email]> 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).
> > >>>      ] timeToRun
> > >>>
> > >>> Do 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
> > >>> [hidden email]
> > >>> https://www.list.inf.unibe.ch/listinfo/moose-dev
> > >>>
> > >>>
> > >>>
> > >>> --
> > >>> Mariano
> > >>> http://marianopeck.wordpress.com
> > >>> _______________________________________________
> > >>> Moose-dev mailing list
> > >>> [hidden email]
> > >>> 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
> > >> [hidden email]
> > >> https://www.list.inf.unibe.ch/listinfo/moose-dev
> > >> <report504.txt>
> > >> <report1175.txt>
> > >
> >
> >
> >
> >
> >
> > --
> > _,,,^..^,,,_
> > best, Eliot
> > _______________________________________________
> > Moose-dev mailing list
> > [hidden email]
> > https://www.list.inf.unibe.ch/listinfo/moose-dev
>
>
>
>
>
> --
> _,,,^..^,,,_
> best, Eliot
> _______________________________________________
> Moose-dev mailing list
> [hidden email]
> https://www.list.inf.unibe.ch/listinfo/moose-dev

_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: [Pharo-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Eliot Miranda-2
In reply to this post by Eliot Miranda-2
Hi Stephan,

On Sun, Jan 24, 2016 at 1:04 PM, Stephan Eggermont <[hidden email]> wrote:
On 24-01-16 21:20, Eliot Miranda 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!).

I'm afraid the dictionaries are part of the model and should not be garbage collected. They do make things slow though, so we need a better model. Garbage collection cycle takes a few seconds now on my 4 GHz 4790K 32GB.

So Vincent's awful sats are no longer showing up?  He reported a 140 second GC pause.  What are you seeing?  (.i.e. can you post the full stats?)  If this has disappeared then I suspect my Slang bug, which I fixed yesterday.  But I will investigate.
 
Stephan

_,,,^..^,,,_
best, Eliot

_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: [Pharo-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Stephan Eggermont-3
On 24/01/16 22:53, Eliot Miranda wrote:
> Hi Stephan,
> So Vincent's awful sats are no longer showing up?  He reported a 140
> second GC pause.  What are you seeing?  (.i.e. can you post the full
> stats?)  If this has disappeared then I suspect my Slang bug, which I
> fixed yesterday.  But I will investigate.

I sent you the stats by mail, they were only posted to the moose mailing
list. I'm afraid my somewhat better results can only be explained
through faster hardware, a 4790K i7 on 4GHz, running Ubuntu 15.10.
Loading the mse file still spends 2/3 of time in garbage collection, at
least mostly. I had one run that was much better 85s -> 66s, I thought
by not creating so much garbage.

Stephan


_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: [Pharo-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Eliot Miranda-2
In reply to this post by Tudor Girba-2
Hi Doru,

On Sun, Jan 24, 2016 at 12:42 PM, Tudor Girba <[hidden email]> 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 <[hidden email]> wrote:
>
> Hi Doru,
>
> On Sun, Jan 24, 2016 at 12:26 PM, Tudor Girba <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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: [hidden email]
> >> [mailto:[hidden email]] 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 <[hidden email]>
> >>> 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 <[hidden email]> 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).
> >>>      ] timeToRun
> >>>
> >>> Do 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
> >>> [hidden email]
> >>> https://www.list.inf.unibe.ch/listinfo/moose-dev
> >>>
> >>>
> >>>
> >>> --
> >>> Mariano
> >>> http://marianopeck.wordpress.com
> >>> _______________________________________________
> >>> Moose-dev mailing list
> >>> [hidden email]
> >>> 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
> >> [hidden email]
> >> https://www.list.inf.unibe.ch/listinfo/moose-dev
> >> <report504.txt>
> >> <report1175.txt>
> >
>
>
>
>
>
> --
> _,,,^..^,,,_
> best, Eliot
> _______________________________________________
> Moose-dev mailing list
> [hidden email]
> https://www.list.inf.unibe.ch/listinfo/moose-dev





--
_,,,^..^,,,_
best, Eliot

_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev
Reply | Threaded
Open this post in threaded view
|

Re: [Pharo-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()

Tudor Girba-2
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 <[hidden email]> wrote:
>
> Hi Doru,
>
> On Sun, Jan 24, 2016 at 12:42 PM, Tudor Girba <[hidden email]> 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 <[hidden email]> wrote:
> >
> > Hi Doru,
> >
> > On Sun, Jan 24, 2016 at 12:26 PM, Tudor Girba <[hidden email]> 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 <[hidden email]> 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 <[hidden email]> 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: [hidden email]
> > >> [mailto:[hidden email]] 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 <[hidden email]>
> > >>> 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 <[hidden email]> 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).
> > >>>      ] timeToRun
> > >>>
> > >>> Do 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
> > >>> [hidden email]
> > >>> https://www.list.inf.unibe.ch/listinfo/moose-dev
> > >>>
> > >>>
> > >>>
> > >>> --
> > >>> Mariano
> > >>> http://marianopeck.wordpress.com
> > >>> _______________________________________________
> > >>> Moose-dev mailing list
> > >>> [hidden email]
> > >>> 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
> > >> [hidden email]
> > >> https://www.list.inf.unibe.ch/listinfo/moose-dev
> > >> <report504.txt>
> > >> <report1175.txt>
> > >
> >
> >
> >
> >
> >
> > --
> > _,,,^..^,,,_
> > best, Eliot
> > _______________________________________________
> > Moose-dev mailing list
> > [hidden email]
> > https://www.list.inf.unibe.ch/listinfo/moose-dev
>
>
>
>
>
> --
> _,,,^..^,,,_
> best, Eliot
> _______________________________________________
> Moose-dev mailing list
> [hidden email]
> https://www.list.inf.unibe.ch/listinfo/moose-dev

_______________________________________________
Moose-dev mailing list
[hidden email]
https://www.list.inf.unibe.ch/listinfo/moose-dev