diff options
| -rw-r--r-- | src/boot/me/trans.ml | 8 | ||||
| -rw-r--r-- | src/rt/circular_buffer.cpp | 30 | ||||
| -rw-r--r-- | src/rt/rust.cpp | 9 | ||||
| -rw-r--r-- | src/rt/rust_builtin.cpp | 115 | ||||
| -rw-r--r-- | src/rt/rust_chan.cpp | 16 | ||||
| -rw-r--r-- | src/rt/rust_crate.cpp | 4 | ||||
| -rw-r--r-- | src/rt/rust_crate_cache.cpp | 52 | ||||
| -rw-r--r-- | src/rt/rust_crate_reader.cpp | 54 | ||||
| -rw-r--r-- | src/rt/rust_dom.cpp | 105 | ||||
| -rw-r--r-- | src/rt/rust_dom.h | 12 | ||||
| -rw-r--r-- | src/rt/rust_internal.h | 2 | ||||
| -rw-r--r-- | src/rt/rust_kernel.cpp | 26 | ||||
| -rw-r--r-- | src/rt/rust_kernel.h | 2 | ||||
| -rw-r--r-- | src/rt/rust_log.cpp | 180 | ||||
| -rw-r--r-- | src/rt/rust_log.h | 91 | ||||
| -rw-r--r-- | src/rt/rust_message.cpp | 10 | ||||
| -rw-r--r-- | src/rt/rust_port.cpp | 17 | ||||
| -rw-r--r-- | src/rt/rust_srv.cpp | 6 | ||||
| -rw-r--r-- | src/rt/rust_task.cpp | 127 | ||||
| -rw-r--r-- | src/rt/rust_task.h | 2 | ||||
| -rw-r--r-- | src/rt/rust_task_list.cpp | 4 | ||||
| -rw-r--r-- | src/rt/rust_timer.cpp | 6 | ||||
| -rw-r--r-- | src/rt/rust_upcall.cpp | 212 | ||||
| -rw-r--r-- | src/rt/rust_util.h | 10 |
24 files changed, 463 insertions, 637 deletions
diff --git a/src/boot/me/trans.ml b/src/boot/me/trans.ml index 3ad3ee06975..1b3ad5d4544 100644 --- a/src/boot/me/trans.ml +++ b/src/boot/me/trans.ml @@ -2664,12 +2664,12 @@ let trans_visitor nabi_rust (upcall_fixup name) args); and trans_log_int lev (a:Ast.atom) : unit = - trans_void_upcall "upcall_log_int" [| simm (Int64.of_int lev); - trans_atom a |] + trans_void_upcall "upcall_log_int_rustboot" [| simm (Int64.of_int lev); + trans_atom a |] and trans_log_str lev (a:Ast.atom) : unit = - trans_void_upcall "upcall_log_str" [| simm (Int64.of_int lev); - trans_atom a |] + trans_void_upcall "upcall_log_str_rustboot" [| simm (Int64.of_int lev); + trans_atom a |] and trans_spawn ((*initializing*)_:bool) diff --git a/src/rt/circular_buffer.cpp b/src/rt/circular_buffer.cpp index d5ba8e13c54..ab98dfe34c4 100644 --- a/src/rt/circular_buffer.cpp +++ b/src/rt/circular_buffer.cpp @@ -14,16 +14,15 @@ circular_buffer::circular_buffer(rust_dom *dom, size_t unit_sz) : A(dom, unit_sz, "Unit size must be larger than zero."); - DLOG(dom, rust_log::MEM | rust_log::COMM, - "new circular_buffer(buffer_sz=%d, unread=%d)" - "-> circular_buffer=0x%" PRIxPTR, - _buffer_sz, _unread, this); + DLOG(dom, mem, "new circular_buffer(buffer_sz=%d, unread=%d)" + "-> circular_buffer=0x%" PRIxPTR, + _buffer_sz, _unread, this); A(dom, _buffer, "Failed to allocate buffer."); } circular_buffer::~circular_buffer() { - DLOG(dom, rust_log::MEM, "~circular_buffer 0x%" PRIxPTR, this); + DLOG(dom, mem, "~circular_buffer 0x%" PRIxPTR, this); I(dom, _buffer); W(dom, _unread == 0, "freeing circular_buffer with %d unread bytes", _unread); @@ -79,10 +78,9 @@ circular_buffer::enqueue(void *src) { grow(); } - DLOG(dom, rust_log::MEM | rust_log::COMM, - "circular_buffer enqueue " - "unread: %d, next: %d, buffer_sz: %d, unit_sz: %d", - _unread, _next, _buffer_sz, unit_sz); + DLOG(dom, mem, "circular_buffer enqueue " + "unread: %d, next: %d, buffer_sz: %d, unit_sz: %d", + _unread, _next, _buffer_sz, unit_sz); I(dom, _unread < _buffer_sz); I(dom, _unread + unit_sz <= _buffer_sz); @@ -101,8 +99,7 @@ circular_buffer::enqueue(void *src) { memcpy(&_buffer[dst_idx], src, unit_sz); _unread += unit_sz; - DLOG(dom, rust_log::MEM | rust_log::COMM, - "circular_buffer pushed data at index: %d", dst_idx); + DLOG(dom, mem, "circular_buffer pushed data at index: %d", dst_idx); } /** @@ -117,7 +114,7 @@ circular_buffer::dequeue(void *dst) { I(dom, _unread <= _buffer_sz); I(dom, _buffer); - DLOG(dom, rust_log::MEM | rust_log::COMM, + DLOG(dom, mem, "circular_buffer dequeue " "unread: %d, next: %d, buffer_sz: %d, unit_sz: %d", _unread, _next, _buffer_sz, unit_sz); @@ -126,8 +123,7 @@ circular_buffer::dequeue(void *dst) { if (dst != NULL) { memcpy(dst, &_buffer[_next], unit_sz); } - DLOG(dom, rust_log::MEM | rust_log::COMM, - "shifted data from index %d", _next); + DLOG(dom, mem, "shifted data from index %d", _next); _unread -= unit_sz; _next += unit_sz; if (_next == _buffer_sz) { @@ -144,8 +140,7 @@ void circular_buffer::grow() { size_t new_buffer_sz = _buffer_sz * 2; I(dom, new_buffer_sz <= MAX_CIRCULAR_BUFFER_SIZE); - DLOG(dom, rust_log::MEM | rust_log::COMM, - "circular_buffer is growing to %d bytes", new_buffer_sz); + DLOG(dom, mem, "circular_buffer is growing to %d bytes", new_buffer_sz); void *new_buffer = dom->malloc(new_buffer_sz); transfer(new_buffer); dom->free(_buffer); @@ -158,8 +153,7 @@ void circular_buffer::shrink() { size_t new_buffer_sz = _buffer_sz / 2; I(dom, initial_size() <= new_buffer_sz); - DLOG(dom, rust_log::MEM | rust_log::COMM, - "circular_buffer is shrinking to %d bytes", new_buffer_sz); + DLOG(dom, mem, "circular_buffer is shrinking to %d bytes", new_buffer_sz); void *new_buffer = dom->malloc(new_buffer_sz); transfer(new_buffer); dom->free(_buffer); diff --git a/src/rt/rust.cpp b/src/rt/rust.cpp index 66ca2dc2643..56c5b4d6672 100644 --- a/src/rt/rust.cpp +++ b/src/rt/rust.cpp @@ -82,6 +82,8 @@ rust_start(uintptr_t main_fn, rust_crate const *crate, int argc, if (crate->abi_tag != ABI_X86_RUSTBOOT_CDECL) update_log_settings(crate_map, getenv("RUST_LOG")); + else + update_log_settings(NULL, getenv("RUST_LOG")); rust_srv *srv = new rust_srv(); rust_kernel *kernel = new rust_kernel(srv); kernel->start(); @@ -89,14 +91,13 @@ rust_start(uintptr_t main_fn, rust_crate const *crate, int argc, rust_dom *dom = handle->referent(); command_line_args *args = new (dom) command_line_args(dom, argc, argv); - DLOG(dom, rust_log::DOM, "startup: %d args in 0x%" PRIxPTR, + DLOG(dom, dom, "startup: %d args in 0x%" PRIxPTR, args->argc, (uintptr_t)args->args); for (int i = 0; i < args->argc; i++) { - DLOG(dom, rust_log::DOM, - "startup: arg[%d] = '%s'", i, args->argv[i]); + DLOG(dom, dom, "startup: arg[%d] = '%s'", i, args->argv[i]); } - if (dom->_log.is_tracing(rust_log::DWARF)) { + if (log_rt_dwarf) { rust_crate_reader create_reader(dom, crate); } diff --git a/src/rt/rust_builtin.cpp b/src/rt/rust_builtin.cpp index 9ef05ce0fec..c1aa5b59413 100644 --- a/src/rt/rust_builtin.cpp +++ b/src/rt/rust_builtin.cpp @@ -6,7 +6,7 @@ extern "C" CDECL rust_str* last_os_error(rust_task *task) { rust_dom *dom = task->dom; - LOG(task, rust_log::TASK, "last_os_error()"); + LOG(task, task, "last_os_error()"); #if defined(__WIN32__) LPTSTR buf; @@ -91,9 +91,8 @@ extern "C" CDECL rust_vec* vec_alloc(rust_task *task, type_desc *t, type_desc *elem_t, size_t n_elts) { rust_dom *dom = task->dom; - LOG(task, rust_log::MEM | rust_log::STDLIB, - "vec_alloc %" PRIdPTR " elements of size %" PRIdPTR, - n_elts, elem_t->size); + LOG(task, mem, "vec_alloc %" PRIdPTR " elements of size %" PRIdPTR, + n_elts, elem_t->size); size_t fill = n_elts * elem_t->size; size_t alloc = next_power_of_two(sizeof(rust_vec) + fill); void *mem = task->malloc(alloc, t->is_stateful ? t : NULL); @@ -126,37 +125,34 @@ vec_len(rust_task *task, type_desc *ty, rust_vec *v) extern "C" CDECL void vec_len_set(rust_task *task, type_desc *ty, rust_vec *v, size_t len) { - LOG(task, rust_log::STDLIB, - "vec_len_set(0x%" PRIxPTR ", %" PRIdPTR ") on vec with " - "alloc = %" PRIdPTR - ", fill = %" PRIdPTR - ", len = %" PRIdPTR - ". New fill is %" PRIdPTR, - v, len, v->alloc, v->fill, v->fill / ty->size, len * ty->size); + LOG(task, stdlib, "vec_len_set(0x%" PRIxPTR ", %" PRIdPTR ") on vec with " + "alloc = %" PRIdPTR + ", fill = %" PRIdPTR + ", len = %" PRIdPTR + ". New fill is %" PRIdPTR, + v, len, v->alloc, v->fill, v->fill / ty->size, len * ty->size); v->fill = len * ty->size; } extern "C" CDECL void vec_print_debug_info(rust_task *task, type_desc *ty, rust_vec *v) { - LOG(task, rust_log::STDLIB, - "vec_print_debug_info(0x%" PRIxPTR ")" - " with tydesc 0x%" PRIxPTR - " (size = %" PRIdPTR ", align = %" PRIdPTR ")" - " alloc = %" PRIdPTR ", fill = %" PRIdPTR ", len = %" PRIdPTR - " , data = ...", - v, - ty, - ty->size, - ty->align, - v->alloc, - v->fill, - v->fill / ty->size); + LOG(task, stdlib, + "vec_print_debug_info(0x%" PRIxPTR ")" + " with tydesc 0x%" PRIxPTR + " (size = %" PRIdPTR ", align = %" PRIdPTR ")" + " alloc = %" PRIdPTR ", fill = %" PRIdPTR ", len = %" PRIdPTR + " , data = ...", + v, + ty, + ty->size, + ty->align, + v->alloc, + v->fill, + v->fill / ty->size); for (size_t i = 0; i < v->fill; ++i) { - LOG(task, rust_log::STDLIB, - " %" PRIdPTR ": 0x%" PRIxPTR, - i, v->data[i]); + LOG(task, stdlib, " %" PRIdPTR ": 0x%" PRIxPTR, i, v->data[i]); } } @@ -306,29 +302,27 @@ task_sleep(rust_task *task, size_t time_in_us) { static void debug_tydesc_helper(rust_task *task, type_desc *t) { - LOG(task, rust_log::STDLIB, - " size %" PRIdPTR ", align %" PRIdPTR - ", stateful %" PRIdPTR ", first_param 0x%" PRIxPTR, - t->size, t->align, t->is_stateful, t->first_param); + LOG(task, stdlib, " size %" PRIdPTR ", align %" PRIdPTR + ", stateful %" PRIdPTR ", first_param 0x%" PRIxPTR, + t->size, t->align, t->is_stateful, t->first_param); } extern "C" CDECL void debug_tydesc(rust_task *task, type_desc *t) { - LOG(task, rust_log::STDLIB, "debug_tydesc"); + LOG(task, stdlib, "debug_tydesc"); debug_tydesc_helper(task, t); } extern "C" CDECL void debug_opaque(rust_task *task, type_desc *t, uint8_t *front) { - LOG(task, rust_log::STDLIB, "debug_opaque"); + LOG(task, stdlib, "debug_opaque"); debug_tydesc_helper(task, t); // FIXME may want to actually account for alignment. `front` may not // indeed be the front byte of the passed-in argument. for (uintptr_t i = 0; i < t->size; ++front, ++i) { - LOG(task, rust_log::STDLIB, - " byte %" PRIdPTR ": 0x%" PRIx8, i, *front); + LOG(task, stdlib, " byte %" PRIdPTR ": 0x%" PRIx8, i, *front); } } @@ -340,15 +334,14 @@ struct rust_box : rc_base<rust_box> { extern "C" CDECL void debug_box(rust_task *task, type_desc *t, rust_box *box) { - LOG(task, rust_log::STDLIB, "debug_box(0x%" PRIxPTR ")", box); + LOG(task, stdlib, "debug_box(0x%" PRIxPTR ")", box); debug_tydesc_helper(task, t); - LOG(task, rust_log::STDLIB, " refcount %" PRIdPTR, - box->ref_count == CONST_REFCOUNT - ? CONST_REFCOUNT - : box->ref_count - 1); // -1 because we ref'ed for this call + LOG(task, stdlib, " refcount %" PRIdPTR, + box->ref_count == CONST_REFCOUNT + ? CONST_REFCOUNT + : box->ref_count - 1); // -1 because we ref'ed for this call for (uintptr_t i = 0; i < t->size; ++i) { - LOG(task, rust_log::STDLIB, - " byte %" PRIdPTR ": 0x%" PRIx8, i, box->data[i]); + LOG(task, stdlib, " byte %" PRIdPTR ": 0x%" PRIx8, i, box->data[i]); } } @@ -360,14 +353,13 @@ struct rust_tag { extern "C" CDECL void debug_tag(rust_task *task, type_desc *t, rust_tag *tag) { - LOG(task, rust_log::STDLIB, "debug_tag"); + LOG(task, stdlib, "debug_tag"); debug_tydesc_helper(task, t); - LOG(task, rust_log::STDLIB, - " discriminant %" PRIdPTR, tag->discriminant); + LOG(task, stdlib, " discriminant %" PRIdPTR, tag->discriminant); for (uintptr_t i = 0; i < t->size - sizeof(tag->discriminant); ++i) - LOG(task, rust_log::STDLIB, - " byte %" PRIdPTR ": 0x%" PRIx8, i, tag->variant[i]); + LOG(task, stdlib, " byte %" PRIdPTR ": 0x%" PRIx8, i, + tag->variant[i]); } struct rust_obj { @@ -379,19 +371,17 @@ extern "C" CDECL void debug_obj(rust_task *task, type_desc *t, rust_obj *obj, size_t nmethods, size_t nbytes) { - LOG(task, rust_log::STDLIB, - "debug_obj with %" PRIdPTR " methods", nmethods); + LOG(task, stdlib, "debug_obj with %" PRIdPTR " methods", nmethods); debug_tydesc_helper(task, t); - LOG(task, rust_log::STDLIB, " vtbl at 0x%" PRIxPTR, obj->vtbl); - LOG(task, rust_log::STDLIB, " body at 0x%" PRIxPTR, obj->body); + LOG(task, stdlib, " vtbl at 0x%" PRIxPTR, obj->vtbl); + LOG(task, stdlib, " body at 0x%" PRIxPTR, obj->body); for (uintptr_t *p = obj->vtbl; p < obj->vtbl + nmethods; ++p) - LOG(task, rust_log::STDLIB, " vtbl word: 0x%" PRIxPTR, *p); + LOG(task, stdlib, " vtbl word: 0x%" PRIxPTR, *p); for (uintptr_t i = 0; i < nbytes; ++i) - LOG(task, rust_log::STDLIB, - " body byte %" PRIdPTR ": 0x%" PRIxPTR, - i, obj->body->data[i]); + LOG(task, stdlib, " body byte %" PRIdPTR ": 0x%" PRIxPTR, + i, obj->body->data[i]); } struct rust_fn { @@ -402,13 +392,12 @@ struct rust_fn { extern "C" CDECL void debug_fn(rust_task *task, type_desc *t, rust_fn *fn) { - LOG(task, rust_log::STDLIB, "debug_fn"); + LOG(task, stdlib, "debug_fn"); debug_tydesc_helper(task, t); - LOG(task, rust_log::STDLIB, " thunk at 0x%" PRIxPTR, fn->thunk); - LOG(task, rust_log::STDLIB, " closure at 0x%" PRIxPTR, fn->closure); + LOG(task, stdlib, " thunk at 0x%" PRIxPTR, fn->thunk); + LOG(task, stdlib, " closure at 0x%" PRIxPTR, fn->closure); if (fn->closure) { - LOG(task, rust_log::STDLIB, " refcount %" PRIdPTR, - fn->closure->ref_count); + LOG(task, stdlib, " refcount %" PRIdPTR, fn->closure->ref_count); } } @@ -418,9 +407,9 @@ debug_ptrcast(rust_task *task, type_desc *to_ty, void *ptr) { - LOG(task, rust_log::STDLIB, "debug_ptrcast from"); + LOG(task, stdlib, "debug_ptrcast from"); debug_tydesc_helper(task, from_ty); - LOG(task, rust_log::STDLIB, "to"); + LOG(task, stdlib, "to"); debug_tydesc_helper(task, to_ty); return ptr; } @@ -428,7 +417,7 @@ debug_ptrcast(rust_task *task, extern "C" CDECL void debug_trap(rust_task *task, rust_str *s) { - LOG(task, rust_log::STDLIB, "trapping: %s", s->data); + LOG(task, stdlib, "trapping: %s", s->data); // FIXME: x86-ism. __asm__("int3"); } diff --git a/src/rt/rust_chan.cpp b/src/rt/rust_chan.cpp index a88579607c4..fdc7f2704d3 100644 --- a/src/rt/rust_chan.cpp +++ b/src/rt/rust_chan.cpp @@ -13,15 +13,13 @@ rust_chan::rust_chan(rust_task *task, if (port) { associate(port); } - LOG(task, rust_log::MEM | rust_log::COMM, - "new rust_chan(task=0x%" PRIxPTR - ", port=0x%" PRIxPTR ") -> chan=0x%" PRIxPTR, - (uintptr_t) task, (uintptr_t) port, (uintptr_t) this); + LOG(task, comm, "new rust_chan(task=0x%" PRIxPTR + ", port=0x%" PRIxPTR ") -> chan=0x%" PRIxPTR, + (uintptr_t) task, (uintptr_t) port, (uintptr_t) this); } rust_chan::~rust_chan() { - LOG(task, rust_log::MEM | rust_log::COMM, - "del rust_chan(task=0x%" PRIxPTR ")", (uintptr_t) this); + LOG(task, comm, "del rust_chan(task=0x%" PRIxPTR ")", (uintptr_t) this); A(task->dom, is_associated() == false, "Channel must be disassociated before being freed."); @@ -33,7 +31,7 @@ rust_chan::~rust_chan() { void rust_chan::associate(maybe_proxy<rust_port> *port) { this->port = port; if (port->is_proxy() == false) { - LOG(task, rust_log::TASK, + LOG(task, task, "associating chan: 0x%" PRIxPTR " with port: 0x%" PRIxPTR, this, port); this->port->referent()->chans.push(this); @@ -51,7 +49,7 @@ void rust_chan::disassociate() { A(task->dom, is_associated(), "Channel must be associated with a port."); if (port->is_proxy() == false) { - LOG(task, rust_log::TASK, + LOG(task, task, "disassociating chan: 0x%" PRIxPTR " from port: 0x%" PRIxPTR, this, port->referent()); port->referent()->chans.swap_delete(this); @@ -84,7 +82,7 @@ void rust_chan::send(void *sptr) { } else { rust_port *target_port = port->referent(); if (target_port->task->blocked_on(target_port)) { - DLOG(dom, rust_log::COMM, "dequeued in rendezvous_ptr"); + DLOG(dom, comm, "dequeued in rendezvous_ptr"); buffer.dequeue(target_port->task->rendezvous_ptr); target_port->task->rendezvous_ptr = 0; target_port->task->wakeup(target_port); diff --git a/src/rt/rust_crate.cpp b/src/rt/rust_crate.cpp index 23f01c0747f..5e64a0125b3 100644 --- a/src/rt/rust_crate.cpp +++ b/src/rt/rust_crate.cpp @@ -41,8 +41,8 @@ rust_crate::mem_area::mem_area(rust_dom *dom, uintptr_t pos, size_t sz) base(pos), lim(pos + sz) { - DLOG(dom, rust_log::MEM, "new mem_area [0x%" PRIxPTR ",0x%" PRIxPTR "]", - base, lim); + DLOG(dom, mem, "new mem_area [0x%" PRIxPTR ",0x%" PRIxPTR "]", + base, lim); } rust_crate::mem_area diff --git a/src/rt/rust_crate_cache.cpp b/src/rt/rust_crate_cache.cpp index 6c498b320f1..3fdb33b9896 100644 --- a/src/rt/rust_crate_cache.cpp +++ b/src/rt/rust_crate_cache.cpp @@ -10,12 +10,12 @@ rust_crate_cache::lib::lib(rust_dom *dom, char const *name) #else handle = (uintptr_t)dlopen(name, RTLD_GLOBAL|RTLD_LAZY); #endif - DLOG(dom, rust_log::CACHE, "loaded library '%s' as 0x%" PRIxPTR, + DLOG(dom, cache, "loaded library '%s' as 0x%" PRIxPTR, name, handle); } rust_crate_cache::lib::~lib() { - DLOG(dom, rust_log::CACHE, "~rust_crate_cache::lib(0x%" PRIxPTR ")", + DLOG(dom, cache, "~rust_crate_cache::lib(0x%" PRIxPTR ")", handle); if (handle) { #if defined(__WIN32__) @@ -46,17 +46,15 @@ rust_crate_cache::c_sym::c_sym(rust_dom *dom, lib *library, char const *name) #else val = (uintptr_t)dlsym((void*)handle, name); #endif - DLOG(dom, rust_log::CACHE, "resolved symbol '%s' to 0x%" PRIxPTR, + DLOG(dom, cache, "resolved symbol '%s' to 0x%" PRIxPTR, name, val); } else { - DLOG(dom, rust_log::CACHE | rust_log::ERR, - "unresolved symbol '%s', null lib handle", - name); + DLOG_ERR(dom, cache, "unresolved symbol '%s', null lib handle", name); } } rust_crate_cache::c_sym::~c_sym() { - DLOG(dom, rust_log::CACHE, + DLOG(dom, cache, "~rust_crate_cache::c_sym(0x%" PRIxPTR ")", val); library->deref(); } @@ -80,8 +78,7 @@ rust_crate_cache::rust_sym::rust_sym(rust_dom *dom, typedef rust_crate_reader::die die; rust_crate const *crate = (rust_crate*)crate_sym->get_val(); if (!crate) { - DLOG(dom, rust_log::CACHE | rust_log::ERR, - "failed to resolve symbol, null crate symbol"); + DLOG_ERR(dom, cache, "failed to resolve symbol, null crate symbol"); return; } rust_crate_reader rdr(dom, crate); @@ -98,17 +95,14 @@ rust_crate_cache::rust_sym::rust_sym(rust_dom *dom, && !t1.is_null() && t1.find_child_by_name(crate_rel(curr_crate, *c), t2)); ++c, t1=t2) { - DLOG(dom, rust_log::DWARF|rust_log::CACHE, - "matched die <0x%" PRIxPTR + DLOG(dom, dwarf, "matched die <0x%" PRIxPTR ">, child '%s' = die<0x%" PRIxPTR ">", t1.off, crate_rel(curr_crate, *c), t2.off); found_root = found_root || true; if (!*(c+1) && t2.find_num_attr(DW_AT_low_pc, val)) { - DLOG(dom, rust_log::DWARF|rust_log::CACHE, - "found relative address: 0x%" PRIxPTR, val); - DLOG(dom, rust_log::DWARF|rust_log::CACHE, - "plus image-base 0x%" PRIxPTR, - crate->get_image_base()); + DLOG(dom, dwarf, "found relative address: 0x%" PRIxPTR, val); + DLOG(dom, dwarf, "plus image-base 0x%" PRIxPTR, + crate->get_image_base()); val += crate->get_image_base(); found_leaf = true; break; @@ -118,15 +112,14 @@ rust_crate_cache::rust_sym::rust_sym(rust_dom *dom, break; } if (found_leaf) { - DLOG(dom, rust_log::CACHE, "resolved symbol to 0x%" PRIxPTR, val); + DLOG(dom, cache, "resolved symbol to 0x%" PRIxPTR, val); } else { - DLOG(dom, rust_log::CACHE | rust_log::ERR, - "failed to resolve symbol"); + DLOG_ERR(dom, cache, "failed to resolve symbol"); } } rust_crate_cache::rust_sym::~rust_sym() { - DLOG(dom, rust_log::CACHE, + DLOG(dom, cache, "~rust_crate_cache::rust_sym(0x%" PRIxPTR ")", val); crate_sym->deref(); } @@ -155,7 +148,7 @@ rust_crate_cache::get_c_sym(size_t n, lib *library, char const *name) { I(dom, n < crate->n_c_syms); c_sym *sym = c_syms[n]; - DLOG(dom, rust_log::CACHE, "cached C symbol %s = 0x%" PRIxPTR, name, sym); + DLOG(dom, cache, "cached C symbol %s = 0x%" PRIxPTR, name, sym); if (!sym) { sym = new (dom) c_sym(dom, library, name); c_syms[n] = sym; @@ -199,10 +192,10 @@ rust_crate_cache::get_type_desc(size_t size, size_t keysz = n_descs * sizeof(type_desc*); HASH_FIND(hh, this->type_descs, descs, keysz, td); if (td) { - DLOG(dom, rust_log::CACHE, "rust_crate_cache::get_type_desc hit"); + DLOG(dom, cache, "rust_crate_cache::get_type_desc hit"); return td; } - DLOG(dom, rust_log::CACHE, "rust_crate_cache::get_type_desc miss"); + DLOG(dom, cache, "rust_crate_cache::get_type_desc miss"); td = (type_desc*) dom->malloc(sizeof(type_desc) + keysz); if (!td) return NULL; @@ -214,7 +207,7 @@ rust_crate_cache::get_type_desc(size_t size, td->size = size; td->align = align; for (size_t i = 0; i < n_descs; ++i) { - DLOG(dom, rust_log::CACHE, + DLOG(dom, cache, "rust_crate_cache::descs[%" PRIdPTR "] = 0x%" PRIxPTR, i, descs[i]); td->descs[i] = descs[i]; @@ -251,11 +244,11 @@ rust_crate_cache::rust_crate_cache(rust_dom *dom, void rust_crate_cache::flush() { - DLOG(dom, rust_log::CACHE, "rust_crate_cache::flush()"); + DLOG(dom, cache, "rust_crate_cache::flush()"); for (size_t i = 0; i < crate->n_rust_syms; ++i) { rust_sym *s = rust_syms[i]; if (s) { - DLOG(dom, rust_log::CACHE, + DLOG(dom, cache, "rust_crate_cache::flush() deref rust_sym %" PRIdPTR " (rc=%" PRIdPTR ")", i, s->ref_count); s->deref(); @@ -266,7 +259,7 @@ rust_crate_cache::flush() { for (size_t i = 0; i < crate->n_c_syms; ++i) { c_sym *s = c_syms[i]; if (s) { - DLOG(dom, rust_log::CACHE, + DLOG(dom, cache, "rust_crate_cache::flush() deref c_sym %" PRIdPTR " (rc=%" PRIdPTR ")", i, s->ref_count); s->deref(); @@ -277,7 +270,7 @@ rust_crate_cache::flush() { for (size_t i = 0; i < crate->n_libs; ++i) { lib *l = libs[i]; if (l) { - DLOG(dom, rust_log::CACHE, "rust_crate_cache::flush() deref lib %" + DLOG(dom, cache, "rust_crate_cache::flush() deref lib %" PRIdPTR " (rc=%" PRIdPTR ")", i, l->ref_count); l->deref(); } @@ -287,8 +280,7 @@ rust_crate_cache::flush() { while (type_descs) { type_desc *d = type_descs; HASH_DEL(type_descs, d); - DLOG(dom, rust_log::MEM, - "rust_crate_cache::flush() tydesc %" PRIxPTR, d); + DLOG(dom, mem, "rust_crate_cache::flush() tydesc %" PRIxPTR, d); dom->free(d); } } diff --git a/src/rt/rust_crate_reader.cpp b/src/rt/rust_crate_reader.cpp index 3e4f80c36ef..9892f88f4f8 100644 --- a/src/rt/rust_crate_reader.cpp +++ b/src/rt/rust_crate_reader.cpp @@ -92,7 +92,7 @@ rust_crate_reader::mem_reader::adv(size_t amt) ok = false; if (!ok) return; - // mem.DLOG(dom, rust_log::MEM, "adv %d bytes", amt); + // mem.DLOG(dom, mem, "adv %d bytes", amt); pos += amt; ok &= !at_end(); I(mem.dom, at_end() || (mem.base <= pos && pos < mem.lim)); @@ -120,7 +120,7 @@ rust_crate_reader::abbrev_reader::abbrev_reader rust_dom *dom = mem.dom; while (is_ok() && !at_end()) { - // DLOG(dom, rust_log::DWARF, "reading new abbrev at 0x%" PRIxPTR, + // DLOG(dom, dwarf, "reading new abbrev at 0x%" PRIxPTR, // tell_off()); uintptr_t idx, tag; @@ -133,13 +133,13 @@ rust_crate_reader::abbrev_reader::abbrev_reader size_t body_off = tell_off(); while (is_ok() && step_attr_form_pair(attr, form)); - // DLOG(dom, rust_log::DWARF, + // DLOG(dom, dwarf, // "finished scanning attr/form pairs, pos=0x%" // PRIxPTR ", lim=0x%" PRIxPTR ", is_ok=%d, at_end=%d", // pos, mem.lim, is_ok(), at_end()); if (is_ok() || at_end()) { - DLOG(dom, rust_log::DWARF, "read abbrev: %" PRIdPTR, idx); + DLOG(dom, dwarf, "read abbrev: %" PRIdPTR, idx); I(dom, idx = abbrevs.length() + 1); abbrevs.push(new (dom) abbrev(dom, body_off, tell_off() - body_off, @@ -162,11 +162,11 @@ rust_crate_reader::abbrev_reader::step_attr_form_pair(uintptr_t &attr, { attr = 0; form = 0; - // mem.DLOG(dom, rust_log::DWARF, "reading attr/form pair at 0x%" PRIxPTR, + // mem.DLOG(dom, dwarf, "reading attr/form pair at 0x%" PRIxPTR, // tell_off()); get_uleb(attr); get_uleb(form); - // mem.DLOG(dom, rust_log::DWARF, "attr 0x%" PRIxPTR ", form 0x%" PRIxPTR, + // mem.DLOG(dom, dwarf, "attr 0x%" PRIxPTR ", form 0x%" PRIxPTR, // attr, form); return ! (attr == 0 && form == 0); } @@ -254,19 +254,17 @@ rust_crate_reader::die::die(die_reader *rdr, uintptr_t off) rdr->get_uleb(ab_idx); if (!ab_idx) { ab = NULL; - DLOG(dom, rust_log::DWARF, "DIE <0x%" PRIxPTR "> (null)", off); - if (dom->get_log().is_tracing(rust_log::DWARF)) - dom->get_log().outdent(); + DLOG(dom, dwarf, "DIE <0x%" PRIxPTR "> (null)", off); } else { ab = rdr->abbrevs.get_abbrev(ab_idx); if (!ab) { - DLOG(dom, rust_log::DWARF, " bad abbrev number: 0x%" + DLOG(dom, dwarf, " bad abbrev number: 0x%" PRIxPTR, ab_idx); rdr->fail(); } else { - DLOG(dom, rust_log::DWARF, "DIE <0x%" PRIxPTR "> abbrev 0x%" + DLOG(dom, dwarf, "DIE <0x%" PRIxPTR "> abbrev 0x%" PRIxPTR, off, ab_idx); - DLOG(dom, rust_log::DWARF, " tag 0x%x, has children: %d", + DLOG(dom, dwarf, " tag 0x%x, has children: %d", ab->tag, ab->has_children); } } @@ -354,7 +352,7 @@ rust_crate_reader::die::step_attr(attr &a) const break; default: - DLOG(rdr->mem.dom, rust_log::DWARF, " unknown dwarf form: 0x%" + DLOG(rdr->mem.dom, dwarf, " unknown dwarf form: 0x%" PRIxPTR, a.form); rdr->fail(); break; @@ -474,17 +472,15 @@ rust_crate_reader::die::next() const while (step_attr(a)) { I(dom, !(a.is_numeric() && a.is_string())); if (a.is_numeric()) - DLOG(dom, rust_log::DWARF, " attr num: 0x%" + DLOG(dom, dwarf, " attr num: 0x%" PRIxPTR, a.get_num(dom)); else if (a.is_string()) - DLOG(dom, rust_log::DWARF, " attr str: %s", + DLOG(dom, dwarf, " attr str: %s", a.get_str(dom)); else - DLOG(dom, rust_log::DWARF, " attr ??:"); + DLOG(dom, dwarf, " attr ??:"); } } - if (has_children() && dom->get_log().is_tracing(rust_log::DWARF)) - dom->get_log().indent(); } return die(rdr, rdr->tell_off()); } @@ -494,12 +490,12 @@ rust_crate_reader::die::next_sibling() const { // FIXME: use DW_AT_sibling, when present. if (has_children()) { - // DLOG(rdr->mem.dom, rust_log::DWARF, "+++ children of die 0x%" + // DLOG(rdr->mem.dom, dwarf, "+++ children of die 0x%" // PRIxPTR, off); die child = next(); while (!child.is_null()) child = child.next_sibling(); - // DLOG(rdr->mem.dom, rust_log::DWARF, "--- children of die 0x%" + // DLOG(rdr->mem.dom, dwarf, "--- children of die 0x%" // PRIxPTR, off); return child.next(); } else { @@ -554,16 +550,16 @@ rust_crate_reader::die_reader::die_reader(rust_crate::mem_area &die_mem, get(sizeof_addr); if (is_ok()) { - DLOG(dom, rust_log::DWARF, "new root CU at 0x%" PRIxPTR, die_mem.base); - DLOG(dom, rust_log::DWARF, "CU unit length: %" PRId32, cu_unit_length); - DLOG(dom, rust_log::DWARF, "dwarf version: %" PRId16, dwarf_vers); - DLOG(dom, rust_log::DWARF, "CU abbrev off: %" PRId32, cu_abbrev_off); - DLOG(dom, rust_log::DWARF, "size of address: %" PRId8, sizeof_addr); + DLOG(dom, dwarf, "new root CU at 0x%" PRIxPTR, die_mem.base); + DLOG(dom, dwarf, "CU unit length: %" PRId32, cu_unit_length); + DLOG(dom, dwarf, "dwarf version: %" PRId16, dwarf_vers); + DLOG(dom, dwarf, "CU abbrev off: %" PRId32, cu_abbrev_off); + DLOG(dom, dwarf, "size of address: %" PRId8, sizeof_addr); I(dom, sizeof_addr == sizeof(uintptr_t)); I(dom, dwarf_vers >= 2); I(dom, cu_base + cu_unit_length == die_mem.lim - die_mem.base); } else { - DLOG(dom, rust_log::DWARF, "failed to read root CU header"); + DLOG(dom, dwarf, "failed to read root CU header"); } } @@ -580,9 +576,9 @@ rust_crate_reader::rust_crate_reader(rust_dom *dom, die_mem(crate->get_debug_info(dom)), dies(die_mem, abbrevs) { - DLOG(dom, rust_log::MEM, "crate_reader on crate: 0x%" PRIxPTR, this); - DLOG(dom, rust_log::MEM, "debug_abbrev: 0x%" PRIxPTR, abbrev_mem.base); - DLOG(dom, rust_log::MEM, "debug_info: 0x%" PRIxPTR, die_mem.base); + DLOG(dom, mem, "crate_reader on crate: 0x%" PRIxPTR, this); + DLOG(dom, mem, "debug_abbrev: 0x%" PRIxPTR, abbrev_mem.base); + DLOG(dom, mem, "debug_info: 0x%" PRIxPTR, die_mem.base); // For now, perform diagnostics only. dies.dump(); } diff --git a/src/rt/rust_dom.cpp b/src/rt/rust_dom.cpp index 9512eeaa3cc..9c4faf56490 100644 --- a/src/rt/rust_dom.cpp +++ b/src/rt/rust_dom.cpp @@ -8,6 +8,7 @@ rust_dom::rust_dom(rust_kernel *kernel, interrupt_flag(0), root_crate(root_crate), _log(srv, this), + log_lvl(log_note), srv(srv), local_region(&srv->local_region), synchronized_region(&srv->synchronized_region), @@ -34,8 +35,7 @@ rust_dom::rust_dom(rust_kernel *kernel, } rust_dom::~rust_dom() { - DLOG(this, rust_log::MEM | rust_log::DOM, - "~rust_dom %s @0x%" PRIxPTR, name, (uintptr_t)this); + DLOG(this, dom, "~rust_dom %s @0x%" PRIxPTR, name, (uintptr_t)this); newborn_tasks.delete_all(); running_tasks.delete_all(); blocked_tasks.delete_all(); @@ -56,43 +56,18 @@ rust_dom::activate(rust_task *task) { } void -rust_dom::log(rust_task *task, uint32_t type_bits, char const *fmt, ...) { +rust_dom::log(rust_task* task, uint32_t level, char const *fmt, ...) { char buf[BUF_BYTES]; - if (_log.is_tracing(type_bits)) { - va_list args; - va_start(args, fmt); - vsnprintf(buf, sizeof(buf), fmt, args); - _log.trace_ln(task, type_bits, buf); - va_end(args); - } + va_list args; + va_start(args, fmt); + vsnprintf(buf, sizeof(buf), fmt, args); + _log.trace_ln(task, level, buf); + va_end(args); } void -rust_dom::log(uint32_t type_bits, char const *fmt, ...) { - char buf[BUF_BYTES]; - if (_log.is_tracing(type_bits)) { - va_list args; - va_start(args, fmt); - vsnprintf(buf, sizeof(buf), fmt, args); - _log.trace_ln(NULL, type_bits, buf); - va_end(args); - } -} - -void -rust_dom::logptr(char const *msg, uintptr_t ptrval) { - log(rust_log::MEM, "%s 0x%" PRIxPTR, msg, ptrval); -} - -template<typename T> void -rust_dom::logptr(char const *msg, T* ptrval) { - log(rust_log::MEM, "%s 0x%" PRIxPTR, msg, (uintptr_t)ptrval); -} - - -void rust_dom::fail() { - log(rust_log::DOM, "domain %s @0x%" PRIxPTR " root task failed", + log(NULL, log_err, "domain %s @0x%" PRIxPTR " root task failed", name, this); I(this, rval == 0); rval = 1; @@ -151,7 +126,7 @@ rust_dom::free(void *mem) { void rust_dom::free(void *mem, memory_region::memory_region_type type) { - DLOG(this, rust_log::MEM, "rust_dom::free(0x%" PRIxPTR ")", mem); + DLOG(this, mem, "rust_dom::free(0x%" PRIxPTR ")", mem); if (type == memory_region::LOCAL) { local_region.free(mem); } else if (type == memory_region::SYNCHRONIZED) { @@ -172,8 +147,7 @@ rust_dom::win32_require(LPCTSTR fn, BOOL ok) { NULL, err, MAKELANGID(LANG_NEUTRAL, SUBLANG_DEFAULT), (LPTSTR) &buf, 0, NULL ); - DLOG(this, rust_log::ERR, "%s failed with error %ld: %s", - fn, err, buf); + DLOG_ERR(this, dom, "%s failed with error %ld: %s", fn, err, buf); LocalFree((HLOCAL)buf); I(this, ok); } @@ -195,7 +169,7 @@ rust_dom::reap_dead_tasks() { if (task->ref_count == 0) { I(this, task->tasks_waiting_to_join.is_empty()); dead_tasks.remove(task); - DLOG(this, rust_log::TASK, + DLOG(this, task, "deleting unreferenced dead task %s @0x%" PRIxPTR, task->name, task); delete task; @@ -211,7 +185,7 @@ rust_dom::reap_dead_tasks() { void rust_dom::drain_incoming_message_queue(bool process) { rust_message *message; while (message_queue->dequeue(&message)) { - DLOG(this, rust_log::COMM, "<== receiving \"%s\" " PTR, + DLOG(this, comm, "<== receiving \"%s\" " PTR, message->label, message); if (process) { message->process(); @@ -244,12 +218,12 @@ rust_dom::schedule_task() { void rust_dom::log_state() { + if (log_rt_task < log_note) return; + if (!running_tasks.is_empty()) { - log(rust_log::TASK, "running tasks:"); + log(NULL, log_note, "running tasks:"); for (size_t i = 0; i < running_tasks.length(); i++) { - log(rust_log::TASK, - "\t task: %s @0x%" PRIxPTR - " timeout: %d", + log(NULL, log_note, "\t task: %s @0x%" PRIxPTR " timeout: %d", running_tasks[i]->name, running_tasks[i], running_tasks[i]->yield_timer.get_timeout()); @@ -257,20 +231,19 @@ rust_dom::log_state() { } if (!blocked_tasks.is_empty()) { - log(rust_log::TASK, "blocked tasks:"); + log(NULL, log_note, "blocked tasks:"); for (size_t i = 0; i < blocked_tasks.length(); i++) { - log(rust_log::TASK, - "\t task: %s @0x%" PRIxPTR ", blocked on: 0x%" PRIxPTR - " '%s'", + log(NULL, log_note, "\t task: %s @0x%" PRIxPTR ", blocked on: 0x%" + PRIxPTR " '%s'", blocked_tasks[i]->name, blocked_tasks[i], blocked_tasks[i]->cond, blocked_tasks[i]->cond_name); } } if (!dead_tasks.is_empty()) { - log(rust_log::TASK, "dead tasks:"); + log(NULL, log_note, "dead tasks:"); for (size_t i = 0; i < dead_tasks.length(); i++) { - log(rust_log::TASK, "\t task: %s 0x%" PRIxPTR ", ref_count: %d", + log(NULL, log_note, "\t task: %s 0x%" PRIxPTR ", ref_count: %d", dead_tasks[i]->name, dead_tasks[i], dead_tasks[i]->ref_count); } @@ -288,9 +261,8 @@ rust_dom::start_main_loop() { // Make sure someone is watching, to pull us out of infinite loops. rust_timer timer(this); - DLOG(this, rust_log::DOM, "started domain loop"); - DLOG(this, rust_log::DOM | rust_log::MEM, - "activate glue: " PTR ", exit glue: " PTR, + DLOG(this, dom, "started domain loop"); + DLOG(this, dom, "activate glue: " PTR ", exit glue: " PTR, root_crate->get_activate_glue(), root_crate->get_exit_task_glue()); while (number_of_live_tasks() > 0) { @@ -305,20 +277,18 @@ rust_dom::start_main_loop() { // for a minimum amount of time. if (scheduled_task == NULL) { - if (_log.is_tracing(rust_log::TASK)) { - log_state(); - } - DLOG(this, rust_log::TASK, + log_state(); + DLOG(this, task, "all tasks are blocked, scheduler yielding ..."); sync::sleep(100); - DLOG(this, rust_log::TASK, + DLOG(this, task, "scheduler resuming ..."); continue; } I(this, scheduled_task->running()); - DLOG(this, rust_log::TASK, + DLOG(this, task, "activating task %s 0x%" PRIxPTR ", sp=0x%" PRIxPTR ", ref_count=%d" @@ -333,7 +303,7 @@ rust_dom::start_main_loop() { activate(scheduled_task); - DLOG(this, rust_log::TASK, + DLOG(this, task, "returned from task %s @0x%" PRIxPTR " in state '%s', sp=0x%" PRIxPTR, scheduled_task->name, @@ -348,18 +318,16 @@ rust_dom::start_main_loop() { reap_dead_tasks(); } - DLOG(this, rust_log::DOM, + DLOG(this, dom, "terminated scheduler loop, reaping dead tasks ..."); while (dead_tasks.length() > 0) { if (message_queue->is_empty()) { - DLOG(this, rust_log::DOM, + DLOG(this, dom, "waiting for %d dead tasks to become dereferenced, " "scheduler yielding ...", dead_tasks.length()); - if (_log.is_tracing(rust_log::TASK)) { - log_state(); - } + log_state(); sync::yield(); } else { drain_incoming_message_queue(true); @@ -367,15 +335,14 @@ rust_dom::start_main_loop() { reap_dead_tasks(); } - DLOG(this, rust_log::DOM, "finished main-loop (dom.rval = %d)", rval); + DLOG(this, dom, "finished main-loop (dom.rval = %d)", rval); return rval; } rust_crate_cache * rust_dom::get_cache(rust_crate const *crate) { - DLOG(this, rust_log::CACHE, - "looking for crate-cache for crate 0x%" PRIxPTR, crate); + DLOG(this, cache, "looking for crate-cache for crate 0x%" PRIxPTR, crate); rust_crate_cache *cache = NULL; for (size_t i = 0; i < caches.length(); ++i) { rust_crate_cache *c = caches[i]; @@ -385,7 +352,7 @@ rust_dom::get_cache(rust_crate const *crate) { } } if (!cache) { - DLOG(this, rust_log::CACHE, + DLOG(this, cache, "making new crate-cache for crate 0x%" PRIxPTR, crate); cache = new (this) rust_crate_cache(this, crate); caches.push(cache); @@ -398,7 +365,7 @@ rust_task * rust_dom::create_task(rust_task *spawner, const char *name) { rust_task *task = new (this) rust_task (this, &newborn_tasks, spawner, name); - DLOG(this, rust_log::TASK, "created task: " PTR ", spawner: %s, name: %s", + DLOG(this, task, "created task: " PTR ", spawner: %s, name: %s", task, spawner ? spawner->name : "null", name); newborn_tasks.append(task); return task; diff --git a/src/rt/rust_dom.h b/src/rt/rust_dom.h index be3ca2f9f18..fa61aa79406 100644 --- a/src/rt/rust_dom.h +++ b/src/rt/rust_dom.h @@ -14,6 +14,7 @@ struct rust_dom : public kernel_owned<rust_dom>, rc_base<rust_dom> // glue. rust_crate const *root_crate; rust_log _log; + uint32_t log_lvl; rust_srv *srv; memory_region local_region; memory_region synchronized_region; @@ -47,16 +48,12 @@ struct rust_dom : public kernel_owned<rust_dom>, rc_base<rust_dom> // Only a pointer to 'name' is kept, so it must live as long as this // domain. rust_dom(rust_kernel *kernel, - rust_message_queue *message_queue, rust_srv *srv, - rust_crate const *root_crate, const char *name); + rust_message_queue *message_queue, rust_srv *srv, + rust_crate const *root_crate, const char *name); ~rust_dom(); void activate(rust_task *task); - void log(rust_task *task, uint32_t logbit, char const *fmt, ...); - void log(uint32_t logbit, char const *fmt, ...); + void log(rust_task *task, uint32_t level, char const *fmt, ...); rust_log & get_log(); - void logptr(char const *msg, uintptr_t ptrval); - template<typename T> - void logptr(char const *msg, T* ptrval); void fail(); void *malloc(size_t size); void *malloc(size_t size, memory_region::memory_region_type type); @@ -83,7 +80,6 @@ struct rust_dom : public kernel_owned<rust_dom>, rc_base<rust_dom> int start_main_loop(); void log_state(); - static void log_all_state(); rust_task *create_task(rust_task *spawner, const char *name); }; diff --git a/src/rt/rust_internal.h b/src/rt/rust_internal.h index 4a1f3e458b3..2676e9b9b19 100644 --- a/src/rt/rust_internal.h +++ b/src/rt/rust_internal.h @@ -48,8 +48,8 @@ extern "C" { #include "sync/lock_free_queue.h" class rust_dom; -class rust_log; class rust_task; +class rust_log; class rust_port; class rust_chan; struct rust_token; diff --git a/src/rt/rust_kernel.cpp b/src/rt/rust_kernel.cpp index 1eba9585ad6..e1629b4fbf3 100644 --- a/src/rt/rust_kernel.cpp +++ b/src/rt/rust_kernel.cpp @@ -1,11 +1,11 @@ #include "rust_internal.h" -#define KLOG(...) \ - do { \ - if (_log.is_tracing(rust_log::KERN)) { \ - log(rust_log::KERN, __VA_ARGS__); \ - } \ - } while(0) +#define KLOG(...) \ + do { \ + if (log_rt_kern >= log_note) { \ + log(log_note, __VA_ARGS__); \ + } \ + } while (0) rust_kernel::rust_kernel(rust_srv *srv) : _region(&srv->local_region), @@ -123,15 +123,13 @@ rust_kernel::is_deadlocked() { } void -rust_kernel::log(uint32_t type_bits, char const *fmt, ...) { +rust_kernel::log(uint32_t level, char const *fmt, ...) { char buf[BUF_BYTES]; - if (_log.is_tracing(type_bits)) { - va_list args; - va_start(args, fmt); - vsnprintf(buf, sizeof(buf), fmt, args); - _log.trace_ln(NULL, type_bits, buf); - va_end(args); - } + va_list args; + va_start(args, fmt); + vsnprintf(buf, sizeof(buf), fmt, args); + _log.trace_ln(NULL, level, buf); + va_end(args); } void diff --git a/src/rt/rust_kernel.h b/src/rt/rust_kernel.h index 3ad7b396575..42ca469e8f1 100644 --- a/src/rt/rust_kernel.h +++ b/src/rt/rust_kernel.h @@ -107,7 +107,7 @@ public: void join_all_domains(); void log_all_domain_state(); - void log(uint32_t type_bits, char const *fmt, ...); + void log(uint32_t level, char const *fmt, ...); virtual ~rust_kernel(); void *malloc(size_t size); diff --git a/src/rt/rust_log.cpp b/src/rt/rust_log.cpp index 8f074cdf3cb..5a2b7142d7b 100644 --- a/src/rt/rust_log.cpp +++ b/src/rt/rust_log.cpp @@ -1,5 +1,5 @@ /* - * Logging infrastructure that aims to support multi-threading, indentation + * Logging infrastructure that aims to support multi-threading, * and ansi colors. */ @@ -9,58 +9,6 @@ #include <stdlib.h> #include <string.h> -// FIXME somehow unify this with the parsing happening in rust_crate.cpp -static uint32_t -read_type_bit_mask() { - uint32_t bits = rust_log::ULOG | rust_log::ERR; - char *env_str = getenv("RUST_LOG"); - if (env_str) { - char *str = new char[strlen(env_str) + 2]; - str[0] = ','; - strcpy(str + 1, env_str); - - bits = rust_log::ULOG; - bits |= strstr(str, ",err") ? rust_log::ERR : 0; - bits |= strstr(str, ",mem") ? rust_log::MEM : 0; - bits |= strstr(str, ",comm") ? rust_log::COMM : 0; - bits |= strstr(str, ",task") ? rust_log::TASK : 0; - bits |= strstr(str, ",up") ? rust_log::UPCALL : 0; - bits |= strstr(str, ",dom") ? rust_log::DOM : 0; - bits |= strstr(str, ",trace") ? rust_log::TRACE : 0; - bits |= strstr(str, ",dwarf") ? rust_log::DWARF : 0; - bits |= strstr(str, ",cache") ? rust_log::CACHE : 0; - bits |= strstr(str, ",timer") ? rust_log::TIMER : 0; - bits |= strstr(str, ",gc") ? rust_log::GC : 0; - bits |= strstr(str, ",stdlib") ? rust_log::STDLIB : 0; - bits |= strstr(str, ",special") ? rust_log::SPECIAL : 0; - bits |= strstr(str, ",kern") ? rust_log::KERN : 0; - bits |= strstr(str, ",bt") ? rust_log::BT : 0; - bits |= strstr(str, ",all") ? rust_log::ALL : 0; - bits = strstr(str, ",none") ? 0 : bits; - - delete[] str; - } - return bits; -} - -rust_log::ansi_color -get_type_color(rust_log::log_type type) { - rust_log::ansi_color color = rust_log::WHITE; - if (type & rust_log::ERR) - color = rust_log::RED; - if (type & rust_log::MEM) - color = rust_log::YELLOW; - if (type & rust_log::UPCALL) - color = rust_log::GREEN; - if (type & rust_log::COMM) - color = rust_log::MAGENTA; - if (type & rust_log::DOM) - color = rust_log::LIGHTTEAL; - if (type & rust_log::TASK) - color = rust_log::LIGHTTEAL; - return color; -} - static const char * _foreground_colors[] = { "[37m", "[31m", "[1;31m", "[32m", "[1;32m", @@ -78,9 +26,7 @@ static uint32_t _last_thread_id; rust_log::rust_log(rust_srv *srv, rust_dom *dom) : _srv(srv), _dom(dom), - _type_bit_mask(read_type_bit_mask()), - _use_colors(getenv("RUST_COLOR_LOG")), - _indent(0) { + _use_colors(getenv("RUST_COLOR_LOG")) { } rust_log::~rust_log() { @@ -141,9 +87,6 @@ rust_log::trace_ln(uint32_t thread_id, char *prefix, char *message) { char buffer[BUF_BYTES] = ""; _log_lock.lock(); append_string(buffer, "%-34s", prefix); - for (uint32_t i = 0; i < _indent; i++) { - append_string(buffer, " "); - } append_string(buffer, "%s", message); if (_last_thread_id != thread_id) { _last_thread_id = thread_id; @@ -154,7 +97,7 @@ rust_log::trace_ln(uint32_t thread_id, char *prefix, char *message) { } void -rust_log::trace_ln(rust_task *task, char *message) { +rust_log::trace_ln(rust_task *task, uint32_t level, char *message) { #if defined(__WIN32__) uint32_t thread_id = 0; #else @@ -178,55 +121,16 @@ rust_log::trace_ln(rust_task *task, char *message) { trace_ln(thread_id, prefix, message); } -/** - * Traces a log message if the specified logging type is not filtered. - */ -void -rust_log::trace_ln(rust_task *task, uint32_t type_bits, char *message) { - trace_ln(task, get_type_color((rust_log::log_type) type_bits), - type_bits, message); -} - -/** - * Traces a log message using the specified ANSI color code. - */ -void -rust_log::trace_ln(rust_task *task, ansi_color color, - uint32_t type_bits, char *message) { - if (is_tracing(type_bits)) { - if (_use_colors) { - char buffer[BUF_BYTES] = ""; - append_string(buffer, color, "%s", message); - trace_ln(task, buffer); - } else { - trace_ln(task, message); - } - } -} - -void -rust_log::indent() { - _indent++; -} - -void -rust_log::outdent() { - _indent--; -} - -void -rust_log::reset_indent(uint32_t indent) { - _indent = indent; -} +// Reading log directives and setting log level vars struct mod_entry { const char* name; - int* state; + size_t* state; }; struct cratemap { - mod_entry* entries; - cratemap* children[1]; + const mod_entry* entries; + const cratemap* children[1]; }; struct log_directive { @@ -235,11 +139,12 @@ struct log_directive { }; const size_t max_log_directives = 255; +const size_t max_log_level = 1; +const size_t default_log_level = 0; // This is a rather ugly parser for strings in the form -// "crate1,crate2.mod3,crate3.x=2". Log levels range 0=err, 1=warn, 2=info, -// 3=debug. Default is 1. Words without an '=X' part set the log level for -// that module (and submodules) to 3. +// "crate1,crate2.mod3,crate3.x=1". Log levels are 0-1 for now, +// eventually we'll have 0-3. size_t parse_logging_spec(char* spec, log_directive* dirs) { size_t dir = 0; while (dir < max_log_directives && *spec) { @@ -251,10 +156,10 @@ size_t parse_logging_spec(char* spec, log_directive* dirs) { if (start == spec) {spec++; break;} *spec = '\0'; spec++; - size_t level = 3; + size_t level = max_log_level; if (cur == '=') { level = *spec - '0'; - if (level > 3) level = 1; + if (level > max_log_level) level = max_log_level; if (*spec) ++spec; } dirs[dir].name = start; @@ -267,10 +172,10 @@ size_t parse_logging_spec(char* spec, log_directive* dirs) { return dir; } -void update_crate_map(cratemap* map, log_directive* dirs, size_t n_dirs) { - // First update log levels for this crate - for (mod_entry* cur = map->entries; cur->name; cur++) { - size_t level = 1, longest_match = 0; +void update_module_map(const mod_entry* map, log_directive* dirs, + size_t n_dirs) { + for (const mod_entry* cur = map; cur->name; cur++) { + size_t level = default_log_level, longest_match = 0; for (size_t d = 0; d < n_dirs; d++) { if (strstr(cur->name, dirs[d].name) == cur->name && strlen(dirs[d].name) > longest_match) { @@ -280,24 +185,69 @@ void update_crate_map(cratemap* map, log_directive* dirs, size_t n_dirs) { } *cur->state = level; } +} +void update_crate_map(const cratemap* map, log_directive* dirs, + size_t n_dirs) { + // First update log levels for this crate + update_module_map(map->entries, dirs, n_dirs); // Then recurse on linked crates + // FIXME this does double work in diamond-shaped deps. could keep + // a set of visited addresses, if it turns out to be actually slow for (size_t i = 0; map->children[i]; i++) { update_crate_map(map->children[i], dirs, n_dirs); } } +// These are pseudo-modules used to control logging in the runtime. + +size_t log_rt_mem; +size_t log_rt_comm; +size_t log_rt_task; +size_t log_rt_dom; +size_t log_rt_trace; +size_t log_rt_dwarf; +size_t log_rt_cache; +size_t log_rt_upcall; +size_t log_rt_timer; +size_t log_rt_gc; +size_t log_rt_stdlib; +size_t log_rt_kern; +size_t log_rt_backtrace; +// Used to turn logging for rustboot-compiled code on and off +size_t log_rustboot; + +static const mod_entry _rt_module_map[] = + {{"rt.mem", &log_rt_mem}, + {"rt.comm", &log_rt_comm}, + {"rt.task", &log_rt_task}, + {"rt.dom", &log_rt_dom}, + {"rt.trace", &log_rt_trace}, + {"rt.dwarf", &log_rt_dwarf}, + {"rt.cache", &log_rt_cache}, + {"rt.upcall", &log_rt_upcall}, + {"rt.timer", &log_rt_timer}, + {"rt.gc", &log_rt_gc}, + {"rt.stdlib", &log_rt_stdlib}, + {"rt.kern", &log_rt_kern}, + {"rt.backtrace", &log_rt_backtrace}, + {"rustboot", &log_rustboot}, + {NULL, NULL}}; + void update_log_settings(void* crate_map, char* settings) { char* buffer = NULL; log_directive dirs[256]; - size_t dir = 0; + size_t n_dirs = 0; if (settings) { buffer = (char*)malloc(strlen(settings)); strcpy(buffer, settings); - dir = parse_logging_spec(buffer, &dirs[0]); + n_dirs = parse_logging_spec(buffer, &dirs[0]); } - update_crate_map((cratemap*)crate_map, &dirs[0], dir); + update_module_map(_rt_module_map, &dirs[0], n_dirs); + // FIXME check can be dropped when rustboot is gone + if (crate_map) + update_crate_map((const cratemap*)crate_map, &dirs[0], n_dirs); free(buffer); } diff --git a/src/rt/rust_log.h b/src/rt/rust_log.h index 150d239a74d..51019a89feb 100644 --- a/src/rt/rust_log.h +++ b/src/rt/rust_log.h @@ -1,28 +1,26 @@ #ifndef RUST_LOG_H #define RUST_LOG_H -#define DLOG(dom, mask, ...) \ - do { \ - rust_dom *_dom = dom; \ - uint32_t _mask = mask; \ - if ((_dom)->get_log().is_tracing(_mask)) { \ - (_dom)->log(_mask, __VA_ARGS__); \ - } \ - } while(0) -#define LOG(task, mask, ...) \ - DLOG((task)->dom, mask, __VA_ARGS__) -#define LOG_I(task, mask, ...) \ - do { \ - rust_task *_task = task; \ - uint32_t _mask = mask; \ - if ((_task)->dom->get_log().is_tracing(_mask)) { \ - (_task)->dom->get_log().reset_indent(0); \ - (_task)->dom->log(_mask, __VA_ARGS__); \ - (_task)->dom->get_log().indent(); \ - } \ - } while(0) -#define LOGPTR(dom, msg, ptrval) \ - DLOG(dom, rust_log::MEM, "%s 0x%" PRIxPTR, msg, ptrval) +const uint32_t log_err = 0; +const uint32_t log_note = 1; + +#define LOG(task, field, ...) \ + DLOG_LVL(log_note, task, task->dom, field, __VA_ARGS__) +#define LOG_ERR(task, field, ...) \ + DLOG_LVL(log_err, task, task->dom, field, __VA_ARGS__) +#define DLOG(dom, field, ...) \ + DLOG_LVL(log_note, NULL, dom, field, __VA_ARGS__) +#define DLOG_ERR(dom, field, ...) \ + DLOG_LVL(log_err, NULL, dom, field, __VA_ARGS__) +#define LOGPTR(dom, msg, ptrval) \ + DLOG_LVL(log_note, NULL, dom, mem, "%s 0x%" PRIxPTR, msg, ptrval) +#define DLOG_LVL(lvl, task, dom, field, ...) \ + do { \ + rust_dom* _d_ = dom; \ + if (log_rt_##field >= lvl && _d_->log_lvl >= lvl) { \ + _d_->log(task, lvl, __VA_ARGS__); \ + } \ + } while (0) class rust_dom; class rust_task; @@ -49,50 +47,33 @@ public: LIGHTTEAL }; - enum log_type { - ERR = 0x1, - MEM = 0x2, - COMM = 0x4, - TASK = 0x8, - DOM = 0x10, - ULOG = 0x20, - TRACE = 0x40, - DWARF = 0x80, - CACHE = 0x100, - UPCALL = 0x200, - TIMER = 0x400, - GC = 0x800, - STDLIB = 0x1000, - SPECIAL = 0x2000, - KERN = 0x4000, - BT = 0x8000, - ALL = 0xffffffff - }; - - void indent(); - void outdent(); - void reset_indent(uint32_t indent); + void trace_ln(rust_task *task, uint32_t level, char *message); void trace_ln(uint32_t thread_id, char *prefix, char *message); - void trace_ln(rust_task *task, uint32_t type_bits, char *message); - void trace_ln(rust_task *task, ansi_color color, - uint32_t type_bits, char *message); bool is_tracing(uint32_t type_bits); private: rust_srv *_srv; rust_dom *_dom; - uint32_t _type_bit_mask; bool _use_labels; bool _use_colors; - uint32_t _indent; void trace_ln(rust_task *task, char *message); }; -inline bool -rust_log::is_tracing(uint32_t type_bits) { - return type_bits & _type_bit_mask; -} - void update_log_settings(void* crate_map, char* settings); +extern size_t log_rt_mem; +extern size_t log_rt_comm; +extern size_t log_rt_task; +extern size_t log_rt_dom; +extern size_t log_rt_trace; +extern size_t log_rt_dwarf; +extern size_t log_rt_cache; +extern size_t log_rt_upcall; +extern size_t log_rt_timer; +extern size_t log_rt_gc; +extern size_t log_rt_stdlib; +extern size_t log_rt_kern; +extern size_t log_rt_backtrace; +extern size_t log_rustboot; + #endif /* RUST_LOG_H */ diff --git a/src/rt/rust_message.cpp b/src/rt/rust_message.cpp index dab13c091e2..19a1d8a367e 100644 --- a/src/rt/rust_message.cpp +++ b/src/rt/rust_message.cpp @@ -51,9 +51,6 @@ send(notification_type type, const char* label, memory_region *region = &target->message_queue->region; notify_message *message = new (region) notify_message(region, type, label, source, target); -// target->referent()->log(rust_log::COMM, -// "==> sending \"%s\" " PTR " in queue " PTR, -// label, message, &target->message_queue); target->message_queue->enqueue(message); } @@ -99,16 +96,13 @@ send(uint8_t *buffer, size_t buffer_sz, const char* label, data_message *message = new (region) data_message(region, buffer, buffer_sz, label, source, port); - source->referent()->log(rust_log::COMM, - "==> sending \"%s\"" PTR " in queue " PTR, - label, message, &port->message_queue); + LOG(source->referent(), comm, "==> sending \"%s\"" PTR " in queue " PTR, + label, message, &port->message_queue); port->message_queue->enqueue(message); } void data_message::process() { _port->referent()->remote_channel->send(_buffer); - // _target->referent()->log(rust_log::COMM, - // "<=== received data via message ==="); } void data_message::kernel_process() { diff --git a/src/rt/rust_port.cpp b/src/rt/rust_port.cpp index 178b46a702b..57d0b216836 100644 --- a/src/rt/rust_port.cpp +++ b/src/rt/rust_port.cpp @@ -5,17 +5,16 @@ rust_port::rust_port(rust_task *task, size_t unit_sz) : maybe_proxy<rust_port>(this), task(task), unit_sz(unit_sz), writers(task->dom), chans(task->dom) { - LOG(task, rust_log::MEM | rust_log::COMM, - "new rust_port(task=0x%" PRIxPTR ", unit_sz=%d) -> port=0x%" - PRIxPTR, (uintptr_t)task, unit_sz, (uintptr_t)this); + LOG(task, comm, + "new rust_port(task=0x%" PRIxPTR ", unit_sz=%d) -> port=0x%" + PRIxPTR, (uintptr_t)task, unit_sz, (uintptr_t)this); // Allocate a remote channel, for remote channel data. remote_channel = new (task->dom) rust_chan(task, this, unit_sz); } rust_port::~rust_port() { - LOG(task, rust_log::COMM | rust_log::MEM, - "~rust_port 0x%" PRIxPTR, (uintptr_t) this); + LOG(task, comm, "~rust_port 0x%" PRIxPTR, (uintptr_t) this); // log_state(); @@ -25,7 +24,7 @@ rust_port::~rust_port() { chan->disassociate(); if (chan->ref_count == 0) { - LOG(task, rust_log::COMM, + LOG(task, comm, "chan: 0x%" PRIxPTR " is dormant, freeing", chan); delete chan; } @@ -39,7 +38,7 @@ bool rust_port::receive(void *dptr) { rust_chan *chan = chans[i]; if (chan->buffer.is_empty() == false) { chan->buffer.dequeue(dptr); - LOG(task, rust_log::COMM, "<=== read data ==="); + LOG(task, comm, "<=== read data ==="); return true; } } @@ -47,12 +46,12 @@ bool rust_port::receive(void *dptr) { } void rust_port::log_state() { - LOG(task, rust_log::COMM, + LOG(task, comm, "rust_port: 0x%" PRIxPTR ", associated channel(s): %d", this, chans.length()); for (uint32_t i = 0; i < chans.length(); i++) { rust_chan *chan = chans[i]; - LOG(task, rust_log::COMM, + LOG(task, comm, "\tchan: 0x%" PRIxPTR ", size: %d, remote: %s", chan, chan->buffer.size(), diff --git a/src/rt/rust_srv.cpp b/src/rt/rust_srv.cpp index 0453abce6cd..4573bd01804 100644 --- a/src/rt/rust_srv.cpp +++ b/src/rt/rust_srv.cpp @@ -11,11 +11,7 @@ rust_srv::rust_srv() : // Nop. } -rust_srv::~rust_srv() { -// char msg[BUF_BYTES]; -// snprintf(msg, sizeof(msg), "~rust_srv %" PRIxPTR, (uintptr_t) this); -// log(msg); -} +rust_srv::~rust_srv() {} void rust_srv::free(void *p) { diff --git a/src/rt/rust_task.cpp b/src/rt/rust_task.cpp index c2fefef0d99..8d7157ed77c 100644 --- a/src/rt/rust_task.cpp +++ b/src/rt/rust_task.cpp @@ -102,24 +102,23 @@ rust_task::rust_task(rust_dom *dom, rust_task_list *state, rust_task::~rust_task() { - DLOG(dom, rust_log::MEM|rust_log::TASK, - "~rust_task %s @0x%" PRIxPTR ", refcnt=%d", - name, (uintptr_t)this, ref_count); + DLOG(dom, task, "~rust_task %s @0x%" PRIxPTR ", refcnt=%d", + name, (uintptr_t)this, ref_count); /* for (uintptr_t fp = get_fp(); fp; fp = get_previous_fp(fp)) { frame_glue_fns *glue_fns = get_frame_glue_fns(fp); - DLOG(dom, rust_log::MEM|rust_log::TASK, + DLOG(dom, task, "~rust_task, frame fp=0x%" PRIxPTR ", glue_fns=0x%" PRIxPTR, fp, glue_fns); if (glue_fns) { - DLOG(dom, rust_log::MEM|rust_log::TASK, + DLOG(dom, task, "~rust_task, mark_glue=0x%" PRIxPTR, glue_fns->mark_glue); - DLOG(dom, rust_log::MEM|rust_log::TASK, + DLOG(dom, task, "~rust_task, drop_glue=0x%" PRIxPTR, glue_fns->drop_glue); - DLOG(dom, rust_log::MEM|rust_log::TASK, + DLOG(dom, task, "~rust_task, reloc_glue=0x%" PRIxPTR, glue_fns->reloc_glue); } @@ -266,28 +265,26 @@ rust_task::grow(size_t n_frame_bytes) uintptr_t old_bottom = (uintptr_t) &old_stk->data[0]; uintptr_t rust_sp_disp = old_top - this->rust_sp; size_t ssz = old_top - old_bottom; - DLOG(dom, rust_log::MEM|rust_log::TASK|rust_log::UPCALL, - "upcall_grow_task(%" PRIdPTR - "), old size %" PRIdPTR - " bytes (old lim: 0x%" PRIxPTR ")", - n_frame_bytes, ssz, old_top); + DLOG(dom, task, "upcall_grow_task(%" PRIdPTR + "), old size %" PRIdPTR " bytes (old lim: 0x%" PRIxPTR ")", + n_frame_bytes, ssz, old_top); ssz *= 2; if (ssz < n_frame_bytes) ssz = n_frame_bytes; ssz = next_power_of_two(ssz); - DLOG(dom, rust_log::MEM|rust_log::TASK, "upcall_grow_task growing stk 0x%" - PRIxPTR " to %d bytes", old_stk, ssz); + DLOG(dom, task, "upcall_grow_task growing stk 0x%" + PRIxPTR " to %d bytes", old_stk, ssz); stk_seg *nstk = new_stk(dom, ssz); uintptr_t new_top = (uintptr_t) &nstk->data[ssz]; size_t n_copy = old_top - old_bottom; - DLOG(dom, rust_log::MEM|rust_log::TASK, - "copying %d bytes of stack from [0x%" PRIxPTR ", 0x%" PRIxPTR "]" - " to [0x%" PRIxPTR ", 0x%" PRIxPTR "]", - n_copy, - old_bottom, old_bottom + n_copy, - new_top - n_copy, new_top); + DLOG(dom, task, + "copying %d bytes of stack from [0x%" PRIxPTR ", 0x%" PRIxPTR "]" + " to [0x%" PRIxPTR ", 0x%" PRIxPTR "]", + n_copy, + old_bottom, old_bottom + n_copy, + new_top - n_copy, new_top); VALGRIND_MAKE_MEM_DEFINED((void*)old_bottom, n_copy); memcpy((void*)(new_top - n_copy), (void*)old_bottom, n_copy); @@ -296,7 +293,7 @@ rust_task::grow(size_t n_frame_bytes) this->stk = nstk; this->rust_sp = new_top - rust_sp_disp; - DLOG(dom, rust_log::MEM|rust_log::TASK, "processing relocations"); + DLOG(dom, task, "processing relocations"); // FIXME (issue #32): this is the most ridiculously crude // relocation scheme ever. Try actually, you know, writing out @@ -305,14 +302,13 @@ rust_task::grow(size_t n_frame_bytes) for (uintptr_t* p = (uintptr_t*)(new_top - n_copy); p < (uintptr_t*)new_top; ++p) { if (old_bottom <= *p && *p < old_top) { - //DLOG(dom, rust_log::MEM, "relocating pointer 0x%" PRIxPTR + //DLOG(dom, mem, "relocating pointer 0x%" PRIxPTR // " by %d bytes", *p, (new_top - old_top)); n_relocs++; *p += (new_top - old_top); } } - DLOG(dom, rust_log::MEM|rust_log::TASK, - "processed %d relocations", n_relocs); + DLOG(dom, task, "processed %d relocations", n_relocs); del_stk(dom, old_stk); LOGPTR(dom, "grown stk limit", new_top); #endif @@ -342,11 +338,11 @@ rust_task::run_after_return(size_t nargs, uintptr_t glue) sp = align_down(sp - nargs * sizeof(uintptr_t)); uintptr_t *retpc = ((uintptr_t *) sp) - 1; - DLOG(dom, rust_log::TASK|rust_log::MEM, - "run_after_return: overwriting retpc=0x%" PRIxPTR - " @ runtime_sp=0x%" PRIxPTR - " with glue=0x%" PRIxPTR, - *retpc, sp, glue); + DLOG(dom, task, + "run_after_return: overwriting retpc=0x%" PRIxPTR + " @ runtime_sp=0x%" PRIxPTR + " with glue=0x%" PRIxPTR, + *retpc, sp, glue); // Move the current return address (which points into rust code) // onto the rust stack and pretend we just called into the glue. @@ -363,7 +359,7 @@ rust_task::run_on_resume(uintptr_t glue) // Inject glue as resume address in the suspended frame. uintptr_t* rsp = (uintptr_t*) rust_sp; rsp += n_callee_saves; - DLOG(dom, rust_log::TASK|rust_log::MEM, + DLOG(dom, task, "run_on_resume: overwriting retpc=0x%" PRIxPTR " @ rust_sp=0x%" PRIxPTR " with glue=0x%" PRIxPTR, @@ -378,8 +374,7 @@ rust_task::yield(size_t nargs) { void rust_task::yield(size_t nargs, size_t time_in_us) { - log(rust_log::TASK, - "task %s @0x%" PRIxPTR " yielding for %d us", + LOG(this, task, "task %s @0x%" PRIxPTR " yielding for %d us", name, this, time_in_us); yield_timer.reset(time_in_us); run_after_return(nargs, dom->root_crate->get_yield_glue()); @@ -401,21 +396,21 @@ rust_task::kill() { // Note the distinction here: kill() is when you're in an upcall // from task A and want to force-fail task B, you do B->kill(). // If you want to fail yourself you do self->fail(upcall_nargs). - log(rust_log::TASK, "killing task %s @0x%" PRIxPTR, name, this); + LOG(this, task, "killing task %s @0x%" PRIxPTR, name, this); // Unblock the task so it can unwind. unblock(); if (this == dom->root_task) dom->fail(); - log(rust_log::TASK, "preparing to unwind task: 0x%" PRIxPTR, this); + LOG(this, task, "preparing to unwind task: 0x%" PRIxPTR, this); run_on_resume(dom->root_crate->get_unwind_glue()); } void rust_task::fail(size_t nargs) { // See note in ::kill() regarding who should call this. - DLOG(dom, rust_log::TASK, "task %s @0x%" PRIxPTR " failing", name, this); + DLOG(dom, task, "task %s @0x%" PRIxPTR " failing", name, this); backtrace(); // Unblock the task so it can unwind. unblock(); @@ -423,10 +418,10 @@ rust_task::fail(size_t nargs) { dom->fail(); run_after_return(nargs, dom->root_crate->get_unwind_glue()); if (supervisor) { - DLOG(dom, rust_log::TASK, - "task %s @0x%" PRIxPTR - " propagating failure to supervisor %s @0x%" PRIxPTR, - name, this, supervisor->name, supervisor); + DLOG(dom, task, + "task %s @0x%" PRIxPTR + " propagating failure to supervisor %s @0x%" PRIxPTR, + name, this, supervisor->name, supervisor); supervisor->kill(); } } @@ -434,7 +429,7 @@ rust_task::fail(size_t nargs) { void rust_task::gc(size_t nargs) { - DLOG(dom, rust_log::TASK|rust_log::MEM, + DLOG(dom, task, "task %s @0x%" PRIxPTR " garbage collecting", name, this); run_after_return(nargs, dom->root_crate->get_gc_glue()); } @@ -442,7 +437,7 @@ rust_task::gc(size_t nargs) void rust_task::unsupervise() { - DLOG(dom, rust_log::TASK, + DLOG(dom, task, "task %s @0x%" PRIxPTR " disconnecting from supervisor %s @0x%" PRIxPTR, name, this, supervisor->name, supervisor); @@ -452,7 +447,7 @@ rust_task::unsupervise() void rust_task::notify_tasks_waiting_to_join() { while (tasks_waiting_to_join.is_empty() == false) { - log(rust_log::TASK, "notify_tasks_waiting_to_join: %d", + LOG(this, task, "notify_tasks_waiting_to_join: %d", tasks_waiting_to_join.size()); maybe_proxy<rust_task> *waiting_task = 0; tasks_waiting_to_join.pop(&waiting_task); @@ -551,10 +546,9 @@ rust_task::malloc(size_t sz, type_desc *td) return mem; if (td) { gc_alloc *gcm = (gc_alloc*) mem; - DLOG(dom, rust_log::TASK|rust_log::MEM|rust_log::GC, - "task %s @0x%" PRIxPTR - " allocated %d GC bytes = 0x%" PRIxPTR, - name, (uintptr_t)this, sz, gcm); + DLOG(dom, task, "task %s @0x%" PRIxPTR + " allocated %d GC bytes = 0x%" PRIxPTR, + name, (uintptr_t)this, sz, gcm); memset((void*) gcm, 0, sizeof(gc_alloc)); link_gc(gcm); gcm->ctrl_word = (uintptr_t)td; @@ -575,10 +569,9 @@ rust_task::realloc(void *data, size_t sz, bool is_gc) unlink_gc(gcm); sz += sizeof(gc_alloc); gcm = (gc_alloc*) dom->realloc((void*)gcm, sz); - DLOG(dom, rust_log::TASK|rust_log::MEM|rust_log::GC, - "task %s @0x%" PRIxPTR - " reallocated %d GC bytes = 0x%" PRIxPTR, - name, (uintptr_t)this, sz, gcm); + DLOG(dom, task, "task %s @0x%" PRIxPTR + " reallocated %d GC bytes = 0x%" PRIxPTR, + name, (uintptr_t)this, sz, gcm); if (!gcm) return gcm; link_gc(gcm); @@ -598,9 +591,9 @@ rust_task::free(void *p, bool is_gc) if (is_gc) { gc_alloc *gcm = (gc_alloc*)(((char *)p) - sizeof(gc_alloc)); unlink_gc(gcm); - DLOG(dom, rust_log::TASK|rust_log::MEM|rust_log::GC, - "task %s @0x%" PRIxPTR " freeing GC memory = 0x%" PRIxPTR, - name, (uintptr_t)this, gcm); + DLOG(dom, mem, + "task %s @0x%" PRIxPTR " freeing GC memory = 0x%" PRIxPTR, + name, (uintptr_t)this, gcm); dom->free(gcm); } else { dom->free(p); @@ -610,7 +603,7 @@ rust_task::free(void *p, bool is_gc) void rust_task::transition(rust_task_list *src, rust_task_list *dst) { I(dom, state == src); - DLOG(dom, rust_log::TASK, + DLOG(dom, task, "task %s " PTR " state change '%s' -> '%s'", name, (uintptr_t)this, src->name, dst->name); src->remove(this); @@ -620,7 +613,7 @@ rust_task::transition(rust_task_list *src, rust_task_list *dst) { void rust_task::block(rust_cond *on, const char* name) { - log(rust_log::TASK, "Blocking on 0x%" PRIxPTR ", cond: 0x%" PRIxPTR, + LOG(this, task, "Blocking on 0x%" PRIxPTR ", cond: 0x%" PRIxPTR, (uintptr_t) on, (uintptr_t) cond); A(dom, cond == NULL, "Cannot block an already blocked task."); A(dom, on != NULL, "Cannot block on a NULL object."); @@ -633,7 +626,7 @@ rust_task::block(rust_cond *on, const char* name) { void rust_task::wakeup(rust_cond *from) { A(dom, cond != NULL, "Cannot wake up unblocked task."); - log(rust_log::TASK, "Blocked on 0x%" PRIxPTR " woken up on 0x%" PRIxPTR, + LOG(this, task, "Blocked on 0x%" PRIxPTR " woken up on 0x%" PRIxPTR, (uintptr_t) cond, (uintptr_t) from); A(dom, cond == from, "Cannot wake up blocked task on wrong condition."); @@ -658,36 +651,22 @@ rust_crate_cache * rust_task::get_crate_cache(rust_crate const *curr_crate) { if (cache && cache->crate != curr_crate) { - DLOG(dom, rust_log::TASK, "switching task crate-cache to crate 0x%" - PRIxPTR, curr_crate); + DLOG(dom, task, "switching task crate-cache to crate 0x%" + PRIxPTR, curr_crate); cache->deref(); cache = NULL; } if (!cache) { - DLOG(dom, rust_log::TASK, "fetching cache for current crate"); + DLOG(dom, task, "fetching cache for current crate"); cache = dom->get_cache(curr_crate); } return cache; } void -rust_task::log(uint32_t type_bits, char const *fmt, ...) { - char buf[BUF_BYTES]; - if (dom->get_log().is_tracing(type_bits)) { - va_list args; - va_start(args, fmt); - vsnprintf(buf, sizeof(buf), fmt, args); - dom->get_log().trace_ln(this, type_bits, buf); - va_end(args); - } -} - -void rust_task::backtrace() { - if (!dom->get_log().is_tracing(rust_log::BT)) - return; - + if (!log_rt_backtrace) return; #ifndef __WIN32__ void *call_stack[256]; int nframes = ::backtrace(call_stack, 256); diff --git a/src/rt/rust_task.h b/src/rt/rust_task.h index 5318ab71edf..7d4ed22139c 100644 --- a/src/rt/rust_task.h +++ b/src/rt/rust_task.h @@ -82,8 +82,6 @@ rust_task : public maybe_proxy<rust_task>, void check_active() { I(dom, dom->curr_task == this); } void check_suspended() { I(dom, dom->curr_task != this); } - void log(uint32_t type_bits, char const *fmt, ...); - // Print a backtrace, if the "bt" logging option is on. void backtrace(); diff --git a/src/rt/rust_task_list.cpp b/src/rt/rust_task_list.cpp index dd6aaeb59af..bb1224afa20 100644 --- a/src/rt/rust_task_list.cpp +++ b/src/rt/rust_task_list.cpp @@ -7,10 +7,10 @@ rust_task_list::rust_task_list (rust_dom *dom, const char* name) : void rust_task_list::delete_all() { - DLOG(dom, rust_log::TASK, "deleting all %s tasks", name); + DLOG(dom, task, "deleting all %s tasks", name); while (is_empty() == false) { rust_task *task = pop_value(); - DLOG(dom, rust_log::TASK, "deleting task " PTR, task); + DLOG(dom, task, "deleting task " PTR, task); delete task; } } diff --git a/src/rt/rust_timer.cpp b/src/rt/rust_timer.cpp index 40044e03678..79cb1615bbc 100644 --- a/src/rt/rust_timer.cpp +++ b/src/rt/rust_timer.cpp @@ -30,7 +30,7 @@ timer_loop(void *ptr) { // We were handed the rust_timer that owns us. rust_timer *timer = (rust_timer *)ptr; rust_dom *dom = timer->dom; - DLOG(dom, rust_log::TIMER, "in timer 0x%" PRIxPTR, (uintptr_t)timer); + DLOG(dom, timer, "in timer 0x%" PRIxPTR, (uintptr_t)timer); size_t ms = TIME_SLICE_IN_MS; while (!timer->exit_flag) { @@ -39,7 +39,7 @@ timer_loop(void *ptr) { #else usleep(ms * 1000); #endif - DLOG(dom, rust_log::TIMER, "timer 0x%" PRIxPTR + DLOG(dom, timer, "timer 0x%" PRIxPTR " interrupting domain 0x%" PRIxPTR, (uintptr_t) timer, (uintptr_t) dom); dom->interrupt_flag = 1; @@ -54,7 +54,7 @@ timer_loop(void *ptr) { rust_timer::rust_timer(rust_dom *dom) : dom(dom), exit_flag(0) { - DLOG(dom, rust_log::TIMER, "creating timer for domain 0x%" PRIxPTR, dom); + DLOG(dom, timer, "creating timer for domain 0x%" PRIxPTR, dom); #if defined(__WIN32__) thread = CreateThread(NULL, 0, timer_loop, this, 0, NULL); dom->win32_require("CreateThread", thread != NULL); diff --git a/src/rt/rust_upcall.cpp b/src/rt/rust_upcall.cpp index b022b8531a5..9178aac2d30 100644 --- a/src/rt/rust_upcall.cpp +++ b/src/rt/rust_upcall.cpp @@ -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); diff --git a/src/rt/rust_util.h b/src/rt/rust_util.h index b36b776372a..8e4bf26c474 100644 --- a/src/rt/rust_util.h +++ b/src/rt/rust_util.h @@ -24,18 +24,16 @@ ptr_vec<T>::ptr_vec(rust_dom *dom) : data(new (dom) T*[alloc]) { I(dom, data); - DLOG(dom, rust_log::MEM, - "new ptr_vec(data=0x%" PRIxPTR ") -> 0x%" PRIxPTR, - (uintptr_t)data, (uintptr_t)this); + DLOG(dom, mem, "new ptr_vec(data=0x%" PRIxPTR ") -> 0x%" PRIxPTR, + (uintptr_t)data, (uintptr_t)this); } template <typename T> ptr_vec<T>::~ptr_vec() { I(dom, data); - DLOG(dom, rust_log::MEM, - "~ptr_vec 0x%" PRIxPTR ", data=0x%" PRIxPTR, - (uintptr_t)this, (uintptr_t)data); + DLOG(dom, mem, "~ptr_vec 0x%" PRIxPTR ", data=0x%" PRIxPTR, + (uintptr_t)this, (uintptr_t)data); I(dom, fill == 0); dom->free(data); } |