Add some DBLOGNAME (".Db") diagnostics (especially for transactions) and

make sure they are the same for BSDDB and for DBAPI.

gramps/gen/db/txn.py

@@ -31,13 +31,16 @@ database.
 import pickle
 import logging
 from collections import defaultdict
+import time
+import inspect
+import os
 
 #-------------------------------------------------------------------------
 #
 # Gramps modules
 #
 #-------------------------------------------------------------------------
-from .dbconst import (DBLOGNAME, TXNADD, TXNUPD, TXNDEL)
+from .dbconst import DBLOGNAME
 
 _LOG = logging.getLogger(DBLOGNAME)
 
@@ -59,6 +62,8 @@ class DbTxn(defaultdict):
         """
         Context manager entry method
         """
+        _LOG.debug("    DbTxn %s entered" % hex(id(self)))
+        self.start_time = time.time()
         self.db.transaction_begin(self)
         return self
 
@@ -70,6 +75,19 @@ class DbTxn(defaultdict):
             self.db.transaction_commit(self)
         else:
             self.db.transaction_abort(self)
+
+        elapsed_time = time.time() - self.start_time
+        if __debug__:
+            caller_frame = inspect.stack()[1]
+            _LOG.debug("    **** DbTxn %s exited. Called from file %s, "
+                       "line %s, in %s **** %.2f seconds" %
+                       ((hex(id(self)),)+
+                        (os.path.split(caller_frame[1])[1],)+
+                        tuple(caller_frame[i] for i in range(2, 4))+
+                        (elapsed_time,)
+                       )
+                      )
+
         return False
 
     def __init__(self, msg, grampsdb, batch=False, **kwargs):
@@ -105,6 +123,26 @@ class DbTxn(defaultdict):
                 data   = pickled representation of the object
         """
 
+        # Conditional on __debug__ because all that frame stuff may be slow
+        if __debug__:
+            caller_frame = inspect.stack()[1]
+            # If the call comes from gramps.gen.db.generic.DbGenericTxn.__init__
+            # then it is just a dummy redirect, so we need to go back another
+            # frame to get any real information. The test does not accurately
+            # check this, but seems to be good enough for the current diagnostic
+            # purposes.
+            if os.path.split(caller_frame[1])[1] == "generic.py" and \
+               caller_frame[3] == "__init__":
+                caller_frame = inspect.stack()[2]
+            _LOG.debug("%sDbTxn %s instantiated for '%s'. Called from file %s, "
+                       "line %s, in %s" %
+                       (("Batch " if batch else "",)+
+                        (hex(id(self)),)+
+                        (msg,)+
+                        (os.path.split(caller_frame[1])[1],)+
+                        (tuple(caller_frame[i] for i in range(2, 4)))
+                       )
+                      )
         defaultdict.__init__(self, list, {})
 
         self.msg = msg

gramps/gen/dbstate.py

@@ -41,6 +41,7 @@ from .db import DbReadBase
 from .proxy.proxybase import ProxyDbBase
 from .utils.callback import Callback
 from .config import config
+from gramps.gen.db.dbconst import DBLOGNAME
 
 #-------------------------------------------------------------------------
 #
@@ -48,6 +49,7 @@ from .config import config
 #
 #-------------------------------------------------------------------------
 LOG = logging.getLogger(".dbstate")
+_LOG = logging.getLogger(DBLOGNAME)
 
 class DbState(Callback):
     """
@@ -182,6 +184,7 @@ class DbState(Callback):
                     self.save_modules()
             mod = pmgr.load_plugin(pdata)
             database = getattr(mod, pdata.databaseclass)
+            _LOG.debug("make_database %s" % database)
             return database()
 
     def open_database(self, dbname, force_unlock=False, callback=None):

gramps/plugins/database/bsddb_support/bsddbtxn.py

@@ -22,6 +22,23 @@
 BSDDBTxn class: Wrapper for BSDDB transaction-oriented methods
 """
 
+#-------------------------------------------------------------------------
+#
+# Standard python modules
+#
+#-------------------------------------------------------------------------
+import logging
+import inspect
+import os
+
+#-------------------------------------------------------------------------
+#
+# Gramps modules
+#
+#-------------------------------------------------------------------------
+from gramps.gen.db.dbconst import DBLOGNAME
+_LOG = logging.getLogger(DBLOGNAME)
+
 #-------------------------------------------------------------------------
 #
 # BSDDBTxn
@@ -54,6 +71,16 @@ class BSDDBTxn:
         """
         Initialize transaction instance
         """
+        # Conditional on __debug__ because all that frame stuff may be slow
+        if __debug__:
+            caller_frame = inspect.stack()[1]
+            _LOG.debug("        BSDDBTxn %s instantiated. Called from file %s,"
+                       " line %s, in %s" %
+                       ((hex(id(self)),)+
+                        (os.path.split(caller_frame[1])[1],)+
+                        (tuple(caller_frame[i] for i in range(2, 4)))
+                       )
+                      )
         self.env = env
         self.db = db
         self.txn = None
@@ -66,6 +93,7 @@ class BSDDBTxn:
 
         Begin the transaction
         """
+        _LOG.debug("    BSDDBTxn %s entered" % hex(id(self)))
         self.txn = self.begin(parent, **kwargs)
         self.parent = parent
         return self
@@ -76,6 +104,7 @@ class BSDDBTxn:
 
         Commit the transaction if no exception occurred
         """
+        _LOG.debug("        BSDDBTxn %s exited" % hex(id(self)))
         if exc_type is not None:
             return False
         if self.txn:
@@ -88,6 +117,11 @@ class BSDDBTxn:
         """
         Create and begin a new transaction. A DBTxn object is returned
         """
+        _LOG.debug("        BSDDBTxn %s begin" % hex(id(self)))
+        _LOG.debug("        BSDDBTxn %s calls %s %s txn_begin" %
+                   (hex(id(self)), self.env.__class__.__name__,
+                    hex(id(self.env)))
+                   )
         self.txn = self.env.txn_begin(*args, **kwargs)
         return self.txn
 
@@ -97,7 +131,7 @@ class BSDDBTxn:
         log and then flush the log
         """
         if self.env:
-             self.env.txn_checkpoint(*args, **kwargs)
+            self.env.txn_checkpoint(*args, **kwargs)
 
     def stat(self):
         """
@@ -128,6 +162,7 @@ class BSDDBTxn:
         """
         End the transaction, committing any changes to the databases
         """
+        _LOG.debug("        BSDDBTxn %s commit" % hex(id(self)))
         if self.txn:
             self.txn.commit(flags)
             self.txn = None

gramps/plugins/database/bsddb_support/write.py

@@ -2197,6 +2197,12 @@ class DbBsddb(DbBsddbRead, DbWriteBase, UpdateCallback):
           Boolean, defaults to False, indicating if secondary indices should be
           disconnected.
         """
+        _LOG.debug("    %s%sDbBsddb %s transaction begin for '%s'"
+                   % ("Magic " if getattr(transaction, 'no_magic', False)
+                      else "",
+                      "Batch " if transaction.batch else "",
+                      hex(id(self)),
+                      transaction.get_description()))
         if self.txn is not None:
             msg = self.transaction.get_description()
             self.transaction_abort(self.transaction)
@@ -2269,6 +2275,12 @@ class DbBsddb(DbBsddbRead, DbWriteBase, UpdateCallback):
         self.undodb.commit(transaction, msg)
         self.__after_commit(transaction)
         self.has_changed = True
+        _LOG.debug("    %s%sDbBsddb %s transaction commit for '%s'"
+                   % ("Magic " if getattr(transaction, 'no_magic', False)
+                      else "",
+                      "Batch " if transaction.batch else "",
+                      hex(id(self)),
+                      transaction.get_description()))
 
     def __emit(self, transaction, obj_type, trans_type, obj, suffix):
         """

gramps/plugins/database/dbapi.py

@@ -18,24 +18,30 @@
 # Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
 #
 
+#-------------------------------------------------------------------------
+#
+# Standard python modules
+#
+#-------------------------------------------------------------------------
+import time
+import sys
+import pickle
+from operator import itemgetter
+
 #------------------------------------------------------------------------
 #
 # Gramps Modules
 #
 #------------------------------------------------------------------------
 from gramps.gen.db.generic import *
+from gramps.gen.db.dbconst import DBLOGNAME
+import dbapi_support
+import logging
 from gramps.gen.const import GRAMPS_LOCALE as glocale
 _ = glocale.translation.gettext
 
-import dbapi_support
-
-import time
-import sys
-import pickle
-from operator import itemgetter
-
-import logging
 LOG = logging.getLogger(".dbapi")
+_LOG = logging.getLogger(DBLOGNAME)
 
 class DBAPI(DbGeneric):
     """
@@ -93,22 +99,30 @@ class DBAPI(DbGeneric):
 
     def write_version(self, directory):
         """Write files for a newly created DB."""
-        versionpath = os.path.join(directory, str(DBBACKEND))
-        LOG.debug("Write database backend file to 'dbapi'")
-        with open(versionpath, "w") as version_file:
-            version_file.write("dbapi")
         versionpath = os.path.join(directory, "bdbversion.txt")
+        _LOG.debug("Write bsddb version %s" % str(self.VERSION))
         with open(versionpath, "w") as version_file:
             version_file.write(str(self.VERSION))
-        versionpath = os.path.join(directory, "pickleupgrade.txt")
+
-        with open(versionpath, "w") as version_file:
-            version_file.write("YES")
         versionpath = os.path.join(directory, "pythonversion.txt")
+        _LOG.debug("Write python version file to %s" % str(sys.version_info[0]))
         with open(versionpath, "w") as version_file:
             version_file.write(str(sys.version_info[0]))
+
+        versionpath = os.path.join(directory, "pickleupgrade.txt")
+        _LOG.debug("Write pickle version file to %s" % "Yes")
+        with open(versionpath, "w") as version_file:
+            version_file.write("YES")
+
+        _LOG.debug("Write schema version file to %s" % str(self.VERSION[0]))
         versionpath = os.path.join(directory, "schemaversion.txt")
         with open(versionpath, "w") as version_file:
             version_file.write(str(self.VERSION[0]))
+
+        versionpath = os.path.join(directory, str(DBBACKEND))
+        _LOG.debug("Write database backend file to 'dbapi'")
+        with open(versionpath, "w") as version_file:
+            version_file.write("dbapi")
         # Write default_settings, sqlite.db
         defaults = os.path.join(os.path.dirname(os.path.abspath(__file__)),
                                 "dbapi_support", "defaults")
@@ -334,6 +348,7 @@ class DBAPI(DbGeneric):
         Lowlevel interface to the backend transaction.
         Executes a db BEGIN;
         """
+        _LOG.debug("    DBAPI %s transaction begin" % hex(id(self)))
         self.dbapi.begin()
 
     def transaction_backend_commit(self):
@@ -341,6 +356,8 @@ class DBAPI(DbGeneric):
         Lowlevel interface to the backend transaction.
         Executes a db END;
         """
+        _LOG.debug("    DBAPI %s transaction commit"
+                   % hex(id(self)))
         self.dbapi.commit()
 
     def transaction_backend_abort(self):
@@ -354,6 +371,9 @@ class DBAPI(DbGeneric):
         """
         Transactions are handled automatically by the db layer.
         """
+        _LOG.debug("    %sDBAPI %s transaction begin for '%s'"
+                   % ("Batch " if transaction.batch else "",
+                      hex(id(self)), transaction.get_description()))
         self.transaction = transaction
         self.dbapi.begin()
         return transaction
@@ -362,6 +382,10 @@ class DBAPI(DbGeneric):
         """
         Executed at the end of a transaction.
         """
+        _LOG.debug("    %sDBAPI %s transaction commit for '%s'"
+                   % ("Batch " if txn.batch else "", hex(id(self)),
+                      txn.get_description()))
+
         action = {TXNADD: "-add",
                   TXNUPD: "-update",
                   TXNDEL: "-delete",