From b221eaaa10301295adff03b00755b417f0b1ae17 Mon Sep 17 00:00:00 2001
From: David Wilson <dw@botanicus.net>
Date: Sun, 18 Feb 2018 13:32:09 +0545
Subject: [PATCH] ansible: log call timings

---
 ansible_mitogen/connection/mitogen.py | 12 +++++++++++-
 docs/api.rst                          |  5 ++++-
 mitogen/utils.py                      |  2 +-
 3 files changed, 16 insertions(+), 3 deletions(-)

diff --git a/ansible_mitogen/connection/mitogen.py b/ansible_mitogen/connection/mitogen.py
index 4e3c506c..8912bfa2 100644
--- a/ansible_mitogen/connection/mitogen.py
+++ b/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.
         """
-        return self.call_async(func, *args, **kwargs).get().unpickle()
+        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):
         """
diff --git a/docs/api.rst b/docs/api.rst
index a3d5f6d1..1050e62a 100644
--- a/docs/api.rst
+++ b/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`.
diff --git a/mitogen/utils.py b/mitogen/utils.py
index cd8a93d1..e6d2d6fe 100644
--- a/mitogen/utils.py
+++ b/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()