Debugging slow knife?


#1

Hi Chefs,

I’m using the opscode platform. Before 0.10 the knife command was
unbearably slow. It’s definately at least twice as fast, but it’s still
kind of sluggish. Even issuing the help command to knife takes 2 seconds.

Some simple stuff:

Off my MacBook Pro…
% time knife node show e02

knife node show e02 3.17s user 0.23s system 74% cpu 4.544 total

% time knife help

knife help 2.12s user 0.17s system 99% cpu 2.296 total

% ruby -v
ruby 1.9.2p180 (2011-02-18 revision 30909) [x86_64-darwin10.7.0]

My results are similar from an ec2 c1.xlarge…

time knife ec2 --help

real 0m1.843s user 0m1.300s sys 0m0.550s

ruby -v

ruby 1.8.7 (2010-01-10 patchlevel 249) [x86_64-linux]

Is this expected? It might not seem like much but it’s enough to really
slow me down and annoy me…

Thanks
Mike


#2

Don’t have a solution for you, just giving some comparison numbers:

MacBook Pro, 2.66Ghz i7, 7200 rpm drive
$ time knife node show i-1a795175
real 0m1.071s
user 0m0.346s
sys 0m0.116s

$ time knife help
real 0m0.410s
user 0m0.311s
sys 0m0.098s

$ ruby -v
ruby 1.8.7 (2010-08-16 patchlevel 302) [i686-darwin10.4.0]

On May 3, 2011, at 9:54 AM, Michael Schueler wrote:

Hi Chefs,

I’m using the opscode platform. Before 0.10 the knife command was unbearably slow. It’s definately at least twice as fast, but it’s still kind of sluggish. Even issuing the help command to knife takes 2 seconds.

Some simple stuff:

Off my MacBook Pro…
% time knife node show e02

knife node show e02 3.17s user 0.23s system 74% cpu 4.544 total

% time knife help

knife help 2.12s user 0.17s system 99% cpu 2.296 total

% ruby -v
ruby 1.9.2p180 (2011-02-18 revision 30909) [x86_64-darwin10.7.0]

My results are similar from an ec2 c1.xlarge…

time knife ec2 --help

real 0m1.843s user 0m1.300s sys 0m0.550s

ruby -v

ruby 1.8.7 (2010-01-10 patchlevel 249) [x86_64-linux]

Is this expected? It might not seem like much but it’s enough to really slow me down and annoy me…

Thanks
Mike


#3

You got something bogus in your knife.rb(s)?

On 4 May 2011 05:28, Alex Soto apsoto@gmail.com wrote:

Don’t have a solution for you, just giving some comparison numbers:

MacBook Pro, 2.66Ghz i7, 7200 rpm drive
$ time knife node show i-1a795175
real 0m1.071s
user 0m0.346s
sys 0m0.116s

$ time knife help
real 0m0.410s
user 0m0.311s
sys 0m0.098s

$ ruby -v
ruby 1.8.7 (2010-08-16 patchlevel 302) [i686-darwin10.4.0]

On May 3, 2011, at 9:54 AM, Michael Schueler wrote:

Hi Chefs,

I’m using the opscode platform. Before 0.10 the knife command was unbearably slow. It’s definately at least twice as fast, but it’s still kind of sluggish. Even issuing the help command to knife takes 2 seconds.

Some simple stuff:

Off my MacBook Pro…
% time knife node show e02

knife node show e02 3.17s user 0.23s system 74% cpu 4.544 total

% time knife help

knife help 2.12s user 0.17s system 99% cpu 2.296 total

% ruby -v
ruby 1.9.2p180 (2011-02-18 revision 30909) [x86_64-darwin10.7.0]

My results are similar from an ec2 c1.xlarge…

time knife ec2 --help

real 0m1.843s user 0m1.300s sys 0m0.550s

ruby -v

ruby 1.8.7 (2010-01-10 patchlevel 249) [x86_64-linux]

Is this expected? It might not seem like much but it’s enough to really slow me down and annoy me…

Thanks
Mike


#4

I get similar timings. knife config dl from the console organization
Generate knife config. 3x runs of each:

$ time knife help

real 0m2.555s
user 0m0.295s
sys 0m1.185s

real 0m1.520s
user 0m0.327s
sys 0m1.045s

real 0m1.524s
user 0m0.343s
sys 0m1.076s

$ time knife client list

real 0m3.039s
user 0m0.343s
sys 0m1.465s

real 0m2.501s
user 0m0.374s
sys 0m1.435s

real 0m2.567s
user 0m0.389s
sys 0m1.419s

-A

On Tue, May 3, 2011 at 1:18 PM, AJ Christensen aj@junglist.gen.nz wrote:

You got something bogus in your knife.rb(s)?

On 4 May 2011 05:28, Alex Soto apsoto@gmail.com wrote:

Don’t have a solution for you, just giving some comparison numbers:

MacBook Pro, 2.66Ghz i7, 7200 rpm drive
$ time knife node show i-1a795175
real 0m1.071s
user 0m0.346s
sys 0m0.116s

$ time knife help
real 0m0.410s
user 0m0.311s
sys 0m0.098s

$ ruby -v
ruby 1.8.7 (2010-08-16 patchlevel 302) [i686-darwin10.4.0]

On May 3, 2011, at 9:54 AM, Michael Schueler wrote:

Hi Chefs,

I’m using the opscode platform. Before 0.10 the knife command was unbearably slow. It’s definately at least twice as fast, but it’s still kind of sluggish. Even issuing the help command to knife takes 2 seconds.

Some simple stuff:

Off my MacBook Pro…
% time knife node show e02

knife node show e02 3.17s user 0.23s system 74% cpu 4.544 total

% time knife help

knife help 2.12s user 0.17s system 99% cpu 2.296 total

% ruby -v
ruby 1.9.2p180 (2011-02-18 revision 30909) [x86_64-darwin10.7.0]

My results are similar from an ec2 c1.xlarge…

time knife ec2 --help

real 0m1.843s user 0m1.300s sys 0m0.550s

ruby -v

ruby 1.8.7 (2010-01-10 patchlevel 249) [x86_64-linux]

Is this expected? It might not seem like much but it’s enough to really slow me down and annoy me…

Thanks
Mike


#5

On Tuesday, May 3, 2011 at 9:54 AM, Michael Schueler wrote:
Hi Chefs,

I’m using the opscode platform. Before 0.10 the knife command was unbearably slow. It’s definately at least twice as fast, but it’s still kind of sluggish. Even issuing the help command to knife takes 2 seconds.

Some simple stuff:

Off my MacBook Pro…
% time knife node show e02

knife node show e02 3.17s user 0.23s system 74% cpu 4.544 total

% time knife help

knife help 2.12s user 0.17s system 99% cpu 2.296 total

% ruby -v
ruby 1.9.2p180 (2011-02-18 revision 30909) [x86_64-darwin10.7.0]

My results are similar from an ec2 c1.xlarge…

time knife ec2 --help

real 0m1.843s user 0m1.300s sys 0m0.550s

ruby -v

ruby 1.8.7 (2010-01-10 patchlevel 249) [x86_64-linux]

Is this expected? It might not seem like much but it’s enough to really slow me down and annoy me…
This is something I’ve optimized as much as possible. Given knife’s current architecture, it has to load all of the files to generate the help output, so whether or not the files are cached makes a huge difference (as shown by the numbers you’ve all posted).

There are some things you can look in to:

  • Since knife has to load all commands including plugins when it runs, it’s important that any plugins you have installed make use of lazy loading.
  • Running gem clean can improve your runtimes dramatically. It can also break things that depend on those gems, so be careful.

After running gem clean, I’m seeing times around 0.6 seconds to run knife -h and knife help when the disk cache is hot.

I’d certainly like to improve this further, especially for the case that the disk cache is cold, but this would require fairly substantial architectural changes to knife–and the gains from doing so could be fairly small compared to the factors that are our of our control (e.g., factors affected by gem clean).


Dan DeLeo

Thanks
Mike


#6

Yo,

On 4 May 2011 13:39, Daniel DeLeo dan@kallistec.com wrote:

On Tuesday, May 3, 2011 at 9:54 AM, Michael Schueler wrote:

Hi Chefs,

I’m using the opscode platform. Before 0.10 the knife command was
unbearably slow. It’s definately at least twice as fast, but it’s still
kind of sluggish. Even issuing the help command to knife takes 2 seconds.

Some simple stuff:

Off my MacBook Pro…
% time knife node show e02

knife node show e02 3.17s user 0.23s system 74% cpu 4.544 total

% time knife help

knife help 2.12s user 0.17s system 99% cpu 2.296 total

% ruby -v
ruby 1.9.2p180 (2011-02-18 revision 30909) [x86_64-darwin10.7.0]

My results are similar from an ec2 c1.xlarge…

time knife ec2 --help

real 0m1.843s user 0m1.300s sys 0m0.550s

ruby -v

ruby 1.8.7 (2010-01-10 patchlevel 249) [x86_64-linux]

Is this expected? It might not seem like much but it’s enough to really
slow me down and annoy me…

This is something I’ve optimized as much as possible. Given knife’s current
architecture, it has to load all of the files to generate the help output,
so whether or not the files are cached makes a huge difference (as shown by
the numbers you’ve all posted).
There are some things you can look in to:

  • Since knife has to load all commands including plugins when it runs, it’s
    important that any plugins you have installed make use of lazy loading.
  • Running gem clean can improve your runtimes dramatically. It can also
    break things that depend on those gems, so be careful.
    After running gem clean, I’m seeing times around 0.6 seconds to run knife -h and knife help when the disk cache is hot.
    I’d certainly like to improve this further, especially for the case that the
    disk cache is cold, but this would require fairly substantial architectural
    changes to knife–and the gains from doing so could be fairly small compared
    to the factors that are our of our control (e.g., factors affected by gem clean).

After ‘gem clean’:

knife -h 0.30s user 0.08s system 98% cpu 0.391 total
knife help 0.49s user 0.16s system 99% cpu 0.663 total

Optimizing more than this seems like a waste of time! =D


Dan DeLeo

Thanks
Mike


#7

On Tue, May 3, 2011 at 6:44 PM, AJ Christensen aj@junglist.gen.nz wrote:

Yo,

On 4 May 2011 13:39, Daniel DeLeo dan@kallistec.com wrote:

On Tuesday, May 3, 2011 at 9:54 AM, Michael Schueler wrote:

Hi Chefs,

I’m using the opscode platform. Before 0.10 the knife command was
unbearably slow. It’s definately at least twice as fast, but it’s still
kind of sluggish. Even issuing the help command to knife takes 2
seconds.

Some simple stuff:

Off my MacBook Pro…
% time knife node show e02

knife node show e02 3.17s user 0.23s system 74% cpu 4.544 total

% time knife help

knife help 2.12s user 0.17s system 99% cpu 2.296 total

% ruby -v
ruby 1.9.2p180 (2011-02-18 revision 30909) [x86_64-darwin10.7.0]

My results are similar from an ec2 c1.xlarge…

time knife ec2 --help

real 0m1.843s user 0m1.300s sys 0m0.550s

ruby -v

ruby 1.8.7 (2010-01-10 patchlevel 249) [x86_64-linux]

Is this expected? It might not seem like much but it’s enough to really
slow me down and annoy me…

This is something I’ve optimized as much as possible. Given knife’s
current
architecture, it has to load all of the files to generate the help
output,
so whether or not the files are cached makes a huge difference (as shown
by
the numbers you’ve all posted).
There are some things you can look in to:

  • Since knife has to load all commands including plugins when it runs,
    it’s
    important that any plugins you have installed make use of lazy loading.
  • Running gem clean can improve your runtimes dramatically. It can also
    break things that depend on those gems, so be careful.
    After running gem clean, I’m seeing times around 0.6 seconds to run
    knife -h and knife help when the disk cache is hot.
    I’d certainly like to improve this further, especially for the case that
    the
    disk cache is cold, but this would require fairly substantial
    architectural
    changes to knife–and the gains from doing so could be fairly small
    compared
    to the factors that are our of our control (e.g., factors affected by
    gem clean).

After ‘gem clean’:

knife -h 0.30s user 0.08s system 98% cpu 0.391 total
knife help 0.49s user 0.16s system 99% cpu 0.663 total

Optimizing more than this seems like a waste of time! =D

Is that knife-ec2 or just plain knife?

I made a new RVM environment for knife and installed Chef and knife-ec2
along with their dependencies.

It’s now down to:

knife -h 1.69s user 0.16s system 99% cpu 1.847 total
knife help 1.73s user 0.17s system 99% cpu 1.905 total

Also this is what my .gemrc looks like:


:benchmark: false
gem: --no-ri --no-rdoc --no-wrappers
:update_sources: true
:bulk_threshold: 1000
:verbose: true
:sources:

Thanks
Mike


Dan DeLeo

Thanks
Mike


#8

On Tuesday, May 3, 2011 at 9:31 PM, Michael Schueler wrote:
On Tue, May 3, 2011 at 6:44 PM, AJ Christensen aj@junglist.gen.nz wrote:

Yo,

On 4 May 2011 13:39, Daniel DeLeo dan@kallistec.com wrote:

On Tuesday, May 3, 2011 at 9:54 AM, Michael Schueler wrote:

Hi Chefs,

I’m using the opscode platform. Before 0.10 the knife command was
unbearably slow. It’s definately at least twice as fast, but it’s still
kind of sluggish. Even issuing the help command to knife takes 2 seconds.

Some simple stuff:

Off my MacBook Pro…
% time knife node show e02

knife node show e02 3.17s user 0.23s system 74% cpu 4.544 total

% time knife help

knife help 2.12s user 0.17s system 99% cpu 2.296 total

% ruby -v
ruby 1.9.2p180 (2011-02-18 revision 30909) [x86_64-darwin10.7.0]

My results are similar from an ec2 c1.xlarge…

time knife ec2 --help

real 0m1.843s user 0m1.300s sys 0m0.550s

ruby -v

ruby 1.8.7 (2010-01-10 patchlevel 249) [x86_64-linux]

Is this expected? It might not seem like much but it’s enough to really
slow me down and annoy me…

This is something I’ve optimized as much as possible. Given knife’s current
architecture, it has to load all of the files to generate the help output,
so whether or not the files are cached makes a huge difference (as shown by
the numbers you’ve all posted).
There are some things you can look in to:

  • Since knife has to load all commands including plugins when it runs, it’s
    important that any plugins you have installed make use of lazy loading.
  • Running gem clean can improve your runtimes dramatically. It can also
    break things that depend on those gems, so be careful.
    After running gem clean, I’m seeing times around 0.6 seconds to run knife -h and knife help when the disk cache is hot.
    I’d certainly like to improve this further, especially for the case that the
    disk cache is cold, but this would require fairly substantial architectural
    changes to knife–and the gains from doing so could be fairly small compared
    to the factors that are our of our control (e.g., factors affected by gem clean).

After ‘gem clean’:

knife -h 0.30s user 0.08s system 98% cpu 0.391 total
knife help 0.49s user 0.16s system 99% cpu 0.663 total

Optimizing more than this seems like a waste of time! =D

Is that knife-ec2 or just plain knife?
With knife-ec2 installed, I’m getting:

knife -h 0.41s user 0.13s system 99% cpu 0.543 total

I made a new RVM environment for knife and installed Chef and knife-ec2 along with their dependencies.

It’s now down to:

knife -h 1.69s user 0.16s system 99% cpu 1.847 total
knife help 1.73s user 0.17s system 99% cpu 1.905 total
Is this with the disk cache hot?

And what version of rubygems? I’m on 1.6.2 ATM.


Dan DeLeo

Also this is what my .gemrc looks like:


:benchmark: false
gem: --no-ri --no-rdoc --no-wrappers
:update_sources: true
:bulk_threshold: 1000
:verbose: true
:sources:

Thanks
Mike


Dan DeLeo

Thanks
Mike


#9

On Tue, May 3, 2011 at 9:43 PM, Daniel DeLeo dan@kallistec.com wrote:

On Tuesday, May 3, 2011 at 9:31 PM, Michael Schueler wrote:

On Tue, May 3, 2011 at 6:44 PM, AJ Christensen aj@junglist.gen.nz wrote:

Yo,

On 4 May 2011 13:39, Daniel DeLeo dan@kallistec.com wrote:

On Tuesday, May 3, 2011 at 9:54 AM, Michael Schueler wrote:

Hi Chefs,

I’m using the opscode platform. Before 0.10 the knife command was
unbearably slow. It’s definately at least twice as fast, but it’s still
kind of sluggish. Even issuing the help command to knife takes 2
seconds.

Some simple stuff:

Off my MacBook Pro…
% time knife node show e02

knife node show e02 3.17s user 0.23s system 74% cpu 4.544 total

% time knife help

knife help 2.12s user 0.17s system 99% cpu 2.296 total

% ruby -v
ruby 1.9.2p180 (2011-02-18 revision 30909) [x86_64-darwin10.7.0]

My results are similar from an ec2 c1.xlarge…

time knife ec2 --help

real 0m1.843s user 0m1.300s sys 0m0.550s

ruby -v

ruby 1.8.7 (2010-01-10 patchlevel 249) [x86_64-linux]

Is this expected? It might not seem like much but it’s enough to really
slow me down and annoy me…

This is something I’ve optimized as much as possible. Given knife’s
current
architecture, it has to load all of the files to generate the help
output,
so whether or not the files are cached makes a huge difference (as shown
by
the numbers you’ve all posted).
There are some things you can look in to:

  • Since knife has to load all commands including plugins when it runs,
    it’s
    important that any plugins you have installed make use of lazy loading.
  • Running gem clean can improve your runtimes dramatically. It can also
    break things that depend on those gems, so be careful.
    After running gem clean, I’m seeing times around 0.6 seconds to run
    knife -h and knife help when the disk cache is hot.
    I’d certainly like to improve this further, especially for the case that
    the
    disk cache is cold, but this would require fairly substantial
    architectural
    changes to knife–and the gains from doing so could be fairly small
    compared
    to the factors that are our of our control (e.g., factors affected by
    gem clean).

After ‘gem clean’:

knife -h 0.30s user 0.08s system 98% cpu 0.391 total
knife help 0.49s user 0.16s system 99% cpu 0.663 total

Optimizing more than this seems like a waste of time! =D

Is that knife-ec2 or just plain knife?

With knife-ec2 installed, I’m getting:

knife -h 0.41s user 0.13s system 99% cpu 0.543 total

I made a new RVM environment for knife and installed Chef and knife-ec2
along with their dependencies.

It’s now down to:

knife -h 1.69s user 0.16s system 99% cpu 1.847 total
knife help 1.73s user 0.17s system 99% cpu 1.905 total

Is this with the disk cache hot?

And what version of rubygems? I’m on 1.6.2 ATM.

Yes it was with the disk cache hot. I was using the latest, 1.7.2

I think we found the primary variable: Rubygems version.

With 1.3.7 I am now getting these numbers:

Ok, wow. I think I found the problem. I didn’t update my rubygems to the
latest this time and kept it at 1.3.7.

knife node list 0.76s user 0.17s system 53% cpu 1.754 total
knife --help 0.62s user 0.14s system 99% cpu 0.761 total
knife -h 0.62s user 0.15s system 99% cpu 0.766 total
knife node show e02 0.85s user 0.19s system 63% cpu 1.647 total

Now to go thru the Rubygems versions and see which is quickest and switch to
it using RVM when I’m working with knife.
Thanks,
Mike


Dan DeLeo

Also this is what my .gemrc looks like:


:benchmark: false
gem: --no-ri --no-rdoc --no-wrappers
:update_sources: true
:bulk_threshold: 1000
:verbose: true
:sources:

Thanks
Mike


Dan DeLeo

Thanks
Mike