Tracing for tdb operations.

diff --git a/ccan/tdb/lock.c b/ccan/tdb/lock.c
index f156c0fa7b2e548640d47db23df71c9427ec73ce..2bb6ddb88385a56de4ca48d57ea4c5f07eb6317f 100644 (file)
--- a/ccan/tdb/lock.c
+++ b/ccan/tdb/lock.c
@@ -413,48 +413,58 @@ static int _tdb_unlockall(struct tdb_context *tdb, int ltype)
 /* lock entire database with write lock */
 int tdb_lockall(struct tdb_context *tdb)
 {
+       tdb_trace(tdb, "tdb_lockall\n");
        return _tdb_lockall(tdb, F_WRLCK, F_SETLKW);
 }
 
 /* lock entire database with write lock - mark only */
 int tdb_lockall_mark(struct tdb_context *tdb)
 {
+       tdb_trace(tdb, "tdb_lockall_mark\n");
        return _tdb_lockall(tdb, F_WRLCK | TDB_MARK_LOCK, F_SETLKW);
 }
 
 /* unlock entire database with write lock - unmark only */
 int tdb_lockall_unmark(struct tdb_context *tdb)
 {
+       tdb_trace(tdb, "tdb_lockall_unmark\n");
        return _tdb_unlockall(tdb, F_WRLCK | TDB_MARK_LOCK);
 }
 
 /* lock entire database with write lock - nonblocking varient */
 int tdb_lockall_nonblock(struct tdb_context *tdb)
 {
-       return _tdb_lockall(tdb, F_WRLCK, F_SETLK);
+       int ret = _tdb_lockall(tdb, F_WRLCK, F_SETLK);
+       tdb_trace(tdb, "tdb_lockall_nonblock = %i\n", ret);
+       return ret;
 }
 
 /* unlock entire database with write lock */
 int tdb_unlockall(struct tdb_context *tdb)
 {
+       tdb_trace(tdb, "tdb_unlockall\n");
        return _tdb_unlockall(tdb, F_WRLCK);
 }
 
 /* lock entire database with read lock */
 int tdb_lockall_read(struct tdb_context *tdb)
 {
+       tdb_trace(tdb, "tdb_lockall_read\n");
        return _tdb_lockall(tdb, F_RDLCK, F_SETLKW);
 }
 
 /* lock entire database with read lock - nonblock varient */
 int tdb_lockall_read_nonblock(struct tdb_context *tdb)
 {
-       return _tdb_lockall(tdb, F_RDLCK, F_SETLK);
+       int ret = _tdb_lockall(tdb, F_RDLCK, F_SETLK);
+       tdb_trace(tdb, "tdb_lockall_read_nonblock = %i\n", ret);
+       return ret;
 }
 
 /* unlock entire database with read lock */
 int tdb_unlockall_read(struct tdb_context *tdb)
 {
+       tdb_trace(tdb, "tdb_unlockall_read\n");
        return _tdb_unlockall(tdb, F_RDLCK);
 }
 
@@ -462,6 +472,9 @@ int tdb_unlockall_read(struct tdb_context *tdb)
    contention - it cannot guarantee how many records will be locked */
 int tdb_chainlock(struct tdb_context *tdb, TDB_DATA key)
 {
+       tdb_trace(tdb, "tdb_chainlock ");
+       tdb_trace_record(tdb, key);
+       tdb_trace(tdb, "\n");
        return tdb_lock(tdb, BUCKET(tdb->hash_fn(&key)), F_WRLCK);
 }
 
@@ -470,33 +483,52 @@ int tdb_chainlock(struct tdb_context *tdb, TDB_DATA key)
    locked */
 int tdb_chainlock_nonblock(struct tdb_context *tdb, TDB_DATA key)
 {
-       return tdb_lock_nonblock(tdb, BUCKET(tdb->hash_fn(&key)), F_WRLCK);
+       int ret = tdb_lock_nonblock(tdb, BUCKET(tdb->hash_fn(&key)), F_WRLCK);
+       tdb_trace(tdb, "tdb_chainlock_nonblock ");
+       tdb_trace_record(tdb, key);
+       tdb_trace(tdb, "= %i\n", ret);
+       return ret;
 }
 
 /* mark a chain as locked without actually locking it. Warning! use with great caution! */
 int tdb_chainlock_mark(struct tdb_context *tdb, TDB_DATA key)
 {
+       tdb_trace(tdb, "tdb_chainlock_mark ");
+       tdb_trace_record(tdb, key);
+       tdb_trace(tdb, "\n");
        return tdb_lock(tdb, BUCKET(tdb->hash_fn(&key)), F_WRLCK | TDB_MARK_LOCK);
 }
 
 /* unmark a chain as locked without actually locking it. Warning! use with great caution! */
 int tdb_chainlock_unmark(struct tdb_context *tdb, TDB_DATA key)
 {
+       tdb_trace(tdb, "tdb_chainlock_unmark ");
+       tdb_trace_record(tdb, key);
+       tdb_trace(tdb, "\n");
        return tdb_unlock(tdb, BUCKET(tdb->hash_fn(&key)), F_WRLCK | TDB_MARK_LOCK);
 }
 
 int tdb_chainunlock(struct tdb_context *tdb, TDB_DATA key)
 {
+       tdb_trace(tdb, "tdb_chainunlock ");
+       tdb_trace_record(tdb, key);
+       tdb_trace(tdb, "\n");
        return tdb_unlock(tdb, BUCKET(tdb->hash_fn(&key)), F_WRLCK);
 }
 
 int tdb_chainlock_read(struct tdb_context *tdb, TDB_DATA key)
 {
+       tdb_trace(tdb, "tdb_chainlock_read ");
+       tdb_trace_record(tdb, key);
+       tdb_trace(tdb, "\n");
        return tdb_lock(tdb, BUCKET(tdb->hash_fn(&key)), F_RDLCK);
 }
 
 int tdb_chainunlock_read(struct tdb_context *tdb, TDB_DATA key)
 {
+       tdb_trace(tdb, "tdb_chainunlock_read ");
+       tdb_trace_record(tdb, key);
+       tdb_trace(tdb, "\n");
        return tdb_unlock(tdb, BUCKET(tdb->hash_fn(&key)), F_RDLCK);
 }
 

diff --git a/ccan/tdb/open.c b/ccan/tdb/open.c
index 8cd25cc5b5bc7802a9ebc3e7ad2ce0b7df4c9c28..a5cf47e7249606ec72093f13f148adcbeb393566 100644 (file)
--- a/ccan/tdb/open.c
+++ b/ccan/tdb/open.c
@@ -153,6 +153,9 @@ struct tdb_context *tdb_open_ex(const char *name, int hash_size, int tdb_flags,
        unsigned char *vp;
        uint32_t vertest;
        unsigned v;
+#ifdef TDB_TRACE
+       char tracefile[strlen(name) + 32];
+#endif
 
        if (!(tdb = (struct tdb_context *)calloc(1, sizeof *tdb))) {
                /* Can't log this */
@@ -160,6 +163,15 @@ struct tdb_context *tdb_open_ex(const char *name, int hash_size, int tdb_flags,
                goto fail;
        }
 
+#ifdef TDB_TRACE
+       sprintf(tracefile, "%s.trace.%u", name, getpid());
+       tdb->tracefd = open(tracefile, O_WRONLY|O_CREAT|O_EXCL, 0600);
+       if (tdb->tracefd < 0)
+               goto fail;
+       tdb_trace(tdb, "tdb_open %s %u %#x %#x %p\n",
+                 name, hash_size, tdb_flags, open_flags, hash_fn);
+#endif
+
        tdb_io_init(tdb);
        tdb->fd = -1;
        tdb->name = NULL;
@@ -329,6 +341,8 @@ struct tdb_context *tdb_open_ex(const char *name, int hash_size, int tdb_flags,
 
        if (!tdb)
                return NULL;
+
+       close(tdb->tracefd);
        
        if (tdb->map_ptr) {
                if (tdb->flags & TDB_INTERNAL)
@@ -365,6 +379,7 @@ int tdb_close(struct tdb_context *tdb)
        struct tdb_context **i;
        int ret = 0;
 
+       tdb_trace(tdb, "tdb_close");
        if (tdb->transaction) {
                tdb_transaction_cancel(tdb);
        }
@@ -388,6 +403,7 @@ int tdb_close(struct tdb_context *tdb)
                }
        }
 
+       close(tdb->tracefd);
        memset(tdb, 0, sizeof(*tdb));
        SAFE_FREE(tdb);
 

diff --git a/ccan/tdb/tdb.c b/ccan/tdb/tdb.c
index 767452c9b34b520a51bed6aace888b3f5b2dcd4f..9cc51eaacfbca2858b10c0b940817abfd4deda00 100644 (file)
--- a/ccan/tdb/tdb.c
+++ b/ccan/tdb/tdb.c
@@ -41,6 +41,8 @@ void tdb_increment_seqnum_nonblock(struct tdb_context *tdb)
                return;
        }
 
+       tdb_trace(tdb, "tdb_increment_seqnum_nonblock");
+
        /* we ignore errors from this, as we have no sane way of
           dealing with them.
        */
@@ -63,6 +65,8 @@ static void tdb_increment_seqnum(struct tdb_context *tdb)
                return;
        }
 
+       tdb_trace(tdb, "tdb_increment_seqnum");
+
        tdb_increment_seqnum_nonblock(tdb);
 
        tdb_brlock(tdb, TDB_SEQNUM_OFS, F_UNLCK, F_SETLKW, 1, 1);
@@ -162,13 +166,21 @@ TDB_DATA tdb_fetch(struct tdb_context *tdb, TDB_DATA key)
 
        /* find which hash bucket it is in */
        hash = tdb->hash_fn(&key);
-       if (!(rec_ptr = tdb_find_lock_hash(tdb,key,hash,F_RDLCK,&rec)))
+       if (!(rec_ptr = tdb_find_lock_hash(tdb,key,hash,F_RDLCK,&rec))) {
+               tdb_trace(tdb, "tdb_fetch ");
+               tdb_trace_record(tdb, key);
+               tdb_trace(tdb, "= ENOENT\n");
                return tdb_null;
-
+       }
        ret.dptr = tdb_alloc_read(tdb, rec_ptr + sizeof(rec) + rec.key_len,
                                  rec.data_len);
        ret.dsize = rec.data_len;
        tdb_unlock(tdb, BUCKET(rec.full_hash), F_RDLCK);
+       tdb_trace(tdb, "tdb_fetch ");
+       tdb_trace_record(tdb, key);
+       tdb_trace(tdb, "= ");
+       tdb_trace_record(tdb, ret);
+       tdb_trace(tdb, "\n"); 
        return ret;
 }
 
@@ -202,9 +214,16 @@ int tdb_parse_record(struct tdb_context *tdb, TDB_DATA key,
        hash = tdb->hash_fn(&key);
 
        if (!(rec_ptr = tdb_find_lock_hash(tdb,key,hash,F_RDLCK,&rec))) {
+               tdb_trace(tdb, "tdb_parse_record ");
+               tdb_trace_record(tdb, key);
+               tdb_trace(tdb, "= ENOENT\n"); 
                return TDB_ERRCODE(TDB_ERR_NOEXIST, 0);
        }
 
+       tdb_trace(tdb, "tdb_parse_record ");
+       tdb_trace_record(tdb, key);
+       tdb_trace(tdb, "= %u\n", rec.data_len); 
+
        ret = tdb_parse_data(tdb, key, rec_ptr + sizeof(rec) + rec.key_len,
                             rec.data_len, parser, private_data);
 
@@ -232,7 +251,13 @@ static int tdb_exists_hash(struct tdb_context *tdb, TDB_DATA key, uint32_t hash)
 int tdb_exists(struct tdb_context *tdb, TDB_DATA key)
 {
        uint32_t hash = tdb->hash_fn(&key);
-       return tdb_exists_hash(tdb, key, hash);
+       int ret;
+
+       ret = tdb_exists_hash(tdb, key, hash);
+       tdb_trace(tdb, "tdb_exists ");
+       tdb_trace_record(tdb, key);
+       tdb_trace(tdb, "= %i\n", ret); 
+       return ret;
 }
 
 /* actually delete an entry in the database given the offset */
@@ -387,7 +412,13 @@ static int tdb_delete_hash(struct tdb_context *tdb, TDB_DATA key, uint32_t hash)
 int tdb_delete(struct tdb_context *tdb, TDB_DATA key)
 {
        uint32_t hash = tdb->hash_fn(&key);
-       return tdb_delete_hash(tdb, key, hash);
+       int ret;
+
+       ret = tdb_delete_hash(tdb, key, hash);
+       tdb_trace(tdb, "tdb_delete ");
+       tdb_trace_record(tdb, key);
+       tdb_trace(tdb, "= %i\n", ret); 
+       return ret;
 }
 
 /*
@@ -442,21 +473,29 @@ int tdb_store(struct tdb_context *tdb, TDB_DATA key, TDB_DATA dbuf, int flag)
        if (tdb_lock(tdb, BUCKET(hash), F_WRLCK) == -1)
                return -1;
 
+       tdb_trace(tdb, "tdb_store %s ", flag == TDB_INSERT ? "insert" :
+                 flag == TDB_MODIFY ? "modify" : "normal");
+       tdb_trace_record(tdb, key);
+       tdb_trace_record(tdb, dbuf);
+
        /* check for it existing, on insert. */
        if (flag == TDB_INSERT) {
                if (tdb_exists_hash(tdb, key, hash)) {
                        tdb->ecode = TDB_ERR_EXISTS;
+                       tdb_trace(tdb, "= EEXIST\n"); 
                        goto fail;
                }
        } else {
                /* first try in-place update, on modify or replace. */
                if (tdb_update_hash(tdb, key, hash, dbuf) == 0) {
+                       tdb_trace(tdb, "= inplace\n"); 
                        goto done;
                }
                if (tdb->ecode == TDB_ERR_NOEXIST &&
                    flag == TDB_MODIFY) {
                        /* if the record doesn't exist and we are in TDB_MODIFY mode then
                         we should fail the store */
+                       tdb_trace(tdb, "= ENOENT\n"); 
                        goto fail;
                }
        }
@@ -504,6 +543,7 @@ int tdb_store(struct tdb_context *tdb, TDB_DATA key, TDB_DATA dbuf, int flag)
                                goto fail;
                        }
                        goto done;
+                       tdb_trace(tdb, "= fromdead\n"); 
                }
        }
 
@@ -541,6 +581,8 @@ int tdb_store(struct tdb_context *tdb, TDB_DATA key, TDB_DATA dbuf, int flag)
        rec.full_hash = hash;
        rec.magic = TDB_MAGIC;
 
+       tdb_trace(tdb, "= allocate\n"); 
+
        /* write out and point the top of the hash chain at it */
        if (tdb_rec_write(tdb, rec_ptr, &rec) == -1
            || tdb->methods->tdb_write(tdb, rec_ptr+sizeof(rec), p, key.dsize+dbuf.dsize)==-1
@@ -575,6 +617,10 @@ int tdb_append(struct tdb_context *tdb, TDB_DATA key, TDB_DATA new_dbuf)
                return -1;
 
        dbuf = tdb_fetch(tdb, key);
+       tdb_trace(tdb, "tdb_append ");
+       tdb_trace_record(tdb, key);
+       tdb_trace_record(tdb, dbuf);
+       tdb_trace(tdb, "= %s\n", dbuf.dptr ? "insert" : "append");
 
        if (dbuf.dptr == NULL) {
                dbuf.dptr = (unsigned char *)malloc(new_dbuf.dsize);
@@ -647,6 +693,7 @@ int tdb_get_seqnum(struct tdb_context *tdb)
 {
        tdb_off_t seqnum=0;
 
+       tdb_trace(tdb, "tdb_get_seqnum\n");
        tdb_ofs_read(tdb, TDB_SEQNUM_OFS, &seqnum);
        return seqnum;
 }
@@ -729,6 +776,8 @@ int tdb_wipe_all(struct tdb_context *tdb)
                return -1;
        }
 
+       tdb_trace(tdb, "tdb_wipe_all\n");
+
        /* see if the tdb has a recovery area, and remember its size
           if so. We don't want to lose this as otherwise each
           tdb_wipe_all() in a transaction will increase the size of
@@ -800,3 +849,31 @@ failed:
        tdb_unlockall(tdb);
        return -1;
 }
+
+#ifdef TDB_TRACE
+#include <stdarg.h>
+
+void tdb_trace(const struct tdb_context *tdb, const char *fmt, ...)
+{
+       char msg[256];
+       va_list args;
+       int len;
+
+       va_start(args, fmt);
+       len = vsprintf(msg, fmt, args);
+       va_end(args);
+
+       write(tdb->tracefd, msg, len);
+}
+
+void tdb_trace_record(const struct tdb_context *tdb, TDB_DATA rec)
+{
+       char msg[20];
+       unsigned int i;
+
+       write(tdb->tracefd, msg, sprintf(msg, "%zu:", rec.dsize));
+       for (i = 0; i < rec.dsize; i++)
+               write(tdb->tracefd, msg, sprintf(msg, "%02x", rec.dptr[i]));
+       write(tdb->tracefd, " ", 1);
+}
+#endif

diff --git a/ccan/tdb/tdb_private.h b/ccan/tdb/tdb_private.h
index c460af4e8dd87d0219dab7e5c1a88089488846fd..e3ec695642d06263e79c62e8ed7ce98a5505ebb8 100644 (file)
--- a/ccan/tdb/tdb_private.h
+++ b/ccan/tdb/tdb_private.h
@@ -86,6 +86,18 @@ typedef uint32_t tdb_off_t;
  * argument. */
 #define TDB_LOG(x) tdb->log.log_fn x
 
+#ifdef TDB_TRACE
+void tdb_trace(const struct tdb_context *tdb, const char *fmt, ...);
+void tdb_trace_record(const struct tdb_context *tdb, TDB_DATA rec);
+#else
+static inline void tdb_trace(const struct tdb_context *tdb, const char *fmt, ...)
+{
+}
+static inline void tdb_trace_record(const struct tdb_context *tdb, TDB_DATA rec)
+{
+}
+#endif /* !TDB_TRACE */
+
 /* lock offsets */
 #define GLOBAL_LOCK      0
 #define ACTIVE_LOCK      4
@@ -185,6 +197,7 @@ struct tdb_context {
        int page_size;
        int max_dead_records;
        bool have_transaction_lock;
+       int tracefd;
        volatile sig_atomic_t *interrupt_sig_ptr;
 };
 

diff --git a/ccan/tdb/transaction.c b/ccan/tdb/transaction.c
index d6db8b01329913e09dbd55e6cec82aa61b0d4f9f..a11224757b30735088aaed32a4a67fa192695469 100644 (file)
--- a/ccan/tdb/transaction.c
+++ b/ccan/tdb/transaction.c
@@ -405,6 +405,8 @@ static const struct tdb_methods transaction_methods = {
 */
 int tdb_transaction_start(struct tdb_context *tdb)
 {
+       tdb_trace(tdb, "tdb_transaction_start\n");
+
        /* some sanity checks */
        if (tdb->read_only || (tdb->flags & TDB_INTERNAL) || tdb->traverse_read) {
                TDB_LOG((tdb, TDB_DEBUG_ERROR, "tdb_transaction_start: cannot start a transaction on a read-only or internal db\n"));
@@ -514,6 +516,7 @@ int tdb_transaction_cancel(struct tdb_context *tdb)
 {      
        int i;
 
+       tdb_trace(tdb, "tdb_transaction_cancel\n");
        if (tdb->transaction == NULL) {
                TDB_LOG((tdb, TDB_DEBUG_ERROR, "tdb_transaction_cancel: no transaction\n"));
                return -1;
@@ -845,6 +848,7 @@ int tdb_transaction_commit(struct tdb_context *tdb)
        uint32_t zero = 0;
        int i;
 
+       tdb_trace(tdb, "tdb_transaction_commit\n");
        if (tdb->transaction == NULL) {
                TDB_LOG((tdb, TDB_DEBUG_ERROR, "tdb_transaction_commit: no transaction\n"));
                return -1;

diff --git a/ccan/tdb/traverse.c b/ccan/tdb/traverse.c
index 07b0c238587eb85fe3945b61b71dbd9dd0729d58..7164ac24fd4a8e25b0b8b10dd2d7d764b9814f97 100644 (file)
--- a/ccan/tdb/traverse.c
+++ b/ccan/tdb/traverse.c
@@ -214,6 +214,7 @@ int tdb_traverse_read(struct tdb_context *tdb,
        tdb->traverse_read++;
        ret = tdb_traverse_internal(tdb, fn, private_data, &tl);
        tdb->traverse_read--;
+       tdb_trace(tdb, "tdb_traverse_read = %i\n", ret);
 
        tdb_transaction_unlock(tdb);
 
@@ -244,6 +245,7 @@ int tdb_traverse(struct tdb_context *tdb,
        tdb->traverse_write++;
        ret = tdb_traverse_internal(tdb, fn, private_data, &tl);
        tdb->traverse_write--;
+       tdb_trace(tdb, "tdb_traverse = %i\n", ret);
 
        tdb_transaction_unlock(tdb);
 
@@ -264,12 +266,18 @@ TDB_DATA tdb_firstkey(struct tdb_context *tdb)
        tdb->travlocks.lock_rw = F_RDLCK;
 
        /* Grab first record: locks chain and returned record. */
-       if (tdb_next_lock(tdb, &tdb->travlocks, &rec) <= 0)
+       if (tdb_next_lock(tdb, &tdb->travlocks, &rec) <= 0) {
+               tdb_trace(tdb, "tdb_firstkey = ENOENT\n");
                return tdb_null;
+       }
        /* now read the key */
        key.dsize = rec.key_len;
        key.dptr =tdb_alloc_read(tdb,tdb->travlocks.off+sizeof(rec),key.dsize);
 
+       tdb_trace(tdb, "tdb_firstkey = ");
+       tdb_trace_record(tdb, key);
+       tdb_trace(tdb, "\n");
+
        /* Unlock the hash chain of the record we just read. */
        if (tdb_unlock(tdb, tdb->travlocks.hash, tdb->travlocks.lock_rw) != 0)
                TDB_LOG((tdb, TDB_DEBUG_FATAL, "tdb_firstkey: error occurred while tdb_unlocking!\n"));
@@ -294,6 +302,9 @@ TDB_DATA tdb_nextkey(struct tdb_context *tdb, TDB_DATA oldkey)
                    || memcmp(k, oldkey.dptr, oldkey.dsize) != 0) {
                        /* No, it wasn't: unlock it and start from scratch */
                        if (tdb_unlock_record(tdb, tdb->travlocks.off) != 0) {
+                               tdb_trace(tdb, "tdb_nextkey ");
+                               tdb_trace_record(tdb, oldkey);
+                               tdb_trace(tdb, "= ENOENT\n");
                                SAFE_FREE(k);
                                return tdb_null;
                        }
@@ -310,8 +321,12 @@ TDB_DATA tdb_nextkey(struct tdb_context *tdb, TDB_DATA oldkey)
        if (!tdb->travlocks.off) {
                /* No previous element: do normal find, and lock record */
                tdb->travlocks.off = tdb_find_lock_hash(tdb, oldkey, tdb->hash_fn(&oldkey), tdb->travlocks.lock_rw, &rec);
-               if (!tdb->travlocks.off)
+               if (!tdb->travlocks.off) {
+                       tdb_trace(tdb, "tdb_nextkey ");
+                       tdb_trace_record(tdb, oldkey);
+                       tdb_trace(tdb, "= ENOENT\n");
                        return tdb_null;
+               }
                tdb->travlocks.hash = BUCKET(rec.full_hash);
                if (tdb_lock_record(tdb, tdb->travlocks.off) != 0) {
                        TDB_LOG((tdb, TDB_DEBUG_FATAL, "tdb_nextkey: lock_record failed (%s)!\n", strerror(errno)));
@@ -333,6 +348,11 @@ TDB_DATA tdb_nextkey(struct tdb_context *tdb, TDB_DATA oldkey)
        /* Unlock the chain of old record */
        if (tdb_unlock(tdb, BUCKET(oldhash), tdb->travlocks.lock_rw) != 0)
                TDB_LOG((tdb, TDB_DEBUG_FATAL, "tdb_nextkey: WARNING tdb_unlock failed!\n"));
+       tdb_trace(tdb, "tdb_nextkey ");
+       tdb_trace_record(tdb, oldkey);
+       tdb_trace(tdb, "= ");
+       tdb_trace_record(tdb, key);
+       tdb_trace(tdb, "\n");
        return key;
 }