Merge pull request #2977 from BrzVlad/fix-major-log2
authorRodrigo Kumpera <kumpera@gmail.com>
Wed, 18 May 2016 23:41:50 +0000 (16:41 -0700)
committerRodrigo Kumpera <kumpera@gmail.com>
Wed, 18 May 2016 23:41:50 +0000 (16:41 -0700)
[sgen] Improve logging

mono/metadata/sgen-mono.c
mono/mini/main.c
mono/sgen/sgen-client.h
mono/sgen/sgen-gc.c
mono/sgen/sgen-gc.h
mono/sgen/sgen-los.c
mono/sgen/sgen-marksweep.c
mono/sgen/sgen-memory-governor.c
mono/sgen/sgen-memory-governor.h
mono/sgen/sgen-simple-nursery.c
mono/sgen/sgen-split-nursery.c

index 644c9ba93cd893c25d3c271d18d1a82bd69cf524..c7a467ce832b3696afca54df2258b153424dd50e 100644 (file)
@@ -2718,7 +2718,7 @@ sgen_client_degraded_allocation (size_t size)
 }
 
 void
-sgen_client_log_timing (GGTimingInfo *info, mword last_major_num_sections, mword last_los_memory_usage)
+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 ();
@@ -2728,22 +2728,24 @@ sgen_client_log_timing (GGTimingInfo *info, mword last_major_num_sections, mword
        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 %dK/%dK",
+               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 / 1024,
-                       last_los_memory_usage / 1024);
+                       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 %dK los %dK",
+               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,
-                       (num_major_sections - last_major_num_sections) * major_collector->section_size / 1024,
+                       (int)promoted_size / 1024,
                        major_collector->section_size * num_major_sections / 1024,
-                       los_memory_usage / 1024);
+                       major_used_size / 1024,
+                       los_memory_usage_total / 1024,
+                       los_memory_usage / 1024);
 }
 
 /*
index de8ab61e3d5b64550e733981fcce690c013d7860..276f7952fba6624a64c7ac93449080c14aa9876f 100644 (file)
@@ -100,17 +100,17 @@ probe_embedded (const char *program, int *ref_argc, char **ref_argv [])
                        if (entry_point == NULL)
                                entry_point = aname;
                } else if (strncmp (kind, "config:", strlen ("config:")) == 0){
-                       printf ("c-Found: %s %llx\n", kind, offset);
+                       printf ("c-Found: %s %llx\n", kind, (long long)offset);
                        char *config = kind + strlen ("config:");
                        char *aname = g_strdup (config);
                        aname [strlen(aname)-strlen(".config")] = 0;
                        mono_register_config_for_assembly (aname, config);
                } else if (strncmp (kind, "system_config:", strlen ("system_config:")) == 0){
-                       printf ("TODO s-Found: %s %llx\n", kind, offset);
+                       printf ("TODO s-Found: %s %llx\n", kind, (long long)offset);
                } else if (strncmp (kind, "options:", strlen ("options:")) == 0){
                        mono_parse_options_from (kind + strlen("options:"), ref_argc, ref_argv);
                } else if (strncmp (kind, "config_dir:", strlen ("config_dir:")) == 0){
-                       printf ("TODO Found: %s %llx\n", kind, offset);
+                       printf ("TODO Found: %s %llx\n", kind, (long long)offset);
                } else {
                        fprintf (stderr, "Unknown stream on embedded package: %s\n", kind);
                        exit (1);
index 4cf9f003d5584bb55b5c7ab30f9170661647c3f7..852d93e366217d9c50f45f136db0845950d02335 100644 (file)
@@ -201,7 +201,7 @@ 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 last_major_num_sections, mword last_los_memory_usage);
+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
index fd8b48f08a20f9fd418b3027a63467805ceba9ed..41843b19cc788f351ee7fd94c3ca211b16db227b 100644 (file)
@@ -1163,7 +1163,7 @@ finish_gray_stack (int generation, ScanCopyContext ctx)
        sgen_client_clear_togglerefs (start_addr, end_addr, ctx);
 
        TV_GETTIME (btv);
-       SGEN_LOG (2, "Finalize queue handling scan for %s generation: %lld usecs %d ephemeron rounds", generation_name (generation), TV_ELAPSED (atv, btv), ephemeron_rounds);
+       SGEN_LOG (2, "Finalize queue handling scan for %s generation: %lld usecs %d ephemeron rounds", generation_name (generation), (long long)TV_ELAPSED (atv, btv), ephemeron_rounds);
 
        /*
         * handle disappearing links
@@ -1557,7 +1557,7 @@ collect_nursery (SgenGrayQueue *unpin_queue, gboolean finish_up_concurrent_mark)
 
        TV_GETTIME (atv);
        time_minor_pinning += TV_ELAPSED (btv, atv);
-       SGEN_LOG (2, "Finding pinned pointers: %zd in %lld usecs", sgen_get_pinned_count (), TV_ELAPSED (btv, atv));
+       SGEN_LOG (2, "Finding pinned pointers: %zd in %lld usecs", sgen_get_pinned_count (), (long long)TV_ELAPSED (btv, atv));
        SGEN_LOG (4, "Start scan with %zd pinned objects", sgen_get_pinned_count ());
 
        sj = (ScanJob*)sgen_thread_pool_job_alloc ("scan remset", job_remembered_set_scan, sizeof (ScanJob));
@@ -1567,7 +1567,7 @@ collect_nursery (SgenGrayQueue *unpin_queue, gboolean finish_up_concurrent_mark)
        /* we don't have complete write barrier yet, so we scan all the old generation sections */
        TV_GETTIME (btv);
        time_minor_scan_remsets += TV_ELAPSED (atv, btv);
-       SGEN_LOG (2, "Old generation scan: %lld usecs", TV_ELAPSED (atv, btv));
+       SGEN_LOG (2, "Old generation scan: %lld usecs", (long long)TV_ELAPSED (atv, btv));
 
        sgen_pin_stats_print_class_stats ();
 
@@ -1608,7 +1608,7 @@ collect_nursery (SgenGrayQueue *unpin_queue, gboolean finish_up_concurrent_mark)
        sgen_client_binary_protocol_reclaim_end (GENERATION_NURSERY);
        TV_GETTIME (btv);
        time_minor_fragment_creation += TV_ELAPSED (atv, btv);
-       SGEN_LOG (2, "Fragment creation: %lld usecs, %lu bytes available", TV_ELAPSED (atv, btv), (unsigned long)fragment_total);
+       SGEN_LOG (2, "Fragment creation: %lld usecs, %lu bytes available", (long long)TV_ELAPSED (atv, btv), (unsigned long)fragment_total);
 
        if (consistency_check_at_minor_collection)
                sgen_check_major_refs ();
@@ -1785,7 +1785,7 @@ major_copy_or_mark_from_roots (size_t *old_next_pin_slot, CopyOrMarkFromRootsMod
 
        TV_GETTIME (btv);
        time_major_pinning += TV_ELAPSED (atv, btv);
-       SGEN_LOG (2, "Finding pinned pointers: %zd in %lld usecs", sgen_get_pinned_count (), TV_ELAPSED (atv, btv));
+       SGEN_LOG (2, "Finding pinned pointers: %zd in %lld usecs", sgen_get_pinned_count (), (long long)TV_ELAPSED (atv, btv));
        SGEN_LOG (4, "Start scan with %zd pinned objects", sgen_get_pinned_count ());
 
        major_collector.init_to_space ();
@@ -2231,6 +2231,7 @@ sgen_perform_collection (size_t requested_size, int generation_to_collect, const
        int overflow_generation_to_collect = -1;
        int oldest_generation_collected = generation_to_collect;
        const char *overflow_reason = NULL;
+       gboolean finish_concurrent = concurrent_collection_in_progress && (major_should_finish_concurrent_collection () || generation_to_collect == GENERATION_OLD);
 
        binary_protocol_collection_requested (generation_to_collect, requested_size, wait_to_finish ? 1 : 0);
 
@@ -2242,47 +2243,26 @@ sgen_perform_collection (size_t requested_size, int generation_to_collect, const
 
        TV_GETTIME (gc_total_start);
 
-       if (concurrent_collection_in_progress) {
-               /*
-                * If the concurrent worker is finished or we are asked to do a major collection
-                * then we finish the concurrent collection.
-                */
-               gboolean finish = major_should_finish_concurrent_collection () || generation_to_collect == GENERATION_OLD;
-
-               if (finish) {
-                       major_finish_concurrent_collection (wait_to_finish);
-                       oldest_generation_collected = GENERATION_OLD;
-               } else {
-                       SGEN_ASSERT (0, generation_to_collect == GENERATION_NURSERY, "Why aren't we finishing the concurrent collection?");
+       // FIXME: extract overflow reason
+       // FIXME: minor overflow for concurrent case
+       if (generation_to_collect == GENERATION_NURSERY && !finish_concurrent) {
+               if (concurrent_collection_in_progress)
                        major_update_concurrent_collection ();
-                       collect_nursery (NULL, FALSE);
-               }
 
-               goto done;
-       }
-
-       SGEN_ASSERT (0, !concurrent_collection_in_progress, "Why did this not get handled above?");
-
-       /*
-        * There's no concurrent collection in progress.  Collect the generation we're asked
-        * to collect.  If the major collector is concurrent and we're not forced to wait,
-        * start a concurrent collection.
-        */
-       // FIXME: extract overflow reason
-       if (generation_to_collect == GENERATION_NURSERY) {
-               if (collect_nursery (NULL, FALSE)) {
+               if (collect_nursery (NULL, FALSE) && !concurrent_collection_in_progress) {
                        overflow_generation_to_collect = GENERATION_OLD;
                        overflow_reason = "Minor overflow";
                }
+       } else if (finish_concurrent) {
+               major_finish_concurrent_collection (wait_to_finish);
+               oldest_generation_collected = GENERATION_OLD;
        } 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);
                        major_start_concurrent_collection (reason);
-                       // FIXME: set infos[0] properly
-                       goto done;
-               }
-
-               if (major_do_collection (reason, wait_to_finish)) {
+                       oldest_generation_collected = GENERATION_NURSERY;
+               } else if (major_do_collection (reason, wait_to_finish)) {
                        overflow_generation_to_collect = GENERATION_NURSERY;
                        overflow_reason = "Excessive pinning";
                }
@@ -2291,15 +2271,15 @@ sgen_perform_collection (size_t requested_size, int generation_to_collect, const
        TV_GETTIME (gc_end);
 
        memset (infos, 0, sizeof (infos));
-       infos [0].generation = generation_to_collect;
+       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);
 
-       SGEN_ASSERT (0, !concurrent_collection_in_progress, "Why did this not get handled above?");
-
        if (overflow_generation_to_collect != -1) {
+               SGEN_ASSERT (0, !concurrent_collection_in_progress, "We don't yet support overflow collections with the concurrent collector");
+
                /*
                 * We need to do an overflow collection, either because we ran out of memory
                 * or the nursery is fully pinned.
@@ -2331,7 +2311,6 @@ sgen_perform_collection (size_t requested_size, int generation_to_collect, const
                degraded_mode = 1;
        }
 
- done:
        g_assert (sgen_gray_object_queue_is_empty (&gray_queue));
 
        TV_GETTIME (gc_total_end);
index 44092858c112a57d0f83b318d9889aaea745af38..d5e149f1bef25ba7a516909f363d1f35659d8558 100644 (file)
@@ -840,6 +840,7 @@ struct _LOSObject {
 
 extern LOSObject *los_object_list;
 extern mword los_memory_usage;
+extern mword los_memory_usage_total;
 
 void sgen_los_free_object (LOSObject *obj);
 void* sgen_los_alloc_large_inner (GCVTable vtable, size_t size);
@@ -951,6 +952,8 @@ extern int default_nursery_size;
 extern guint32 tlab_size;
 extern NurseryClearPolicy nursery_clear_policy;
 extern gboolean sgen_try_free_some_memory;
+extern mword total_promoted_size;
+extern mword total_allocated_major;
 
 extern MonoCoopMutex gc_mutex;
 
index c22afd22f21d01c67998ee4e75dadedc444eb737..4b52eefb3f00cdf295504d29a21780667e99f144 100644 (file)
@@ -64,7 +64,10 @@ struct _LOSSection {
 
 /* We allow read only access on the list while sweep is not running */
 LOSObject *los_object_list = NULL;
+/* Memory used by LOS objects */
 mword los_memory_usage = 0;
+/* Total memory used by the LOS allocator */
+mword los_memory_usage_total = 0;
 
 static LOSSection *los_sections = NULL;
 static LOSFreeChunks *los_fast_free_lists [LOS_NUM_FAST_SIZES]; /* 0 is for larger sizes */
@@ -268,6 +271,7 @@ get_los_section_memory (size_t size)
        section->next = los_sections;
        los_sections = section;
 
+       los_memory_usage_total += LOS_SECTION_SIZE;
        ++los_num_sections;
 
        goto retry;
@@ -326,6 +330,7 @@ sgen_los_free_object (LOSObject *obj)
                size += sizeof (LOSObject);
                size = SGEN_ALIGN_UP_TO (size, pagesize);
                sgen_free_os_memory ((gpointer)SGEN_ALIGN_DOWN_TO ((mword)obj, pagesize), size, SGEN_ALLOC_HEAP);
+               los_memory_usage_total -= size;
                sgen_memgov_release_space (size, SPACE_LOS);
        } else {
                free_los_section_memory (obj, size + sizeof (LOSObject));
@@ -383,8 +388,10 @@ sgen_los_alloc_large_inner (GCVTable vtable, size_t size)
                size_t alloc_size = SGEN_ALIGN_UP_TO (obj_size, pagesize);
                if (sgen_memgov_try_alloc_space (alloc_size, SPACE_LOS)) {
                        obj = (LOSObject *)sgen_alloc_os_memory (alloc_size, (SgenAllocFlags)(SGEN_ALLOC_HEAP | SGEN_ALLOC_ACTIVATE), NULL);
-                       if (obj)
+                       if (obj) {
+                               los_memory_usage_total += alloc_size;
                                obj = randomize_los_object_start (obj, obj_size, alloc_size, pagesize);
+                       }
                }
        } else {
                obj = get_los_section_memory (size + sizeof (LOSObject));
@@ -476,6 +483,7 @@ sgen_los_sweep (void)
                        sgen_memgov_release_space (LOS_SECTION_SIZE, SPACE_LOS);
                        section = next;
                        --los_num_sections;
+                       los_memory_usage_total -= LOS_SECTION_SIZE;
                        continue;
                }
 
index 4c63191ad447d0ea5c9fb76bf44f9eba3ee19b46..dad1b249af11f4c68e570f0c11d63d9fe960b8d9 100644 (file)
@@ -652,6 +652,8 @@ alloc_obj (GCVTable vtable, size_t size, gboolean pinned, gboolean has_reference
        /* FIXME: assumes object layout */
        *(GCVTable*)obj = vtable;
 
+       total_allocated_major += block_obj_sizes [size_index]; 
+
        return (GCObject *)obj;
 }
 
@@ -1652,6 +1654,7 @@ sweep_job_func (void *thread_data_untyped, SgenThreadPoolJob *job)
 static void
 sweep_finish (void)
 {
+       mword used_slots_size = 0;
        int i;
 
        for (i = 0; i < num_block_obj_sizes; ++i) {
@@ -1665,9 +1668,11 @@ sweep_finish (void)
                } else {
                        evacuate_block_obj_sizes [i] = FALSE;
                }
+
+               used_slots_size += sweep_slots_used [i] * block_obj_sizes [i];
        }
 
-       sgen_memgov_major_post_sweep ();
+       sgen_memgov_major_post_sweep (used_slots_size);
 
        set_sweep_state (SWEEP_STATE_SWEPT, SWEEP_STATE_COMPACTING);
        if (concurrent_sweep)
index 7415ce3bff1b3ce63468582f8e1d4cc888e0fc3c..4648d8d761d444cbb8b6ec411d6fff6d3d2ad4da 100644 (file)
 
 #define MIN_MINOR_COLLECTION_ALLOWANCE ((mword)(DEFAULT_NURSERY_SIZE * default_allowance_nursery_size_ratio))
 
+mword total_promoted_size = 0;
+mword total_allocated_major = 0;
+static mword total_promoted_size_start;
+static mword total_allocated_major_end;
+
 /*Heap limits and allocation knobs*/
 static mword max_heap_size = ((mword)0)- ((mword)1);
 static mword soft_heap_limit = ((mword)0) - ((mword)1);
@@ -48,13 +53,11 @@ static mword major_collection_trigger_size;
 static mword major_pre_sweep_heap_size;
 static mword major_start_heap_size;
 
-static mword last_major_num_sections = 0;
-static mword last_los_memory_usage = 0;
-
 static gboolean need_calculate_minor_collection_allowance;
 
 /* The size of the LOS after the last major collection, after sweeping. */
 static mword last_collection_los_memory_usage = 0;
+static mword last_used_slots_size = 0;
 
 static mword sgen_memgov_available_free_space (void);
 
@@ -160,6 +163,7 @@ sgen_need_major_collection (mword space_needed)
 void
 sgen_memgov_minor_collection_start (void)
 {
+       total_promoted_size_start = total_promoted_size;
 }
 
 void
@@ -179,14 +183,14 @@ sgen_memgov_major_pre_sweep (void)
 }
 
 void
-sgen_memgov_major_post_sweep (void)
+sgen_memgov_major_post_sweep (mword used_slots_size)
 {
        mword num_major_sections = major_collector.get_num_major_sections ();
 
-       mono_trace (G_LOG_LEVEL_INFO, MONO_TRACE_GC, "GC_MAJOR_SWEEP: major %dK/%dK",
+       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,
-               last_major_num_sections * major_collector.section_size / 1024);
-       last_major_num_sections = num_major_sections;
+               (used_slots_size + total_allocated_major - total_allocated_major_end) / 1024);
+       last_used_slots_size = used_slots_size;
 }
 
 void
@@ -205,6 +209,7 @@ sgen_memgov_major_collection_end (gboolean forced)
 {
        last_collection_los_memory_usage = los_memory_usage;
 
+       total_allocated_major_end = total_allocated_major;
        if (forced) {
                sgen_get_major_collector ()->finish_sweeping ();
                sgen_memgov_calculate_minor_collection_allowance ();
@@ -222,9 +227,8 @@ sgen_memgov_collection_end (int generation, GGTimingInfo* info, int info_count)
        int i;
        for (i = 0; i < info_count; ++i) {
                if (info[i].generation != -1)
-                       sgen_client_log_timing (&info [i], last_major_num_sections, last_los_memory_usage);
+                       sgen_client_log_timing (&info [i], total_promoted_size - total_promoted_size_start, last_used_slots_size + total_allocated_major - total_allocated_major_end);
        }
-       last_los_memory_usage = los_memory_usage;
 }
 
 /*
index 9bcd55b4d80ad157417567512f7363438029f468..5e33b042837a983ed97cbbe1cbe84b8ac24833e9 100644 (file)
@@ -17,7 +17,7 @@ void sgen_memgov_minor_collection_start (void);
 void sgen_memgov_minor_collection_end (void);
 
 void sgen_memgov_major_pre_sweep (void);
-void sgen_memgov_major_post_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);
 
index 56a235aa30f42473511957269500bc45a86870c1..62c14a5392bc394ffef8420e9741629b458d1b2b 100644 (file)
@@ -22,6 +22,7 @@
 static inline GCObject*
 alloc_for_promotion (GCVTable vtable, GCObject *obj, size_t objsize, gboolean has_references)
 {
+       total_promoted_size += objsize;
        return major_collector.alloc_object (vtable, objsize, has_references);
 }
 
index 3606607809e954c2888f1dceae8b70d0ea4cb135..3b7ae668a203d537bd2372d15d62e7630c5db7e6 100644 (file)
@@ -254,8 +254,10 @@ alloc_for_promotion (GCVTable vtable, GCObject *obj, size_t objsize, gboolean ha
        int age;
 
        age = get_object_age (obj);
-       if (age >= promote_age)
+       if (age >= promote_age) {
+               total_promoted_size += objsize;
                return major_collector.alloc_object (vtable, objsize, has_references);
+       }
 
        /* Promote! */
        ++age;
@@ -265,8 +267,10 @@ alloc_for_promotion (GCVTable vtable, GCObject *obj, size_t objsize, gboolean ha
         age_alloc_buffers [age].next += objsize;
        } else {
                p = alloc_for_promotion_slow_path (age, objsize);
-               if (!p)
+               if (!p) {
+                       total_promoted_size += objsize;
                        return major_collector.alloc_object (vtable, objsize, has_references);
+               }
        }
 
        /* FIXME: assumes object layout */