commit 0ec94dd0bb1b11b8aec292fbdc1135244db570d7
author Simran Basi <sbasi@chromium.org> Tue Aug 28 09:50:10 2012 -0700
committer Gerrit <chrome-bot@google.com> Tue Aug 28 15:04:03 2012 -0700
tree e655322d365e0d07ce1dfa3022211bd4dc3a532d
parent 66ceb13f62e656a22a201504f10dbafdb6423c0d

Autotest: Add more logging to the tick.

Added a line of logging before each major step of the tick so that we
can better determine where the tick time is being used.

I put this in monitor_db.py instead of site_monitor_db.py since it does not
the proper scope to view the global variable _drone_manager.

BUG=chromium-os:33890
TEST=Made sure monitor_db ran locally and my new messages were being
printed.

Change-Id: I2c8e08bab835c4ee1a92c0a6502242048b13293a
Reviewed-on: https://gerrit.chromium.org/gerrit/31601
Commit-Ready: Simran Basi <sbasi@google.com>
Reviewed-by: Simran Basi <sbasi@google.com>
Tested-by: Simran Basi <sbasi@google.com>

global_config.ini

diff --git a/global_config.ini b/global_config.ini
index b6da726..979713e 100644
--- a/global_config.ini
+++ b/global_config.ini
@@ -92,6 +92,7 @@
 enable_archiving: False
 copy_task_results_back: False
 copy_parse_log_back: False
+tick_debug: True
 
 
 [HOSTS]

scheduler/monitor_db.py

diff --git a/scheduler/monitor_db.py b/scheduler/monitor_db.py
index 3a8c7d7..c533f85 100755
--- a/scheduler/monitor_db.py
+++ b/scheduler/monitor_db.py
@@ -268,6 +268,9 @@
                 global_config.global_config.get_config_value(
                         scheduler_config.CONFIG_SECTION,
                         'gc_stats_interval_mins', type=int, default=6*60))
+        self._tick_debug = global_config.global_config.get_config_value(
+                scheduler_config.CONFIG_SECTION, 'tick_debug', type=bool,
+                default=False)
 
 
     def initialize(self, recover_hosts=True):
@@ -283,20 +286,45 @@
         self._host_scheduler.recovery_on_startup()
 
 
+    def _log_tick_msg(self, msg):
+        if self._tick_debug:
+            logging.debug(msg)
+
+
     def tick(self):
+        """
+        This is an altered version of tick() where we keep track of when each
+        major step begins so we can try to figure out where we are using most
+        of the tick time.
+        """
+        self._log_tick_msg('Starting new tick, starting garbage collection().')
         self._garbage_collection()
+        self._log_tick_msg('Starting _drone_manager.refresh().')
         _drone_manager.refresh()
+        self._log_tick_msg('Starting _run_cleanup().')
         self._run_cleanup()
+        self._log_tick_msg('Starting _find_aborting().')
         self._find_aborting()
+        self._log_tick_msg('Starting _process_recurring_runs().')
         self._process_recurring_runs()
+        self._log_tick_msg('Starting _schedule_delay_tasks().')
         self._schedule_delay_tasks()
+        self._log_tick_msg('Starting _schedule_running_host_queue_entries().')
         self._schedule_running_host_queue_entries()
+        self._log_tick_msg('Starting _schedule_special_tasks().')
         self._schedule_special_tasks()
+        self._log_tick_msg('Starting _schedule_new_jobs().')
         self._schedule_new_jobs()
+        self._log_tick_msg('Starting _handle_agents().')
         self._handle_agents()
+        self._log_tick_msg('Starting _host_scheduler.tick().')
         self._host_scheduler.tick()
+        self._log_tick_msg('Starting _drone_manager.execute_actions().')
         _drone_manager.execute_actions()
+        self._log_tick_msg('Starting '
+                           'email_manager.manager.send_queued_emails().')
         email_manager.manager.send_queued_emails()
+        self._log_tick_msg('Starting django.db.reset_queries().')
         django.db.reset_queries()
         self._tick_count += 1