From 5af65e317c70de721b27bb0eb2c199b950fb9aa0 Mon Sep 17 00:00:00 2001 From: kulath Date: Tue, 7 Jun 2016 18:41:40 +0100 Subject: [PATCH] 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 | 40 +++++++++++++- gramps/gen/dbstate.py | 3 ++ .../database/bsddb_support/bsddbtxn.py | 37 ++++++++++++- .../plugins/database/bsddb_support/write.py | 12 +++++ gramps/plugins/database/dbapi.py | 54 +++++++++++++------ 5 files changed, 129 insertions(+), 17 deletions(-) diff --git a/gramps/gen/db/txn.py b/gramps/gen/db/txn.py index 4508aaae8..9162397c4 100644 --- a/gramps/gen/db/txn.py +++ b/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 diff --git a/gramps/gen/dbstate.py b/gramps/gen/dbstate.py index c2c192bea..124b00097 100644 --- a/gramps/gen/dbstate.py +++ b/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): diff --git a/gramps/plugins/database/bsddb_support/bsddbtxn.py b/gramps/plugins/database/bsddb_support/bsddbtxn.py index 6902c48fb..400baffb8 100644 --- a/gramps/plugins/database/bsddb_support/bsddbtxn.py +++ b/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 diff --git a/gramps/plugins/database/bsddb_support/write.py b/gramps/plugins/database/bsddb_support/write.py index 90375984a..0e2fbcfb6 100644 --- a/gramps/plugins/database/bsddb_support/write.py +++ b/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): """ diff --git a/gramps/plugins/database/dbapi.py b/gramps/plugins/database/dbapi.py index 58c90784e..bb6a98634 100644 --- a/gramps/plugins/database/dbapi.py +++ b/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",