Tracing for tdb operations.

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);
 }
 

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;
@@ -330,6 +342,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)
 			SAFE_FREE(tdb->map_ptr);
@@ -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);
 

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

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;
 };
 

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;

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;
 }