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