2008-11-10 Hans Boehm <Hans.Boehm@hp.com> (Really Ivan Maidansky)

	* alloc.c (GC_try_to_collect_inner): Don't print redundant
	GC_bytes_allocd and GC_gc_no.
	(GC_stopped_mark): Print average world stop time.
	* include/private/gc_priv.h (MS_TIME_DIFF): Add cast.

diff --git a/ChangeLog b/ChangeLog
index 90ed1262f544b337fc9c9fe3407b32f3301f4872..75e10a209e52c54b08c6b32c11a019311f5004c1 100644 (file)
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,3 +1,9 @@
+2008-11-10  Hans Boehm <Hans.Boehm@hp.com> (Really Ivan Maidansky)
+       * alloc.c (GC_try_to_collect_inner): Don't print redundant
+       GC_bytes_allocd and GC_gc_no.
+       (GC_stopped_mark): Print average world stop time.
+       * include/private/gc_priv.h (MS_TIME_DIFF): Add cast.
+
 2008-11-10  Hans Boehm <Hans.Boehm@hp.com> (Really mostly Ivan Maidansky)
        * misc.c, doc/README.environment: Add support  for
        GC_FREE_SPACE_DIVISOR and GC-disable-incremental.

diff --git a/alloc.c b/alloc.c
index 8596a17b8fb7f273d841b0f258c8077cdd935ea5..f40282a63d9c494560fcdfd40eef4164bd7ef957 100644 (file)
--- a/alloc.c
+++ b/alloc.c
@@ -340,9 +340,7 @@ GC_bool GC_try_to_collect_inner(GC_stop_func stop_func)
 #   ifndef SMALL_CONFIG
       if (GC_print_stats) {
        GET_TIME(start_time);
-       GC_log_printf(
-          "Initiating full world-stop collection %lu after %ld allocd bytes\n",
-          (unsigned long)GC_gc_no+1, (long)GC_bytes_allocd);
+       GC_log_printf("Initiating full world-stop collection!\n");
       }
 #   endif
     GC_promote_black_lists();
@@ -463,6 +461,21 @@ GC_API int GC_CALL GC_collect_a_little(void)
 #ifdef MAKE_BACK_GRAPH
   void GC_build_back_graph(void);
 #endif
+
+#ifndef SMALL_CONFIG
+  /* Variables for world-stop average delay time statistic computation.        */
+  /* "divisor" is incremented every world-stop and halved when reached */
+  /* its maximum (or upon "total_time" oveflow).                       */
+  STATIC unsigned world_stopped_total_time = 0;
+  STATIC unsigned world_stopped_total_divisor = 0;
+# ifndef MAX_TOTAL_TIME_DIVISOR
+    /* We shall not use big values here (so "outdated" delay time      */
+    /* values would have less impact on "average" delay time value than        */
+    /* newer ones).                                                    */
+#   define MAX_TOTAL_TIME_DIVISOR 1000
+# endif
+#endif
+
 /*
  * Assumes lock is held, signals are disabled.
  * We stop the world.
@@ -475,17 +488,20 @@ GC_bool GC_stopped_mark(GC_stop_func stop_func)
     int dummy;
 #   ifndef SMALL_CONFIG
       CLOCK_TYPE start_time, current_time;
-       
-      if (GC_print_stats)
-       GET_TIME(start_time);
 #   endif
-
+       
 #   if !defined(REDIRECT_MALLOC) && (defined(MSWIN32) || defined(MSWINCE))
         GC_add_current_malloc_heap();
 #   endif
 #   if defined(REGISTER_LIBRARIES_EARLY)
         GC_cond_register_dynamic_libraries();
 #   endif
+
+#   ifndef SMALL_CONFIG
+      if (GC_print_stats)
+       GET_TIME(start_time);
+#   endif
+
     STOP_WORLD();
     IF_THREADS(GC_world_stopped = TRUE);
     if (GC_print_stats) {
@@ -540,9 +556,29 @@ GC_bool GC_stopped_mark(GC_stop_func stop_func)
     START_WORLD();
 #   ifndef SMALL_CONFIG
       if (GC_print_stats) {
+       unsigned long time_diff;
+       unsigned total_time, divisor;
        GET_TIME(current_time);
-       GC_log_printf("World-stopped marking took %lu msecs\n",
-                     MS_TIME_DIFF(current_time,start_time));
+       time_diff = MS_TIME_DIFF(current_time,start_time);
+
+       /* Compute new world-stop delay total time */
+       total_time = world_stopped_total_time;
+       divisor = world_stopped_total_divisor;
+       if ((int)total_time < 0 || divisor >= MAX_TOTAL_TIME_DIVISOR) {
+         /* Halve values if overflow occurs */
+         total_time >>= 1;
+         divisor >>= 1;
+       }
+       total_time += time_diff < (((unsigned)-1) >> 1) ?
+                       (unsigned)time_diff : ((unsigned)-1) >> 1;
+       /* Update old world_stopped_total_time and its divisor */
+       world_stopped_total_time = total_time;
+       world_stopped_total_divisor = ++divisor;
+       
+       GC_ASSERT(divisor != 0);
+       GC_log_printf(
+               "World-stopped marking took %lu msecs (%lu in average)\n",
+               time_diff, total_time / divisor);
       }
 #   endif
     return(TRUE);

diff --git a/include/private/gc_priv.h b/include/private/gc_priv.h
index b803469e1eb2c3573a174005ceb30b1d23b1f0e4..a86f765392b3fe27aa581674dc378dcec5b7ffd0 100644 (file)
--- a/include/private/gc_priv.h
+++ b/include/private/gc_priv.h
@@ -234,8 +234,9 @@ void GC_print_callers(struct callinfo info[NFRAMES]);
 #   define GET_TIME(x) { struct rusage rusage; \
                         getrusage (RUSAGE_SELF,  &rusage); \
                         x = rusage.ru_utime; }
-#   define MS_TIME_DIFF(a,b) ((double) (a.tv_sec - b.tv_sec) * 1000.0 \
-                               + (double) (a.tv_usec - b.tv_usec) / 1000.0)
+#   define MS_TIME_DIFF(a,b) \
+               ((unsigned long)((double) (a.tv_sec - b.tv_sec) * 1000.0 \
+                               + (double) (a.tv_usec - b.tv_usec) / 1000.0))
 #else /* !BSD_TIME */
 # if defined(MSWIN32) || defined(MSWINCE)
 #   include <windows.h>