wip log timings

product/ERP5Type/dynamic/lazy_class.py

@@ -20,6 +20,26 @@ from accessor_holder import AccessorHolderType
 import persistent_migration
 from ZODB.POSException import ConflictError
 
+from contextlib import contextmanager
+import time
+import logging
+@contextmanager
+def _log_time_usage(prefix=""):
+    '''log the time usage in a code block
+    prefix: the prefix text to show
+    '''
+    start = time.time()
+    try:
+        yield
+    finally:
+        end = time.time()
+        elapsed_seconds = float("%.4f" % (end - start))
+        if elapsed_seconds > 0.5:
+          logging.critical('%s: elapsed seconds: %s', prefix, elapsed_seconds)
+
+        logging.info('%s: elapsed seconds: %s', prefix, elapsed_seconds)
+
+
 class ERP5BaseBroken(Broken, ERP5Base, PersistentBroken):
   # PersistentBroken can't be reused directly
   # because its « layout differs from 'GhostPortalType' »
@@ -269,6 +289,7 @@ class PortalTypeMetaClass(GhostBaseMetaClass, PropertyHolder):
       return getattr(cls.__bases__[0], name)
 
     if not name.startswith('__') and cls.__isghost__:
+      with _log_time_usage('loadClass (%s)' % cls):
         cls.loadClass()
       return getattr(cls, name)
 
@@ -297,6 +318,7 @@ class PortalTypeMetaClass(GhostBaseMetaClass, PropertyHolder):
     # generate all methods on Base accessor holder, with all methods
     # returning False, and redefine on portal types only those returning True,
     # aka only those for the group they belong to
+    if 1: #with _log_time_usage("generating isAccessors for %s" % cls):
       for group in ERP5TypeInformation.defined_group_list:
         value = cls.__name__ in site._getPortalGroupedTypeSet(group)
         accessor_name = 'is' + UpperCase(group) + 'Type'

product/ERP5Type/dynamic/portal_type_class.py

@@ -348,6 +348,24 @@ def generatePortalTypeClass(site, portal_type_name):
           interface_class_list,
           attribute_dict)
 
+
+from contextlib import contextmanager
+import time
+import logging
+@contextmanager
+def _log_time_usage(prefix=""):
+    '''log the time usage in a code block
+    prefix: the prefix text to show
+    '''
+    start = time.time()
+    try:
+        yield
+    finally:
+        end = time.time()
+        elapsed_seconds = float("%.4f" % (end - start))
+        logging.info('%s: elapsed seconds: %s', prefix, elapsed_seconds)
+
+
 def loadTempPortalTypeClass(portal_type_name):
   """
   Returns a class suitable for a temporary portal type
@@ -463,6 +481,8 @@ def synchronizeDynamicModules(context, force=False):
 
     LOG("ERP5Type.dynamic", 0, "Resetting dynamic classes")
     try:
+      with _log_time_usage("Resetting dynamic classes"):
+
         for _, klass in inspect.getmembers(erp5.portal_type,
                                           inspect.isclass):
           # Zope Interface is implemented through __implements__,