added logging of function call durations

inventory_provider/tasks/worker.py

@@ -4,6 +4,7 @@ import json
 import logging
 import os
 import re
+import time
 from typing import List
 
 from celery import Task, states, chord
@@ -50,10 +51,13 @@ def log_task_entry_and_exit(f):
     @functools.wraps(f)
     def _w(*args, **kwargs):
         logger.debug(f'>>> {f.__name__}{args}')
+        start_time = time.time()
         try:
             return f(*args, **kwargs)
         finally:
-            logger.debug(f'<<< {f.__name__}{args}')
+            end_time = time.time()
+            duration = end_time - start_time
+            logger.debug(f'<<< {f.__name__}{args} -- duration {duration}')
     return _w
 
 
@@ -727,33 +731,40 @@ def extract_ims_data():
     port_id_details = defaultdict(list)
     port_id_services = defaultdict(list)
 
+    @log_task_entry_and_exit
     def _populate_locations():
         nonlocal locations
         locations = {k: v for k, v in ims_data.get_node_locations(ds=_ds())}
 
+    @log_task_entry_and_exit
     def _populate_lg_routers():
         nonlocal lg_routers
         lg_routers = list(ims_data.lookup_lg_routers(ds=_ds()))
 
+    @log_task_entry_and_exit
     def _populate_geant_nodes():
         nonlocal geant_nodes
         geant_nodes = list(ims_data.lookup_geant_nodes(ds=_ds()))
 
+    @log_task_entry_and_exit
     def _populate_customer_contacts():
         nonlocal customer_contacts
         customer_contacts = \
             {k: v for k, v in ims_data.get_customer_service_emails(ds=_ds())}
 
+    @log_task_entry_and_exit
     def _populate_circuit_ids_to_monitor():
         nonlocal circuit_ids_to_monitor
         circuit_ids_to_monitor = \
             list(ims_data.get_monitored_circuit_ids(ds=_ds()))
 
+    @log_task_entry_and_exit
     def _populate_sids():
         nonlocal circuit_ids_and_sids
         circuit_ids_and_sids = \
             {cid: sid for cid, sid in ims_data.get_ids_and_sids(ds=_ds())}
 
+    @log_task_entry_and_exit
     def _populate_additional_circuit_customer_ids():
         nonlocal additional_circuit_customer_ids
         additional_circuit_customer_ids = \
@@ -780,12 +791,14 @@ def extract_ims_data():
     if exceptions:
         raise InventoryTaskError(json.dumps(exceptions, indent=2))
 
+    @log_task_entry_and_exit
     def _populate_hierarchy():
         nonlocal hierarchy
         hierarchy = {
             d['id']: d for d in ims_data.get_circuit_hierarchy(ds=_ds())}
         logger.debug("hierarchy complete")
 
+    @log_task_entry_and_exit
     def _populate_port_id_details():
         nonlocal port_id_details
         for x in ims_data.get_port_details(ds=_ds()):
@@ -793,6 +806,7 @@ def extract_ims_data():
             pd.append(x)
         logger.debug("Port details complete")
 
+    @log_task_entry_and_exit
     def _populate_circuit_info():
         for x in ims_data.get_port_id_services(ds=_ds()):
             port_id_services[x['port_a_id']].append(x)