$ time python -c 'import boto.utils; boto.utils.get_instance_metadata()'
real 0m5.740s
user 0m0.190s
sys 0m0.110s
I've not done a lot of digging on this, but I suspect that
nova/api/ec2/cloud.py:get_metadata is doing some heavy queries.
cloud-init does at least 2 separate hits of the metadata service on boot, this means we see something like this in cloud-init.log:
2011-09-15 18:17:53,844 - cloud-init[INFO]: cloud-init start running: Thu, 15 Sep 2011 18:17:53 +0000. up 6.01 seconds
2011-09-15 18:17:53,855 - __init__.py[DEBUG]: searching for data source in ['DataSourceNoCloudNet', 'DataSourceOVFNet', 'DataSourceEc2']
2011-09-15 18:17:53,989 - DataSourceEc2.py[DEBUG]: removed the following from metadata urls: ['http://instance-data:8773']
2011-09-15 18:17:53,989 - DataSourceEc2.py[DEBUG]: Searching the following metadata urls: ['http://169.254.169.254']
2011-09-15 18:17:54,350 - DataSourceEc2.py[DEBUG]: Using metadata source: 'http://169.254.169.254'
2011-09-15 18:18:00,027 - __init__.py[DEBUG]: found data source DataSourceEc2
2011-09-15 18:18:00,050 - cloud-init[DEBUG]: found data source: DataSourceEc2
Note the 5 second time lapse between 'Using' and 'found'. Using just indicated there the port was open. found actually used data from it.
Not only does it do heavy queries, but it rebuilds the entire metadata set for every single request that is made to the metadata server. Horribly inefficient! I want to break the metadata code out into its own binary as well. I will be filing a blueprint to that affect soon. We definitely need some efficiency cleanup for the metadata server as well.
On Sep 15, 2011, at 11:26 AM, Scott Moser wrote:
> Public bug reported: get_instance_ metadata( )' ec2/cloud. py:get_ metadata is doing some heavy queries. loudNet' , 'DataSourceOVFNet', 'DataSourceEc2'] py[DEBUG] : removed the following from metadata urls: ['http:// instance- data:8773'] py[DEBUG] : Searching the following metadata urls: ['http:// 169.254. 169.254'] py[DEBUG] : Using metadata source: 'http:// 169.254. 169.254' /bugs.launchpad .net/bugs/ 851159 get_instance_ metadata( )' ec2/cloud. py:get_ metadata is doing some heavy queries. loudNet' , 'DataSourceOVFNet', 'DataSourceEc2'] py[DEBUG] : removed the following from metadata urls: ['http:// instance- data:8773'] py[DEBUG] : Searching the following metadata urls: ['http:// 169.254. 169.254'] py[DEBUG] : Using metadata source: 'http:// 169.254. 169.254'
>
> $ time python -c 'import boto.utils; boto.utils.
>
> real 0m5.740s
> user 0m0.190s
> sys 0m0.110s
>
> I've not done a lot of digging on this, but I suspect that
> nova/api/
>
> cloud-init does at least 2 separate hits of the metadata service on
> boot, this means we see something like this in cloud-init.log:
>
> 2011-09-15 18:17:53,844 - cloud-init[INFO]: cloud-init start running: Thu, 15 Sep 2011 18:17:53 +0000. up 6.01 seconds
> 2011-09-15 18:17:53,855 - __init__.py[DEBUG]: searching for data source in ['DataSourceNoC
> 2011-09-15 18:17:53,989 - DataSourceEc2.
> 2011-09-15 18:17:53,989 - DataSourceEc2.
> 2011-09-15 18:17:54,350 - DataSourceEc2.
> 2011-09-15 18:18:00,027 - __init__.py[DEBUG]: found data source DataSourceEc2
> 2011-09-15 18:18:00,050 - cloud-init[DEBUG]: found data source: DataSourceEc2
>
>
> Note the 5 second time lapse between 'Using' and 'found'. Using just indicated there the port was open. found actually used data from it.
>
> ** Affects: nova
> Importance: Undecided
> Status: New
>
> --
> You received this bug notification because you are a member of Nova Bug
> Team, which is subscribed to OpenStack Compute (nova).
> https:/
>
> Title:
> ec2 metadata service is very slow
>
> Status in OpenStack Compute (Nova):
> New
>
> Bug description:
> $ time python -c 'import boto.utils;
> boto.utils.
>
> real 0m5.740s
> user 0m0.190s
> sys 0m0.110s
>
> I've not done a lot of digging on this, but I suspect that
> nova/api/
>
> cloud-init does at least 2 separate hits of the metadata service on
> boot, this means we see something like this in cloud-init.log:
>
> 2011-09-15 18:17:53,844 - cloud-init[INFO]: cloud-init start running: Thu, 15 Sep 2011 18:17:53 +0000. up 6.01 seconds
> 2011-09-15 18:17:53,855 - __init__.py[DEBUG]: searching for data source in ['DataSourceNoC
> 2011-09-15 18:17:53,989 - DataSourceEc2.
> 2011-09-15 18:17:53,989 - DataSourceEc2.
> 2011-09-15 18:17:54,350 - DataSourceEc2.
> 2011-09-15 18:18:00,027 - __init...