builder log

bt5/erp5_base/MixinTemplateItem/portal_components/mixin.erp5.BuilderMixin.py

@@ -110,6 +110,10 @@ class BuilderMixin(XMLObject, Amount, Predicate):
       restrict selection to a given root Applied Rule caused by a single Order
       or to Simulation Movements related to a limited set of existing
     """
+    import datetime
+    import logging
+    logger = logging.getLogger("%s(%s)" % (__name__, self.getRelativeUrl()))
+    total_start = datetime.datetime.now()
     # Parameter initialization
     if delivery_relative_url_list is None:
       delivery_relative_url_list = []
@@ -133,19 +137,35 @@ class BuilderMixin(XMLObject, Amount, Predicate):
             kw['causality_uid'] = [link_value.getUid() for link_value in business_link_value_list]
         if applied_rule_uid is not None:
           kw['applied_rule_uid'] = applied_rule_uid
+
+        start = datetime.datetime.now()
         movement_list = self.searchMovementList(**kw)
+        logger.info(
+            'Found %s movements in %s', len(movement_list), datetime.datetime.now() - start )
         if not movement_list:
+          logger.info('No movement found')
           return []
+
     # Collect
+    start = datetime.datetime.now()
     root_group_node = self.collectMovement(movement_list, merge_delivery=merge_delivery)
+    logger.info('Collected in %s', datetime.datetime.now() - start )
+
     # Build
+    start = datetime.datetime.now()
     delivery_list = self.buildDeliveryList(
                        root_group_node,
                        delivery_relative_url_list=delivery_relative_url_list,
                        movement_list=movement_list, activate_kw=activate_kw,
                        merge_delivery=merge_delivery, **kw)
+    logger.info('Built %s deliveries in %s', len(delivery_list), datetime.datetime.now() - start )
+
     # Call a script after building
+    start = datetime.datetime.now()
     self.callAfterBuildingScript(delivery_list, movement_list, **kw)
+    logger.info('callAfterBuildingScript in %s', datetime.datetime.now() - start )
+
+    logger.info('Total build() time for %s deliveries in %s', len(delivery_list), datetime.datetime.now() - total_start )
     return delivery_list
 
   def getRelatedBusinessLinkValueList(self):