From 73071ad186007bee85a0cc7fa5db2cb73b727be5 Mon Sep 17 00:00:00 2001 From: Matthew Flatt Date: Thu, 29 Sep 2011 09:34:46 -0600 Subject: [PATCH] improve GC logging (3m) Show process time of start of GC and otherwise adjust to make the output more compact, and attach a prefab struct to the logged message to report all available data in Racket form (including real start and end times, which are not shown in the output). --- collects/scribblings/reference/memory.scrbl | 39 ++++++++++++++ src/racket/include/schthread.h | 6 +++ src/racket/src/thread.c | 59 ++++++++++++++++----- 3 files changed, 91 insertions(+), 13 deletions(-) diff --git a/collects/scribblings/reference/memory.scrbl b/collects/scribblings/reference/memory.scrbl index 6fe042fb71..a9f4734ebe 100644 --- a/collects/scribblings/reference/memory.scrbl +++ b/collects/scribblings/reference/memory.scrbl @@ -173,6 +173,45 @@ execution. Otherwise, @racket[#f] is returned.} Set the @as-index{@envvar{PLTDISABLEGC}} environment variable (to any value) before Racket starts to disable @tech{garbage collection}. +In Racket 3m (the main variant of Racket), each garbage collection +logs a message (see @secref["logging"]) at the @racket['debug] level. +The data portion of the message is an instance of a @racket[gc-info] +@tech{prefab} structure type with 10 fields as follows, but future +versions of Racket may use a @racket[gc-info] @tech{prefab} structure +with additional fields: + +@racketblock[ +(struct gc-info (major? pre-amount pre-admin-amount code-amount + post-amount post-admin-amount + start-process-time end-process-time + start-time end-time) + #:prefab) +] + +The @racket[major?] field indicates whether the collection was a +``major'' collection that inspects all memory or a ``minor'' +collection that mostly inspects just recent allocations. The +@racket[pre-amount] field reports place-local memory use (i.e., not +counting the memory use of child places) in bytes at the time that the +@tech{garbage collection} started. The @racket[pre-admin-amount] is a +larger number that includes memory use for the garbage collector's +overhead (such as space on memory pages that is not yet used). The +@racket[code-amount] field reports additional memory use for generated +native code (which is the same just before and after a garbage +collection, since it is released via finalization). The +@racket[post-amount] and @racket[post-admin-amount] fields correspond +to @racket[pre-amount] and @racket[pre-admin-amount], but after garbage +collection. The @racket[start-process-time] and +@racket[end-process-time] fields report processor time (in the sense +of @racket[current-process-milliseconds]) at the start and end of +garbage collection; the difference is the processor time consumed by +collection. The @racket[start-time] and @racket[end-time] fields +report real time (in the sense of +@racket[current-inexact-milliseconds]) at the start and end of garbage +collection; the difference is the real time consumed by garbage +collection. + + @defproc[(collect-garbage) void?]{ Forces an immediate @tech{garbage collection} (unless garbage diff --git a/src/racket/include/schthread.h b/src/racket/include/schthread.h index b2a02c4d5b..7f19aa9257 100644 --- a/src/racket/include/schthread.h +++ b/src/racket/include/schthread.h @@ -301,6 +301,9 @@ typedef struct Thread_Local_Variables { intptr_t scheme_total_gc_time_; intptr_t start_this_gc_time_; intptr_t end_this_gc_time_; + double start_this_gc_real_time_; + double end_this_gc_real_time_; + struct Scheme_Struct_Type *gc_info_prefab_; volatile short delayed_break_ready_; struct Scheme_Thread *main_break_target_thread_; intptr_t scheme_code_page_total_; @@ -636,6 +639,9 @@ XFORM_GC_VARIABLE_STACK_THROUGH_THREAD_LOCAL; #define scheme_total_gc_time XOA (scheme_get_thread_local_variables()->scheme_total_gc_time_) #define start_this_gc_time XOA (scheme_get_thread_local_variables()->start_this_gc_time_) #define end_this_gc_time XOA (scheme_get_thread_local_variables()->end_this_gc_time_) +#define start_this_gc_real_time XOA (scheme_get_thread_local_variables()->start_this_gc_real_time_) +#define end_this_gc_real_time XOA (scheme_get_thread_local_variables()->end_this_gc_real_time_) +#define gc_info_prefab XOA (scheme_get_thread_local_variables()->gc_info_prefab_) #define delayed_break_ready XOA (scheme_get_thread_local_variables()->delayed_break_ready_) #define main_break_target_thread XOA (scheme_get_thread_local_variables()->main_break_target_thread_) #define scheme_code_page_total XOA (scheme_get_thread_local_variables()->scheme_code_page_total_) diff --git a/src/racket/src/thread.c b/src/racket/src/thread.c index eee10b860f..9b13e7e3d5 100644 --- a/src/racket/src/thread.c +++ b/src/racket/src/thread.c @@ -194,6 +194,8 @@ ROSYM Scheme_Object *scheme_break_enabled_key; THREAD_LOCAL_DECL(intptr_t scheme_total_gc_time); THREAD_LOCAL_DECL(static intptr_t start_this_gc_time); THREAD_LOCAL_DECL(static intptr_t end_this_gc_time); +THREAD_LOCAL_DECL(static double start_this_gc_real_time); +THREAD_LOCAL_DECL(static double end_this_gc_real_time); static void get_ready_for_GC(void); static void done_with_GC(void); #ifdef MZ_PRECISE_GC @@ -240,6 +242,7 @@ THREAD_LOCAL_DECL(static Scheme_Object *thread_swap_out_callbacks); THREAD_LOCAL_DECL(static Scheme_Object *recycle_cell); THREAD_LOCAL_DECL(static Scheme_Object *maybe_recycle_cell); THREAD_LOCAL_DECL(static int recycle_cc_count); +THREAD_LOCAL_DECL(static Scheme_Struct_Type *gc_info_prefab); THREAD_LOCAL_DECL(struct Scheme_Hash_Table *place_local_misc_table); @@ -563,6 +566,8 @@ void scheme_init_thread_places(void) { REGISTER_SO(maybe_recycle_cell); REGISTER_SO(gc_prepost_callback_descs); REGISTER_SO(place_local_misc_table); + REGISTER_SO(gc_info_prefab); + gc_info_prefab = scheme_lookup_prefab_type(scheme_intern_symbol("gc-info"), 10); } void scheme_init_memtrace(Scheme_Env *env) @@ -7613,6 +7618,7 @@ void scheme_prepare_this_thread_for_GC(Scheme_Thread *p) static void get_ready_for_GC() { + start_this_gc_real_time = scheme_get_inexact_milliseconds(); start_this_gc_time = scheme_get_process_milliseconds(); #ifdef MZ_USE_FUTURES @@ -7687,6 +7693,7 @@ static void done_with_GC() #endif end_this_gc_time = scheme_get_process_milliseconds(); + end_this_gc_real_time = scheme_get_inexact_milliseconds(); scheme_total_gc_time += (end_this_gc_time - start_this_gc_time); run_gc_callbacks(0); @@ -7744,18 +7751,24 @@ static char *gc_num(char *nums, int v) return nums + i; } +#ifdef MZ_XFORM +END_XFORM_SKIP; +#endif + 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, intptr_t post_child_places_used) { - Scheme_Logger *logger = scheme_get_main_logger(); - if (logger) { + Scheme_Logger *logger; + logger = scheme_get_main_logger(); + if (logger && scheme_log_level_p(logger, SCHEME_LOG_DEBUG)) { /* 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], nums[128]; + char buf[256], nums[128]; intptr_t buflen, delta, admin_delta; + Scheme_Object *vec, *v; #ifdef MZ_USE_PLACES # define PLACE_ID_FORMAT "%d:" @@ -7763,24 +7776,49 @@ static void inform_GC(int master_gc, int major_gc, # define PLACE_ID_FORMAT "" #endif + vec = scheme_false; + if (!master_gc && gc_info_prefab) { + vec = scheme_make_vector(11, scheme_false); + SCHEME_VEC_ELS(vec)[1] = (major_gc ? scheme_true : scheme_false); + SCHEME_VEC_ELS(vec)[2] = scheme_make_integer(pre_used); + SCHEME_VEC_ELS(vec)[3] = scheme_make_integer((pre_admin - pre_used)); + SCHEME_VEC_ELS(vec)[4] = scheme_make_integer(scheme_code_page_total); + SCHEME_VEC_ELS(vec)[5] = scheme_make_integer(pre_used - delta); + SCHEME_VEC_ELS(vec)[6] = scheme_make_integer(pre_admin - admin_delta); + v = scheme_make_integer_value(start_this_gc_time); + SCHEME_VEC_ELS(vec)[7] = v; + v = scheme_make_integer_value(end_this_gc_time); + SCHEME_VEC_ELS(vec)[8] = v; + v = scheme_make_double(start_this_gc_real_time); + SCHEME_VEC_ELS(vec)[9] = v; + v = scheme_make_double(end_this_gc_real_time); + SCHEME_VEC_ELS(vec)[10] = v; + vec = scheme_make_prefab_struct_instance(gc_info_prefab, vec); + } + + START_XFORM_SKIP; + memset(nums, 0, sizeof(nums)); delta = pre_used - post_used; admin_delta = (pre_admin - post_admin) - delta; sprintf(buf, - "GC [" PLACE_ID_FORMAT "%s] at %sK(+%sK)[+%sK];" - " freed %sK(%s%sK) in %" PRIdPTR " msec", + "GC[" PLACE_ID_FORMAT "%s] @ %sK(+%sK)[+%sK];" + " free %sK(%s%sK) %" PRIdPTR "ms @ %" PRIdPTR, #ifdef MZ_USE_PLACES scheme_current_place_id, #endif - (master_gc ? "MASTER" : (major_gc ? "MAJOR" : "minor")), + (master_gc ? "MST" : (major_gc ? "MAJ" : "min")), gc_num(nums, pre_used), gc_num(nums, pre_admin - pre_used), gc_num(nums, scheme_code_page_total), gc_num(nums, delta), ((admin_delta < 0) ? "" : "+"), gc_num(nums, admin_delta), - (master_gc ? 0 : (end_this_gc_time - start_this_gc_time))); + (master_gc ? 0 : (end_this_gc_time - start_this_gc_time)), + start_this_gc_time); buflen = strlen(buf); - scheme_log_message(logger, SCHEME_LOG_DEBUG, buf, buflen, NULL); + END_XFORM_SKIP; + + scheme_log_message(logger, SCHEME_LOG_DEBUG, buf, buflen, vec); } #ifdef MZ_USE_PLACES @@ -7791,11 +7829,6 @@ static void inform_GC(int master_gc, int major_gc, } #endif - -#ifdef MZ_XFORM -END_XFORM_SKIP; -#endif - /*========================================================================*/ /* stats */ /*========================================================================*/