We had the problem that we were logging at sweep finish which can happen anytime. If we happen to suspend a thread, while doing a GC, in the middle of logging we might deadlock if we wait for sweep to finish (which can be blocked waiting for logging).
When logging multiple collections in the same stw pause, we would not log the real results for both collections since we would compute the major sizes at the very end.
We logged collections in sgen_perform_collection, outside the function calls for specific collections, which makes it cumbersome to add additional log entries.
This refactoring solves these issues by having GC code log info at any time. This log entry is enqueued in a list of pending entries. We flush the list of logs, as before, at the end of the stw, when the world is restarted.
sgen_object_layout_dump (stdout);
}
- sgen_restart_world (0, NULL);
+ sgen_restart_world (0);
binary_protocol_domain_unload_end (domain);
binary_protocol_flush_buffers (FALSE);
}
}
-void
-sgen_client_log_timing (GGTimingInfo *info, mword promoted_size, mword major_used_size)
-{
- SgenMajorCollector *major_collector = sgen_get_major_collector ();
- mword num_major_sections = major_collector->get_num_major_sections ();
- char full_timing_buff [1024];
- full_timing_buff [0] = '\0';
-
- if (!info->is_overflow)
- sprintf (full_timing_buff, "total %.2fms", info->stw_time / 10000.0f);
- if (info->generation == GENERATION_OLD)
- mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_GC, "GC_MAJOR%s: (%s) pause %.2fms, %s los size: %dK in use: %dK",
- info->is_overflow ? "_OVERFLOW" : "",
- info->reason ? info->reason : "",
- (int)info->total_time / 10000.0f,
- full_timing_buff,
- los_memory_usage_total / 1024,
- los_memory_usage / 1024);
- else
- mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_GC, "GC_MINOR%s: (%s) pause %.2fms, %s promoted %dK major size: %dK in use: %dK los size: %dK in use: %dK",
- info->is_overflow ? "_OVERFLOW" : "",
- info->reason ? info->reason : "",
- (int)info->total_time / 10000.0f,
- full_timing_buff,
- (int)promoted_size / 1024,
- major_collector->section_size * num_major_sections / 1024,
- major_used_size / 1024,
- los_memory_usage_total / 1024,
- los_memory_usage / 1024);
-}
-
/*
* Debugging
*/
/* LOCKING: assumes the GC lock is held */
void
-sgen_client_restart_world (int generation, GGTimingInfo *timing)
+sgen_client_restart_world (int generation, gint64 *stw_time)
{
TV_DECLARE (end_sw);
TV_DECLARE (start_handshake);
*/
release_gc_locks ();
- if (timing) {
- timing [0].stw_time = usec;
- }
+ *stw_time = usec;
}
void
* single-threaded programs this is a nop.
*/
void sgen_client_stop_world (int generation);
-void sgen_client_restart_world (int generation, GGTimingInfo *timing);
+void sgen_client_restart_world (int generation, gint64 *stw_time);
/*
* Must return FALSE. The bridge is not supported outside of Mono.
void sgen_client_mark_togglerefs (char *start, char *end, ScanCopyContext ctx);
void sgen_client_clear_togglerefs (char *start, char *end, ScanCopyContext ctx);
-/*
- * Called after collections, reporting the amount of time they took. No action is
- * necessary.
- */
-void sgen_client_log_timing (GGTimingInfo *info, mword promoted_size, mword major_used_size);
-
/*
* Called to handle `MONO_GC_PARAMS` and `MONO_GC_DEBUG` options. The `handle` functions
* must return TRUE if they have recognized and processed the option, FALSE otherwise.
* Return whether any objects were late-pinned due to being out of memory.
*/
static gboolean
-collect_nursery (SgenGrayQueue *unpin_queue, gboolean finish_up_concurrent_mark)
+collect_nursery (const char *reason, gboolean is_overflow, SgenGrayQueue *unpin_queue, gboolean finish_up_concurrent_mark)
{
gboolean needs_major;
size_t max_garbage_amount;
binary_protocol_flush_buffers (FALSE);
- sgen_memgov_minor_collection_end ();
+ sgen_memgov_minor_collection_end (reason, is_overflow);
/*objects are late pinned because of lack of memory, so a major is a good call*/
needs_major = objects_pinned > 0;
}
static void
-major_start_collection (gboolean concurrent, size_t *old_next_pin_slot)
+major_start_collection (const char *reason, gboolean concurrent, size_t *old_next_pin_slot)
{
SgenObjectOperations *object_ops;
reset_pinned_from_failed_allocation ();
- sgen_memgov_major_collection_start ();
+ sgen_memgov_major_collection_start (concurrent, reason);
//count_ref_nonref_objs ();
//consistency_check ();
}
static void
-major_finish_collection (const char *reason, size_t old_next_pin_slot, gboolean forced)
+major_finish_collection (const char *reason, gboolean is_overflow, size_t old_next_pin_slot, gboolean forced)
{
ScannedObjectCounts counts;
SgenObjectOperations *object_ops;
g_assert (sgen_gray_object_queue_is_empty (&gray_queue));
- sgen_memgov_major_collection_end (forced);
+ sgen_memgov_major_collection_end (forced, concurrent_collection_in_progress, reason, is_overflow);
current_collection_generation = -1;
memset (&counts, 0, sizeof (ScannedObjectCounts));
}
static gboolean
-major_do_collection (const char *reason, gboolean forced)
+major_do_collection (const char *reason, gboolean is_overflow, gboolean forced)
{
TV_DECLARE (time_start);
TV_DECLARE (time_end);
/* world must be stopped already */
TV_GETTIME (time_start);
- major_start_collection (FALSE, &old_next_pin_slot);
- major_finish_collection (reason, old_next_pin_slot, forced);
+ major_start_collection (reason, FALSE, &old_next_pin_slot);
+ major_finish_collection (reason, is_overflow, old_next_pin_slot, forced);
TV_GETTIME (time_end);
gc_stats.major_gc_time += TV_ELAPSED (time_start, time_end);
binary_protocol_concurrent_start ();
// FIXME: store reason and pass it when finishing
- major_start_collection (TRUE, NULL);
+ major_start_collection (reason, TRUE, NULL);
gray_queue_redirect (&gray_queue);
current_collection_generation = GENERATION_OLD;
sgen_cement_reset ();
- major_finish_collection ("finishing", -1, forced);
+ major_finish_collection ("finishing", FALSE, -1, forced);
if (whole_heap_check_before_collection)
sgen_check_whole_heap (FALSE);
void
sgen_perform_collection (size_t requested_size, int generation_to_collect, const char *reason, gboolean wait_to_finish)
{
- TV_DECLARE (gc_start);
- TV_DECLARE (gc_end);
TV_DECLARE (gc_total_start);
TV_DECLARE (gc_total_end);
- GGTimingInfo infos [2];
int overflow_generation_to_collect = -1;
int oldest_generation_collected = generation_to_collect;
const char *overflow_reason = NULL;
SGEN_ASSERT (0, generation_to_collect == GENERATION_NURSERY || generation_to_collect == GENERATION_OLD, "What generation is this?");
- TV_GETTIME (gc_start);
-
sgen_stop_world (generation_to_collect);
TV_GETTIME (gc_total_start);
if (concurrent_collection_in_progress)
major_update_concurrent_collection ();
- if (collect_nursery (NULL, FALSE) && !concurrent_collection_in_progress) {
+ if (collect_nursery (reason, FALSE, NULL, FALSE) && !concurrent_collection_in_progress) {
overflow_generation_to_collect = GENERATION_OLD;
overflow_reason = "Minor overflow";
}
} else {
SGEN_ASSERT (0, generation_to_collect == GENERATION_OLD, "We should have handled nursery collections above");
if (major_collector.is_concurrent && !wait_to_finish) {
- collect_nursery (NULL, FALSE);
+ collect_nursery ("Concurrent start", FALSE, NULL, FALSE);
major_start_concurrent_collection (reason);
oldest_generation_collected = GENERATION_NURSERY;
- } else if (major_do_collection (reason, wait_to_finish)) {
+ } else if (major_do_collection (reason, FALSE, wait_to_finish)) {
overflow_generation_to_collect = GENERATION_NURSERY;
overflow_reason = "Excessive pinning";
}
}
- TV_GETTIME (gc_end);
-
- memset (infos, 0, sizeof (infos));
- infos [0].generation = oldest_generation_collected;
- infos [0].reason = reason;
- infos [0].is_overflow = FALSE;
- infos [1].generation = -1;
- infos [0].total_time = SGEN_TV_ELAPSED (gc_start, gc_end);
-
if (overflow_generation_to_collect != -1) {
SGEN_ASSERT (0, !concurrent_collection_in_progress, "We don't yet support overflow collections with the concurrent collector");
* or the nursery is fully pinned.
*/
- infos [1].generation = overflow_generation_to_collect;
- infos [1].reason = overflow_reason;
- infos [1].is_overflow = TRUE;
- gc_start = gc_end;
-
if (overflow_generation_to_collect == GENERATION_NURSERY)
- collect_nursery (NULL, FALSE);
+ collect_nursery (overflow_reason, TRUE, NULL, FALSE);
else
- major_do_collection (overflow_reason, wait_to_finish);
-
- TV_GETTIME (gc_end);
- infos [1].total_time = SGEN_TV_ELAPSED (gc_start, gc_end);
+ major_do_collection (overflow_reason, TRUE, wait_to_finish);
oldest_generation_collected = MAX (oldest_generation_collected, overflow_generation_to_collect);
}
TV_GETTIME (gc_total_end);
time_max = MAX (time_max, TV_ELAPSED (gc_total_start, gc_total_end));
- sgen_restart_world (oldest_generation_collected, infos);
+ sgen_restart_world (oldest_generation_collected);
}
/*
/* LOCKING: assumes the GC lock is held */
void
-sgen_restart_world (int generation, GGTimingInfo *timing)
+sgen_restart_world (int generation)
{
long long major_total = -1, major_marked = -1, los_total = -1, los_marked = -1;
+ gint64 stw_time;
SGEN_ASSERT (0, world_is_stopped, "Why are we restarting a running world?");
world_is_stopped = FALSE;
- sgen_client_restart_world (generation, timing);
+ sgen_client_restart_world (generation, &stw_time);
binary_protocol_world_restarted (generation, sgen_timestamp ());
if (sgen_client_bridge_need_processing ())
sgen_client_bridge_processing_finish (generation);
- sgen_memgov_collection_end (generation, timing, timing ? 2 : 0);
+ sgen_memgov_collection_end (generation, stw_time);
}
gboolean
sgen_stop_world (0);
sgen_clear_nursery_fragments ();
sgen_check_whole_heap (FALSE);
- sgen_restart_world (0, NULL);
+ sgen_restart_world (0);
}
gint64
INTERNAL_MEM_CARDTABLE_MOD_UNION,
INTERNAL_MEM_BINARY_PROTOCOL,
INTERNAL_MEM_TEMPORARY,
+ INTERNAL_MEM_LOG_ENTRY,
INTERNAL_MEM_FIRST_CLIENT
};
/* STW */
-typedef struct {
- int generation;
- const char *reason;
- gboolean is_overflow;
- gint64 total_time;
- gint64 stw_time;
-} GGTimingInfo;
-
void sgen_stop_world (int generation);
-void sgen_restart_world (int generation, GGTimingInfo *timing);
+void sgen_restart_world (int generation);
gboolean sgen_is_world_stopped (void);
gboolean sgen_set_allow_synchronous_major (gboolean flag);
#define MIN_MINOR_COLLECTION_ALLOWANCE ((mword)(DEFAULT_NURSERY_SIZE * default_allowance_nursery_size_ratio))
+static SgenPointerQueue log_entries = SGEN_POINTER_QUEUE_INIT (INTERNAL_MEM_TEMPORARY);
+static MonoCoopMutex log_entries_mutex;
+
mword total_promoted_size = 0;
mword total_allocated_major = 0;
static mword total_promoted_size_start;
static mword total_alloc = 0;
static mword total_alloc_max = 0;
+static SGEN_TV_DECLARE(last_minor_start);
+static SGEN_TV_DECLARE(last_major_start);
+
/* GC triggers. */
static gboolean debug_print_allowance = FALSE;
sgen_memgov_minor_collection_start (void)
{
total_promoted_size_start = total_promoted_size;
+ SGEN_TV_GETTIME (last_minor_start);
+}
+
+static void
+sgen_add_log_entry (SgenLogEntry *log_entry)
+{
+ mono_coop_mutex_lock (&log_entries_mutex);
+ sgen_pointer_queue_add (&log_entries, log_entry);
+ mono_coop_mutex_unlock (&log_entries_mutex);
}
void
-sgen_memgov_minor_collection_end (void)
+sgen_memgov_minor_collection_end (const char *reason, gboolean is_overflow)
{
+ if (mono_trace_is_traced (G_LOG_LEVEL_INFO, MONO_TRACE_GC)) {
+ SgenLogEntry *log_entry = (SgenLogEntry*)sgen_alloc_internal (INTERNAL_MEM_LOG_ENTRY);
+ SGEN_TV_DECLARE (current_time);
+ SGEN_TV_GETTIME (current_time);
+
+ log_entry->type = SGEN_LOG_NURSERY;
+ log_entry->reason = reason;
+ log_entry->is_overflow = is_overflow;
+ log_entry->time = SGEN_TV_ELAPSED (last_minor_start, current_time);
+ log_entry->promoted_size = total_promoted_size - total_promoted_size_start;
+ log_entry->major_size = major_collector.get_num_major_sections () * major_collector.section_size;
+ log_entry->major_size_in_use = last_used_slots_size + total_allocated_major - total_allocated_major_end;
+ log_entry->los_size = los_memory_usage_total;
+ log_entry->los_size_in_use = los_memory_usage;
+
+ sgen_add_log_entry (log_entry);
+ }
}
void
void
sgen_memgov_major_post_sweep (mword used_slots_size)
{
- mword num_major_sections = major_collector.get_num_major_sections ();
+ if (mono_trace_is_traced (G_LOG_LEVEL_INFO, MONO_TRACE_GC)) {
+ SgenLogEntry *log_entry = (SgenLogEntry*)sgen_alloc_internal (INTERNAL_MEM_LOG_ENTRY);
+
+ log_entry->type = SGEN_LOG_MAJOR_SWEEP_FINISH;
+ log_entry->major_size = major_collector.get_num_major_sections () * major_collector.section_size;
+ log_entry->major_size_in_use = used_slots_size + total_allocated_major - total_allocated_major_end;
- mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_GC, "GC_MAJOR_SWEEP: major size: %dK in use: %dK",
- num_major_sections * major_collector.section_size / 1024,
- (used_slots_size + total_allocated_major - total_allocated_major_end) / 1024);
+ sgen_add_log_entry (log_entry);
+ }
last_used_slots_size = used_slots_size;
}
void
-sgen_memgov_major_collection_start (void)
+sgen_memgov_major_collection_start (gboolean concurrent, const char *reason)
{
need_calculate_minor_collection_allowance = TRUE;
major_start_heap_size = get_heap_size ();
if (debug_print_allowance) {
SGEN_LOG (0, "Starting collection with heap size %ld bytes", (long)major_start_heap_size);
}
+ if (concurrent && mono_trace_is_traced (G_LOG_LEVEL_INFO, MONO_TRACE_GC)) {
+ SgenLogEntry *log_entry = (SgenLogEntry*)sgen_alloc_internal (INTERNAL_MEM_LOG_ENTRY);
+
+ log_entry->type = SGEN_LOG_MAJOR_CONC_START;
+ log_entry->reason = reason;
+
+ sgen_add_log_entry (log_entry);
+ }
+ SGEN_TV_GETTIME (last_major_start);
}
void
-sgen_memgov_major_collection_end (gboolean forced)
+sgen_memgov_major_collection_end (gboolean forced, gboolean concurrent, const char *reason, gboolean is_overflow)
{
- last_collection_los_memory_usage = los_memory_usage;
+ if (mono_trace_is_traced (G_LOG_LEVEL_INFO, MONO_TRACE_GC)) {
+ SgenLogEntry *log_entry = (SgenLogEntry*)sgen_alloc_internal (INTERNAL_MEM_LOG_ENTRY);
+ SGEN_TV_DECLARE (current_time);
+ SGEN_TV_GETTIME (current_time);
+
+ if (concurrent) {
+ log_entry->type = SGEN_LOG_MAJOR_CONC_FINISH;
+ } else {
+ log_entry->type = SGEN_LOG_MAJOR_SERIAL;
+ }
+ log_entry->time = SGEN_TV_ELAPSED (last_major_start, current_time);
+ log_entry->reason = reason;
+ log_entry->is_overflow = is_overflow;
+ log_entry->los_size = los_memory_usage_total;
+ log_entry->los_size_in_use = los_memory_usage;
+
+ sgen_add_log_entry (log_entry);
+ }
+ last_collection_los_memory_usage = los_memory_usage;
total_allocated_major_end = total_allocated_major;
if (forced) {
sgen_get_major_collector ()->finish_sweeping ();
{
}
+static void
+sgen_output_log_entry (SgenLogEntry *entry, gint64 stw_time, int generation)
+{
+ char full_timing_buff [1024];
+ full_timing_buff [0] = '\0';
+
+ if (!entry->is_overflow)
+ sprintf (full_timing_buff, "stw %.2fms", stw_time / 10000.0f);
+
+ switch (entry->type) {
+ case SGEN_LOG_NURSERY:
+ mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_GC, "GC_MINOR%s: (%s) time %.2fms, %s promoted %dK major size: %dK in use: %dK los size: %dK in use: %dK",
+ entry->is_overflow ? "_OVERFLOW" : "",
+ entry->reason ? entry->reason : "",
+ entry->time / 10000.0f,
+ (generation == GENERATION_NURSERY) ? full_timing_buff : "",
+ entry->promoted_size / 1024,
+ entry->major_size / 1024,
+ entry->major_size_in_use / 1024,
+ entry->los_size / 1024,
+ entry->los_size_in_use / 1024);
+ break;
+ case SGEN_LOG_MAJOR_SERIAL:
+ mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_GC, "GC_MAJOR%s: (%s) time %.2fms, %s los size: %dK in use: %dK",
+ entry->is_overflow ? "_OVERFLOW" : "",
+ entry->reason ? entry->reason : "",
+ (int)entry->time / 10000.0f,
+ full_timing_buff,
+ entry->los_size / 1024,
+ entry->los_size_in_use / 1024);
+ break;
+ case SGEN_LOG_MAJOR_CONC_START:
+ mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_GC, "GC_MAJOR_CONCURRENT_START: (%s)", entry->reason ? entry->reason : "");
+ break;
+ case SGEN_LOG_MAJOR_CONC_FINISH:
+ mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_GC, "GC_MAJOR_CONCURRENT_FINISH: (%s) time %.2fms, %s los size: %dK in use: %dK",
+ entry->reason ? entry->reason : "",
+ entry->time / 10000.0f,
+ full_timing_buff,
+ entry->los_size / 1024,
+ entry->los_size_in_use / 1024);
+ break;
+ case SGEN_LOG_MAJOR_SWEEP_FINISH:
+ mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_GC, "GC_MAJOR_SWEEP: major size: %dK in use: %dK",
+ entry->major_size / 1024,
+ entry->major_size_in_use / 1024);
+ break;
+ default:
+ SGEN_ASSERT (0, FALSE, "Invalid log entry type");
+ break;
+ }
+}
+
void
-sgen_memgov_collection_end (int generation, GGTimingInfo* info, int info_count)
+sgen_memgov_collection_end (int generation, gint64 stw_time)
{
- int i;
- for (i = 0; i < info_count; ++i) {
- if (info[i].generation != -1)
- sgen_client_log_timing (&info [i], total_promoted_size - total_promoted_size_start, last_used_slots_size + total_allocated_major - total_allocated_major_end);
+ /*
+ * At this moment the world has been restarted which means we can log all pending entries
+ * without risking deadlocks.
+ */
+ if (mono_trace_is_traced (G_LOG_LEVEL_INFO, MONO_TRACE_GC)) {
+ size_t i;
+ SGEN_ASSERT (0, !sgen_is_world_stopped (), "We can't log if the world is stopped");
+ mono_coop_mutex_lock (&log_entries_mutex);
+ for (i = 0; i < log_entries.next_slot; i++) {
+ sgen_output_log_entry (log_entries.data [i], stw_time, generation);
+ sgen_free_internal (log_entries.data [i], INTERNAL_MEM_LOG_ENTRY);
+ }
+ sgen_pointer_queue_clear (&log_entries);
+ mono_coop_mutex_unlock (&log_entries_mutex);
}
}
mono_counters_register ("Memgov alloc", MONO_COUNTER_GC | MONO_COUNTER_WORD | MONO_COUNTER_BYTES | MONO_COUNTER_VARIABLE, &total_alloc);
mono_counters_register ("Memgov max alloc", MONO_COUNTER_GC | MONO_COUNTER_WORD | MONO_COUNTER_BYTES | MONO_COUNTER_MONOTONIC, &total_alloc_max);
+ mono_coop_mutex_init (&log_entries_mutex);
+
+ sgen_register_fixed_internal_mem_type (INTERNAL_MEM_LOG_ENTRY, sizeof (SgenLogEntry));
+
if (max_heap == 0)
return;
/* GC trigger heuristics */
void sgen_memgov_minor_collection_start (void);
-void sgen_memgov_minor_collection_end (void);
+void sgen_memgov_minor_collection_end (const char *reason, gboolean is_overflow);
void sgen_memgov_major_pre_sweep (void);
void sgen_memgov_major_post_sweep (mword used_slots_size);
-void sgen_memgov_major_collection_start (void);
-void sgen_memgov_major_collection_end (gboolean forced);
+void sgen_memgov_major_collection_start (gboolean concurrent, const char *reason);
+void sgen_memgov_major_collection_end (gboolean forced, gboolean concurrent, const char *reason, gboolean is_overflow);
void sgen_memgov_collection_start (int generation);
-void sgen_memgov_collection_end (int generation, GGTimingInfo* info, int info_count);
+void sgen_memgov_collection_end (int generation, gint64 stw);
gboolean sgen_need_major_collection (mword space_needed);
SGEN_ALLOC_ACTIVATE = 2
} SgenAllocFlags;
+typedef enum {
+ SGEN_LOG_NURSERY,
+ SGEN_LOG_MAJOR_SERIAL,
+ SGEN_LOG_MAJOR_CONC_START,
+ SGEN_LOG_MAJOR_CONC_FINISH,
+ SGEN_LOG_MAJOR_SWEEP_FINISH
+} SgenLogType;
+
+typedef struct {
+ SgenLogType type;
+ const char *reason;
+ gboolean is_overflow;
+ gint64 time;
+ mword promoted_size;
+ mword major_size;
+ mword major_size_in_use;
+ mword los_size;
+ mword los_size_in_use;
+} SgenLogEntry;
+
/* OS memory allocation */
void* sgen_alloc_os_memory (size_t size, SgenAllocFlags flags, const char *assert_description);
void* sgen_alloc_os_memory_aligned (size_t size, mword alignment, SgenAllocFlags flags, const char *assert_description);
projects / mono.git / commitdiff