improve logging related to GC and places

src/racket/gc2/gc2.h

@@ -31,7 +31,9 @@ typedef int (*Fixup_Proc)(void *obj);
 typedef int (*Fixup2_Proc)(void *obj, struct NewGC *);
 typedef void (*GC_collect_start_callback_Proc)(void);
 typedef void (*GC_collect_end_callback_Proc)(void);
-typedef void (*GC_collect_inform_callback_Proc)(int major_gc, intptr_t pre_used, intptr_t post_used);
+typedef void (*GC_collect_inform_callback_Proc)(int master_gc, int major_gc, 
+                                                intptr_t pre_used, intptr_t post_used,
+                                                intptr_t pre_admin, intptr_t post_admin);
 typedef uintptr_t (*GC_get_thread_stack_base_Proc)(void);
 /* 
    Types of the traversal procs (supplied by Racket); see overview in README

src/racket/gc2/newgc.c

@@ -275,7 +275,7 @@ GC_collect_end_callback_Proc GC_set_collect_end_callback(GC_collect_end_callback
   gc->GC_collect_end_callback = func;
   return old;
 }
-void GC_set_collect_inform_callback(void (*func)(int major_gc, intptr_t pre_used, intptr_t post_used)) {
+void GC_set_collect_inform_callback(GC_collect_inform_callback_Proc func) {
   NewGC *gc = GC_get_GC();
   gc->GC_collect_inform_callback = func;
 }
@@ -4134,6 +4134,7 @@ static void garbage_collect(NewGC *gc, int force_full, int switching_master)
 {
   uintptr_t old_mem_use;
   uintptr_t old_gen0;
+  uintptr_t old_mem_allocated;
 
   int next_gc_full;
 #ifdef MZ_USE_PLACES
@@ -4142,6 +4143,7 @@ static void garbage_collect(NewGC *gc, int force_full, int switching_master)
 
   old_mem_use = gc->memory_in_use;
   old_gen0    = gc->gen0.current_size;
+  old_mem_allocated = mmu_memory_allocated(gc->mmu);
 
   TIME_DECLS();
 
@@ -4348,8 +4350,15 @@ static void garbage_collect(NewGC *gc, int force_full, int switching_master)
   /* inform the system (if it wants us to) that we're done with collection */
   if (gc->GC_collect_end_callback)
     gc->GC_collect_end_callback();
-  if (gc->GC_collect_inform_callback)
+  if (gc->GC_collect_inform_callback) {
-    gc->GC_collect_inform_callback(gc->gc_full, old_mem_use + old_gen0, gc->memory_in_use);
+    int is_master = 0;
+#ifdef MZ_USE_PLACES
+    is_master = (gc == MASTERGC);
+#endif
+    gc->GC_collect_inform_callback(is_master, gc->gc_full, 
+                                   old_mem_use + old_gen0, gc->memory_in_use, 
+                                   old_mem_allocated, mmu_memory_allocated(gc->mmu));
+  }
 
   TIME_STEP("ended");
 

src/racket/gc2/newgc.h

@@ -211,7 +211,7 @@ typedef struct NewGC {
   /* Callbacks */
   void (*GC_collect_start_callback)(void);
   void (*GC_collect_end_callback)(void);
-  void (*GC_collect_inform_callback)(int major_gc, intptr_t pre_used, intptr_t post_used);
+  GC_collect_inform_callback_Proc GC_collect_inform_callback;
   uintptr_t (*GC_get_thread_stack_base)(void);
 
   GC_Immobile_Box *immobile_boxes;

src/racket/include/schthread.h

@@ -114,6 +114,7 @@ typedef intptr_t objhead;
 /* **************************************** */
 
 typedef struct Thread_Local_Variables {
+  int scheme_current_place_id_;
   void **GC_variable_stack_;
   struct NewGC *GC_instance_;
   uintptr_t GC_gen0_alloc_page_ptr_;
@@ -430,6 +431,7 @@ XFORM_GC_VARIABLE_STACK_THROUGH_THREAD_LOCAL;
 # define XOA /* empty */
 #endif
 
+#define scheme_current_place_id XOA (scheme_get_thread_local_variables()->scheme_current_place_id_)
 #define GC_objhead_template XOA (scheme_get_thread_local_variables()->GC_objhead_template_)
 #define GC_instance XOA (scheme_get_thread_local_variables()->GC_instance_)
 #define GC_gen0_alloc_page_ptr XOA (scheme_get_thread_local_variables()->GC_gen0_alloc_page_ptr_)

src/racket/src/places.c

@@ -3,6 +3,8 @@
 static Scheme_Object* scheme_place_enabled(int argc, Scheme_Object *args[]);
 static Scheme_Object* scheme_place_shared(int argc, Scheme_Object *args[]);
 
+THREAD_LOCAL_DECL(int scheme_current_place_id);
+
 #ifdef MZ_USE_PLACES
 
 #include "mzrt.h"
@@ -13,6 +15,9 @@ static Scheme_Object* scheme_place_shared(int argc, Scheme_Object *args[]);
 READ_ONLY static Scheme_Object *scheme_def_place_exit_proc;
 SHARED_OK static int scheme_places_enabled = 1;
 
+static int id_counter;
+static mzrt_mutex *id_counter_mutex;
+
 SHARED_OK mz_proc_thread *scheme_master_proc_thread;
 THREAD_LOCAL_DECL(mz_proc_thread *proc_thread_self);
 THREAD_LOCAL_DECL(void *place_object);
@@ -115,6 +120,7 @@ void scheme_init_places_once() {
 #ifdef MZ_USE_PLACES
   scheme_add_evt(scheme_place_type,            (Scheme_Ready_Fun)scheme_place_channel_ready, NULL, NULL, 1); 
   scheme_add_evt(scheme_place_bi_channel_type, (Scheme_Ready_Fun)scheme_place_channel_ready, NULL, NULL, 1);
+  mzrt_mutex_create(&id_counter_mutex);
 #endif
 }
 
@@ -1123,6 +1129,10 @@ static void *place_start_proc_after_stack(void *data_arg, void *stack_base) {
   /* create pristine THREAD_LOCAL variables*/
   null_out_runtime_globals();
 
+  mzrt_mutex_lock(id_counter_mutex);
+  scheme_current_place_id = ++id_counter;
+  mzrt_mutex_unlock(id_counter_mutex);
+
   /* scheme_make_thread behaves differently if the above global vars are not null */
   scheme_place_instance_init(stack_base);
 
@@ -1161,6 +1171,9 @@ static void *place_start_proc_after_stack(void *data_arg, void *stack_base) {
 
   scheme_set_root_param(MZCONFIG_EXIT_HANDLER, scheme_def_place_exit_proc);
 
+  
+  scheme_log(NULL, SCHEME_LOG_DEBUG, 0, "place %d: started", scheme_current_place_id);
+
   {
     Scheme_Thread * volatile p;
     mz_jmp_buf * volatile saved_error_buf;
@@ -1184,6 +1197,8 @@ static void *place_start_proc_after_stack(void *data_arg, void *stack_base) {
     p->error_buf = saved_error_buf;
   }
 
+  scheme_log(NULL, SCHEME_LOG_DEBUG, 0, "place %d: exiting", scheme_current_place_id);
+
   /*printf("Leavin place: proc thread id%u\n", ptid);*/
   scheme_place_instance_destroy();
   free(place_object);

src/racket/src/schpriv.h

@@ -104,6 +104,7 @@ Scheme_Object *scheme_dump_gc_stats(int c, Scheme_Object *p[]);
 
 #define REGISTER_SO(x) MZ_REGISTER_STATIC(x)
 
+THREAD_LOCAL_DECL(extern int scheme_current_place_id);
 THREAD_LOCAL_DECL(extern intptr_t scheme_total_gc_time);
 THREAD_LOCAL_DECL(extern int scheme_cont_capture_count);
 THREAD_LOCAL_DECL(extern int scheme_continuation_application_count);
@@ -3537,8 +3538,10 @@ Scheme_Object *scheme_checked_set_mcar (int argc, Scheme_Object *argv[]);
 Scheme_Object *scheme_checked_set_mcdr (int argc, Scheme_Object *argv[]);
 Scheme_Object *scheme_checked_vector_ref(int argc, Scheme_Object **argv);
 Scheme_Object *scheme_checked_vector_set(int argc, Scheme_Object **argv);
+Scheme_Object *scheme_string_length(Scheme_Object *v);
 Scheme_Object *scheme_checked_string_ref(int argc, Scheme_Object *argv[]);
 Scheme_Object *scheme_checked_string_set(int argc, Scheme_Object *argv[]);
+Scheme_Object *scheme_byte_string_length(Scheme_Object *v);
 Scheme_Object *scheme_checked_byte_string_ref(int argc, Scheme_Object *argv[]);
 Scheme_Object *scheme_checked_byte_string_set(int argc, Scheme_Object *argv[]);
 Scheme_Object *scheme_checked_syntax_e(int argc, Scheme_Object **argv);

src/racket/src/strops.inc

@@ -235,6 +235,12 @@ X__(string_length) (int argc, Scheme_Object *argv[])
   return scheme_make_integer(SCHEME_X_STRTAG_VAL(argv[0]));
 }
 
+Scheme_Object *
+X_(scheme, string_length) (Scheme_Object *v)
+{
+  return X__(string_length)(1, &v);
+}
+
 Scheme_Object *
 X_(scheme_checked, string_ref) (int argc, Scheme_Object *argv[])
 {

src/racket/src/thread.c

@@ -196,7 +196,8 @@ THREAD_LOCAL_DECL(static intptr_t end_this_gc_time);
 static void get_ready_for_GC(void);
 static void done_with_GC(void);
 #ifdef MZ_PRECISE_GC
-static void inform_GC(int major_gc, intptr_t pre_used, intptr_t post_used);
+static void inform_GC(int master_gc, int major_gc, intptr_t pre_used, intptr_t post_used,
+                      intptr_t pre_admin, intptr_t post_admin);
 #endif
 
 THREAD_LOCAL_DECL(static volatile short delayed_break_ready);
@@ -7615,21 +7616,65 @@ static void done_with_GC()
 }
 
 #ifdef MZ_PRECISE_GC
-static void inform_GC(int major_gc, intptr_t pre_used, intptr_t post_used)
+static char *gc_num(char *nums, int v)
+/* format a number with commas */
+{
+  int i, j, len, clen, c, d;
+  for (i = 0; nums[i] || nums[i+1]; i++) {
+  }
+  i++;
+
+  sprintf(nums+i, "%d", v);
+  for (len = 0; nums[i+len]; len++) { }
+  clen = len + ((len + ((nums[i] == '-') ? -2 : -1)) / 3);
+  
+  c = 0;
+  d = (clen - len);
+  for (j = i + clen - 1; j > i; j--) {
+    if (c == 3) {
+      nums[j] = ',';
+      d--;
+      c = 0;
+    } else {
+      nums[j] = nums[j - d];
+      c++;
+    }
+  }
+
+  return nums + i;
+}
+
+static void inform_GC(int master_gc, int major_gc, 
+                      intptr_t pre_used, intptr_t post_used,
+                      intptr_t pre_admin, intptr_t post_admin)
 {
   Scheme_Logger *logger = scheme_get_main_logger();
   if (logger) {
     /* Don't use scheme_log(), because it wants to allocate a buffer
        based on the max value-print width, and we may not be at a
        point where parameters are available. */
-    char buf[128];
+    char buf[128], nums[128];
-    intptr_t buflen;
+    intptr_t buflen, delta, admin_delta;
 
+#ifdef MZ_USE_PLACES
+# define PLACE_ID_FORMAT "%s%d:"
+#else
+# define PLACE_ID_FORMAT ""
+#endif
+
+    memset(nums, 0, sizeof(nums));
+
+    delta = pre_used - post_used;
+    admin_delta = (pre_admin - post_admin) - delta;
     sprintf(buf,
-            "GC [%s] at %" PRIdPTR " bytes; %" PRIdPTR 
+            "GC [" PLACE_ID_FORMAT "%s] at %s(+%s) bytes;"
-	    " collected in %" PRIdPTR " msec",
+            " %s(%s%s) collected in %" PRIdPTR " msec",
-            (major_gc ? "major" : "minor"),
+#ifdef MZ_USE_PLACES
-            pre_used, pre_used - post_used,
+            (master_gc ? "M" : ""), scheme_current_place_id,
+#endif
+            (major_gc ? "MAJOR" : "minor"),
+            gc_num(nums, pre_used), gc_num(nums, pre_admin - pre_used),
+            gc_num(nums, delta), ((admin_delta < 0) ? "" : "+"),  gc_num(nums, admin_delta),
             end_this_gc_time - start_this_gc_time);
     buflen = strlen(buf);