Merge pull request #3057 from BrzVlad/fix-major-log3
authorVlad Brezae <brezaevlad@gmail.com>
Mon, 30 May 2016 16:04:28 +0000 (19:04 +0300)
committerVlad Brezae <brezaevlad@gmail.com>
Mon, 30 May 2016 16:04:28 +0000 (19:04 +0300)
[sgen] Refactor collection logging

mono/metadata/sgen-mono.c
mono/metadata/sgen-stw.c
mono/sgen/sgen-client.h
mono/sgen/sgen-gc.c
mono/sgen/sgen-gc.h
mono/sgen/sgen-memory-governor.c
mono/sgen/sgen-memory-governor.h

index 2a71d2fbd46b480c88c8937125c2111cec528d77..862871c771206b1b1fb73ecf4ccee1ed57bbf895 100644 (file)
@@ -901,7 +901,7 @@ mono_gc_clear_domain (MonoDomain * domain)
                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);
@@ -2717,37 +2717,6 @@ sgen_client_degraded_allocation (size_t size)
        }
 }
 
-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
  */
index 17f4d6e7f7d60769ee643adc29a289d444c9dd1d..ea14448ccfbfaeb7b376fbf06abd59135cf6b680 100644 (file)
@@ -240,7 +240,7 @@ sgen_client_stop_world (int generation)
 
 /* 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);
@@ -283,9 +283,7 @@ sgen_client_restart_world (int generation, GGTimingInfo *timing)
         */
        release_gc_locks ();
 
-       if (timing) {
-               timing [0].stw_time = usec;
-       }
+       *stw_time = usec;
 }
 
 void
index 852d93e366217d9c50f45f136db0845950d02335..6d60c3516c6a380c8a2de1c47827a34229ea853a 100644 (file)
@@ -174,7 +174,7 @@ void sgen_client_scan_thread_data (void *start_nursery, void *end_nursery, gbool
  * 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.
@@ -197,12 +197,6 @@ void sgen_client_bridge_register_finalized_object (GCObject *object);
 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.
index 41843b19cc788f351ee7fd94c3ca211b16db227b..37a162b240c3c44a9957d69a072ea18a6ff20301 100644 (file)
@@ -1474,7 +1474,7 @@ enqueue_scan_from_roots_jobs (char *heap_start, char *heap_end, SgenObjectOperat
  * 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;
@@ -1638,7 +1638,7 @@ collect_nursery (SgenGrayQueue *unpin_queue, gboolean finish_up_concurrent_mark)
 
        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;
@@ -1869,7 +1869,7 @@ major_finish_copy_or_mark (CopyOrMarkFromRootsMode mode)
 }
 
 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;
 
@@ -1893,7 +1893,7 @@ major_start_collection (gboolean concurrent, size_t *old_next_pin_slot)
 
        reset_pinned_from_failed_allocation ();
 
-       sgen_memgov_major_collection_start ();
+       sgen_memgov_major_collection_start (concurrent, reason);
 
        //count_ref_nonref_objs ();
        //consistency_check ();
@@ -1912,7 +1912,7 @@ major_start_collection (gboolean concurrent, size_t *old_next_pin_slot)
 }
 
 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;
@@ -2025,7 +2025,7 @@ major_finish_collection (const char *reason, size_t old_next_pin_slot, gboolean
 
        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));
@@ -2047,7 +2047,7 @@ major_finish_collection (const char *reason, size_t old_next_pin_slot, gboolean
 }
 
 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);
@@ -2064,8 +2064,8 @@ major_do_collection (const char *reason, gboolean forced)
        /* 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);
@@ -2096,7 +2096,7 @@ major_start_concurrent_collection (const char *reason)
        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);
 
@@ -2163,7 +2163,7 @@ major_finish_concurrent_collection (gboolean forced)
 
        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);
@@ -2223,11 +2223,8 @@ sgen_ensure_free_space (size_t size, int generation)
 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;
@@ -2237,8 +2234,6 @@ sgen_perform_collection (size_t requested_size, int generation_to_collect, const
 
        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);
@@ -2249,7 +2244,7 @@ sgen_perform_collection (size_t requested_size, int generation_to_collect, const
                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";
                }
@@ -2259,24 +2254,15 @@ sgen_perform_collection (size_t requested_size, int generation_to_collect, const
        } 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");
 
@@ -2285,18 +2271,10 @@ sgen_perform_collection (size_t requested_size, int generation_to_collect, const
                 * 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);
        }
@@ -2316,7 +2294,7 @@ sgen_perform_collection (size_t requested_size, int generation_to_collect, const
        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);
 }
 
 /*
@@ -3214,9 +3192,10 @@ sgen_stop_world (int generation)
 
 /* 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?");
 
@@ -3226,14 +3205,14 @@ sgen_restart_world (int generation, GGTimingInfo *timing)
 
        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
@@ -3248,7 +3227,7 @@ sgen_check_whole_heap_stw (void)
        sgen_stop_world (0);
        sgen_clear_nursery_fragments ();
        sgen_check_whole_heap (FALSE);
-       sgen_restart_world (0, NULL);
+       sgen_restart_world (0);
 }
 
 gint64
index d5e149f1bef25ba7a516909f363d1f35659d8558..f688748a45e455887b68f438278b9b89943b9c7b 100644 (file)
@@ -315,6 +315,7 @@ enum {
        INTERNAL_MEM_CARDTABLE_MOD_UNION,
        INTERNAL_MEM_BINARY_PROTOCOL,
        INTERNAL_MEM_TEMPORARY,
+       INTERNAL_MEM_LOG_ENTRY,
        INTERNAL_MEM_FIRST_CLIENT
 };
 
@@ -811,16 +812,8 @@ size_t sgen_gc_get_total_heap_allocation (void);
 
 /* 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);
index 4648d8d761d444cbb8b6ec411d6fff6d3d2ad4da..e7de362976055377c0a67e6da9e4874d0c3b2db5 100644 (file)
@@ -25,6 +25,9 @@
 
 #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;
@@ -42,6 +45,9 @@ static mword allocated_heap;
 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;
@@ -164,11 +170,37 @@ void
 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
@@ -185,16 +217,20 @@ sgen_memgov_major_pre_sweep (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 ();
@@ -202,13 +238,40 @@ sgen_memgov_major_collection_start (void)
        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 ();
@@ -221,13 +284,76 @@ sgen_memgov_collection_start (int generation)
 {
 }
 
+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);
        }
 }
 
@@ -353,6 +479,10 @@ sgen_memgov_init (size_t max_heap, size_t soft_limit, gboolean debug_allowance,
        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;
 
index 5e33b042837a983ed97cbbe1cbe84b8ac24833e9..d669e4730d18a058c44a026e9ae7dd48446c71a5 100644 (file)
@@ -14,15 +14,15 @@ gboolean sgen_memgov_try_alloc_space (mword size, int space);
 
 /* 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);
 
@@ -33,6 +33,26 @@ typedef enum {
        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);