suzanne.soy/racket
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

improve GC logging (3m)

Browse Source 
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).
This commit is contained in:
Matthew Flatt 2011-09-29 09:34:46 -06:00
parent d279593c15
commit 73071ad186
3 changed files with 91 additions and 13 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

39
collects/scribblings/reference/memory.scrbl
View File

@ -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

6
src/racket/include/schthread.h
View File

@ -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_)

59
src/racket/src/thread.c
View File

@ -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 */
/*========================================================================*/