From: Rusty Russell Date: Tue, 23 Jun 2009 13:21:49 +0000 (+0930) Subject: Tracing for tdb operations. X-Git-Url: https://git.ozlabs.org/?p=ccan;a=commitdiff_plain;h=e1f11b7b1e39ceb092155ba742b34f0785d88d06 Tracing for tdb operations. --- diff --git a/ccan/tdb/lock.c b/ccan/tdb/lock.c index f156c0fa..2bb6ddb8 100644 --- 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 8cd25cc5..a5cf47e7 100644 --- 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 767452c9..9cc51eaa 100644 --- 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 + +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 c460af4e..e3ec6956 100644 --- 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 d6db8b01..a1122475 100644 --- 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 07b0c238..7164ac24 100644 --- 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; }