thread worker timing attempt for ipdevpoll

workerthreadtiming.patch

diff --git a/python/nav/ipdevpoll/db.py b/python/nav/ipdevpoll/db.py
index ae8aa91..a96e497 100644
--- a/python/nav/ipdevpoll/db.py
+++ b/python/nav/ipdevpoll/db.py
@@ -16,6 +16,7 @@
 """Database related functionality for ipdevpoll."""
 
 import gc
+from time import time
 from pprint import pformat
 from twisted.internet import threads
 import threading
@@ -29,7 +30,7 @@ from psycopg2 import InterfaceError, OperationalError
 
 import logging
 _logger = logging.getLogger(__name__)
-
+_timing_logger = logging.getLogger(__name__ + '.timings')
 
 class ResetDBConnectionError(Exception):
     pass
@@ -84,8 +85,34 @@ def run_in_thread(func, *args, **kwargs):
     database errors.
 
     """
-    return threads.deferToThread(reset_connection_on_interface_error(func),
-                                 *args, **kwargs)
+    if _timing_logger.isEnabledFor(logging.DEBUG):
+        call_time = time()
+        thread_start = []
+        func_desc = repr(func.func_code)
+
+        def _log_end_time(result):
+            end_time = time()
+            duration = end_time - call_time
+            thread_duration = end_time - thread_start[0]
+            overhead = duration - thread_duration
+
+            _timing_logger.debug(
+                "thread job %s: total duration=%.4f thread_duration=%.4f"
+                " overhead=%.4f",
+                func_desc, duration, thread_duration, overhead)
+            return result
+
+        def _timer(*_args, **_kwargs):
+            thread_start.append(time())
+            return func(*_args, **_kwargs)
+
+        decorated_func = reset_connection_on_interface_error(_timer)
+        return threads.deferToThread(
+            decorated_func, *args, **kwargs).addBoth(_log_end_time)
+    else:
+        decorated_func = reset_connection_on_interface_error(func)
+        return threads.deferToThread(
+            decorated_func, *args, **kwargs)
 
 
 def reset_connection_on_interface_error(func):