refs: add GIT_TRACE_REFS debugging mechanism

When set in the environment, GIT_TRACE_REFS makes git print operations and
results as they flow through the ref storage backend. This helps debug
discrepancies between different ref backends.

Example:

    $ GIT_TRACE_REFS="1" ./git branch
    15:42:09.769631 refs/debug.c:26         ref_store for .git
    15:42:09.769681 refs/debug.c:249        read_raw_ref: HEAD: 0000000000000000000000000000000000000000 (=> refs/heads/ref-debug) type 1: 0
    15:42:09.769695 refs/debug.c:249        read_raw_ref: refs/heads/ref-debug: 3a238e539b (=> refs/heads/ref-debug) type 0: 0
    15:42:09.770282 refs/debug.c:233        ref_iterator_begin: refs/heads/ (0x1)
    15:42:09.770290 refs/debug.c:189        iterator_advance: refs/heads/b4 (0)
    15:42:09.770295 refs/debug.c:189        iterator_advance: refs/heads/branch3 (0)

Signed-off-by: Han-Wen Nienhuys <hanwen@google.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
This commit is contained in:
Han-Wen Nienhuys 2020-09-09 10:15:08 +00:00 committed by Junio C Hamano
parent 3a238e539b
commit 4441f42707
5 changed files with 409 additions and 0 deletions

View File

@ -722,6 +722,10 @@ of clones and fetches.
time of each Git command.
See `GIT_TRACE` for available trace output options.
`GIT_TRACE_REFS`::
Enables trace messages for operations on the ref database.
See `GIT_TRACE` for available trace output options.
`GIT_TRACE_SETUP`::
Enables trace messages printing the .git, working tree and current
working directory after Git has completed its setup phase.

View File

@ -950,6 +950,7 @@ LIB_OBJS += rebase.o
LIB_OBJS += ref-filter.o
LIB_OBJS += reflog-walk.o
LIB_OBJS += refs.o
LIB_OBJS += refs/debug.o
LIB_OBJS += refs/files-backend.o
LIB_OBJS += refs/iterator.o
LIB_OBJS += refs/packed-backend.o

1
refs.c
View File

@ -1774,6 +1774,7 @@ struct ref_store *get_main_ref_store(struct repository *r)
BUG("attempting to get main_ref_store outside of repository");
r->refs_private = ref_store_init(r->gitdir, REF_STORE_ALL_CAPS);
r->refs_private = maybe_debug_wrap_ref_store(r->gitdir, r->refs_private);
return r->refs_private;
}

398
refs/debug.c Normal file
View File

@ -0,0 +1,398 @@
#include "refs-internal.h"
#include "trace.h"
static struct trace_key trace_refs = TRACE_KEY_INIT(REFS);
struct debug_ref_store {
struct ref_store base;
struct ref_store *refs;
};
extern struct ref_storage_be refs_be_debug;
struct ref_store *maybe_debug_wrap_ref_store(const char *gitdir, struct ref_store *store)
{
struct debug_ref_store *res;
struct ref_storage_be *be_copy;
if (!trace_want(&trace_refs)) {
return store;
}
res = xmalloc(sizeof(struct debug_ref_store));
be_copy = xmalloc(sizeof(*be_copy));
*be_copy = refs_be_debug;
/* we never deallocate backends, so safe to copy the pointer. */
be_copy->name = store->be->name;
trace_printf_key(&trace_refs, "ref_store for %s\n", gitdir);
res->refs = store;
base_ref_store_init((struct ref_store *)res, be_copy);
return (struct ref_store *)res;
}
static int debug_init_db(struct ref_store *refs, struct strbuf *err)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)refs;
int res = drefs->refs->be->init_db(drefs->refs, err);
trace_printf_key(&trace_refs, "init_db: %d\n", res);
return res;
}
static int debug_transaction_prepare(struct ref_store *refs,
struct ref_transaction *transaction,
struct strbuf *err)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)refs;
int res;
transaction->ref_store = drefs->refs;
res = drefs->refs->be->transaction_prepare(drefs->refs, transaction,
err);
trace_printf_key(&trace_refs, "transaction_prepare: %d\n", res);
return res;
}
static void print_update(int i, const char *refname,
const struct object_id *old_oid,
const struct object_id *new_oid, unsigned int flags,
unsigned int type, const char *msg)
{
char o[GIT_MAX_HEXSZ + 1] = "null";
char n[GIT_MAX_HEXSZ + 1] = "null";
if (old_oid)
oid_to_hex_r(o, old_oid);
if (new_oid)
oid_to_hex_r(n, new_oid);
type &= 0xf; /* see refs.h REF_* */
flags &= REF_HAVE_NEW | REF_HAVE_OLD | REF_NO_DEREF |
REF_FORCE_CREATE_REFLOG;
trace_printf_key(&trace_refs, "%d: %s %s -> %s (F=0x%x, T=0x%x) \"%s\"\n", i, refname,
o, n, flags, type, msg);
}
static void print_transaction(struct ref_transaction *transaction)
{
int i;
trace_printf_key(&trace_refs, "transaction {\n");
for (i = 0; i < transaction->nr; i++) {
struct ref_update *u = transaction->updates[i];
print_update(i, u->refname, &u->old_oid, &u->new_oid, u->flags,
u->type, u->msg);
}
trace_printf_key(&trace_refs, "}\n");
}
static int debug_transaction_finish(struct ref_store *refs,
struct ref_transaction *transaction,
struct strbuf *err)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)refs;
int res;
transaction->ref_store = drefs->refs;
res = drefs->refs->be->transaction_finish(drefs->refs, transaction,
err);
print_transaction(transaction);
trace_printf_key(&trace_refs, "finish: %d\n", res);
return res;
}
static int debug_transaction_abort(struct ref_store *refs,
struct ref_transaction *transaction,
struct strbuf *err)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)refs;
int res;
transaction->ref_store = drefs->refs;
res = drefs->refs->be->transaction_abort(drefs->refs, transaction, err);
return res;
}
static int debug_initial_transaction_commit(struct ref_store *refs,
struct ref_transaction *transaction,
struct strbuf *err)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)refs;
int res;
transaction->ref_store = drefs->refs;
res = drefs->refs->be->initial_transaction_commit(drefs->refs,
transaction, err);
return res;
}
static int debug_pack_refs(struct ref_store *ref_store, unsigned int flags)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
int res = drefs->refs->be->pack_refs(drefs->refs, flags);
trace_printf_key(&trace_refs, "pack_refs: %d\n", res);
return res;
}
static int debug_create_symref(struct ref_store *ref_store,
const char *ref_name, const char *target,
const char *logmsg)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
int res = drefs->refs->be->create_symref(drefs->refs, ref_name, target,
logmsg);
trace_printf_key(&trace_refs, "create_symref: %s -> %s \"%s\": %d\n", ref_name,
target, logmsg, res);
return res;
}
static int debug_delete_refs(struct ref_store *ref_store, const char *msg,
struct string_list *refnames, unsigned int flags)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
int res =
drefs->refs->be->delete_refs(drefs->refs, msg, refnames, flags);
int i;
trace_printf_key(&trace_refs, "delete_refs {\n");
for (i = 0; i < refnames->nr; i++)
trace_printf_key(&trace_refs, "%s\n", refnames->items[i].string);
trace_printf_key(&trace_refs, "}: %d\n", res);
return res;
}
static int debug_rename_ref(struct ref_store *ref_store, const char *oldref,
const char *newref, const char *logmsg)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
int res = drefs->refs->be->rename_ref(drefs->refs, oldref, newref,
logmsg);
trace_printf_key(&trace_refs, "rename_ref: %s -> %s \"%s\": %d\n", oldref, newref,
logmsg, res);
return res;
}
static int debug_copy_ref(struct ref_store *ref_store, const char *oldref,
const char *newref, const char *logmsg)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
int res =
drefs->refs->be->copy_ref(drefs->refs, oldref, newref, logmsg);
trace_printf_key(&trace_refs, "copy_ref: %s -> %s \"%s\": %d\n", oldref, newref,
logmsg, res);
return res;
}
struct debug_ref_iterator {
struct ref_iterator base;
struct ref_iterator *iter;
};
static int debug_ref_iterator_advance(struct ref_iterator *ref_iterator)
{
struct debug_ref_iterator *diter =
(struct debug_ref_iterator *)ref_iterator;
int res = diter->iter->vtable->advance(diter->iter);
if (res)
trace_printf_key(&trace_refs, "iterator_advance: (%d)\n", res);
else
trace_printf_key(&trace_refs, "iterator_advance: %s (0)\n",
diter->iter->refname);
diter->base.ordered = diter->iter->ordered;
diter->base.refname = diter->iter->refname;
diter->base.oid = diter->iter->oid;
diter->base.flags = diter->iter->flags;
return res;
}
static int debug_ref_iterator_peel(struct ref_iterator *ref_iterator,
struct object_id *peeled)
{
struct debug_ref_iterator *diter =
(struct debug_ref_iterator *)ref_iterator;
int res = diter->iter->vtable->peel(diter->iter, peeled);
trace_printf_key(&trace_refs, "iterator_peel: %s: %d\n", diter->iter->refname, res);
return res;
}
static int debug_ref_iterator_abort(struct ref_iterator *ref_iterator)
{
struct debug_ref_iterator *diter =
(struct debug_ref_iterator *)ref_iterator;
int res = diter->iter->vtable->abort(diter->iter);
trace_printf_key(&trace_refs, "iterator_abort: %d\n", res);
return res;
}
static struct ref_iterator_vtable debug_ref_iterator_vtable = {
debug_ref_iterator_advance, debug_ref_iterator_peel,
debug_ref_iterator_abort
};
static struct ref_iterator *
debug_ref_iterator_begin(struct ref_store *ref_store, const char *prefix,
unsigned int flags)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
struct ref_iterator *res =
drefs->refs->be->iterator_begin(drefs->refs, prefix, flags);
struct debug_ref_iterator *diter = xcalloc(1, sizeof(*diter));
base_ref_iterator_init(&diter->base, &debug_ref_iterator_vtable, 1);
diter->iter = res;
trace_printf_key(&trace_refs, "ref_iterator_begin: %s (0x%x)\n", prefix, flags);
return &diter->base;
}
static int debug_read_raw_ref(struct ref_store *ref_store, const char *refname,
struct object_id *oid, struct strbuf *referent,
unsigned int *type)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
int res = 0;
oidcpy(oid, &null_oid);
res = drefs->refs->be->read_raw_ref(drefs->refs, refname, oid, referent,
type);
if (res == 0) {
trace_printf_key(&trace_refs, "read_raw_ref: %s: %s (=> %s) type %x: %d\n",
refname, oid_to_hex(oid), referent->buf, *type, res);
} else {
trace_printf_key(&trace_refs, "read_raw_ref: %s: %d\n", refname, res);
}
return res;
}
static struct ref_iterator *
debug_reflog_iterator_begin(struct ref_store *ref_store)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
struct ref_iterator *res =
drefs->refs->be->reflog_iterator_begin(drefs->refs);
trace_printf_key(&trace_refs, "for_each_reflog_iterator_begin\n");
return res;
}
struct debug_reflog {
const char *refname;
each_reflog_ent_fn *fn;
void *cb_data;
};
static int debug_print_reflog_ent(struct object_id *old_oid,
struct object_id *new_oid,
const char *committer, timestamp_t timestamp,
int tz, const char *msg, void *cb_data)
{
struct debug_reflog *dbg = (struct debug_reflog *)cb_data;
int ret;
char o[GIT_MAX_HEXSZ + 1] = "null";
char n[GIT_MAX_HEXSZ + 1] = "null";
if (old_oid)
oid_to_hex_r(o, old_oid);
if (new_oid)
oid_to_hex_r(n, new_oid);
ret = dbg->fn(old_oid, new_oid, committer, timestamp, tz, msg,
dbg->cb_data);
trace_printf_key(&trace_refs, "reflog_ent %s (ret %d): %s -> %s, %s %ld \"%s\"\n",
dbg->refname, ret, o, n, committer, (long int)timestamp, msg);
return ret;
}
static int debug_for_each_reflog_ent(struct ref_store *ref_store,
const char *refname, each_reflog_ent_fn fn,
void *cb_data)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
struct debug_reflog dbg = {
.refname = refname,
.fn = fn,
.cb_data = cb_data,
};
int res = drefs->refs->be->for_each_reflog_ent(
drefs->refs, refname, &debug_print_reflog_ent, &dbg);
trace_printf_key(&trace_refs, "for_each_reflog: %s: %d\n", refname, res);
return res;
}
static int debug_for_each_reflog_ent_reverse(struct ref_store *ref_store,
const char *refname,
each_reflog_ent_fn fn,
void *cb_data)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
struct debug_reflog dbg = {
.refname = refname,
.fn = fn,
.cb_data = cb_data,
};
int res = drefs->refs->be->for_each_reflog_ent_reverse(
drefs->refs, refname, &debug_print_reflog_ent, &dbg);
trace_printf_key(&trace_refs, "for_each_reflog_reverse: %s: %d\n", refname, res);
return res;
}
static int debug_reflog_exists(struct ref_store *ref_store, const char *refname)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
int res = drefs->refs->be->reflog_exists(drefs->refs, refname);
trace_printf_key(&trace_refs, "reflog_exists: %s: %d\n", refname, res);
return res;
}
static int debug_create_reflog(struct ref_store *ref_store, const char *refname,
int force_create, struct strbuf *err)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
int res = drefs->refs->be->create_reflog(drefs->refs, refname,
force_create, err);
trace_printf_key(&trace_refs, "create_reflog: %s: %d\n", refname, res);
return res;
}
static int debug_delete_reflog(struct ref_store *ref_store, const char *refname)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
int res = drefs->refs->be->delete_reflog(drefs->refs, refname);
trace_printf_key(&trace_refs, "delete_reflog: %s: %d\n", refname, res);
return res;
}
static int debug_reflog_expire(struct ref_store *ref_store, const char *refname,
const struct object_id *oid, unsigned int flags,
reflog_expiry_prepare_fn prepare_fn,
reflog_expiry_should_prune_fn should_prune_fn,
reflog_expiry_cleanup_fn cleanup_fn,
void *policy_cb_data)
{
struct debug_ref_store *drefs = (struct debug_ref_store *)ref_store;
int res = drefs->refs->be->reflog_expire(drefs->refs, refname, oid,
flags, prepare_fn,
should_prune_fn, cleanup_fn,
policy_cb_data);
trace_printf_key(&trace_refs, "reflog_expire: %s: %d\n", refname, res);
return res;
}
struct ref_storage_be refs_be_debug = {
NULL,
"debug",
NULL,
debug_init_db,
debug_transaction_prepare,
debug_transaction_finish,
debug_transaction_abort,
debug_initial_transaction_commit,
debug_pack_refs,
debug_create_symref,
debug_delete_refs,
debug_rename_ref,
debug_copy_ref,
debug_ref_iterator_begin,
debug_read_raw_ref,
debug_reflog_iterator_begin,
debug_for_each_reflog_ent,
debug_for_each_reflog_ent_reverse,
debug_reflog_exists,
debug_create_reflog,
debug_delete_reflog,
debug_reflog_expire,
};

View File

@ -690,4 +690,9 @@ int parse_loose_ref_contents(const char *buf, struct object_id *oid,
void base_ref_store_init(struct ref_store *refs,
const struct ref_storage_be *be);
/*
* Support GIT_TRACE_REFS by optionally wrapping the given ref_store instance.
*/
struct ref_store *maybe_debug_wrap_ref_store(const char *gitdir, struct ref_store *store);
#endif /* REFS_REFS_INTERNAL_H */