Adds useful debug logging to filter_scheduler

On a large system (>500 hosts) the amount of logging
information if everything is at DEBUG is vasts, due to
the number of hosts checked for each filter

However at the moment some useful information is only
available within the filter's debug entrys (such as
parts of the request_spec).   Also instance uuids are
not logged making it hard to search for instance entries.

This set of changes allows it to be used in a very
large install with debug turned off for everything
except nova.filters

Specifically:
 - Log.Info the instance_uuids at the start of schedule
 - Log.debug the request_spec at the start of schedule
 - Log.debug hosts in weighted order
 - Log.info which host has been allocated to a specific
   instance_uuid
 - Log.debug how many hosts are returned by each filter

To get a count from each filter nova.filters had to be
changed to generate a list after each filter rather than
building a recursive generator object.   Although this
new approach is less elegant it does provide simple and
useful insight into the behaviour of the filters, and s
the impact on execution time on a system with several
hundred hosts and 10 filters was negligible

Change-Id: Ibbdd14f87b1dfd3cee8bf3cf6388e40b474e530a

2 files changed, 21 insertions, 6 deletions

diff --git a/nova/filters.py b/nova/filters.py
index 59028a542..18e3a7d66 100644
--- a/nova/filters.py
+++ b/nova/filters.py
@@ -18,6 +18,9 @@ Filter support
 """
 
 from nova import loadables
+from nova.openstack.common import log as logging
+
+LOG = logging.getLogger(__name__)
 
 
 class BaseFilter(object):
@@ -48,6 +51,11 @@ class BaseFilterHandler(loadables.BaseLoader):
 
     def get_filtered_objects(self, filter_classes, objs,
             filter_properties):
+        list_objs = list(objs)
+        LOG.debug("Starting with %d host(s)", len(list_objs))
         for filter_cls in filter_classes:
-            objs = filter_cls().filter_all(objs, filter_properties)
-        return list(objs)
+            list_objs = list(filter_cls().filter_all(list_objs,
+                             filter_properties))
+            LOG.debug("Filter %s returned %d host(s)",
+                      filter_cls.__name__, len(list_objs))
+        return list_objs
diff --git a/nova/scheduler/filter_scheduler.py b/nova/scheduler/filter_scheduler.py
index 8f99db0ae..2a96d0a0c 100644
--- a/nova/scheduler/filter_scheduler.py
+++ b/nova/scheduler/filter_scheduler.py
@@ -70,8 +70,11 @@ class FilterScheduler(driver.Scheduler):
                         'scheduler.run_instance.start', notifier.INFO, payload)
 
         instance_uuids = request_spec.pop('instance_uuids')
-        LOG.debug(_("Attempting to build %(num_instances)d instance(s)"),
-                  {'num_instances': len(instance_uuids)})
+        LOG.info(_("Attempting to build %(num_instances)d instance(s) "
+                    "uuids: %(instance_uuids)s"),
+                  {'num_instances': len(instance_uuids),
+                   'instance_uuids': instance_uuids})
+        LOG.debug(_("Request Spec: %s") % request_spec)
 
         weighed_hosts = self._schedule(context, request_spec,
                                        filter_properties, instance_uuids)
@@ -86,6 +89,10 @@ class FilterScheduler(driver.Scheduler):
             try:
                 try:
                     weighed_host = weighed_hosts.pop(0)
+                    LOG.info(_("Choosing host %(weighed_host)s "
+                                "for instance %(instance_uuid)s"),
+                              {'weighed_host': weighed_host,
+                               'instance_uuid': instance_uuid})
                 except IndexError:
                     raise exception.NoValidHost(reason="")
 
@@ -346,6 +353,8 @@ class FilterScheduler(driver.Scheduler):
             weighed_hosts = self.host_manager.get_weighed_hosts(hosts,
                     filter_properties)
 
+            LOG.debug(_("Weighed %(hosts)s"), {'hosts': weighed_hosts})
+
             scheduler_host_subset_size = CONF.scheduler_host_subset_size
             if scheduler_host_subset_size > len(weighed_hosts):
                 scheduler_host_subset_size = len(weighed_hosts)
@@ -354,8 +363,6 @@ class FilterScheduler(driver.Scheduler):
 
             chosen_host = random.choice(
                 weighed_hosts[0:scheduler_host_subset_size])
-            LOG.debug(_("Choosing host %(chosen_host)s"),
-                      {'chosen_host': chosen_host})
             selected_hosts.append(chosen_host)
 
             # Now consume the resources so the filter/weights