ansible: log call timings

ansible_mitogen/connection/mitogen.py

@@ -26,7 +26,9 @@
 # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 
 from __future__ import absolute_import
+import logging
 import os
+import time
 
 import ansible.errors
 import ansible.plugins.connection
@@ -38,6 +40,9 @@ import ansible_mitogen.helpers
 from ansible_mitogen.strategy.mitogen import ContextService
 
 
+LOG = logging.getLogger(__name__)
+
+
 class Connection(ansible.plugins.connection.ConnectionBase):
     #: mitogen.master.Router for this worker.
     router = None
@@ -174,7 +179,12 @@ class Connection(ansible.plugins.connection.ConnectionBase):
         :returns:
             Function return value.
         """
+        t0 = time.time()
+        try:
             return self.call_async(func, *args, **kwargs).get().unpickle()
+        finally:
+            LOG.debug('Call %s%r took %d ms', func.func_name, args,
+                      1000 * (time.time() - t0))
 
     def exec_command(self, cmd, in_data='', sudoable=True):
         """

docs/api.rst

@@ -1000,11 +1000,14 @@ A random assortment of utility functions useful on masters and children.
     OS X bundles some ancient version of the :py:mod:`six` module.
 
 .. currentmodule:: mitogen.utils
-.. function:: log_to_file (path=None, io=True, usec=False, level='INFO')
+.. function:: log_to_file (path=None, io=False, usec=False, level='INFO')
 
     Install a new :py:class:`logging.Handler` writing applications logs to the
     filesystem. Useful when debugging slave IO problems.
 
+    Parameters to this function may be overridden at runtime using environment
+    variables. See :ref:`logging-env-vars`.
+
     :param str path:
         If not ``None``, a filesystem path to write logs to. Otherwise, logs
         are written to :py:data:`sys.stderr`.

mitogen/utils.py

@@ -49,7 +49,7 @@ def _formatTime(record, datefmt=None):
     return dt.strftime(datefmt)
 
 
-def log_to_file(path=None, io=True, usec=False, level='INFO'):
+def log_to_file(path=None, io=False, usec=False, level='INFO'):
     io = ('MITOGEN_LOG_IO' in os.environ) or io
     usec = ('MITOGEN_LOG_USEC' in os.environ) or usec
     level = os.environ.get('MITOGEN_LOG_LEVEL', level).upper()