Use ExecutionTimer

lib/galaxy/tools/search/__init__.py

@@ -5,7 +5,6 @@ installed within this Galaxy.
 import logging
 import re
 import tempfile
-from datetime import datetime
 
 from whoosh import analysis
 from whoosh.analysis import StandardAnalyzer
@@ -22,6 +21,7 @@ from whoosh.filedb.filestore import (
 from whoosh.qparser import MultifieldParser
 from whoosh.scoring import BM25F
 
+from galaxy.util import ExecutionTimer
 from galaxy.web.framework.helpers import to_unicode
 
 log = logging.getLogger( __name__ )
@@ -50,19 +50,18 @@ class ToolBoxSearch( object ):
 
     def build_index( self, index_help=True ):
         """Prepare search index for tools loaded in toolbox."""
+        log.debug( 'Starting to build toolbox index.' )
+        execution_timer = ExecutionTimer()
         RamStorage.temp_storage = _temp_storage
         # Works around https://bitbucket.org/mchaput/whoosh/issues/391/race-conditions-with-temp-storage
         self.storage = RamStorage()
         self.index = self.storage.create_index( self.schema )
         writer = self.index.writer()
-        start_time = datetime.now()
-        log.debug( 'Starting to build toolbox index.' )
         for tool_id, tool in self.toolbox.tools():
             add_doc_kwds = self._create_doc(tool_id=tool_id, tool=tool, index_help=index_help)
             writer.add_document( **add_doc_kwds )
         writer.commit()
-        stop_time = datetime.now()
-        log.debug( 'Toolbox index finished. It took: ' + str(stop_time - start_time) )
+        log.debug("Toolbox index finished %s", execution_timer )
 
     def _create_doc(self, tool_id, tool, index_help=True):
         #  Do not add data managers to the public index

lib/galaxy/tools/toolbox/base.py

@@ -14,6 +14,7 @@ from galaxy.exceptions import MessageException, ObjectNotFound
 from galaxy.tools.deps import build_dependency_manager
 from galaxy.tools.loader_directory import looks_like_a_tool
 from galaxy.util import (
+    ExecutionTimer,
     listify,
     parse_xml,
     string_as_bool
@@ -97,7 +98,7 @@ class AbstractToolBox( Dictifiable, ManagesIntegratedToolPanelMixin, object ):
         """ Read through all tool config files and initialize tools in each
         with init_tools_from_config below.
         """
-        start = time.time()
+        execution_timer = ExecutionTimer()
         self._tool_tag_manager.reset_tags()
         config_filenames = listify( config_filenames )
         for config_filename in config_filenames:
@@ -120,7 +121,7 @@ class AbstractToolBox( Dictifiable, ManagesIntegratedToolPanelMixin, object ):
                     raise
             except Exception:
                 log.exception( "Error loading tools defined in config %s", config_filename )
-        log.debug("Reading tools from config files took %f seconds", time.time() - start)
+        log.debug("Reading tools from config files finshed %s", execution_timer)
 
     def _init_tools_from_config( self, config_filename ):
         """
@@ -323,7 +324,7 @@ class AbstractToolBox( Dictifiable, ManagesIntegratedToolPanelMixin, object ):
             log.debug(log_msg)
 
     def _load_tool_panel( self ):
-        start = time.time()
+        execution_timer = ExecutionTimer()
         for key, item_type, val in self._integrated_tool_panel.panel_items_iter():
             if item_type == panel_item_types.TOOL:
                 tool_id = key.replace( 'tool_', '', 1 )
@@ -363,7 +364,7 @@ class AbstractToolBox( Dictifiable, ManagesIntegratedToolPanelMixin, object ):
                             section.elems[ section_key ] = section_val
                             log.debug( "Loaded label: %s" % ( section_val.text ) )
                 self._tool_panel[ key ] = section
-        log.debug("loading tool panel took %d seconds", time.time() - start)
+        log.debug("Loading tool panel finished %s", execution_timer)
 
     def _load_integrated_tool_panel_keys( self ):
         """