rust-lang/rust
1
0
Fork 0
Code Issues Pull Requests Actions 1 Packages Projects Releases Wiki Activity

Overhaul logging system in runtime

Browse Source 
See https://github.com/graydon/rust/wiki/Logging-vision

The runtime logging categories are now treated in the same way as
modules in compiled code. Each domain now has a log_lvl that can be
used to restrict the logging from that domain (will be used to allow
logging to be restricted to a single domain).

Features dropped (can be brought back to life if there is interest):
  - Logger indentation
  - Multiple categories per log statement
  - I possibly broke some of the color code -- it confuses me
This commit is contained in:
Marijn Haverbeke
2011-04-19 12:21:57 +02:00
parent 6511d471ba
commit 880be6a940
24 changed files with 463 additions and 637 deletions
Download Patch File Download Diff File Expand all files Collapse all files

212
src/rt/rust_upcall.cpp
View File

@@ -3,20 +3,19 @@
// Upcalls.
#ifdef __GNUC__
#define LOG_UPCALL_ENTRY(task) \
LOG_I(task, rust_log::UPCALL, \
"> UPCALL %s - task: %s 0x%" PRIxPTR \
" retpc: x%" PRIxPTR \
" ref_count: %d", \
__FUNCTION__, \
(task)->name, (task), \
__builtin_return_address(0), \
(task->ref_count));
#define LOG_UPCALL_ENTRY(task) \
LOG(task, upcall, \
"> UPCALL %s - task: %s 0x%" PRIxPTR \
" retpc: x%" PRIxPTR \
" ref_count: %d", \
__FUNCTION__, \
(task)->name, (task), \
__builtin_return_address(0), \
(task->ref_count));
#else
#define LOG_UPCALL_ENTRY(task) \
LOG_I(task, rust_log::UPCALL, \
"> UPCALL task: %s @x%" PRIxPTR, \
(task)->name, (task));
#define LOG_UPCALL_ENTRY(task) \
LOG(task, upcall, "> UPCALL task: %s @x%" PRIxPTR, \
(task)->name, (task));
#endif
extern "C" CDECL char const *
@@ -29,61 +28,78 @@ upcall_grow_task(rust_task *task, size_t n_frame_bytes) {
}
extern "C" CDECL
void upcall_log_int(rust_task *task, int32_t level, int32_t i) {
void upcall_log_int(rust_task *task, uint32_t level, int32_t i) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::ULOG,
"rust: %" PRId32 " (0x%" PRIx32 ")", i, i);
if (task->dom->log_lvl >= level)
task->dom->log(task, level, "rust: %" PRId32 " (0x%" PRIx32 ")",
i, i);
}
extern "C" CDECL
void upcall_log_float(rust_task *task, int32_t level, float f) {
void upcall_log_int_rustboot(rust_task *task, uint32_t level, int32_t i) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::ULOG,
"rust: %12.12f", f);
if (task->dom->log_lvl >= level && log_rustboot >= level)
task->dom->log(task, level, "rust: %" PRId32 " (0x%" PRIx32 ")",
i, i);
}
extern "C" CDECL
void upcall_log_double(rust_task *task, int32_t level, double *f) {
void upcall_log_float(rust_task *task, uint32_t level, float f) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::ULOG,
"rust: %12.12f", *f);
if (task->dom->log_lvl >= level)
task->dom->log(task, level, "rust: %12.12f", f);
}
extern "C" CDECL
void upcall_log_double(rust_task *task, uint32_t level, double *f) {
LOG_UPCALL_ENTRY(task);
if (task->dom->log_lvl >= level)
task->dom->log(task, level, "rust: %12.12f", *f);
}
extern "C" CDECL void
upcall_log_str(rust_task *task, int32_t level, rust_str *str) {
upcall_log_str_rustboot(rust_task *task, uint32_t level, rust_str *str) {
LOG_UPCALL_ENTRY(task);
const char *c = str_buf(task, str);
LOG(task, rust_log::UPCALL | rust_log::ULOG, "rust: %s", c);
if (task->dom->log_lvl >= level && log_rustboot >= level) {
const char *c = str_buf(task, str);
task->dom->log(task, level, "rust: %s", c);
}
}
extern "C" CDECL void
upcall_log_str(rust_task *task, uint32_t level, rust_str *str) {
LOG_UPCALL_ENTRY(task);
if (task->dom->log_lvl >= level) {
const char *c = str_buf(task, str);
task->dom->log(task, level, "rust: %s", c);
}
}
extern "C" CDECL void
upcall_trace_word(rust_task *task, uintptr_t i) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::TRACE, "trace: 0x%" PRIxPTR "", i,
i, (char) i);
task->dom->log(task, 2, "trace: 0x%" PRIxPTR "", i, i, (char) i);
}
extern "C" CDECL void
upcall_trace_str(rust_task *task, char const *c) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::TRACE, "trace: %s", c);
task->dom->log(task, 2, "trace: %s", c);
}
extern "C" CDECL rust_port*
upcall_new_port(rust_task *task, size_t unit_sz) {
LOG_UPCALL_ENTRY(task);
rust_dom *dom = task->dom;
LOG(task, rust_log::UPCALL | rust_log::MEM | rust_log::COMM,
"upcall_new_port(task=0x%" PRIxPTR " (%s), unit_sz=%d)",
(uintptr_t) task, task->name, unit_sz);
LOG(task, comm, "upcall_new_port(task=0x%" PRIxPTR " (%s), unit_sz=%d)",
(uintptr_t) task, task->name, unit_sz);
return new (dom) rust_port(task, unit_sz);
}
extern "C" CDECL void
upcall_del_port(rust_task *task, rust_port *port) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::MEM | rust_log::COMM,
"upcall del_port(0x%" PRIxPTR ")", (uintptr_t) port);
LOG(task, comm, "upcall del_port(0x%" PRIxPTR ")", (uintptr_t) port);
I(task->dom, !port->ref_count);
delete port;
}
@@ -95,10 +111,9 @@ extern "C" CDECL rust_chan*
upcall_new_chan(rust_task *task, rust_port *port) {
LOG_UPCALL_ENTRY(task);
rust_dom *dom = task->dom;
LOG(task, rust_log::UPCALL | rust_log::MEM | rust_log::COMM,
"upcall_new_chan("
"task=0x%" PRIxPTR " (%s), port=0x%" PRIxPTR ")",
(uintptr_t) task, task->name, port);
LOG(task, comm, "upcall_new_chan("
"task=0x%" PRIxPTR " (%s), port=0x%" PRIxPTR ")",
(uintptr_t) task, task->name, port);
I(dom, port);
return new (dom) rust_chan(task, port, port->unit_sz);
}
@@ -124,8 +139,7 @@ extern "C" CDECL
void upcall_del_chan(rust_task *task, rust_chan *chan) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::MEM | rust_log::COMM,
"upcall del_chan(0x%" PRIxPTR ")", (uintptr_t) chan);
LOG(task, comm, "upcall del_chan(0x%" PRIxPTR ")", (uintptr_t) chan);
A(task->dom, chan->ref_count == 0,
"Channel's ref count should be zero.");
@@ -175,7 +189,7 @@ upcall_clone_chan(rust_task *task, maybe_proxy<rust_task> *target,
rust_handle<rust_port> *handle =
task->dom->kernel->get_port_handle(port->as_referent());
maybe_proxy<rust_port> *proxy = new rust_proxy<rust_port> (handle);
LOG(task, rust_log::MEM, "new proxy: " PTR, proxy);
LOG(task, mem, "new proxy: " PTR, proxy);
port = proxy;
target_task = target->as_proxy()->handle()->referent();
}
@@ -185,16 +199,16 @@ upcall_clone_chan(rust_task *task, maybe_proxy<rust_task> *target,
extern "C" CDECL void
upcall_yield(rust_task *task) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::COMM, "upcall yield()");
LOG(task, comm, "upcall yield()");
task->yield(1);
}
extern "C" CDECL void
upcall_sleep(rust_task *task, size_t time_in_us) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::TASK, "elapsed %d",
LOG(task, task, "elapsed %d",
task->yield_timer.get_elapsed_time());
LOG(task, rust_log::UPCALL | rust_log::TASK, "sleep %d us", time_in_us);
LOG(task, task, "sleep %d us", time_in_us);
task->yield(2, time_in_us);
}
@@ -228,17 +242,16 @@ extern "C" CDECL void
upcall_send(rust_task *task, rust_chan *chan, void *sptr) {
LOG_UPCALL_ENTRY(task);
chan->send(sptr);
LOG(task, rust_log::COMM, "=== sent data ===>");
LOG(task, comm, "=== sent data ===>");
}
extern "C" CDECL void
upcall_recv(rust_task *task, uintptr_t *dptr, rust_port *port) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::COMM,
"port: 0x%" PRIxPTR ", dptr: 0x%" PRIxPTR
", size: 0x%" PRIxPTR ", chan_no: %d",
(uintptr_t) port, (uintptr_t) dptr, port->unit_sz,
port->chans.length());
LOG(task, comm, "port: 0x%" PRIxPTR ", dptr: 0x%" PRIxPTR
", size: 0x%" PRIxPTR ", chan_no: %d",
(uintptr_t) port, (uintptr_t) dptr, port->unit_sz,
port->chans.length());
if (port->receive(dptr)) {
return;
@@ -248,7 +261,7 @@ upcall_recv(rust_task *task, uintptr_t *dptr, rust_port *port) {
// on the port. Remember the rendezvous location so that any sender
// task can write to it before waking up this task.
LOG(task, rust_log::COMM, "<=== waiting for rendezvous data ===");
LOG(task, comm, "<=== waiting for rendezvous data ===");
task->rendezvous_ptr = dptr;
task->block(port, "waiting for rendezvous data");
task->yield(3);
@@ -260,8 +273,7 @@ upcall_fail(rust_task *task,
char const *file,
size_t line) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::ERR,
"upcall fail '%s', %s:%" PRIdPTR, expr, file, line);
LOG_ERR(task, upcall, "upcall fail '%s', %s:%" PRIdPTR, expr, file, line);
task->fail(4);
if (getenv("RUST_TRAP_FAILURE")) {
// FIXME: x86-ism.
@@ -292,8 +304,7 @@ upcall_kill(rust_task *task, maybe_proxy<rust_task> *target) {
extern "C" CDECL void
upcall_exit(rust_task *task) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::TASK,
"task ref_count: %d", task->ref_count);
LOG(task, task, "task ref_count: %d", task->ref_count);
A(task->dom, task->ref_count >= 0,
"Task ref_count should not be negative on exit!");
task->die();
@@ -305,12 +316,12 @@ extern "C" CDECL uintptr_t
upcall_malloc(rust_task *task, size_t nbytes, type_desc *td) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL|rust_log::MEM,
LOG(task, mem,
"upcall malloc(%" PRIdPTR ", 0x%" PRIxPTR ")"
" with gc-chain head = 0x%" PRIxPTR,
nbytes, td, task->gc_alloc_chain);
void *p = task->malloc(nbytes, td);
LOG(task, rust_log::UPCALL|rust_log::MEM,
LOG(task, mem,
"upcall malloc(%" PRIdPTR ", 0x%" PRIxPTR
") = 0x%" PRIxPTR
" with gc-chain head = 0x%" PRIxPTR,
@@ -325,7 +336,7 @@ extern "C" CDECL void
upcall_free(rust_task *task, void* ptr, uintptr_t is_gc) {
LOG_UPCALL_ENTRY(task);
rust_dom *dom = task->dom;
DLOG(dom, rust_log::UPCALL|rust_log::MEM,
DLOG(dom, mem,
"upcall free(0x%" PRIxPTR ", is_gc=%" PRIdPTR ")",
(uintptr_t)ptr, is_gc);
task->free(ptr, (bool) is_gc);
@@ -339,8 +350,7 @@ upcall_mark(rust_task *task, void* ptr) {
if (ptr) {
gc_alloc *gcm = (gc_alloc*) (((char*)ptr) - sizeof(gc_alloc));
uintptr_t marked = (uintptr_t) gcm->mark();
DLOG(dom, rust_log::UPCALL|rust_log::MEM|rust_log::GC,
"upcall mark(0x%" PRIxPTR ") = %" PRIdPTR,
DLOG(dom, gc, "upcall mark(0x%" PRIxPTR ") = %" PRIdPTR,
(uintptr_t)gcm, marked);
return marked;
}
@@ -358,9 +368,9 @@ upcall_new_str(rust_task *task, char const *s, size_t fill) {
return NULL;
}
rust_str *st = new (mem) rust_str(dom, alloc, fill, (uint8_t const *) s);
LOG(task, rust_log::UPCALL | rust_log::MEM,
"upcall new_str('%s', %" PRIdPTR ") = 0x%" PRIxPTR,
s, fill, st);
LOG(task, mem,
"upcall new_str('%s', %" PRIdPTR ") = 0x%" PRIxPTR,
s, fill, st);
return st;
}
@@ -368,9 +378,7 @@ extern "C" CDECL rust_vec *
upcall_new_vec(rust_task *task, size_t fill, type_desc *td) {
LOG_UPCALL_ENTRY(task);
rust_dom *dom = task->dom;
DLOG(dom, rust_log::UPCALL|rust_log::MEM,
"upcall new_vec(%" PRIdPTR ")",
fill);
DLOG(dom, mem, "upcall new_vec(%" PRIdPTR ")", fill);
size_t alloc = next_power_of_two(sizeof(rust_vec) + fill);
void *mem = task->malloc(alloc, td);
if (!mem) {
@@ -378,7 +386,7 @@ upcall_new_vec(rust_task *task, size_t fill, type_desc *td) {
return NULL;
}
rust_vec *v = new (mem) rust_vec(dom, alloc, 0, NULL);
LOG(task, rust_log::UPCALL | rust_log::MEM,
LOG(task, mem,
"upcall new_vec(%" PRIdPTR ") = 0x%" PRIxPTR, fill, v);
return v;
}
@@ -392,7 +400,7 @@ upcall_vec_grow(rust_task *task,
{
LOG_UPCALL_ENTRY(task);
rust_dom *dom = task->dom;
LOG(task, rust_log::UPCALL | rust_log::MEM,
LOG(task, mem,
"upcall vec_grow(0x%" PRIxPTR ", %" PRIdPTR
"), alloc=%" PRIdPTR ", fill=%" PRIdPTR
", need_copy=0x%" PRIxPTR,
@@ -405,12 +413,12 @@ upcall_vec_grow(rust_task *task,
// Fastest path: already large enough.
if (v->alloc >= alloc) {
LOG(task, rust_log::UPCALL | rust_log::MEM, "no-growth path");
LOG(task, mem, "no-growth path");
return v;
}
// Second-fastest path: can at least realloc.
LOG(task, rust_log::UPCALL | rust_log::MEM, "realloc path");
LOG(task, mem, "realloc path");
v = (rust_vec*) task->realloc(v, alloc, td->is_stateful);
if (!v) {
task->fail(4);
@@ -432,7 +440,7 @@ upcall_vec_grow(rust_task *task,
* need_copy outparam flag to indicate to our caller (vec-copy glue)
* that we need the copies performed for us.
*/
LOG(task, rust_log::UPCALL | rust_log::MEM, "new vec path");
LOG(task, mem, "new vec path");
void *mem = task->malloc(alloc, td);
if (!mem) {
task->fail(4);
@@ -472,24 +480,22 @@ upcall_require_rust_sym(rust_task *task,
LOG_UPCALL_ENTRY(task);
rust_dom *dom = task->dom;
LOG(task, rust_log::UPCALL | rust_log::CACHE,
"upcall require rust sym: lib #%" PRIdPTR
" = %s, c_sym #%" PRIdPTR
", rust_sym #%" PRIdPTR
", curr_crate = 0x%" PRIxPTR, lib_num, library, c_sym_num,
rust_sym_num, curr_crate);
LOG(task, cache, "upcall require rust sym: lib #%" PRIdPTR
" = %s, c_sym #%" PRIdPTR
", rust_sym #%" PRIdPTR
", curr_crate = 0x%" PRIxPTR, lib_num, library, c_sym_num,
rust_sym_num, curr_crate);
for (char const **c = crate_rel(curr_crate, path); *c; ++c) {
LOG(task, rust_log::UPCALL, " + %s", crate_rel(curr_crate, *c));
LOG(task, upcall, " + %s", crate_rel(curr_crate, *c));
}
LOG(task, rust_log::UPCALL | rust_log::CACHE,
"require C symbol 'rust_crate' from lib #%" PRIdPTR, lib_num);
LOG(task, cache, "require C symbol 'rust_crate' from lib #%" PRIdPTR,
lib_num);
rust_crate_cache::c_sym *c =
fetch_c_sym(task, curr_crate, lib_num, c_sym_num, library,
"rust_crate");
LOG(task, rust_log::UPCALL | rust_log::CACHE,
"require rust symbol inside crate");
LOG(task, cache, "require rust symbol inside crate");
rust_crate_cache::rust_sym *s = task->cache->get_rust_sym(rust_sym_num,
dom,
curr_crate, c,
@@ -497,11 +503,9 @@ upcall_require_rust_sym(rust_task *task,
uintptr_t addr = s->get_val();
if (addr) {
LOG(task, rust_log::UPCALL | rust_log::CACHE,
"found-or-cached addr: 0x%" PRIxPTR, addr);
LOG(task, cache, "found-or-cached addr: 0x%" PRIxPTR, addr);
} else {
LOG(task, rust_log::UPCALL | rust_log::CACHE | rust_log::ERR,
"failed to resolve symbol");
LOG_ERR(task, cache, "failed to resolve symbol");
task->fail(7);
}
return addr;
@@ -516,23 +520,22 @@ upcall_require_c_sym(rust_task *task,
char const *symbol) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::CACHE,
"upcall require c sym: lib #%" PRIdPTR
" = %s, c_sym #%" PRIdPTR
" = %s"
", curr_crate = 0x%" PRIxPTR, lib_num, library, c_sym_num,
symbol, curr_crate);
LOG(task, cache, "upcall require c sym: lib #%" PRIdPTR
" = %s, c_sym #%" PRIdPTR
" = %s"
", curr_crate = 0x%" PRIxPTR, lib_num, library, c_sym_num,
symbol, curr_crate);
rust_crate_cache::c_sym *c = fetch_c_sym(task, curr_crate, lib_num,
c_sym_num, library, symbol);
uintptr_t addr = c->get_val();
if (addr) {
LOG(task, rust_log::UPCALL | rust_log::CACHE,
LOG(task, cache,
"found-or-cached addr: 0x%" PRIxPTR, addr);
} else {
LOG(task, rust_log::UPCALL | rust_log::CACHE | rust_log::ERR,
"failed to resolve symbol %s in %s", symbol, library);
LOG_ERR(task, cache, "failed to resolve symbol %s in %s",
symbol, library);
task->fail(6);
}
return addr;
@@ -546,14 +549,12 @@ upcall_get_type_desc(rust_task *task,
size_t n_descs,
type_desc const **descs) {
LOG_UPCALL_ENTRY(task);
LOG(task, rust_log::UPCALL | rust_log::CACHE,
"upcall get_type_desc with size=%" PRIdPTR
", align=%" PRIdPTR ", %" PRIdPTR " descs", size, align,
n_descs);
LOG(task, cache, "upcall get_type_desc with size=%" PRIdPTR
", align=%" PRIdPTR ", %" PRIdPTR " descs", size, align,
n_descs);
rust_crate_cache *cache = task->get_crate_cache(curr_crate);
type_desc *td = cache->get_type_desc(size, align, n_descs, descs);
LOG(task, rust_log::UPCALL | rust_log::CACHE,
"returning tydesc 0x%" PRIxPTR, td);
LOG(task, cache, "returning tydesc 0x%" PRIxPTR, td);
return td;
}
@@ -575,7 +576,7 @@ upcall_start_task(rust_task *spawner,
LOG_UPCALL_ENTRY(spawner);
rust_dom *dom = spawner->dom;
DLOG(dom, rust_log::UPCALL | rust_log::MEM | rust_log::TASK,
DLOG(dom, task,
"upcall start_task(task %s @0x%" PRIxPTR
" exit_task_glue 0x%" PRIxPTR
", spawnee 0x%" PRIxPTR
@@ -598,10 +599,9 @@ upcall_new_thread(rust_task *task, const char *name) {
kernel->create_domain(parent_dom->root_crate, name);
rust_handle<rust_task> *child_task_handle =
kernel->get_task_handle(child_dom_handle->referent()->root_task);
LOG(task, rust_log::UPCALL | rust_log::MEM,
"child name: %s, child_dom_handle: " PTR
", child_task_handle: " PTR,
name, child_dom_handle, child_task_handle);
LOG(task, mem, "child name: %s, child_dom_handle: " PTR
", child_task_handle: " PTR,
name, child_dom_handle, child_task_handle);
rust_proxy<rust_task> *child_task_proxy =
new rust_proxy<rust_task> (child_task_handle);
return child_task_proxy;
@@ -641,7 +641,7 @@ upcall_start_thread(rust_task *task,
LOG_UPCALL_ENTRY(task);
rust_dom *parenet_dom = task->dom;
rust_handle<rust_task> *child_task_handle = child_task_proxy->handle();
LOG(task, rust_log::UPCALL | rust_log::MEM | rust_log::TASK,
LOG(task, task,
"exit_task_glue: " PTR ", spawnee_fn " PTR
", callsz %" PRIdPTR ")",
exit_task_glue, spawnee_fn, callsz);