You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@buildr.apache.org by Ittay Dror <it...@gmail.com> on 2008/08/06 14:06:02 UTC
inaccurate time measures under windows
Hi,
I ran buildr and it says 'Completed in 2.782'. Then I use the command
'echo > tstamp.begin && buildr && echo > tstamp.end' and comparing the
timestamps I see it took 8 seconds.
The time is probably the bootstrap of ruby + gems. Can this be improved?
Can the time that buildr prints be more accurate?
Thank you,
Ittay
--
--
Ittay Dror <it...@gmail.com>
Re: inaccurate time measures under windows
Posted by Assaf Arkin <ar...@intalio.com>.
On Aug 6, 2008, at 10:50 PM, Ittay Dror wrote:
>
>
> Assaf Arkin wrote:
>> On Aug 6, 2008, at 9:04 PM, Ittay Dror wrote:
>>
>>> do you know any tips for improving the bootstrap time?
>>
>> On my machine it loads a simple buildfile in 2 seconds (and I'd be
>> much happier when it goes down to 0.5). JRuby takes closer to 7
>> seconds, which is much better than 10+ when we first started, and
>> will keep dropping in future versions.
>>
>> Anything beyond that is affected by the complexity of the
>> buildfile. Lots of task setup and checking files would affect
>> that. You can find some hotspots by using Benchmark.measure
>> { ... } and also ruby-prof:
>> http://ruby-prof.rubyforge.org/
> I tried ruby-prof, below are the results I got. Kernel#system is
> because I call the windows compiler. Am I correct in analyzing that
> 'require' takes a lot of time?
Try running ruby-prof -p graph_html -f graph.html That will create
an HTML page for the call graph which helps make sense of some of
these numbers.
I'm running this against the buildfile used by Buildr itself, which
doesn't do much. It reports 77.97% total for Kernel.require, which
just means 77% of the work happens while loading Buildr and all its
dependencies, the other 23.11% is Buildr.application.run, which loads
the buildfile and runs the tasks.
Most of Buildr.application.run is spent in Task.invoke (20%),
evaluating the process definitions. On the loading side, 20% is spent
in Gem::GemPathSearcher#find, mostly on calls to Dir[].
Assaf
>
>
> Ittay
>
> %self total self wait child calls name
> 12.26 0.98 0.98 0.00 0.00 13 Kernel#system
> 9.72 2.52 0.78 0.00 1.74 97
> Kernel#gem_original_require-6
> 8.01 1.70 0.64 0.00 1.06 94
> Kernel#gem_original_require-7
> 7.97 4.41 0.64 0.00 3.77 79
> Kernel#gem_original_require-3
> 7.40 3.14 0.59 0.00 2.55 68
> Kernel#gem_original_require-5
> 7.38 3.75 0.59 0.00 3.16 60
> Kernel#gem_original_require-4
> 5.63 1.04 0.45 0.00 0.59 74
> Kernel#gem_original_require-8
> 3.70 4.75 0.30 0.00 4.45 35
> Kernel#gem_original_require-2
> 2.90 0.58 0.23 0.00 0.34 40
> Kernel#gem_original_require-9
> 2.74 0.34 0.22 0.00 0.12 29
> Kernel#gem_original_require-10
> 2.13 0.17 0.17 0.00 0.00 1549 <Class::Proc>#new
> 1.94 0.16 0.16 0.00 0.00 21 <Class::Dir>#glob
> 1.57 0.13 0.13 0.00 0.00 598 <Class::Dir>#[]
> 1.57 4.88 0.13 0.00 4.75 10
> Kernel#gem_original_require-1
> 1.17 0.09 0.09 0.00 0.00 4 IO#read
> 1.17 0.11 0.09 0.00 0.02 3233
> Pathname#chop_basename
> 0.98 0.08 0.08 0.00 0.00 1 <Module::Rjb>#load
> 0.97 4.95 0.08 0.00 4.88 35
> Kernel#gem_original_require
> 0.97 0.09 0.08 0.00 0.01 5418
> Rake::FileList#initialize
> 0.97 0.11 0.08 0.00 0.03 11
> Kernel#gem_original_require-11
> 0.77 0.28 0.06 0.00 0.22 1360
> Buildr::Project#task
> 0.76 0.22 0.06 0.00 0.16 1462
> Rake::TaskManager#define_task
> 0.75 0.06 0.06 0.00 0.00 4674 Array#|
> 0.59 1.94 0.05 0.00 1.89 2915 Array#each-7
> 0.57 0.05 0.05 0.00 0.00 905
> <Class::File>#exist?
> 0.57 0.08 0.05 0.00 0.03 3203
> Rake::TaskManager#resolve_args
> 0.57 0.25 0.05 0.00 0.20 920
> Buildr::Layout#expand
> ....
>
>
>
>
>>
>> I didn't run any profiling tests yet, so I'm just as curious to
>> find out where we're spending too much processing.
>>
>> Assaf
>>
>>>
>>>
>>> btw, it still outperforms maven by factors of 2 to 10 ;-)
>>>
>>> ittay
>>>
>>> Assaf Arkin wrote:
>>>> On Wed, Aug 6, 2008 at 5:06 AM, Ittay Dror <it...@gmail.com>
>>>> wrote:
>>>>
>>>>> Hi,
>>>>>
>>>>> I ran buildr and it says 'Completed in 2.782'. Then I use the
>>>>> command 'echo
>>>>>
>>>>>> tstamp.begin && buildr && echo > tstamp.end' and comparing the
>>>>>> timestamps
>>>>>>
>>>>> I see it took 8 seconds.
>>>>>
>>>>> The time is probably the bootstrap of ruby + gems. Can this be
>>>>> improved? Can
>>>>> the time that buildr prints be more accurate?
>>>>>
>>>>
>>>> Good point. I moved the benchmark to bin/buildr, so now it will
>>>> measure everything, except for the startup time of Ruby itself
>>>> (which
>>>> should be sub-second):
>>>>
>>>> ~/work/buildr (master) $ time ruby -Ilib -Iaddon bin/buildr
>>>> (in /Users/assaf/work/buildr, development)
>>>> Building buildr
>>>> Testing buildr
>>>> Testing buildr:extra
>>>> Testing buildr:java
>>>> Completed in 1.948s
>>>>
>>>> real 0m2.008s
>>>> user 0m1.447s
>>>> sys 0m0.423s
>>>>
>>>> Assaf
>>>>
>>>>
>>>>> Thank you,
>>>>> Ittay
>>>>>
>>>>> --
>>>>> --
>>>>> Ittay Dror <it...@gmail.com>
>>>>>
>>>>>
>>>>>
>>>>>
>>>
>>> --
>>> --
>>> Ittay Dror <it...@gmail.com>
>>>
>>
>
> --
> --
> Ittay Dror <it...@gmail.com>
>
>
Re: inaccurate time measures under windows
Posted by Ittay Dror <it...@gmail.com>.
Assaf Arkin wrote:
> On Aug 6, 2008, at 9:04 PM, Ittay Dror wrote:
>
>> do you know any tips for improving the bootstrap time?
>
> On my machine it loads a simple buildfile in 2 seconds (and I'd be
> much happier when it goes down to 0.5). JRuby takes closer to 7
> seconds, which is much better than 10+ when we first started, and will
> keep dropping in future versions.
>
> Anything beyond that is affected by the complexity of the buildfile.
> Lots of task setup and checking files would affect that. You can find
> some hotspots by using Benchmark.measure { ... } and also ruby-prof:
> http://ruby-prof.rubyforge.org/
I tried ruby-prof, below are the results I got. Kernel#system is because
I call the windows compiler. Am I correct in analyzing that 'require'
takes a lot of time?
Ittay
%self total self wait child calls name
12.26 0.98 0.98 0.00 0.00 13 Kernel#system
9.72 2.52 0.78 0.00 1.74 97
Kernel#gem_original_require-6
8.01 1.70 0.64 0.00 1.06 94
Kernel#gem_original_require-7
7.97 4.41 0.64 0.00 3.77 79
Kernel#gem_original_require-3
7.40 3.14 0.59 0.00 2.55 68
Kernel#gem_original_require-5
7.38 3.75 0.59 0.00 3.16 60
Kernel#gem_original_require-4
5.63 1.04 0.45 0.00 0.59 74
Kernel#gem_original_require-8
3.70 4.75 0.30 0.00 4.45 35
Kernel#gem_original_require-2
2.90 0.58 0.23 0.00 0.34 40
Kernel#gem_original_require-9
2.74 0.34 0.22 0.00 0.12 29
Kernel#gem_original_require-10
2.13 0.17 0.17 0.00 0.00 1549 <Class::Proc>#new
1.94 0.16 0.16 0.00 0.00 21 <Class::Dir>#glob
1.57 0.13 0.13 0.00 0.00 598 <Class::Dir>#[]
1.57 4.88 0.13 0.00 4.75 10
Kernel#gem_original_require-1
1.17 0.09 0.09 0.00 0.00 4 IO#read
1.17 0.11 0.09 0.00 0.02 3233 Pathname#chop_basename
0.98 0.08 0.08 0.00 0.00 1 <Module::Rjb>#load
0.97 4.95 0.08 0.00 4.88 35
Kernel#gem_original_require
0.97 0.09 0.08 0.00 0.01 5418
Rake::FileList#initialize
0.97 0.11 0.08 0.00 0.03 11
Kernel#gem_original_require-11
0.77 0.28 0.06 0.00 0.22 1360 Buildr::Project#task
0.76 0.22 0.06 0.00 0.16 1462
Rake::TaskManager#define_task
0.75 0.06 0.06 0.00 0.00 4674 Array#|
0.59 1.94 0.05 0.00 1.89 2915 Array#each-7
0.57 0.05 0.05 0.00 0.00 905 <Class::File>#exist?
0.57 0.08 0.05 0.00 0.03 3203
Rake::TaskManager#resolve_args
0.57 0.25 0.05 0.00 0.20 920 Buildr::Layout#expand
....
>
> I didn't run any profiling tests yet, so I'm just as curious to find
> out where we're spending too much processing.
>
> Assaf
>
>>
>>
>> btw, it still outperforms maven by factors of 2 to 10 ;-)
>>
>> ittay
>>
>> Assaf Arkin wrote:
>>> On Wed, Aug 6, 2008 at 5:06 AM, Ittay Dror <it...@gmail.com>
>>> wrote:
>>>
>>>> Hi,
>>>>
>>>> I ran buildr and it says 'Completed in 2.782'. Then I use the
>>>> command 'echo
>>>>
>>>>> tstamp.begin && buildr && echo > tstamp.end' and comparing the
>>>>> timestamps
>>>>>
>>>> I see it took 8 seconds.
>>>>
>>>> The time is probably the bootstrap of ruby + gems. Can this be
>>>> improved? Can
>>>> the time that buildr prints be more accurate?
>>>>
>>>
>>> Good point. I moved the benchmark to bin/buildr, so now it will
>>> measure everything, except for the startup time of Ruby itself (which
>>> should be sub-second):
>>>
>>> ~/work/buildr (master) $ time ruby -Ilib -Iaddon bin/buildr
>>> (in /Users/assaf/work/buildr, development)
>>> Building buildr
>>> Testing buildr
>>> Testing buildr:extra
>>> Testing buildr:java
>>> Completed in 1.948s
>>>
>>> real 0m2.008s
>>> user 0m1.447s
>>> sys 0m0.423s
>>>
>>> Assaf
>>>
>>>
>>>> Thank you,
>>>> Ittay
>>>>
>>>> --
>>>> --
>>>> Ittay Dror <it...@gmail.com>
>>>>
>>>>
>>>>
>>>>
>>
>> --
>> --
>> Ittay Dror <it...@gmail.com>
>>
>
--
--
Ittay Dror <it...@gmail.com>
Re: inaccurate time measures under windows
Posted by Assaf Arkin <ar...@intalio.com>.
On Aug 6, 2008, at 9:04 PM, Ittay Dror wrote:
> do you know any tips for improving the bootstrap time?
On my machine it loads a simple buildfile in 2 seconds (and I'd be
much happier when it goes down to 0.5). JRuby takes closer to 7
seconds, which is much better than 10+ when we first started, and will
keep dropping in future versions.
Anything beyond that is affected by the complexity of the buildfile.
Lots of task setup and checking files would affect that. You can find
some hotspots by using Benchmark.measure { ... } and also ruby-prof:
http://ruby-prof.rubyforge.org/
I didn't run any profiling tests yet, so I'm just as curious to find
out where we're spending too much processing.
Assaf
>
>
> btw, it still outperforms maven by factors of 2 to 10 ;-)
>
> ittay
>
> Assaf Arkin wrote:
>> On Wed, Aug 6, 2008 at 5:06 AM, Ittay Dror <it...@gmail.com>
>> wrote:
>>
>>> Hi,
>>>
>>> I ran buildr and it says 'Completed in 2.782'. Then I use the
>>> command 'echo
>>>
>>>> tstamp.begin && buildr && echo > tstamp.end' and comparing the
>>>> timestamps
>>>>
>>> I see it took 8 seconds.
>>>
>>> The time is probably the bootstrap of ruby + gems. Can this be
>>> improved? Can
>>> the time that buildr prints be more accurate?
>>>
>>
>> Good point. I moved the benchmark to bin/buildr, so now it will
>> measure everything, except for the startup time of Ruby itself (which
>> should be sub-second):
>>
>> ~/work/buildr (master) $ time ruby -Ilib -Iaddon bin/buildr
>> (in /Users/assaf/work/buildr, development)
>> Building buildr
>> Testing buildr
>> Testing buildr:extra
>> Testing buildr:java
>> Completed in 1.948s
>>
>> real 0m2.008s
>> user 0m1.447s
>> sys 0m0.423s
>>
>> Assaf
>>
>>
>>> Thank you,
>>> Ittay
>>>
>>> --
>>> --
>>> Ittay Dror <it...@gmail.com>
>>>
>>>
>>>
>>>
>
> --
> --
> Ittay Dror <it...@gmail.com>
>
Re: inaccurate time measures under windows
Posted by Daniel Spiewak <dj...@gmail.com>.
It would be nice if simple Rake tasks in the buildfile (ones which don't
require advanced Buildr features) would start as quickly as possible. After
all, there are those times that all we need is a scripting environment and
some path normalization.
Daniel
On Wed, Aug 6, 2008 at 11:04 PM, Ittay Dror <it...@gmail.com> wrote:
> do you know any tips for improving the bootstrap time?
>
> btw, it still outperforms maven by factors of 2 to 10 ;-)
>
> ittay
>
>
> Assaf Arkin wrote:
>
>> On Wed, Aug 6, 2008 at 5:06 AM, Ittay Dror <it...@gmail.com> wrote:
>>
>>
>>> Hi,
>>>
>>> I ran buildr and it says 'Completed in 2.782'. Then I use the command
>>> 'echo
>>>
>>>
>>>> tstamp.begin && buildr && echo > tstamp.end' and comparing the
>>>> timestamps
>>>>
>>>>
>>> I see it took 8 seconds.
>>>
>>> The time is probably the bootstrap of ruby + gems. Can this be improved?
>>> Can
>>> the time that buildr prints be more accurate?
>>>
>>>
>>
>> Good point. I moved the benchmark to bin/buildr, so now it will
>> measure everything, except for the startup time of Ruby itself (which
>> should be sub-second):
>>
>> ~/work/buildr (master) $ time ruby -Ilib -Iaddon bin/buildr
>> (in /Users/assaf/work/buildr, development)
>> Building buildr
>> Testing buildr
>> Testing buildr:extra
>> Testing buildr:java
>> Completed in 1.948s
>>
>> real 0m2.008s
>> user 0m1.447s
>> sys 0m0.423s
>>
>> Assaf
>>
>>
>>
>>> Thank you,
>>> Ittay
>>>
>>> --
>>> --
>>> Ittay Dror <it...@gmail.com>
>>>
>>>
>>>
>>>
>>>
>>
> --
> --
>
> Ittay Dror <it...@gmail.com>
>
>
Re: inaccurate time measures under windows
Posted by Ittay Dror <it...@gmail.com>.
do you know any tips for improving the bootstrap time?
btw, it still outperforms maven by factors of 2 to 10 ;-)
ittay
Assaf Arkin wrote:
> On Wed, Aug 6, 2008 at 5:06 AM, Ittay Dror <it...@gmail.com> wrote:
>
>> Hi,
>>
>> I ran buildr and it says 'Completed in 2.782'. Then I use the command 'echo
>>
>>> tstamp.begin && buildr && echo > tstamp.end' and comparing the timestamps
>>>
>> I see it took 8 seconds.
>>
>> The time is probably the bootstrap of ruby + gems. Can this be improved? Can
>> the time that buildr prints be more accurate?
>>
>
> Good point. I moved the benchmark to bin/buildr, so now it will
> measure everything, except for the startup time of Ruby itself (which
> should be sub-second):
>
> ~/work/buildr (master) $ time ruby -Ilib -Iaddon bin/buildr
> (in /Users/assaf/work/buildr, development)
> Building buildr
> Testing buildr
> Testing buildr:extra
> Testing buildr:java
> Completed in 1.948s
>
> real 0m2.008s
> user 0m1.447s
> sys 0m0.423s
>
> Assaf
>
>
>> Thank you,
>> Ittay
>>
>> --
>> --
>> Ittay Dror <it...@gmail.com>
>>
>>
>>
>>
--
--
Ittay Dror <it...@gmail.com>
Re: inaccurate time measures under windows
Posted by Assaf Arkin <ar...@intalio.com>.
On Wed, Aug 6, 2008 at 5:06 AM, Ittay Dror <it...@gmail.com> wrote:
> Hi,
>
> I ran buildr and it says 'Completed in 2.782'. Then I use the command 'echo
>> tstamp.begin && buildr && echo > tstamp.end' and comparing the timestamps
> I see it took 8 seconds.
>
> The time is probably the bootstrap of ruby + gems. Can this be improved? Can
> the time that buildr prints be more accurate?
Good point. I moved the benchmark to bin/buildr, so now it will
measure everything, except for the startup time of Ruby itself (which
should be sub-second):
~/work/buildr (master) $ time ruby -Ilib -Iaddon bin/buildr
(in /Users/assaf/work/buildr, development)
Building buildr
Testing buildr
Testing buildr:extra
Testing buildr:java
Completed in 1.948s
real 0m2.008s
user 0m1.447s
sys 0m0.423s
Assaf
>
> Thank you,
> Ittay
>
> --
> --
> Ittay Dror <it...@gmail.com>
>
>
>