Log time taken by is_active() calls for plugin listing (#662)

This is a preliminary step in addressing #625 that just adds logging (at INFO) for the amount of time taken by the is_active() call for each plugin loaded by TensorBoard when the plugins listing endpoint is invoked. This way as we make fixes we can monitor for regressions, and it also can help isolate the problematic plugin if we get reports from users that TensorBoard is taking a long time to respond with the list of active plugins (which is a prerequisite for basically any other usage of TensorBoard).

I also bundled in a couple small tweaks to other logging lines that can help diagnose slow plugin behavior.

Author: nfelt

tensorboard/backend/application.py

@@ -227,10 +227,15 @@ def _serve_plugins_listing(self, request):
     Returns:
       A werkzeug.Response object.
     """
-    return http_util.Respond(
-        request,
-        {plugin.plugin_name: plugin.is_active() for plugin in self._plugins},
-        'application/json')
+    response = {}
+    for plugin in self._plugins:
+      start = time.time()
+      response[plugin.plugin_name] = plugin.is_active()
+      elapsed = time.time() - start
+      tf.logging.info(
+          'Plugin listing: is_active() for %s took %0.3f seconds',
+          plugin.plugin_name, elapsed)
+    return http_util.Respond(request, response, 'application/json')
 
   def __call__(self, environ, start_response):  # pylint: disable=invalid-name
     """Central entry point for the TensorBoard application.

tensorboard/backend/event_processing/event_file_loader.py

@@ -46,6 +46,7 @@ def Load(self):
     Yields:
       All values that were written to disk that have not been yielded yet.
     """
+    tf.logging.debug('Loading events from %s', self._file_path)
     while True:
       try:
         with tf.errors.raise_exception_on_not_ok_status() as status:

tensorboard/backend/event_processing/plugin_event_multiplexer.py

@@ -173,7 +173,7 @@ def AddRunsFromDirectory(self, path, name=None):
     """
     tf.logging.info('Starting AddRunsFromDirectory: %s', path)
     for subdir in GetLogdirSubdirectories(path):
-      tf.logging.info('Adding events from directory %s', subdir)
+      tf.logging.info('Adding run from directory %s', subdir)
       rpath = os.path.relpath(subdir, path)
       subname = os.path.join(name, rpath) if name else rpath
       self.AddRun(subdir, name=subname)