Eric Nicholson
2008-Feb-06 19:38 UTC
[Ironruby-core] Weird performance problem with "find"
I noticed some strange issues in an application I''m working on where it works speedy at first, and then gets progressively slower and slower. After a little bit of investigation, it seems that Enumerable#find is the culprit. The more times you run a find statement the slower it gets. Does anybody have any ideas why this is? Here''s a sample that demonstrates the issue: require ''mscorlib'' require ''C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\System.dll'' a = (1..1000).to_a s = System::Diagnostics::Stopwatch.new() 100.times { s.start a.find {|x| x == 1000} s.stop puts "find took: #{s.elapsed.ToString}" } which outputs: find took: 00:00:00.0743446 ...snip... find took: 00:00:00.2290894 ...snip... find took: 00:00:00.4942105 I understand you guys aren''t optimizing yet, but I thought you might be interested to see growth where there shouldn''t be any. Also, if you have any ideas off the top of your head, I wouldn''t mind looking into it a little. -Eric -------------- next part -------------- An HTML attachment was scrubbed... URL: http://rubyforge.org/pipermail/ironruby-core/attachments/20080206/db2837b1/attachment.html
Eric Nicholson
2008-Feb-06 20:04 UTC
[Ironruby-core] Weird performance problem with "find"
Whoops, had the stopwatch setup wrong in that last message require ''mscorlib'' require ''C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\System.dll'' a = (1..1000).to_a 1000.times { s = System::Diagnostics::Stopwatch.new() s.start a.find {|x| x == 1000} s.stop puts "find took: #{s.elapsed.ToString}" } and the output is: find took: 00:00:00.0732210 find took: 00:00:00.0048562 find took: 00:00:00.0022469 find took: 00:00:00.0021351 ... snip ... find took: 00:00:00.0196016 find took: 00:00:00.0201994 find took: 00:00:00.0218765 ... snip ... find took: 00:00:00.0371834 find took: 00:00:00.0367817 find took: 00:00:00.0361911 On Feb 6, 2008 2:38 PM, Eric Nicholson <enicholson at gmail.com> wrote:> I noticed some strange issues in an application I''m working on where it > works speedy at first, and then gets progressively slower and slower. After > a little bit of investigation, it seems that Enumerable#find is the > culprit. The more times you run a find statement the slower it gets. Does > anybody have any ideas why this is? > > Here''s a sample that demonstrates the issue: > > require ''mscorlib'' > require ''C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\System.dll'' > > a = (1..1000).to_a > s = System::Diagnostics::Stopwatch.new() > > 100.times { > s.start > a.find {|x| x == 1000} > s.stop > puts "find took: #{s.elapsed.ToString}" > } > > which outputs: > > find took: 00:00:00.0743446 > ...snip... > find took: 00:00:00.2290894 > ...snip... > find took: 00:00:00.4942105 > > I understand you guys aren''t optimizing yet, but I thought you might be > interested to see growth where there shouldn''t be any. Also, if you have > any ideas off the top of your head, I wouldn''t mind looking into it a > little. > > -Eric >-------------- next part -------------- An HTML attachment was scrubbed... URL: http://rubyforge.org/pipermail/ironruby-core/attachments/20080206/270140e9/attachment-0001.html
M. David Peterson
2008-Feb-06 20:13 UTC
[Ironruby-core] Weird performance problem with "find"
On Wed, 06 Feb 2008 12:38:46 -0700, Eric Nicholson <enicholson at gmail.com> wrote:> require ''mscorlib'' > require ''C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\System.dll'' > > a = (1..1000).to_a > s = System::Diagnostics::Stopwatch.new() > > 100.times { > s.start > a.find {|x| x == 1000} > s.stop > puts "find took: #{s.elapsed.ToString}" > }You''re reusing the same Stopwatch instance, so you have to add a call to the Reset method at the end of each iteration. In doing so you should find your timings are as they should be. -- /M:D M. David Peterson Co-Founder & Chief Architect, 3rd&Urban, LLC Email: m.david at 3rdandUrban.com | m.david at amp.fm Mobile: (206) 418-9027 http://3rdandUrban.com | http://amp.fm | http://www.oreillynet.com/pub/au/2354
Michael Letterle
2008-Feb-06 20:23 UTC
[Ironruby-core] Weird performance problem with "find"
He''s right about the issue however: find took: 00:00:00.0081136 find took: 00:00:00.0022516 find took: 00:00:00.0021312 [snip] find took: 00:00:00.0220530 find took: 00:00:00.0245721 find took: 00:00:00.0238102 [snip] find took: 00:00:00.0377458 find took: 00:00:00.0453373 find took: 00:00:00.0369415 On Feb 6, 2008 3:13 PM, M. David Peterson <m.david at xmlhacker.com> wrote:> On Wed, 06 Feb 2008 12:38:46 -0700, Eric Nicholson <enicholson at gmail.com> > wrote: > > > require ''mscorlib'' > > require ''C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\System.dll'' > > > > a = (1..1000).to_a > > s = System::Diagnostics::Stopwatch.new() > > > > 100.times { > > s.start > > a.find {|x| x == 1000} > > s.stop > > puts "find took: #{s.elapsed.ToString}" > > } > > > You''re reusing the same Stopwatch instance, so you have to add a call to > the Reset method at the end of each iteration. In doing so you should > find your timings are as they should be. > > > -- > /M:D > > M. David Peterson > Co-Founder & Chief Architect, 3rd&Urban, LLC > Email: m.david at 3rdandUrban.com | m.david at amp.fm > Mobile: (206) 418-9027 > http://3rdandUrban.com | http://amp.fm | > http://www.oreillynet.com/pub/au/2354 > _______________________________________________ > Ironruby-core mailing list > Ironruby-core at rubyforge.org > http://rubyforge.org/mailman/listinfo/ironruby-core >-- Michael Letterle [Polymath Programmer] http://michaeldotnet.blogspot.com
M. David Peterson
2008-Feb-06 20:31 UTC
[Ironruby-core] Weird performance problem with "find"
On Wed, 06 Feb 2008 13:23:10 -0700, Michael Letterle <michael.letterle at gmail.com> wrote:> He''s right about the issue however: > ... > find took: 00:00:00.0377458 > find took: 00:00:00.0453373 > find took: 00:00:00.0369415Whoops. My bad. I was testing via Ruby.NET which, coincidentally, doesn''t showcase this type of behavior, find took: 00:00:00.0216940 find took: 00:00:00.0012342 find took: 00:00:00.0012423 ... find took: 00:00:00.0013994 find took: 00:00:00.0013016 find took: 00:00:00.0017697 ... find took: 00:00:00.0012989 find took: 00:00:00.0014228 find took: 00:00:00.0013389 ... I guess maybe Ruby.NET still has its place in this world afterall. ;-) :D --- (the modified code in case anyone wants to run the comparison on their own machine) require ''mscorlib'' require ''C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\System.dll'' a = (1..1000).to_a s = System::Diagnostics::Stopwatch.new() 100.times { s.Start a.find {|x| x == 1000} s.Stop puts "find took: #{s.Elapsed}" s.Reset } -- /M:D M. David Peterson Co-Founder & Chief Architect, 3rd&Urban, LLC Email: m.david at 3rdandUrban.com | m.david at amp.fm Mobile: (206) 418-9027 http://3rdandUrban.com | http://amp.fm | http://www.oreillynet.com/pub/au/2354
Michael Letterle
2008-Feb-06 21:22 UTC
[Ironruby-core] Weird performance problem with "find"
I have some ideas on what some of the issues may be, primarily related to how the Enumerable class creates a new Proc object every time through the loop. Anyway, doing the following seems to help to some extent: require ''mscorlib'' require ''C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\System.dll'' a = (1..1000).to_a s = System::Diagnostics::Stopwatch.new() m = Proc.new {|x| x == 1000 } 1000.times { s.start y = a.find &m s.stop puts "find took: #{s.elapsed.ToString}" s.reset } find took: 00:00:00.0012998 find took: 00:00:00.0012719 find took: 00:00:00.0012915 [snip] find took: 00:00:00.0049048 find took: 00:00:00.0052548 find took: 00:00:00.0051403 [snip] find took: 00:00:00.0127650 find took: 00:00:00.0141006 find took: 00:00:00.0106432 You can see the times still going up (rules are being created based on Proc.Id?) but not nearly the same pace. On Feb 6, 2008 3:31 PM, M. David Peterson <m.david at xmlhacker.com> wrote:> On Wed, 06 Feb 2008 13:23:10 -0700, Michael Letterle > <michael.letterle at gmail.com> wrote: > > > He''s right about the issue however: > > ... > > find took: 00:00:00.0377458 > > find took: 00:00:00.0453373 > > find took: 00:00:00.0369415 > > Whoops. My bad. I was testing via Ruby.NET which, coincidentally, > doesn''t showcase this type of behavior, > > find took: 00:00:00.0216940 > find took: 00:00:00.0012342 > find took: 00:00:00.0012423 > ... > find took: 00:00:00.0013994 > find took: 00:00:00.0013016 > find took: 00:00:00.0017697 > ... > find took: 00:00:00.0012989 > find took: 00:00:00.0014228 > find took: 00:00:00.0013389 > ... > > I guess maybe Ruby.NET still has its place in this world afterall. ;-) :D > > --- > > (the modified code in case anyone wants to run the comparison on their own > machine) > > require ''mscorlib'' > require ''C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\System.dll'' > > a = (1..1000).to_a > s = System::Diagnostics::Stopwatch.new() > > 100.times { > s.Start > a.find {|x| x == 1000} > s.Stop > puts "find took: #{s.Elapsed}" > s.Reset > } > > -- > > /M:D > > M. David Peterson > Co-Founder & Chief Architect, 3rd&Urban, LLC > Email: m.david at 3rdandUrban.com | m.david at amp.fm > Mobile: (206) 418-9027 > http://3rdandUrban.com | http://amp.fm | > http://www.oreillynet.com/pub/au/2354 > _______________________________________________ > Ironruby-core mailing list > Ironruby-core at rubyforge.org > http://rubyforge.org/mailman/listinfo/ironruby-core >-- Michael Letterle [Polymath Programmer] http://michaeldotnet.blogspot.com
John Lam (DLR)
2008-Feb-06 22:58 UTC
[Ironruby-core] Weird performance problem with "find"
Michael Letterle:> I have some ideas on what some of the issues may be, primarily related > to how the Enumerable class creates a new Proc object every time > through the loop. Anyway, doing the following seems to help to some > extent: > > require ''mscorlib'' > require ''C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\System.dll'' > > a = (1..1000).to_a > s = System::Diagnostics::Stopwatch.new() > m = Proc.new {|x| x == 1000 } > 1000.times { > s.start > y = a.find &m > s.stop > puts "find took: #{s.elapsed.ToString}" > s.reset > } > > find took: 00:00:00.0012998 > find took: 00:00:00.0012719 > find took: 00:00:00.0012915 > > [snip] > > find took: 00:00:00.0049048 > find took: 00:00:00.0052548 > find took: 00:00:00.0051403 > > [snip] > > find took: 00:00:00.0127650 > find took: 00:00:00.0141006 > find took: 00:00:00.0106432This is a strange; nothing obvious jumps out right now. We''ll have to look at this down the road when we do our perf push. Clearly this is a bug. Can someone open up a bug for this? Thanks, -John
Michael Letterle
2008-Feb-06 23:06 UTC
[Ironruby-core] Weird performance problem with "find"
Bug has been submitted. I''ll probably poke it with a stick some while I''m at it. On Feb 6, 2008 5:58 PM, John Lam (DLR) <jflam at microsoft.com> wrote:> Michael Letterle: > > > > I have some ideas on what some of the issues may be, primarily related > > to how the Enumerable class creates a new Proc object every time > > through the loop. Anyway, doing the following seems to help to some > > extent: > > > > require ''mscorlib'' > > require ''C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\System.dll'' > > > > a = (1..1000).to_a > > s = System::Diagnostics::Stopwatch.new() > > m = Proc.new {|x| x == 1000 } > > 1000.times { > > s.start > > y = a.find &m > > s.stop > > puts "find took: #{s.elapsed.ToString}" > > s.reset > > } > > > > find took: 00:00:00.0012998 > > find took: 00:00:00.0012719 > > find took: 00:00:00.0012915 > > > > [snip] > > > > find took: 00:00:00.0049048 > > find took: 00:00:00.0052548 > > find took: 00:00:00.0051403 > > > > [snip] > > > > find took: 00:00:00.0127650 > > find took: 00:00:00.0141006 > > find took: 00:00:00.0106432 > > This is a strange; nothing obvious jumps out right now. We''ll have to look at this down the road when we do our perf push. Clearly this is a bug. Can someone open up a bug for this? > > Thanks, > -John > > > _______________________________________________ > Ironruby-core mailing list > Ironruby-core at rubyforge.org > http://rubyforge.org/mailman/listinfo/ironruby-core >-- Michael Letterle [Polymath Programmer] http://michaeldotnet.blogspot.com
Eric Nicholson
2008-Feb-06 23:56 UTC
[Ironruby-core] Weird performance problem with "find"
So "Enumerable#find" is definitely a red herring. I''m guessing it has something to do with block creation. Here''s a better example without the find: 10000.times { | iter | s.reset s.start x = 0 1000.times { x += 1} s.stop puts "iteration #{iter} took: #{s.elapsed.ToString}" if iter % 100 == 0 } Output: iteration 0 took: 00:00:00.0471160 iteration 100 took: 00:00:00.0024187 iteration 200 took: 00:00:00.0037267 iteration 300 took: 00:00:00.0039901 iteration 400 took: 00:00:00.0054012 iteration 500 took: 00:00:00.0063639 iteration 600 took: 00:00:00.0070567 iteration 700 took: 00:00:00.0103230 iteration 800 took: 00:00:00.0093428 iteration 900 took: 00:00:00.0095257 [snip] iteration 9700 took: 00:00:00.0892543 iteration 9800 took: 00:00:00.0899337 iteration 9900 took: 00:00:00.0963234 It''s very consistent linear growth. Several iterations took much longer presumably due to garbage collection. Compare that to this version without the inner block: 1000.times do |iter| s.reset s.start x = 0 x+= 1 while x < 1000 s.stop puts "iteration #{iter} took: #{s.elapsed.ToString}" if iter % 100 == 0 iter += 1 end Output: iteration 0 took: 00:00:00.1119421 iteration 100 took: 00:00:00.0001190 iteration 200 took: 00:00:00.0001430 iteration 300 took: 00:00:00.0001326 iteration 400 took: 00:00:00.0001212 iteration 500 took: 00:00:00.0001173 iteration 600 took: 00:00:00.0001190 iteration 700 took: 00:00:00.0001178 iteration 800 took: 00:00:00.0001176 iteration 900 took: 00:00:00.0001178 [snip] iteration 9900 took: 00:00:00.0001142 So maybe block creation/parsing/execution is a little slower each time? On Feb 6, 2008 6:06 PM, Michael Letterle <michael.letterle at gmail.com> wrote:> Bug has been submitted. I''ll probably poke it with a stick some while > I''m at it. > > On Feb 6, 2008 5:58 PM, John Lam (DLR) <jflam at microsoft.com> wrote: > > Michael Letterle: > > > > > > > I have some ideas on what some of the issues may be, primarily related > > > to how the Enumerable class creates a new Proc object every time > > > through the loop. Anyway, doing the following seems to help to some > > > extent: > > > > > > require ''mscorlib'' > > > require ''C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\System.dll'' > > > > > > a = (1..1000).to_a > > > s = System::Diagnostics::Stopwatch.new() > > > m = Proc.new {|x| x == 1000 } > > > 1000.times { > > > s.start > > > y = a.find &m > > > s.stop > > > puts "find took: #{s.elapsed.ToString}" > > > s.reset > > > } > > > > > > find took: 00:00:00.0012998 > > > find took: 00:00:00.0012719 > > > find took: 00:00:00.0012915 > > > > > > [snip] > > > > > > find took: 00:00:00.0049048 > > > find took: 00:00:00.0052548 > > > find took: 00:00:00.0051403 > > > > > > [snip] > > > > > > find took: 00:00:00.0127650 > > > find took: 00:00:00.0141006 > > > find took: 00:00:00.0106432 > > > > This is a strange; nothing obvious jumps out right now. We''ll have to > look at this down the road when we do our perf push. Clearly this is a bug. > Can someone open up a bug for this? > > > > Thanks, > > -John > > > > > > _______________________________________________ > > Ironruby-core mailing list > > Ironruby-core at rubyforge.org > > http://rubyforge.org/mailman/listinfo/ironruby-core > > > > > > -- > Michael Letterle > [Polymath Programmer] > http://michaeldotnet.blogspot.com > _______________________________________________ > Ironruby-core mailing list > Ironruby-core at rubyforge.org > http://rubyforge.org/mailman/listinfo/ironruby-core >-------------- next part -------------- An HTML attachment was scrubbed... URL: http://rubyforge.org/pipermail/ironruby-core/attachments/20080206/c3f1117e/attachment-0001.html
Michael Letterle
2008-Feb-07 00:18 UTC
[Ironruby-core] Weird performance problem with "find"
I don''t know if i''d call it a "red herring" as the performance with find dropped considerably faster, it''s probably a combination. On Feb 6, 2008 6:56 PM, Eric Nicholson <enicholson at gmail.com> wrote:> So "Enumerable#find" is definitely a red herring. I''m guessing it has > something to do with block creation. Here''s a better example without the > find: > > 10000.times { | iter | > s.reset > s.start > x = 0 > 1000.times { x += 1} > s.stop > puts "iteration #{iter} took: #{s.elapsed.ToString}" if iter % 100 == 0 > } > Output: > > iteration 0 took: 00:00:00.0471160 > iteration 100 took: 00:00:00.0024187 > iteration 200 took: 00:00:00.0037267 > iteration 300 took: 00:00:00.0039901 > iteration 400 took: 00:00:00.0054012 > iteration 500 took: 00:00:00.0063639 > iteration 600 took: 00:00:00.0070567 > iteration 700 took: 00:00:00.0103230 > iteration 800 took: 00:00:00.0093428 > iteration 900 took: 00:00:00.0095257 > [snip] > iteration 9700 took: 00:00:00.0892543 > iteration 9800 took: 00:00:00.0899337 > iteration 9900 took: 00:00:00.0963234 > > It''s very consistent linear growth. Several iterations took much longer > presumably due to garbage collection. > > Compare that to this version without the inner block: > > 1000.times do |iter| > s.reset > s.start > x = 0 > x+= 1 while x < 1000 > s.stop > puts "iteration #{iter} took: #{s.elapsed.ToString}" if iter % 100 == 0 > iter += 1 > end > > Output: > > iteration 0 took: 00:00:00.1119421 > iteration 100 took: 00:00:00.0001190 > iteration 200 took: 00:00:00.0001430 > iteration 300 took: 00:00:00.0001326 > iteration 400 took: 00:00:00.0001212 > iteration 500 took: 00:00:00.0001173 > iteration 600 took: 00:00:00.0001190 > iteration 700 took: 00:00:00.0001178 > iteration 800 took: 00:00:00.0001176 > iteration 900 took: 00:00:00.0001178 > [snip] > iteration 9900 took: 00:00:00.0001142 > > So maybe block creation/parsing/execution is a little slower each time? > > > > On Feb 6, 2008 6:06 PM, Michael Letterle <michael.letterle at gmail.com> wrote: > > > Bug has been submitted. I''ll probably poke it with a stick some while > > I''m at it. > > > > > > > > > > On Feb 6, 2008 5:58 PM, John Lam (DLR) <jflam at microsoft.com> wrote: > > > Michael Letterle: > > > > > > > > > > I have some ideas on what some of the issues may be, primarily related > > > > to how the Enumerable class creates a new Proc object every time > > > > through the loop. Anyway, doing the following seems to help to some > > > > extent: > > > > > > > > require ''mscorlib'' > > > > require ''C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\System.dll'' > > > > > > > > a = (1..1000).to_a > > > > s = System::Diagnostics::Stopwatch.new() > > > > m = Proc.new {|x| x == 1000 } > > > > 1000.times { > > > > s.start > > > > y = a.find &m > > > > s.stop > > > > puts "find took: #{s.elapsed.ToString}" > > > > s.reset > > > > } > > > > > > > > find took: 00:00:00.0012998 > > > > find took: 00:00:00.0012719 > > > > find took: 00:00:00.0012915 > > > > > > > > [snip] > > > > > > > > find took: 00:00:00.0049048 > > > > find took: 00:00:00.0052548 > > > > find took: 00:00:00.0051403 > > > > > > > > [snip] > > > > > > > > find took: 00:00:00.0127650 > > > > find took: 00:00:00.0141006 > > > > find took: 00:00:00.0106432 > > > > > > This is a strange; nothing obvious jumps out right now. We''ll have to > look at this down the road when we do our perf push. Clearly this is a bug. > Can someone open up a bug for this? > > > > > > Thanks, > > > -John > > > > > > > > > _______________________________________________ > > > Ironruby-core mailing list > > > Ironruby-core at rubyforge.org > > > http://rubyforge.org/mailman/listinfo/ironruby-core > > > > > > > > > > > > > -- > > Michael Letterle > > [Polymath Programmer] > > http://michaeldotnet.blogspot.com > > _______________________________________________ > > > > > > > > Ironruby-core mailing list > > Ironruby-core at rubyforge.org > > http://rubyforge.org/mailman/listinfo/ironruby-core > > > > > _______________________________________________ > Ironruby-core mailing list > Ironruby-core at rubyforge.org > http://rubyforge.org/mailman/listinfo/ironruby-core > >-- Michael Letterle [Polymath Programmer] http://michaeldotnet.blogspot.com
Michael Letterle:> I don''t know if i''d call it a "red herring" as the performance with > find dropped considerably faster, it''s probably a combination.Probably because Enumerable#find uses a block internally when it calls #each, so you get two block dispatches instead of one. - John
Michael Letterle
2008-Feb-07 01:12 UTC
[Ironruby-core] Weird performance problem with "find"
The example with a nested times call also consists of two block dispatches and doesn''t ramp up nearly as bad, or am I missing something? On Feb 6, 2008 7:41 PM, John Messerly <jomes at microsoft.com> wrote:> Michael Letterle: > > > I don''t know if i''d call it a "red herring" as the performance with > > find dropped considerably faster, it''s probably a combination. > > Probably because Enumerable#find uses a block internally when it calls #each, so you get two block dispatches instead of one. > > - John > > _______________________________________________ > Ironruby-core mailing list > Ironruby-core at rubyforge.org > http://rubyforge.org/mailman/listinfo/ironruby-core >-- Michael Letterle [Polymath Programmer] http://michaeldotnet.blogspot.com