added mass eagerloading profile, debug log in EagerLoader conditional based on flag

diff --git a/lib/sqlalchemy/orm/strategies.py b/lib/sqlalchemy/orm/strategies.py
index c4b75f64441b4ebeb4d41385fe1460be5058abc4..28fbdcfd31165d8e245eeb8b0f87140c4875d263 100644 (file)
--- a/lib/sqlalchemy/orm/strategies.py
+++ b/lib/sqlalchemy/orm/strategies.py
@@ -293,7 +293,7 @@ class EagerLoader(AbstractRelationLoader):
 
         self.clauses = {}
         self.clauses_by_lead_mapper = {}
-        
+        self.__should_log_debug = logging.is_debug_enabled(self.logger)
     class AliasedClauses(object):
         """defines a set of join conditions and table aliases which are aliased on a randomly-generated
         alias name, corresponding to the connection of an optional parent AliasedClauses object and a 
@@ -476,7 +476,8 @@ class EagerLoader(AbstractRelationLoader):
             identity_key = self.mapper.identity_key_from_row(decorated_row)
         except KeyError:
             # else degrade to a lazy loader
-            self.logger.debug("degrade to lazy loader on %s" % mapperutil.attribute_str(instance, self.key))
+            if self.__should_log_debug:
+                self.logger.debug("degrade to lazy loader on %s" % mapperutil.attribute_str(instance, self.key))
             self.parent_property._get_strategy(LazyLoader).process_row(selectcontext, instance, row, identitykey, isnew)
             return
             
@@ -485,7 +486,8 @@ class EagerLoader(AbstractRelationLoader):
         selectcontext.recursion_stack.add(self)
         try:
             if not self.uselist:
-                self.logger.debug("eagerload scalar instance on %s" % mapperutil.attribute_str(instance, self.key))
+                if self.__should_log_debug:
+                    self.logger.debug("eagerload scalar instance on %s" % mapperutil.attribute_str(instance, self.key))
                 if isnew:
                     # set a scalar object instance directly on the parent object, 
                     # bypassing SmartProperty event handlers.
@@ -496,7 +498,8 @@ class EagerLoader(AbstractRelationLoader):
                     self.mapper._instance(selectcontext, decorated_row, None)
             else:
                 if isnew:
-                    self.logger.debug("initialize UniqueAppender on %s" % mapperutil.attribute_str(instance, self.key))
+                    if self.__should_log_debug:
+                        self.logger.debug("initialize UniqueAppender on %s" % mapperutil.attribute_str(instance, self.key))
                     # call the SmartProperty's initialize() method to create a new, blank list
                     l = getattr(instance.__class__, self.key).initialize(instance)
                 
@@ -506,7 +509,8 @@ class EagerLoader(AbstractRelationLoader):
                     # store it in the "scratch" area, which is local to this load operation.
                     selectcontext.attributes[(instance, self.key)] = appender
                 result_list = selectcontext.attributes[(instance, self.key)]
-                self.logger.debug("eagerload list instance on %s" % mapperutil.attribute_str(instance, self.key))
+                if self.__should_log_debug:
+                    self.logger.debug("eagerload list instance on %s" % mapperutil.attribute_str(instance, self.key))
                 self.mapper._instance(selectcontext, decorated_row, result_list)
         finally:
             selectcontext.recursion_stack.remove(self)

diff --git a/test/perf/masseagerload.py b/test/perf/masseagerload.py
new file mode 100644 (file)
index 0000000..8563dab
--- /dev/null
+++ b/test/perf/masseagerload.py
@@ -0,0 +1,54 @@
+from testbase import PersistTest, AssertMixin
+import unittest, sys, os
+from sqlalchemy import *
+import StringIO
+import testbase
+import gc
+import time
+
+db = testbase.db
+
+NUM = 25000
+
+class LoadTest(AssertMixin):
+    def setUpAll(self):
+        global items, meta,subitems
+        meta = BoundMetaData(db)
+        items = Table('items', meta, 
+            Column('item_id', Integer, primary_key=True),
+            Column('value', String(100)))
+        subitems = Table('subitems', meta, 
+            Column('sub_id', Integer, primary_key=True),
+            Column('parent_id', Integer, ForeignKey('items.item_id')),
+            Column('value', String(100)))
+        meta.create_all()
+    def tearDownAll(self):
+        meta.drop_all()
+    def setUp(self):
+        clear_mappers()
+        l = []
+        for x in range(1,NUM/500):
+            l.append({'item_id':x, 'value':'this is item #%d' % x})
+        items.insert().execute(*l)
+        for x in range(1, NUM/500):
+            l = []
+            for y in range(1, NUM/(NUM/500)):
+                z = ((x-1) * NUM/(NUM/500)) + y
+                l.append({'sub_id':z,'value':'this is iteim #%d' % z, 'parent_id':x})
+            #print l
+            subitems.insert().execute(*l)    
+    def testload(self):
+        class Item(object):pass
+        class SubItem(object):pass
+        mapper(Item, items, properties={'subs':relation(SubItem, lazy=False)})
+        mapper(SubItem, subitems)
+        sess = create_session()
+        now = time.time()
+        query = sess.query(Item)
+        l = query.select()
+        print "loaded ", len(l), " items each with ", len(l[0].subs), "subitems"
+        total = time.time() -now
+        print "total time ", total
+        
+if __name__ == "__main__":
+    testbase.main()