Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
Locked
Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
 
|
Hi,
I made the benchmarks with the files you provided. I have more or less the same magnitude: Version 504: 0:00:01:09.021 Version 1175: 0:00:02:37.507 However, by launching it in the time profiler (MooseModel new importFromMSEStream: (StandardFileStream readOnlyFileNamed: 'd:/ArgoUML-0-34.mse')), it takes 504: 1 min 55 1175: 4 min 25 Well there is a delta... After investigation, the standard process has almost the same duration (120 secs for prespur and 140 secs for spur). But, there is a large difference in GC time: 504: not spur **Memory** old +144,822,000 bytes young -8,293,660 bytes used +136,528,340 bytes free -104,186,788 bytes **GCs** full 1 totalling 965ms (1.0% uptime), avg 965.0ms incr 3264 totalling 42,279ms (33.0% uptime), avg 13.0ms tenures 2,497 (avg 1 GCs/tenure) root table 0 overflows 1175: spur **Memory** old +0 bytes young +340,048 bytes used +340,048 bytes free -340,048 bytes **GCs** full 7 totalling 145,003ms (66.0% uptime), avg 20715.0ms incr 3288 totalling 30,912ms (14.0% uptime), avg 9.0ms tenures 7,146,505 (avg 0 GCs/tenure) root table 0 overflows Total GC time 504: 43 secs 1175: 176 secs See the performance reports attached. I let VM people take care of the issue ;) Cheers, Vincent -----Original Message----- From: [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 > (FileSystem workingDirectory / 'src' / > ] 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 (13K) |
|
Thanks for this analysis. This is really interesting.
I wonder what is the type of the garbage collected object. In MSE we have mainly strings. Stef Le 24/1/16 12:43, Vincent BLONDEAU a écrit : > 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 |
Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
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. Vincent -----Original Message----- From: Pharo-dev [mailto:[hidden email]] On Behalf Of stepharo Sent: dimanche 24 janvier 2016 13:40 To: Pharo Development List Subject: Re: [Pharo-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :() Thanks for this analysis. This is really interesting. I wonder what is the type of the garbage collected object. In MSE we have mainly strings. Stef Le 24/1/16 12:43, Vincent BLONDEAU a écrit : > 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]> >> 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 |
Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
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. At least a lot of Announcements and Announcers Stephan |
Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
> On 24 Jan 2016, at 16:09, Stephan Eggermont <[hidden email]> wrote: > > 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. > > At least a lot of Announcements and Announcers > > Stephan Of course it is good to optimise code (generating too much garbage is a delayed slowdown), but if GC is slower in Spur then that sounds like a regression that has to be studied. Sven |
Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
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 |
Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
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)) |
Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
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> |
Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
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> > |
Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
Hi Doru,
On Sun, Jan 24, 2016 at 12:26 PM, Tudor Girba <[hidden email]> wrote: Hi Eliot, 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?
_,,,^..^,,,_ best, Eliot |
Re: [Moose-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
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 |
Re: [Moose-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
On Sun, Jan 24, 2016 at 12:42 PM, Tudor Girba <[hidden email]> wrote: Hi Eliot, 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"
_,,,^..^,,,_ best, Eliot |
Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
In reply to this post by Eliot Miranda-2
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. Stephan |
Re: [Moose-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
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 |
Re: Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
In reply to this post by Stephan Eggermont-3
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: 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 |
Re: [Moose-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
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 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...
_,,,^..^,,,_ best, Eliot |
Re: [Moose-dev] Spur Garbage collection takes 4 times more when loading MSE (WAS: mse loading looks slower :()
|
|
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 |
«
Return to Pharo Smalltalk Developers
|
1 view|%1 views
| Free forum by Nabble | Edit this page |