Some pretty printing in the runtime.

6 files changed, 66 insertions, 18 deletions

diff --git a/src/rt/circular_buffer.cpp b/src/rt/circular_buffer.cpp
index a93f2572..dbf5059b 100644
--- a/src/rt/circular_buffer.cpp
+++ b/src/rt/circular_buffer.cpp
@@ -31,9 +31,7 @@ circular_buffer::circular_buffer(rust_dom *dom, size_t unit_sz) :
 }
 
 circular_buffer::~circular_buffer() {
-    dom->log(rust_log::MEM | rust_log::COMM,
-             "~circular_buffer 0x%" PRIxPTR,
-             this);
+    dom->log(rust_log::MEM, "~circular_buffer 0x%" PRIxPTR, this);
     I(dom, _buffer);
     W(dom, _unread == 0, "~circular_buffer with unread messages.");
     dom->free(_buffer);
diff --git a/src/rt/rust_dom.cpp b/src/rt/rust_dom.cpp
index 97e32746..f0739097 100644
--- a/src/rt/rust_dom.cpp
+++ b/src/rt/rust_dom.cpp
@@ -38,7 +38,8 @@ static void
 del_all_tasks(rust_dom *dom, ptr_vec<rust_task> *v) {
     I(dom, v);
     while (v->length()) {
-        dom->log(rust_log::TASK, "deleting task %" PRIdPTR, v->length() - 1);
+        dom->log(rust_log::TASK, "deleting task 0x%" PRIdPTR,
+                 v->length() - 1);
         delete v->pop();
     }
 }
@@ -48,16 +49,18 @@ rust_dom::delete_proxies() {
     rust_task *task;
     rust_proxy<rust_task> *task_proxy;
     while (_task_proxies.pop(&task, &task_proxy)) {
-        log(rust_log::TASK, "deleting proxy %" PRIxPTR
-                            " in dom %" PRIxPTR, task_proxy, task_proxy->dom);
+        log(rust_log::TASK, "deleting proxy 0x%" PRIxPTR
+                            " in dom 0x%" PRIxPTR,
+                            task_proxy, task_proxy->dom);
         delete task_proxy;
     }
 
     rust_port *port;
     rust_proxy<rust_port> *port_proxy;
     while (_port_proxies.pop(&port, &port_proxy)) {
-        log(rust_log::TASK, "deleting proxy %" PRIxPTR
-                            " in dom %" PRIxPTR, port_proxy, port_proxy->dom);
+        log(rust_log::TASK, "deleting proxy 0x%" PRIxPTR
+                            " in dom 0x%" PRIxPTR,
+                            port_proxy, port_proxy->dom);
         delete port_proxy;
     }
 }
@@ -251,10 +254,12 @@ rust_dom::reap_dead_tasks() {
  */
 void rust_dom::send_message(rust_message *message) {
     log(rust_log::COMM, "==> enqueueing \"%s\" 0x%" PRIxPTR
-                        " in queue 0x%" PRIxPTR,
+                        " in queue 0x%" PRIxPTR
+                        " in domain 0x%" PRIxPTR,
                         message->label,
                         message,
-                        &_incoming_message_queue);
+                        &_incoming_message_queue,
+                        this);
     A(this, message->dom == this, "Message owned by non-local domain.");
     _incoming_message_queue.enqueue(message);
     _incoming_message_pending.signal();
@@ -358,7 +363,8 @@ rust_dom::log_state() {
     if (!dead_tasks.is_empty()) {
         log(rust_log::TASK, "dead tasks:");
         for (size_t i = 0; i < dead_tasks.length(); i++) {
-            log(rust_log::TASK, "\t task: 0x%" PRIxPTR, dead_tasks[i]);
+            log(rust_log::TASK, "\t task: 0x%" PRIxPTR ", ref_count: %d",
+                dead_tasks[i], dead_tasks[i]->ref_count);
         }
     }
 }
@@ -401,8 +407,14 @@ rust_dom::start_main_loop()
         I(this, scheduled_task->running());
 
         log(rust_log::TASK,
-                 "activating task 0x%" PRIxPTR ", sp=0x%" PRIxPTR,
-                 (uintptr_t)scheduled_task, scheduled_task->rust_sp);
+                 "activating task 0x%" PRIxPTR
+                 ", sp=0x%" PRIxPTR
+                 ", ref_count=%d"
+                 ", state: %s",
+                 (uintptr_t)scheduled_task,
+                 scheduled_task->rust_sp,
+                 scheduled_task->ref_count,
+                 scheduled_task->state_str());
 
         interrupt_flag = 0;
 
diff --git a/src/rt/rust_port.cpp b/src/rt/rust_port.cpp
index 0a5b7ee7..bd9af6f9 100644
--- a/src/rt/rust_port.cpp
+++ b/src/rt/rust_port.cpp
@@ -17,6 +17,8 @@ rust_port::~rust_port() {
     task->log(rust_log::COMM | rust_log::MEM,
               "~rust_port 0x%" PRIxPTR, (uintptr_t) this);
 
+    log_state();
+
     // Disassociate channels from this port.
     while (chans.is_empty() == false) {
         chans.pop()->disassociate();
@@ -27,6 +29,20 @@ rust_port::~rust_port() {
     delete remote_channel;
 }
 
+void rust_port::log_state() {
+    task->log(rust_log::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];
+        task->log(rust_log::COMM,
+            "\tchan: 0x%" PRIxPTR ", data pending: %s, remote: %s",
+            chan,
+            !chan->buffer.is_empty() ? "yes" : "no",
+            chan == remote_channel ? "yes" : "no");
+    }
+}
+
 //
 // Local Variables:
 // mode: C++
diff --git a/src/rt/rust_port.h b/src/rt/rust_port.h
index 49a89437..3330701a 100644
--- a/src/rt/rust_port.h
+++ b/src/rt/rust_port.h
@@ -15,6 +15,7 @@ public:
 
     rust_port(rust_task *task, size_t unit_sz);
     ~rust_port();
+    void log_state();
 };
 
 //
diff --git a/src/rt/rust_task.cpp b/src/rt/rust_task.cpp
index 9f4fa611..63724bbb 100644
--- a/src/rt/rust_task.cpp
+++ b/src/rt/rust_task.cpp
@@ -333,6 +333,7 @@ rust_task::kill() {
     if (this == dom->root_task)
         dom->fail();
 
+    log(rust_log::TASK, "preparing to unwind task: 0x%" PRIxPTR, this);
     run_on_resume(dom->root_crate->get_unwind_glue());
 }
 
@@ -515,6 +516,10 @@ rust_task::free(void *p, bool is_gc)
     }
 }
 
+const char *
+rust_task::state_str() {
+    return dom->state_vec_name(state);
+}
 
 void
 rust_task::transition(ptr_vec<rust_task> *src, ptr_vec<rust_task> *dst)
diff --git a/src/rt/rust_upcall.cpp b/src/rt/rust_upcall.cpp
index 574cb703..5040a157 100644
--- a/src/rt/rust_upcall.cpp
+++ b/src/rt/rust_upcall.cpp
@@ -7,9 +7,11 @@
     (task)->dom->get_log().reset_indent(0);                 \
     (task)->log(rust_log::UPCALL,                           \
                 "> UPCALL %s - task: 0x%" PRIxPTR           \
-                " retpc: x%" PRIxPTR,                       \
+                " retpc: x%" PRIxPTR                        \
+                " ref_count: %d",                           \
                 __FUNCTION__,                               \
-                (task), __builtin_return_address(0));       \
+                (task), __builtin_return_address(0),        \
+                (task->ref_count));                         \
     (task)->dom->get_log().indent();
 #else
 #define LOG_UPCALL_ENTRY(task)                              \
@@ -19,6 +21,20 @@
     (task)->dom->get_log().indent();
 #endif
 
+void
+log_task_state(rust_task *task, maybe_proxy<rust_task> *target) {
+    rust_task *delegate = target->delegate();
+    if (target->is_proxy()) {
+        task->log(rust_log::TASK,
+                  "remote task: 0x%" PRIxPTR ", ref_count: %d state: %s",
+                  delegate, delegate->ref_count, delegate->state_str());
+    } else {
+        task->log(rust_log::TASK,
+                  "local task: 0x%" PRIxPTR ", ref_count: %d state: %s",
+                  delegate, delegate->ref_count, delegate->state_str());
+    }
+}
+
 extern "C" CDECL char const *str_buf(rust_task *task, rust_str *s);
 
 extern "C" void upcall_grow_task(rust_task *task, size_t n_frame_bytes) {
@@ -29,14 +45,13 @@ extern "C" void upcall_grow_task(rust_task *task, size_t n_frame_bytes) {
 extern "C" CDECL void upcall_log_int(rust_task *task, int32_t i) {
     LOG_UPCALL_ENTRY(task);
     task->log(rust_log::UPCALL | rust_log::ULOG,
-              "upcall log_int(0x%" PRIx32 " = %" PRId32 " = '%c')", i, i,
-              (char) i);
+              "rust: %" PRId32 " (0x%" PRIx32 ")", i, i);
 }
 
 extern "C" CDECL void upcall_log_str(rust_task *task, rust_str *str) {
     LOG_UPCALL_ENTRY(task);
     const char *c = str_buf(task, str);
-    task->log(rust_log::UPCALL | rust_log::ULOG, "upcall log_str(\"%s\")", c);
+    task->log(rust_log::UPCALL | rust_log::ULOG, "rust: %s", c);
 }
 
 extern "C" CDECL void upcall_trace_word(rust_task *task, uintptr_t i) {
@@ -219,6 +234,7 @@ extern "C" CDECL void upcall_fail(rust_task *task, char const *expr,
 extern "C" CDECL void
 upcall_kill(rust_task *task, maybe_proxy<rust_task> *target) {
     LOG_UPCALL_ENTRY(task);
+    log_task_state(task, target);
     rust_task *target_task = target->delegate();
 
     task->log(rust_log::UPCALL | rust_log::TASK,