Unify event logging and debug tracing.

  - tracing facilities are now enabled with -DTRACING, and -DDEBUG
    additionally enables debug-tracing.  -DEVENTLOG has been
    removed.

  - -debug now implies -eventlog

  - events can be printed to stderr instead of being sent to the
    binary .eventlog file by adding +RTS -v (which is implied by the
    +RTS -Dx options).

  - -Dx debug messages can be sent to the binary .eventlog file
    by adding +RTS -l.  This should help debugging by reducing
    the impact of debug tracing on execution time.

  - Various debug messages that duplicated the information in events
    have been removed.

diff --git a/compiler/main/StaticFlags.hs b/compiler/main/StaticFlags.hs
index ffa1584..8035211 100644 (file)
--- a/compiler/main/StaticFlags.hs
+++ b/compiler/main/StaticFlags.hs
@@ -406,8 +406,8 @@ way_details =
        , "-optc-DPROFILING" ],
 
     Way WayEventLog "l" True "RTS Event Logging"
        , "-optc-DPROFILING" ],
 
     Way WayEventLog "l" True "RTS Event Logging"

-       [ "-DEVENTLOG"
-       , "-optc-DEVENTLOG" ],
+       [ "-DTRACING"
+       , "-optc-DTRACING" ],

 
     Way WayTicky "t" True "Ticky-ticky Profiling"  
        [ "-DTICKY_TICKY"
 
     Way WayTicky "t" True "Ticky-ticky Profiling"  
        [ "-DTICKY_TICKY"

diff --git a/includes/rts/Config.h b/includes/rts/Config.h
index 9e4d683..b8aa246 100644 (file)
--- a/includes/rts/Config.h
+++ b/includes/rts/Config.h
@@ -27,6 +27,12 @@
 #define USING_LIBBFD 1
 #endif
 
 #define USING_LIBBFD 1
 #endif
 

+/* DEBUG implies TRACING
+ */
+#if defined(DEBUG)
+#define TRACING
+#endif
+

 /* -----------------------------------------------------------------------------
    Signals - supported on non-PAR versions of the runtime.  See RtsSignals.h.
    -------------------------------------------------------------------------- */
 /* -----------------------------------------------------------------------------
    Signals - supported on non-PAR versions of the runtime.  See RtsSignals.h.
    -------------------------------------------------------------------------- */

diff --git a/includes/rts/EventLogFormat.h b/includes/rts/EventLogFormat.h
index 363c1ca..a860822 100644 (file)
--- a/includes/rts/EventLogFormat.h
+++ b/includes/rts/EventLogFormat.h
@@ -112,11 +112,17 @@
 #define EVENT_GC_END              10 /* (cap)                       */
 #define EVENT_REQUEST_SEQ_GC      11 /* (cap)                       */
 #define EVENT_REQUEST_PAR_GC      12 /* (cap)                       */
 #define EVENT_GC_END              10 /* (cap)                       */
 #define EVENT_REQUEST_SEQ_GC      11 /* (cap)                       */
 #define EVENT_REQUEST_PAR_GC      12 /* (cap)                       */

-#define EVENT_CREATE_SPARK        13 /* (cap, thread)               */
-#define EVENT_SPARK_TO_THREAD     14 /* DEPRECATED! (cap, thread, spark_thread) */

 #define EVENT_CREATE_SPARK_THREAD 15 /* (cap, thread, spark_thread) */
 #define EVENT_CREATE_SPARK_THREAD 15 /* (cap, thread, spark_thread) */

+#define EVENT_LOG_CAP_MSG         16 /* (cap, message ...) */
+#define EVENT_LOG_MSG             17 /* (message ...) */
+#define EVENT_STARTUP             18 /* (num_capabilities) */

 
 

-#define NUM_EVENT_TAGS        16 
+#define NUM_EVENT_TAGS            19
+
+#if 0  /* DEPRECATED EVENTS: */
+#define EVENT_CREATE_SPARK        13 /* (cap, thread) */
+#define EVENT_SPARK_TO_THREAD     14 /* (cap, thread, spark_thread) */
+#endif

 
 /*
  * Status values for EVENT_STOP_THREAD
 
 /*
  * Status values for EVENT_STOP_THREAD

@@ -137,6 +143,7 @@ typedef StgWord16 EventTypeNum;
 typedef StgWord64 EventTimestamp; // in nanoseconds
 typedef StgWord64 EventThreadID;
 typedef StgWord16 EventCapNo;
 typedef StgWord64 EventTimestamp; // in nanoseconds
 typedef StgWord64 EventThreadID;
 typedef StgWord16 EventCapNo;

+typedef StgWord16 EventPayloadSize; // variable-size events

 
 #endif
 
 
 #endif
 

diff --git a/includes/rts/Flags.h b/includes/rts/Flags.h
index d9e3be9..3d0230a 100644 (file)
--- a/includes/rts/Flags.h
+++ b/includes/rts/Flags.h
@@ -65,13 +65,12 @@ struct DEBUG_FLAGS {
     rtsBool sanity;         /* 'S'   warning: might be expensive! */
     rtsBool stable;         /* 't' */
     rtsBool prof;           /* 'p' */
     rtsBool sanity;         /* 'S'   warning: might be expensive! */
     rtsBool stable;         /* 't' */
     rtsBool prof;           /* 'p' */

-    rtsBool eventlog;       /* 'e' */

     rtsBool linker;         /* 'l'   the object linker */
     rtsBool apply;          /* 'a' */
     rtsBool stm;            /* 'm' */
     rtsBool squeeze;        /* 'z'  stack squeezing & lazy blackholing */
     rtsBool hpc;           /* 'c' coverage */
     rtsBool linker;         /* 'l'   the object linker */
     rtsBool apply;          /* 'a' */
     rtsBool stm;            /* 'm' */
     rtsBool squeeze;        /* 'z'  stack squeezing & lazy blackholing */
     rtsBool hpc;           /* 'c' coverage */

-    rtsBool timestamp;          /* add timestamps to traces */
+    rtsBool sparks;        /* 'r' */

 };
 
 struct COST_CENTRE_FLAGS {
 };
 
 struct COST_CENTRE_FLAGS {

@@ -118,11 +117,12 @@ struct PROFILING_FLAGS {
 
 };
 
 
 };
 

-#ifdef EVENTLOG
-struct EVENTLOG_FLAGS {
-  rtsBool doEventLogging;
+struct TRACE_FLAGS {
+    rtsBool trace_stderr;
+    rtsBool timestamp;      /* show timestamp in stderr output */
+
+    rtsBool scheduler;      /* trace scheduler events */

 };
 };

-#endif

 
 struct CONCURRENT_FLAGS {
     int ctxtSwitchTime;                /* in milliseconds */
 
 struct CONCURRENT_FLAGS {
     int ctxtSwitchTime;                /* in milliseconds */

@@ -184,9 +184,7 @@ typedef struct _RTS_FLAGS {
     struct DEBUG_FLAGS      DebugFlags;
     struct COST_CENTRE_FLAGS CcFlags;
     struct PROFILING_FLAGS   ProfFlags;
     struct DEBUG_FLAGS      DebugFlags;
     struct COST_CENTRE_FLAGS CcFlags;
     struct PROFILING_FLAGS   ProfFlags;

-#ifdef EVENTLOG
-    struct EVENTLOG_FLAGS    EventLogFlags;
-#endif
+    struct TRACE_FLAGS       TraceFlags;

     struct TICKY_FLAGS      TickyFlags;
 
 #if defined(THREADED_RTS)
     struct TICKY_FLAGS      TickyFlags;
 
 #if defined(THREADED_RTS)

diff --git a/mk/config.mk.in b/mk/config.mk.in
index a516e6d..e1d79cf 100644 (file)
--- a/mk/config.mk.in
+++ b/mk/config.mk.in
@@ -241,7 +241,6 @@ endif
 #   debug_t    : debugging ticky-ticky profiling
 #   l           : event logging
 #   thr_l       : threaded and event logging
 #   debug_t    : debugging ticky-ticky profiling
 #   l           : event logging
 #   thr_l       : threaded and event logging

-#   thr_debug_l        : threaded and debugging and event logging

 #
 GhcRTSWays=l
 
 #
 GhcRTSWays=l
 

@@ -775,8 +774,7 @@ endif
 #
 # The ways currently defined.
 #
 #
 # The ways currently defined.
 #

-ALL_WAYS=v p t l s mp mg debug dyn thr thr_l debug_dyn thr_dyn thr_debug_dyn thr_p thr_debug thr_debug_l debug_p thr_debug_p
-USER_WAYS=a b c d e f g h j k l m n o A B
+ALL_WAYS=v p t l s mp mg debug dyn thr thr_l debug_dyn thr_dyn thr_debug_dyn thr_p thr_debug debug_p thr_debug_p

 
 #
 # The following ways currently have treated specially, p t mg,
 
 #
 # The following ways currently have treated specially, p t mg,

@@ -846,10 +844,6 @@ WAY_thr_debug_HC_OPTS=-optc-DTHREADED_RTS -optc-DDEBUG
 WAY_thr_debug_p_NAME=threaded debug profiling
 WAY_thr_debug_p_HC_OPTS=-optc-DTHREADED_RTS -optc-DDEBUG -prof
 
 WAY_thr_debug_p_NAME=threaded debug profiling
 WAY_thr_debug_p_HC_OPTS=-optc-DTHREADED_RTS -optc-DDEBUG -prof
 

-# Way 'thr_debug_l':
-WAY_thr_debug_l_NAME=threaded debug event logging
-WAY_thr_debug_l_HC_OPTS=-optc-DTHREADED_RTS -optc-DDEBUG -eventlog
-

 # Way 'dyn': build dynamic shared libraries
 WAY_dyn_NAME=dyn
 WAY_dyn_HC_OPTS=-fPIC -dynamic
 # Way 'dyn': build dynamic shared libraries
 WAY_dyn_NAME=dyn
 WAY_dyn_HC_OPTS=-fPIC -dynamic

@@ -866,57 +860,6 @@ WAY_thr_debug_dyn_HC_OPTS=-fPIC -dynamic -optc-DTHREADED_RTS -optc-DDEBUG
 WAY_debug_dyn_NAME=thr_dyn
 WAY_debug_dyn_HC_OPTS=-fPIC -dynamic -optc-DDEBUG
 
 WAY_debug_dyn_NAME=thr_dyn
 WAY_debug_dyn_HC_OPTS=-fPIC -dynamic -optc-DDEBUG
 

-#
-# Add user-way configurations here:
-#
-WAY_A_NAME=
-WAY_A_HC_OPTS=
-
-WAY_B_NAME=
-WAY_B_HC_OPTS=
-
-WAY_a_NAME=
-WAY_a_HC_OPTS=
-
-WAY_b_NAME=
-WAY_b_HC_OPTS=
-
-WAY_c_NAME=
-WAY_c_HC_OPTS=
-
-WAY_d_NAME=
-WAY_d_HC_OPTS=
-
-WAY_e_NAME=
-WAY_e_HC_OPTS=
-
-WAY_f_NAME=
-WAY_f_HC_OPTS=
-
-WAY_g_NAME=
-WAY_g_HC_OPTS=
-
-WAY_h_NAME=
-WAY_h_HC_OPTS=
-
-WAY_j_NAME=
-WAY_j_HC_OPTS=
-
-WAY_k_NAME=
-WAY_k_HC_OPTS=
-
-WAY_l_NAME=
-WAY_l_HC_OPTS=
-
-WAY_m_NAME=
-WAY_m_HC_OPTS=
-
-WAY_n_NAME=
-WAY_n_HC_OPTS=
-
-WAY_o_NAME=
-WAY_o_HC_OPTS=
-

 ################################################################################
 #
 #              31-bit-Int Core files
 ################################################################################
 #
 #              31-bit-Int Core files

diff --git a/rts/Capability.c b/rts/Capability.c
index 4264f0f..0e4d5a6 100644 (file)
--- a/rts/Capability.c
+++ b/rts/Capability.c
@@ -95,7 +95,7 @@ findSpark (Capability *cap)
       cap->sparks_converted++;
 
       // Post event for running a spark from capability's own pool.
       cap->sparks_converted++;
 
       // Post event for running a spark from capability's own pool.

-      postEvent(cap, EVENT_RUN_SPARK, cap->r.rCurrentTSO->id, 0);
+      traceSchedEvent(cap, EVENT_RUN_SPARK, cap->r.rCurrentTSO, 0);

 
       return spark;
   }
 
       return spark;
   }

@@ -127,14 +127,10 @@ findSpark (Capability *cap)
           }
 
           if (spark != NULL) {
           }
 
           if (spark != NULL) {

-              debugTrace(DEBUG_sched,
-                "cap %d: Stole a spark from capability %d",
-                         cap->no, robbed->no);

               cap->sparks_converted++;
 
               cap->sparks_converted++;
 

-              postEvent(cap, EVENT_STEAL_SPARK, 
-                        cap->r.rCurrentTSO->id, robbed->no);
-                        
+              traceSchedEvent(cap, EVENT_STEAL_SPARK, 
+                              cap->r.rCurrentTSO, robbed->no);

               
               return spark;
           }
               
               return spark;
           }

@@ -580,10 +576,9 @@ yieldCapability (Capability** pCap, Task *task)
     Capability *cap = *pCap;
 
     if (waiting_for_gc == PENDING_GC_PAR) {
     Capability *cap = *pCap;
 
     if (waiting_for_gc == PENDING_GC_PAR) {

-       debugTrace(DEBUG_sched, "capability %d: becoming a GC thread", cap->no);
-        postEvent(cap, EVENT_GC_START, 0, 0);
+        traceSchedEvent(cap, EVENT_GC_START, 0, 0);

         gcWorkerThread(cap);
         gcWorkerThread(cap);

-        postEvent(cap, EVENT_GC_END, 0, 0);
+        traceSchedEvent(cap, EVENT_GC_END, 0, 0);

         return;
     }
 
         return;
     }
 

@@ -790,8 +785,7 @@ shutdownCapability (Capability *cap, Task *task, rtsBool safe)
             continue;
         }
             
             continue;
         }
             

-        postEvent(cap, EVENT_SHUTDOWN, 0, 0);
-       debugTrace(DEBUG_sched, "capability %d is stopped.", cap->no);
+        traceSchedEvent(cap, EVENT_SHUTDOWN, 0, 0);

        RELEASE_LOCK(&cap->lock);
        break;
     }
        RELEASE_LOCK(&cap->lock);
        break;
     }

@@ -880,8 +874,6 @@ markSomeCapabilities (evac_fn evac, void *user, nat i0, nat delta,
 #endif
        for (task = cap->suspended_ccalling_tasks; task != NULL; 
             task=task->next) {
 #endif
        for (task = cap->suspended_ccalling_tasks; task != NULL; 
             task=task->next) {

-           debugTrace(DEBUG_sched,
-                      "evac'ing suspended TSO %lu", (unsigned long)task->suspended_tso->id);

            evac(user, (StgClosure **)(void *)&task->suspended_tso);
        }
 
            evac(user, (StgClosure **)(void *)&task->suspended_tso);
        }
 

diff --git a/rts/Printer.c b/rts/Printer.c
index 91bc6c8..1b6e57e 100644 (file)
--- a/rts/Printer.c
+++ b/rts/Printer.c
@@ -1051,6 +1051,15 @@ void prettyPrintClosure_ (StgClosure *obj)
     }
 }
 
     }
 }
 

+char *what_next_strs[] = {
+  [0]               = "(unknown)",
+  [ThreadRunGHC]    = "ThreadRunGHC",
+  [ThreadInterpret] = "ThreadInterpret",
+  [ThreadKilled]    = "ThreadKilled",
+  [ThreadRelocated] = "ThreadRelocated",
+  [ThreadComplete]  = "ThreadComplete"
+};
+

 #else /* DEBUG */
 void printPtr( StgPtr p )
 {
 #else /* DEBUG */
 void printPtr( StgPtr p )
 {

diff --git a/rts/Printer.h b/rts/Printer.h
index 33fe6a8..fd89aa0 100644 (file)
--- a/rts/Printer.h
+++ b/rts/Printer.h
@@ -30,6 +30,8 @@ extern void        printTSO        ( StgTSO *tso );
 extern void DEBUG_LoadSymbols( char *name );
 
 extern const char *lookupGHCName( void *addr );
 extern void DEBUG_LoadSymbols( char *name );
 
 extern const char *lookupGHCName( void *addr );

+
+extern char *what_next_strs[];

 #endif
 
 #pragma GCC visibility pop
 #endif
 
 #pragma GCC visibility pop

diff --git a/rts/RaiseAsync.c b/rts/RaiseAsync.c
index 4ca1cba..3078cf9 100644 (file)
--- a/rts/RaiseAsync.c
+++ b/rts/RaiseAsync.c
@@ -18,7 +18,6 @@
 #include "STM.h"
 #include "Sanity.h"
 #include "Profiling.h"
 #include "STM.h"
 #include "Sanity.h"
 #include "Profiling.h"

-#include "eventlog/EventLog.h"

 #if defined(mingw32_HOST_OS)
 #include "win32/IOManager.h"
 #endif
 #if defined(mingw32_HOST_OS)
 #include "win32/IOManager.h"
 #endif

@@ -162,11 +161,7 @@ throwTo (Capability *cap,  // the Capability we hold
               (unsigned long)source->id, (unsigned long)target->id);
 
 #ifdef DEBUG
               (unsigned long)source->id, (unsigned long)target->id);
 
 #ifdef DEBUG

-    if (traceClass(DEBUG_sched)) {
-       debugTraceBegin("throwTo: target");
-       printThreadStatus(target);
-       debugTraceEnd();
-    }
+    traceThreadStatus(DEBUG_sched, target);

 #endif
 
     goto check_target;
 #endif
 
     goto check_target;

diff --git a/rts/RtsFlags.c b/rts/RtsFlags.c
index 1204c59..d200bf2 100644 (file)
--- a/rts/RtsFlags.c
+++ b/rts/RtsFlags.c
@@ -106,12 +106,11 @@ void initRtsFlagsDefaults(void)
     RtsFlags.DebugFlags.stable         = rtsFalse;
     RtsFlags.DebugFlags.stm             = rtsFalse;
     RtsFlags.DebugFlags.prof           = rtsFalse;
     RtsFlags.DebugFlags.stable         = rtsFalse;
     RtsFlags.DebugFlags.stm             = rtsFalse;
     RtsFlags.DebugFlags.prof           = rtsFalse;

-    RtsFlags.DebugFlags.eventlog        = rtsFalse;

     RtsFlags.DebugFlags.apply          = rtsFalse;
     RtsFlags.DebugFlags.linker         = rtsFalse;
     RtsFlags.DebugFlags.squeeze                = rtsFalse;
     RtsFlags.DebugFlags.hpc            = rtsFalse;
     RtsFlags.DebugFlags.apply          = rtsFalse;
     RtsFlags.DebugFlags.linker         = rtsFalse;
     RtsFlags.DebugFlags.squeeze                = rtsFalse;
     RtsFlags.DebugFlags.hpc            = rtsFalse;

-    RtsFlags.DebugFlags.timestamp      = rtsFalse;
+    RtsFlags.DebugFlags.sparks         = rtsFalse;

 #endif
 
 #if defined(PROFILING)
 #endif
 
 #if defined(PROFILING)

@@ -135,8 +134,10 @@ void initRtsFlagsDefaults(void)
     RtsFlags.ProfFlags.bioSelector        = NULL;
 #endif
 
     RtsFlags.ProfFlags.bioSelector        = NULL;
 #endif
 

-#ifdef EVENTLOG
-    RtsFlags.EventLogFlags.doEventLogging = rtsFalse;
+#ifdef TRACING
+    RtsFlags.TraceFlags.trace_stderr  = rtsFalse;
+    RtsFlags.TraceFlags.timestamp     = rtsFalse;
+    RtsFlags.TraceFlags.scheduler     = rtsFalse;

 #endif
 
     RtsFlags.MiscFlags.tickInterval    = 20;  /* In milliseconds */
 #endif
 
     RtsFlags.MiscFlags.tickInterval    = 20;  /* In milliseconds */

@@ -196,9 +197,11 @@ usage_text[] = {
 "  -m<n>    Minimum % of heap which must be available (default 3%)",
 "  -G<n>    Number of generations (default: 2)",
 "  -T<n>    Number of steps in younger generations (default: 2)",
 "  -m<n>    Minimum % of heap which must be available (default 3%)",
 "  -G<n>    Number of generations (default: 2)",
 "  -T<n>    Number of steps in younger generations (default: 2)",

-"  -c<n>    Auto-enable compaction of the oldest generation when live data is",
-"           at least <n>% of the maximum heap size set with -M (default: 30%)",
-"  -c       Enable compaction for all major collections",
+"  -c<n>    Use in-place compaction instead of copying in the oldest generation",
+"           when live data is at least <n>% of the maximum heap size set with",
+"           -M (default: 30%)",
+"  -c       Use in-place compaction for all oldest generation collections",
+"           (the default is to use copying)",

 "  -w       Use mark-region for the oldest generation (experimental)",
 #if defined(THREADED_RTS)
 "  -I<sec>  Perform full GC after <sec> idle time (default: 0.3, 0 == off)",
 "  -w       Use mark-region for the oldest generation (experimental)",
 #if defined(THREADED_RTS)
 "  -I<sec>  Perform full GC after <sec> idle time (default: 0.3, 0 == off)",

@@ -252,9 +255,13 @@ usage_text[] = {
 # endif
 #endif /* PROFILING or PAR */
 
 # endif
 #endif /* PROFILING or PAR */
 

-#ifdef EVENTLOG
+#ifdef TRACING

 "",
 "",

-"  -l       Log runtime events (generates binary trace file <program>.eventlog)",
+"  -v       Log events to stderr",
+"  -l       Log events in binary format to the file <program>.eventlog",
+"  -vt      Include time stamps when tracing events to stderr with -v",
+"",
+"  -ls      Log scheduler events",

 "",
 #endif
 
 "",
 #endif
 

@@ -275,8 +282,6 @@ usage_text[] = {
 "            This sets the resolution for -C and the profile timer -i.",
 "            Default: 0.02 sec.",
 "",
 "            This sets the resolution for -C and the profile timer -i.",
 "            Default: 0.02 sec.",
 "",

-"  -vt       Time-stamp debug messages",
-"",

 #if defined(DEBUG)
 "  -Ds  DEBUG: scheduler",
 "  -Di  DEBUG: interpreter",
 #if defined(DEBUG)
 "  -Ds  DEBUG: scheduler",
 "  -Di  DEBUG: interpreter",

@@ -293,6 +298,10 @@ usage_text[] = {
 "  -Dm  DEBUG: stm",
 "  -Dz  DEBUG: stack squezing",
 "  -Dc  DEBUG: program coverage",
 "  -Dm  DEBUG: stm",
 "  -Dz  DEBUG: stack squezing",
 "  -Dc  DEBUG: program coverage",

+"  -Dr  DEBUG: sparks",
+"",
+"     NOTE: all -D options also enable -v automatically.  Use -l to create a",
+"     binary event log file instead.",

 "",
 #endif /* DEBUG */
 #if defined(THREADED_RTS) && !defined(NOSMP)
 "",
 #endif /* DEBUG */
 #if defined(THREADED_RTS) && !defined(NOSMP)

@@ -472,10 +481,10 @@ errorBelch("not built for: -prof"); \
 error = rtsTrue;
 #endif
 
 error = rtsTrue;
 #endif
 

-#ifdef EVENTLOG
-# define EVENTLOG_BUILD_ONLY(x)   x
+#ifdef TRACING
+# define TRACING_BUILD_ONLY(x)   x

 #else
 #else

-# define EVENTLOG_BUILD_ONLY(x) \
+# define TRACING_BUILD_ONLY(x) \

 errorBelch("not built for: -par-prof"); \
 error = rtsTrue;
 #endif
 errorBelch("not built for: -par-prof"); \
 error = rtsTrue;
 #endif

@@ -617,9 +626,6 @@ error = rtsTrue;
                      case 'p':
                          RtsFlags.DebugFlags.prof = rtsTrue;
                          break;
                      case 'p':
                          RtsFlags.DebugFlags.prof = rtsTrue;
                          break;

-                     case 'e':
-                         RtsFlags.DebugFlags.eventlog = rtsTrue;
-                          break;

                      case 'l':
                          RtsFlags.DebugFlags.linker = rtsTrue;
                          break;
                      case 'l':
                          RtsFlags.DebugFlags.linker = rtsTrue;
                          break;

@@ -635,10 +641,16 @@ error = rtsTrue;
                      case 'c':
                          RtsFlags.DebugFlags.hpc = rtsTrue;
                          break;
                      case 'c':
                          RtsFlags.DebugFlags.hpc = rtsTrue;
                          break;

+                     case 'r':
+                         RtsFlags.DebugFlags.sparks = rtsTrue;
+                         break;

                      default:
                          bad_option( rts_argv[arg] );
                      }
                  }
                      default:
                          bad_option( rts_argv[arg] );
                      }
                  }

+                  // -Dx also turns on -v.  Use -l to direct trace
+                  // events to the .eventlog file instead.
+                  RtsFlags.TraceFlags.trace_stderr = rtsTrue;

                  break;
              }
 #endif
                  break;
              }
 #endif

@@ -743,8 +755,19 @@ error = rtsTrue;
              /* =========== PROFILING ========================== */
 
               case 'l':
              /* =========== PROFILING ========================== */
 
               case 'l':

-#ifdef EVENTLOG
-                  RtsFlags.EventLogFlags.doEventLogging = rtsTrue;
+#ifdef TRACING
+                switch(rts_argv[arg][2]) {
+               case '\0':
+                  RtsFlags.TraceFlags.trace_stderr = rtsFalse;
+                  break;
+                case 's':
+                  RtsFlags.TraceFlags.scheduler = rtsTrue;
+                  break;
+               default:
+                   errorBelch("unknown RTS option: %s",rts_argv[arg]);
+                   error = rtsTrue;
+                   break;
+                }

 #else
                   errorBelch("not built for: -eventlog");
 #endif
 #else
                   errorBelch("not built for: -eventlog");
 #endif

@@ -1049,13 +1072,14 @@ error = rtsTrue;
 
              case 'v':
                 switch(rts_argv[arg][2]) {
 
              case 'v':
                 switch(rts_argv[arg][2]) {

-               case '\0':
-                   errorBelch("incomplete RTS option: %s",rts_argv[arg]);
-                   error = rtsTrue;
-                   break;
+#ifdef TRACING
+                case '\0':
+                    RtsFlags.TraceFlags.trace_stderr = rtsTrue;
+                    break;

                case 't':
                case 't':

-                   RtsFlags.DebugFlags.timestamp = rtsTrue;
+                   RtsFlags.TraceFlags.timestamp = rtsTrue;

                    break;
                    break;

+#endif

                case 's':
                case 'g':
                     // ignored for backwards-compat
                case 's':
                case 'g':
                     // ignored for backwards-compat

diff --git a/rts/RtsStartup.c b/rts/RtsStartup.c
index f0b2170..1c39cf8 100644 (file)
--- a/rts/RtsStartup.c
+++ b/rts/RtsStartup.c
@@ -29,7 +29,6 @@
 #include "sm/BlockAlloc.h"
 #include "Trace.h"
 #include "Stable.h"
 #include "sm/BlockAlloc.h"
 #include "Trace.h"
 #include "Stable.h"

-#include "eventlog/EventLog.h"

 #include "Hash.h"
 #include "Profiling.h"
 #include "Timer.h"
 #include "Hash.h"
 #include "Profiling.h"
 #include "Timer.h"

@@ -146,7 +145,7 @@ hs_init(int *argc, char **argv[])
 #endif
 
     /* initTracing must be after setupRtsFlags() */
 #endif
 
     /* initTracing must be after setupRtsFlags() */

-#ifdef DEBUG
+#ifdef TRACING

     initTracing();
 #endif
 
     initTracing();
 #endif
 

@@ -190,12 +189,6 @@ hs_init(int *argc, char **argv[])
 
     initProfiling1();
 
 
     initProfiling1();
 

-#ifdef EVENTLOG
-    if (RtsFlags.EventLogFlags.doEventLogging) {
-        initEventLogging();
-    }
-#endif
-

     /* start the virtual timer 'subsystem'. */
     initTimer();
     startTimer();
     /* start the virtual timer 'subsystem'. */
     initTimer();
     startTimer();

@@ -421,11 +414,9 @@ hs_exit_(rtsBool wait_foreign)
     if (prof_file != NULL) fclose(prof_file);
 #endif
 
     if (prof_file != NULL) fclose(prof_file);
 #endif
 

-#ifdef EVENTLOG
-    if (RtsFlags.EventLogFlags.doEventLogging) {
-        endEventLogging();
-        freeEventLogging();
-    }
+#ifdef TRACING
+    endTracing();
+    freeTracing();

 #endif
 
 #if defined(TICKY_TICKY)
 #endif
 
 #if defined(TICKY_TICKY)

diff --git a/rts/Schedule.c b/rts/Schedule.c
index 05315a5..9b261cf 100644 (file)
--- a/rts/Schedule.c
+++ b/rts/Schedule.c
@@ -26,7 +26,6 @@
 #include "Proftimer.h"
 #include "ProfHeap.h"
 #include "Weak.h"
 #include "Proftimer.h"
 #include "ProfHeap.h"
 #include "Weak.h"

-#include "eventlog/EventLog.h"

 #include "sm/GC.h" // waitForGcThreads, releaseGCThreads, N
 #include "Sparks.h"
 #include "Capability.h"
 #include "sm/GC.h" // waitForGcThreads, releaseGCThreads, N
 #include "Sparks.h"
 #include "Capability.h"

@@ -172,17 +171,6 @@ static void deleteAllThreads (Capability *cap);
 static void deleteThread_(Capability *cap, StgTSO *tso);
 #endif
 
 static void deleteThread_(Capability *cap, StgTSO *tso);
 #endif
 

-#ifdef DEBUG
-static char *whatNext_strs[] = {
-  [0]               = "(unknown)",
-  [ThreadRunGHC]    = "ThreadRunGHC",
-  [ThreadInterpret] = "ThreadInterpret",
-  [ThreadKilled]    = "ThreadKilled",
-  [ThreadRelocated] = "ThreadRelocated",
-  [ThreadComplete]  = "ThreadComplete"
-};
-#endif
-

 /* -----------------------------------------------------------------------------
  * Putting a thread on the run queue: different scheduling policies
  * -------------------------------------------------------------------------- */
 /* -----------------------------------------------------------------------------
  * Putting a thread on the run queue: different scheduling policies
  * -------------------------------------------------------------------------- */

@@ -249,9 +237,7 @@ schedule (Capability *initialCapability, Task *task)
   // The sched_mutex is *NOT* held
   // NB. on return, we still hold a capability.
 
   // The sched_mutex is *NOT* held
   // NB. on return, we still hold a capability.
 

-  debugTrace (DEBUG_sched, 
-             "### NEW SCHEDULER LOOP (task: %p, cap: %p)",
-             task, initialCapability);
+  debugTrace (DEBUG_sched, "cap %d: schedule()", initialCapability->no);

 
   schedulePreLoop();
 
 
   schedulePreLoop();
 

@@ -396,12 +382,11 @@ schedule (Capability *initialCapability, Task *task)
       
        if (bound) {
            if (bound == task) {
       
        if (bound) {
            if (bound == task) {

-               debugTrace(DEBUG_sched,
-                          "### Running thread %lu in bound thread", (unsigned long)t->id);

                // yes, the Haskell thread is bound to the current native thread
            } else {
                debugTrace(DEBUG_sched,
                // yes, the Haskell thread is bound to the current native thread
            } else {
                debugTrace(DEBUG_sched,

-                          "### thread %lu bound to another OS thread", (unsigned long)t->id);
+                          "thread %lu bound to another OS thread",
+                           (unsigned long)t->id);

                // no, bound to a different Haskell thread: pass to that thread
                pushOnRunQueue(cap,t);
                continue;
                // no, bound to a different Haskell thread: pass to that thread
                pushOnRunQueue(cap,t);
                continue;

@@ -410,7 +395,8 @@ schedule (Capability *initialCapability, Task *task)
            // The thread we want to run is unbound.
            if (task->tso) { 
                debugTrace(DEBUG_sched,
            // The thread we want to run is unbound.
            if (task->tso) { 
                debugTrace(DEBUG_sched,

-                          "### this OS thread cannot run thread %lu", (unsigned long)t->id);
+                          "this OS thread cannot run thread %lu",
+                           (unsigned long)t->id);

                // no, the current native thread is bound to a different
                // Haskell thread, so pass it to any worker thread
                pushOnRunQueue(cap,t);
                // no, the current native thread is bound to a different
                // Haskell thread, so pass it to any worker thread
                pushOnRunQueue(cap,t);

@@ -445,9 +431,6 @@ run_thread:
     // that.
     cap->r.rCurrentTSO = t;
 
     // that.
     cap->r.rCurrentTSO = t;
 

-    debugTrace(DEBUG_sched, "-->> running thread %ld %s ...", 
-                             (long)t->id, whatNext_strs[t->what_next]);
-

     startHeapProfTimer();
 
     // Check for exceptions blocked on this thread
     startHeapProfTimer();
 
     // Check for exceptions blocked on this thread

@@ -485,7 +468,7 @@ run_thread:
     }
 #endif
 
     }
 #endif
 

-    postEvent(cap, EVENT_RUN_THREAD, t->id, 0);
+    traceSchedEvent(cap, EVENT_RUN_THREAD, t, 0);

 
     switch (prev_what_next) {
        
 
     switch (prev_what_next) {
        

@@ -535,7 +518,7 @@ run_thread:
     t->saved_winerror = GetLastError();
 #endif
 
     t->saved_winerror = GetLastError();
 #endif
 

-    postEvent (cap, EVENT_STOP_THREAD, t->id, ret);
+    traceSchedEvent (cap, EVENT_STOP_THREAD, t, ret);

 
 #if defined(THREADED_RTS)
     // If ret is ThreadBlocked, and this Task is bound to the TSO that
 
 #if defined(THREADED_RTS)
     // If ret is ThreadBlocked, and this Task is bound to the TSO that

@@ -545,9 +528,6 @@ run_thread:
     // that task->cap != cap.  We better yield this Capability
     // immediately and return to normaility.
     if (ret == ThreadBlocked) {
     // that task->cap != cap.  We better yield this Capability
     // immediately and return to normaility.
     if (ret == ThreadBlocked) {

-       debugTrace(DEBUG_sched,
-                  "--<< thread %lu (%s) stopped: blocked",
-                  (unsigned long)t->id, whatNext_strs[t->what_next]);

         force_yield = rtsTrue;
         goto yield;
     }
         force_yield = rtsTrue;
         goto yield;
     }

@@ -798,7 +778,7 @@ schedulePushWork(Capability *cap USED_IF_THREADS,
                    debugTrace(DEBUG_sched, "pushing thread %lu to capability %d", (unsigned long)t->id, free_caps[i]->no);
                    appendToRunQueue(free_caps[i],t);
 
                    debugTrace(DEBUG_sched, "pushing thread %lu to capability %d", (unsigned long)t->id, free_caps[i]->no);
                    appendToRunQueue(free_caps[i],t);
 

-        postEvent (cap, EVENT_MIGRATE_THREAD, t->id, free_caps[i]->no);
+                    traceSchedEvent (cap, EVENT_MIGRATE_THREAD, t, free_caps[i]->no);

 
                    if (t->bound) { t->bound->cap = free_caps[i]; }
                    t->cap = free_caps[i];
 
                    if (t->bound) { t->bound->cap = free_caps[i]; }
                    t->cap = free_caps[i];

@@ -822,7 +802,7 @@ schedulePushWork(Capability *cap USED_IF_THREADS,
                    if (spark != NULL) {
                        debugTrace(DEBUG_sched, "pushing spark %p to capability %d", spark, free_caps[i]->no);
 
                    if (spark != NULL) {
                        debugTrace(DEBUG_sched, "pushing spark %p to capability %d", spark, free_caps[i]->no);
 

-      postEvent(free_caps[i], EVENT_STEAL_SPARK, t->id, cap->no);
+      traceSchedEvent(free_caps[i], EVENT_STEAL_SPARK, t, cap->no);

 
                        newSpark(&(free_caps[i]->r), spark);
                    }
 
                        newSpark(&(free_caps[i]->r), spark);
                    }

@@ -1106,7 +1086,7 @@ scheduleHandleHeapOverflow( Capability *cap, StgTSO *t )
        
        debugTrace(DEBUG_sched,
                   "--<< thread %ld (%s) stopped: requesting a large block (size %ld)\n", 
        
        debugTrace(DEBUG_sched,
                   "--<< thread %ld (%s) stopped: requesting a large block (size %ld)\n", 

-                  (long)t->id, whatNext_strs[t->what_next], blocks);
+                  (long)t->id, what_next_strs[t->what_next], blocks);

     
        // don't do this if the nursery is (nearly) full, we'll GC first.
        if (cap->r.rCurrentNursery->link != NULL ||
     
        // don't do this if the nursery is (nearly) full, we'll GC first.
        if (cap->r.rCurrentNursery->link != NULL ||

@@ -1160,10 +1140,6 @@ scheduleHandleHeapOverflow( Capability *cap, StgTSO *t )
        }
     }
     
        }
     }
     

-    debugTrace(DEBUG_sched,
-              "--<< thread %ld (%s) stopped: HeapOverflow",
-              (long)t->id, whatNext_strs[t->what_next]);
-

     if (cap->r.rHpLim == NULL || cap->context_switch) {
         // Sometimes we miss a context switch, e.g. when calling
         // primitives in a tight loop, MAYBE_GC() doesn't check the
     if (cap->r.rHpLim == NULL || cap->context_switch) {
         // Sometimes we miss a context switch, e.g. when calling
         // primitives in a tight loop, MAYBE_GC() doesn't check the

@@ -1185,10 +1161,6 @@ scheduleHandleHeapOverflow( Capability *cap, StgTSO *t )
 static void
 scheduleHandleStackOverflow (Capability *cap, Task *task, StgTSO *t)
 {
 static void
 scheduleHandleStackOverflow (Capability *cap, Task *task, StgTSO *t)
 {

-    debugTrace (DEBUG_sched,
-               "--<< thread %ld (%s) stopped, StackOverflow", 
-               (long)t->id, whatNext_strs[t->what_next]);
-

     /* just adjust the stack for this thread, then pop it back
      * on the run queue.
      */
     /* just adjust the stack for this thread, then pop it back
      * on the run queue.
      */

@@ -1230,11 +1202,7 @@ scheduleHandleYield( Capability *cap, StgTSO *t, nat prev_what_next )
     if (t->what_next != prev_what_next) {
        debugTrace(DEBUG_sched,
                   "--<< thread %ld (%s) stopped to switch evaluators", 
     if (t->what_next != prev_what_next) {
        debugTrace(DEBUG_sched,
                   "--<< thread %ld (%s) stopped to switch evaluators", 

-                  (long)t->id, whatNext_strs[t->what_next]);
-    } else {
-       debugTrace(DEBUG_sched,
-                  "--<< thread %ld (%s) stopped, yielding",
-                  (long)t->id, whatNext_strs[t->what_next]);
+                  (long)t->id, what_next_strs[t->what_next]);

     }
 #endif
     
     }
 #endif
     

@@ -1281,12 +1249,7 @@ scheduleHandleThreadBlocked( StgTSO *t
     //      exception, see maybePerformBlockedException().
 
 #ifdef DEBUG
     //      exception, see maybePerformBlockedException().
 
 #ifdef DEBUG

-    if (traceClass(DEBUG_sched)) {
-       debugTraceBegin("--<< thread %lu (%s) stopped: ", 
-                       (unsigned long)t->id, whatNext_strs[t->what_next]);
-       printThreadBlockage(t);
-       debugTraceEnd();
-    }
+    traceThreadStatus(DEBUG_sched, t);

 #endif
 }
 
 #endif
 }
 

@@ -1303,8 +1266,6 @@ scheduleHandleThreadFinished (Capability *cap STG_UNUSED, Task *task, StgTSO *t)
      * We also end up here if the thread kills itself with an
      * uncaught exception, see Exception.cmm.
      */
      * We also end up here if the thread kills itself with an
      * uncaught exception, see Exception.cmm.
      */

-    debugTrace(DEBUG_sched, "--++ thread %lu (%s) finished", 
-              (unsigned long)t->id, whatNext_strs[t->what_next]);

 
     // blocked exceptions can now complete, even if the thread was in
     // blocked mode (see #2910).  This unconditionally calls
 
     // blocked exceptions can now complete, even if the thread was in
     // blocked mode (see #2910).  This unconditionally calls

@@ -1456,7 +1417,7 @@ scheduleDoGC (Capability *cap, Task *task USED_IF_THREADS, rtsBool force_major)
     
     if (gc_type == PENDING_GC_SEQ)
     {
     
     if (gc_type == PENDING_GC_SEQ)
     {

-        postEvent(cap, EVENT_REQUEST_SEQ_GC, 0, 0);
+        traceSchedEvent(cap, EVENT_REQUEST_SEQ_GC, 0, 0);

         // single-threaded GC: grab all the capabilities
         for (i=0; i < n_capabilities; i++) {
             debugTrace(DEBUG_sched, "ready_to_gc, grabbing all the capabilies (%d/%d)", i, n_capabilities);
         // single-threaded GC: grab all the capabilities
         for (i=0; i < n_capabilities; i++) {
             debugTrace(DEBUG_sched, "ready_to_gc, grabbing all the capabilies (%d/%d)", i, n_capabilities);

@@ -1479,7 +1440,7 @@ scheduleDoGC (Capability *cap, Task *task USED_IF_THREADS, rtsBool force_major)
     {
         // multi-threaded GC: make sure all the Capabilities donate one
         // GC thread each.
     {
         // multi-threaded GC: make sure all the Capabilities donate one
         // GC thread each.

-        postEvent(cap, EVENT_REQUEST_PAR_GC, 0, 0);
+        traceSchedEvent(cap, EVENT_REQUEST_PAR_GC, 0, 0);

         debugTrace(DEBUG_sched, "ready_to_gc, grabbing GC threads");
 
         waitForGcThreads(cap);
         debugTrace(DEBUG_sched, "ready_to_gc, grabbing GC threads");
 
         waitForGcThreads(cap);

@@ -1505,8 +1466,7 @@ delete_threads_and_gc:
     heap_census = scheduleNeedHeapProfile(rtsTrue);
 
 #if defined(THREADED_RTS)
     heap_census = scheduleNeedHeapProfile(rtsTrue);
 
 #if defined(THREADED_RTS)

-    postEvent(cap, EVENT_GC_START, 0, 0);
-    debugTrace(DEBUG_sched, "doing GC");
+    traceSchedEvent(cap, EVENT_GC_START, 0, 0);

     // reset waiting_for_gc *before* GC, so that when the GC threads
     // emerge they don't immediately re-enter the GC.
     waiting_for_gc = 0;
     // reset waiting_for_gc *before* GC, so that when the GC threads
     // emerge they don't immediately re-enter the GC.
     waiting_for_gc = 0;

@@ -1514,7 +1474,7 @@ delete_threads_and_gc:
 #else
     GarbageCollect(force_major || heap_census, 0, cap);
 #endif
 #else
     GarbageCollect(force_major || heap_census, 0, cap);
 #endif

-    postEvent(cap, EVENT_GC_END, 0, 0);
+    traceSchedEvent(cap, EVENT_GC_END, 0, 0);

 
     if (recent_activity == ACTIVITY_INACTIVE && force_major)
     {
 
     if (recent_activity == ACTIVITY_INACTIVE && force_major)
     {

@@ -1829,10 +1789,7 @@ suspendThread (StgRegTable *reg)
   task = cap->running_task;
   tso = cap->r.rCurrentTSO;
 
   task = cap->running_task;
   tso = cap->r.rCurrentTSO;
 

-  postEvent(cap, EVENT_STOP_THREAD, tso->id, THREAD_SUSPENDED_FOREIGN_CALL);
-  debugTrace(DEBUG_sched, 
-            "thread %lu did a safe foreign call", 
-            (unsigned long)cap->r.rCurrentTSO->id);
+  traceSchedEvent(cap, EVENT_STOP_THREAD, tso, THREAD_SUSPENDED_FOREIGN_CALL);

 
   // XXX this might not be necessary --SDM
   tso->what_next = ThreadRunGHC;
 
   // XXX this might not be necessary --SDM
   tso->what_next = ThreadRunGHC;

@@ -1858,13 +1815,6 @@ suspendThread (StgRegTable *reg)
   
   RELEASE_LOCK(&cap->lock);
 
   
   RELEASE_LOCK(&cap->lock);
 

-#if defined(THREADED_RTS)
-  /* Preparing to leave the RTS, so ensure there's a native thread/task
-     waiting to take over.
-  */
-  debugTrace(DEBUG_sched, "thread %lu: leaving RTS", (unsigned long)tso->id);
-#endif
-

   errno = saved_errno;
 #if mingw32_HOST_OS
   SetLastError(saved_winerror);
   errno = saved_errno;
 #if mingw32_HOST_OS
   SetLastError(saved_winerror);

@@ -1902,8 +1852,7 @@ resumeThread (void *task_)
     task->suspended_tso = NULL;
     tso->_link = END_TSO_QUEUE; // no write barrier reqd
 
     task->suspended_tso = NULL;
     tso->_link = END_TSO_QUEUE; // no write barrier reqd
 

-    postEvent(cap, EVENT_RUN_THREAD, tso->id, 0);
-    debugTrace(DEBUG_sched, "thread %lu: re-entering RTS", (unsigned long)tso->id);
+    traceSchedEvent(cap, EVENT_RUN_THREAD, tso, tso->what_next);

     
     if (tso->why_blocked == BlockedOnCCall) {
         // avoid locking the TSO if we don't have to
     
     if (tso->why_blocked == BlockedOnCCall) {
         // avoid locking the TSO if we don't have to

@@ -1959,7 +1908,7 @@ scheduleThreadOn(Capability *cap, StgWord cpu USED_IF_THREADS, StgTSO *tso)
     if (cpu == cap->no) {
        appendToRunQueue(cap,tso);
     } else {
     if (cpu == cap->no) {
        appendToRunQueue(cap,tso);
     } else {

-        postEvent (cap, EVENT_MIGRATE_THREAD, tso->id, capabilities[cpu].no);
+        traceSchedEvent (cap, EVENT_MIGRATE_THREAD, tso, capabilities[cpu].no);

        wakeupThreadOnCapability(cap, &capabilities[cpu], tso);
     }
 #else
        wakeupThreadOnCapability(cap, &capabilities[cpu], tso);
     }
 #else

diff --git a/rts/Schedule.h b/rts/Schedule.h
index c83b6fd..1214fd8 100644 (file)
--- a/rts/Schedule.h
+++ b/rts/Schedule.h
@@ -12,7 +12,7 @@
 
 #include "rts/OSThreads.h"
 #include "Capability.h"
 
 #include "rts/OSThreads.h"
 #include "Capability.h"

-#include "eventlog/EventLog.h"
+#include "Trace.h"

 
 #pragma GCC visibility push(hidden)
 
 
 #pragma GCC visibility push(hidden)
 

@@ -136,7 +136,7 @@ appendToRunQueue (Capability *cap, StgTSO *tso)
        setTSOLink(cap, cap->run_queue_tl, tso);
     }
     cap->run_queue_tl = tso;
        setTSOLink(cap, cap->run_queue_tl, tso);
     }
     cap->run_queue_tl = tso;

-    postEvent (cap, EVENT_THREAD_RUNNABLE, tso->id, 0);
+    traceSchedEvent (cap, EVENT_THREAD_RUNNABLE, tso, 0);

 }
 
 /* Push a thread on the beginning of the run queue.
 }
 
 /* Push a thread on the beginning of the run queue.

diff --git a/rts/Sparks.c b/rts/Sparks.c
index ff4beb7..a17b78c 100644 (file)
--- a/rts/Sparks.c
+++ b/rts/Sparks.c
@@ -47,7 +47,7 @@ createSparkThread (Capability *cap)
     tso = createIOThread (cap, RtsFlags.GcFlags.initialStkSize, 
                           &base_GHCziConc_runSparks_closure);
 
     tso = createIOThread (cap, RtsFlags.GcFlags.initialStkSize, 
                           &base_GHCziConc_runSparks_closure);
 

-    postEvent(cap, EVENT_CREATE_SPARK_THREAD, 0, tso->id);
+    traceSchedEvent(cap, EVENT_CREATE_SPARK_THREAD, 0, tso->id);

 
     appendToRunQueue(cap,tso);
 }
 
     appendToRunQueue(cap,tso);
 }

@@ -75,8 +75,6 @@ newSpark (StgRegTable *reg, StgClosure *p)
 
     cap->sparks_created++;
 
 
     cap->sparks_created++;
 

-    postEvent(cap, EVENT_CREATE_SPARK, cap->r.rCurrentTSO->id, 0);
-

     return 1;
 }
 
     return 1;
 }
 

@@ -140,7 +138,7 @@ pruneSparkQueue (evac_fn evac, void *user, Capability *cap)
     pool->top     &= pool->moduloSize;
     pool->topBound = pool->top;
 
     pool->top     &= pool->moduloSize;
     pool->topBound = pool->top;
 

-    debugTrace(DEBUG_sched,
+    debugTrace(DEBUG_sparks,

                "markSparkQueue: current spark queue len=%ld; (hd=%ld; tl=%ld)",
                sparkPoolSize(pool), pool->bottom, pool->top);
 
                "markSparkQueue: current spark queue len=%ld; (hd=%ld; tl=%ld)",
                sparkPoolSize(pool), pool->bottom, pool->top);
 

@@ -238,9 +236,9 @@ pruneSparkQueue (evac_fn evac, void *user, Capability *cap)
     pool->bottom = (oldBotInd <= botInd) ? botInd : (botInd + pool->size); 
     // first free place we did not use (corrected by wraparound)
 
     pool->bottom = (oldBotInd <= botInd) ? botInd : (botInd + pool->size); 
     // first free place we did not use (corrected by wraparound)
 

-    debugTrace(DEBUG_sched, "pruned %d sparks", pruned_sparks);
+    debugTrace(DEBUG_sparks, "pruned %d sparks", pruned_sparks);

     
     

-    debugTrace(DEBUG_sched,
+    debugTrace(DEBUG_sparks,

                "new spark queue len=%ld; (hd=%ld; tl=%ld)",
                sparkPoolSize(pool), pool->bottom, pool->top);
 
                "new spark queue len=%ld; (hd=%ld; tl=%ld)",
                sparkPoolSize(pool), pool->bottom, pool->top);
 

@@ -274,7 +272,7 @@ traverseSparkQueue (evac_fn evac, void *user, Capability *cap)
       top++;
     }
 
       top++;
     }
 

-    debugTrace(DEBUG_sched,
+    debugTrace(DEBUG_sparks,

                "traversed spark queue, len=%ld; (hd=%ld; tl=%ld)",
                sparkPoolSize(pool), pool->bottom, pool->top);
 }
                "traversed spark queue, len=%ld; (hd=%ld; tl=%ld)",
                sparkPoolSize(pool), pool->bottom, pool->top);
 }

diff --git a/rts/Threads.c b/rts/Threads.c
index 8318e28..3b209ea 100644 (file)
--- a/rts/Threads.c
+++ b/rts/Threads.c
@@ -106,11 +106,9 @@ createThread(Capability *cap, nat size)
     g0s0->threads = tso;
     RELEASE_LOCK(&sched_mutex);
     
     g0s0->threads = tso;
     RELEASE_LOCK(&sched_mutex);
     

-    postEvent (cap, EVENT_CREATE_THREAD, tso->id, 0);
+    // ToDo: report the stack size in the event?
+    traceSchedEvent (cap, EVENT_CREATE_THREAD, tso, tso->stack_size);

 
 

-    debugTrace(DEBUG_sched,
-              "created thread %ld, stack size = %lx words", 
-              (long)tso->id, (long)tso->stack_size);

     return tso;
 }
 
     return tso;
 }
 

@@ -256,10 +254,7 @@ unblockOne_ (Capability *cap, StgTSO *tso,
   cap->context_switch = 1;
 #endif
 
   cap->context_switch = 1;
 #endif
 

-  postEvent (cap, EVENT_THREAD_WAKEUP, tso->id, tso->cap->no);
-
-  debugTrace(DEBUG_sched, "waking up thread %ld on cap %d",
-            (long)tso->id, tso->cap->no);
+  traceSchedEvent (cap, EVENT_THREAD_WAKEUP, tso, tso->cap->no);

 
   return next;
 }
 
   return next;
 }

@@ -357,6 +352,7 @@ printThreadBlockage(StgTSO *tso)
   }
 }
 
   }
 }
 

+

 void
 printThreadStatus(StgTSO *t)
 {
 void
 printThreadStatus(StgTSO *t)
 {

diff --git a/rts/Trace.c b/rts/Trace.c
index 0a47ea3..eee3554 100644 (file)
--- a/rts/Trace.c
+++ b/rts/Trace.c
@@ -6,25 +6,18 @@
  *
  * ---------------------------------------------------------------------------*/
 
  *
  * ---------------------------------------------------------------------------*/
 

-#ifdef DEBUG
-

 // external headers
 #include "Rts.h"
 // external headers
 #include "Rts.h"

-#include "rts/Flags.h"
+
+#ifdef TRACING

 
 // internal headers
 #include "Trace.h"
 #include "GetTime.h"
 #include "Stats.h"
 
 // internal headers
 #include "Trace.h"
 #include "GetTime.h"
 #include "Stats.h"

-
-/*
-  Features we want:
-    - multiple log message classes
-    - outpout thread ID & time on each message
-    - thread-safe
-    - trace source locations?
-    - break into the debugger?
-*/
+#include "eventlog/EventLog.h"
+#include "Threads.h"
+#include "Printer.h"

 
 StgWord32 classes_enabled; // not static due to inline funcs
 
 
 StgWord32 classes_enabled; // not static due to inline funcs
 

@@ -32,8 +25,9 @@ StgWord32 classes_enabled; // not static due to inline funcs
 static Mutex trace_utx;
 #endif
 
 static Mutex trace_utx;
 #endif
 

-#define DEBUG_FLAG(name, class) \
-    if (RtsFlags.DebugFlags.name) classes_enabled |= class;
+/* ---------------------------------------------------------------------------
+   Starting up / shuttting down the tracing facilities
+ --------------------------------------------------------------------------- */

 
 void initTracing (void)
 {
 
 void initTracing (void)
 {

@@ -41,7 +35,13 @@ void initTracing (void)
     initMutex(&trace_utx);
 #endif
 
     initMutex(&trace_utx);
 #endif
 

+#ifdef DEBUG
+#define DEBUG_FLAG(name, class) \
+    if (RtsFlags.DebugFlags.name) classes_enabled |= class;
+

     DEBUG_FLAG(scheduler,    DEBUG_sched);
     DEBUG_FLAG(scheduler,    DEBUG_sched);

+    DEBUG_FLAG(scheduler,    TRACE_sched); // -Ds enabled all sched events
+

     DEBUG_FLAG(interpreter,  DEBUG_interp);
     DEBUG_FLAG(weak,         DEBUG_weak);
     DEBUG_FLAG(gccafs,       DEBUG_gccafs);
     DEBUG_FLAG(interpreter,  DEBUG_interp);
     DEBUG_FLAG(weak,         DEBUG_weak);
     DEBUG_FLAG(gccafs,       DEBUG_gccafs);

@@ -51,40 +51,204 @@ void initTracing (void)
     DEBUG_FLAG(stable,       DEBUG_stable);
     DEBUG_FLAG(stm,          DEBUG_stm);
     DEBUG_FLAG(prof,         DEBUG_prof);
     DEBUG_FLAG(stable,       DEBUG_stable);
     DEBUG_FLAG(stm,          DEBUG_stm);
     DEBUG_FLAG(prof,         DEBUG_prof);

-    DEBUG_FLAG(eventlog,     DEBUG_eventlog);

     DEBUG_FLAG(linker,       DEBUG_linker);
     DEBUG_FLAG(squeeze,      DEBUG_squeeze);
     DEBUG_FLAG(hpc,          DEBUG_hpc);
     DEBUG_FLAG(linker,       DEBUG_linker);
     DEBUG_FLAG(squeeze,      DEBUG_squeeze);
     DEBUG_FLAG(hpc,          DEBUG_hpc);

+    DEBUG_FLAG(sparks,       DEBUG_sparks);
+#endif
+
+#define TRACE_FLAG(name, class) \
+    if (RtsFlags.TraceFlags.name) classes_enabled |= class;
+
+    TRACE_FLAG(scheduler, TRACE_sched);
+
+    initEventLogging();
+}
+
+void endTracing (void)
+{
+    endEventLogging();
+}
+
+void freeTracing (void)
+{
+    freeEventLogging();

 }
 
 }
 

+/* ---------------------------------------------------------------------------
+   Emitting trace messages/events
+ --------------------------------------------------------------------------- */
+
+#ifdef DEBUG

 static void tracePreface (void)
 {
 #ifdef THREADED_RTS
     debugBelch("%12lx: ", (unsigned long)osThreadId());
 #endif
 static void tracePreface (void)
 {
 #ifdef THREADED_RTS
     debugBelch("%12lx: ", (unsigned long)osThreadId());
 #endif

-    if (RtsFlags.DebugFlags.timestamp) {
+    if (RtsFlags.TraceFlags.timestamp) {

        debugBelch("%9" FMT_Word64 ": ", stat_getElapsedTime());
     }
 }
        debugBelch("%9" FMT_Word64 ": ", stat_getElapsedTime());
     }
 }

+#endif
+
+#ifdef DEBUG
+static char *thread_stop_reasons[] = {
+    [HeapOverflow] = "heap overflow",
+    [StackOverflow] = "stack overflow",
+    [ThreadYielding] = "yielding",
+    [ThreadBlocked] = "blocked",
+    [ThreadFinished] = "finished",
+    [THREAD_SUSPENDED_FOREIGN_CALL] = "suspended while making a foreign call"
+};
+#endif

 
 

-void trace (StgWord32 class, const char *str, ...)
+#ifdef DEBUG
+static void traceSchedEvent_stderr (Capability *cap, EventTypeNum tag, 
+                                    StgTSO *tso, 
+                                    StgWord64 other STG_UNUSED)

 {
 {

-    va_list ap;
-    va_start(ap,str);
+    ACQUIRE_LOCK(&trace_utx);
+
+    tracePreface();
+    switch (tag) {
+    case EVENT_CREATE_THREAD:   // (cap, thread)
+        debugBelch("cap %d: created thread %ld\n", cap->no, tso->id);
+        break;
+    case EVENT_RUN_THREAD:      //  (cap, thread)
+        debugBelch("cap %d: running thread %ld (%s)\n", cap->no, 
+                   tso->id, what_next_strs[tso->what_next]);
+        break;
+    case EVENT_THREAD_RUNNABLE: // (cap, thread)
+        debugBelch("cap %d: thread %ld appended to run queue\n", 
+                   cap->no, tso->id);
+        break;
+    case EVENT_RUN_SPARK:       // (cap, thread)
+        debugBelch("cap %d: thread %ld running a spark\n", 
+                   cap->no, tso->id);
+        break;
+    case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
+        debugBelch("cap %d: creating spark thread %ld\n", 
+                   cap->no, (long)other);
+        break;
+    case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
+        debugBelch("cap %d: thread %ld migrating to cap %d\n", 
+                   cap->no, tso->id, (int)other);
+        break;
+    case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
+        debugBelch("cap %d: thread %ld stealing a spark from cap %d\n", 
+                   cap->no, tso->id, (int)other);
+        break;
+    case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
+        debugBelch("cap %d: waking up thread %ld on cap %d\n", 
+                   cap->no, tso->id, (int)other);
+        break;
+        
+    case EVENT_STOP_THREAD:     // (cap, thread, status)
+        debugBelch("cap %d: thread %ld stopped (%s)\n", 
+                   cap->no, tso->id, thread_stop_reasons[other]);
+        break;
+    case EVENT_SHUTDOWN:        // (cap)
+        debugBelch("cap %d: shutting down\n", cap->no);
+        break;
+    case EVENT_REQUEST_SEQ_GC:  // (cap)
+        debugBelch("cap %d: requesting sequential GC\n", cap->no);
+        break;
+    case EVENT_REQUEST_PAR_GC:  // (cap)
+        debugBelch("cap %d: requesting parallel GC\n", cap->no);
+        break;
+    case EVENT_GC_START:        // (cap)
+        debugBelch("cap %d: starting GC\n", cap->no);
+        break;
+    case EVENT_GC_END:          // (cap)
+        debugBelch("cap %d: finished GC\n", cap->no);
+        break;
+    default:
+        debugBelch("cap %2d: thread %ld: event %d\n\n", cap->no, tso->id, tag);
+        break;
+    }
+
+    RELEASE_LOCK(&trace_utx);
+}
+#endif

 
 

+void traceSchedEvent_ (Capability *cap, EventTypeNum tag, 
+                      StgTSO *tso, StgWord64 other)
+{
+#ifdef DEBUG
+    if (RtsFlags.TraceFlags.trace_stderr) {
+        traceSchedEvent_stderr(cap, tag, tso, other);
+    } else
+#endif
+    {
+        postSchedEvent(cap,tag,tso ? tso->id : 0,other);
+    }
+}
+
+#ifdef DEBUG
+static void traceCap_stderr(Capability *cap, char *msg, va_list ap)
+{

     ACQUIRE_LOCK(&trace_utx);
 
     ACQUIRE_LOCK(&trace_utx);
 

-    if ((classes_enabled & class) != 0) {
-       tracePreface();
-       vdebugBelch(str,ap);
-       debugBelch("\n");
+    tracePreface();
+    debugBelch("cap %2d: ", cap->no);
+    vdebugBelch(msg,ap);
+    debugBelch("\n");
+
+    RELEASE_LOCK(&trace_utx);
+}
+#endif
+
+void traceCap_(Capability *cap, char *msg, va_list ap)
+{
+#ifdef DEBUG
+    if (RtsFlags.TraceFlags.trace_stderr) {
+        traceCap_stderr(cap, msg, ap);
+    } else
+#endif
+    {
+        postCapMsg(cap, msg, ap);

     }
     }

+}
+
+#ifdef DEBUG
+static void trace_stderr(char *msg, va_list ap)
+{
+    ACQUIRE_LOCK(&trace_utx);
+
+    tracePreface();
+    vdebugBelch(msg,ap);
+    debugBelch("\n");

 
     RELEASE_LOCK(&trace_utx);
 
     RELEASE_LOCK(&trace_utx);

+}
+#endif

 
 

-    va_end(ap);
+void trace_(char *msg, va_list ap)
+{
+#ifdef DEBUG
+    if (RtsFlags.TraceFlags.trace_stderr) {
+        trace_stderr(msg, ap);
+    } else
+#endif
+    {
+        postMsg(msg, ap);
+    }

 }
 
 }
 

+void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
+{
+#ifdef DEBUG
+    if (RtsFlags.TraceFlags.trace_stderr) {
+        printThreadStatus(tso);
+    } else
+#endif
+    {
+        /* nothing - no event for this one yet */
+    }
+}
+
+
+#ifdef DEBUG

 void traceBegin (const char *str, ...)
 {
     va_list ap;
 void traceBegin (const char *str, ...)
 {
     va_list ap;

@@ -101,5 +265,6 @@ void traceEnd (void)
     debugBelch("\n");
     RELEASE_LOCK(&trace_utx);
 }
     debugBelch("\n");
     RELEASE_LOCK(&trace_utx);
 }

+#endif /* DEBUG */

 
 

-#endif
+#endif /* TRACING */

diff --git a/rts/Trace.h b/rts/Trace.h
index 8820075..3ab6df4 100644 (file)
--- a/rts/Trace.h
+++ b/rts/Trace.h
@@ -1,61 +1,55 @@
 /* -----------------------------------------------------------------------------
  *
 /* -----------------------------------------------------------------------------
  *

- * (c) The GHC Team 2006
+ * (c) The GHC Team, 2008-2009

  *
  *

- * Debug tracing.  
- *
- * This is a layer over RtsMessages, which provides for generating
- * trace messages with timestamps and task IDs attached
- * automatically.  Also, multiple classes of messages are supported,
- * which can be enabled separately via RTS flags.
- *
- * All debug trace messages go through here.
+ * Support for fast binary event logging.

  *
  * ---------------------------------------------------------------------------*/
 
 #ifndef TRACE_H
 #define TRACE_H
 
  *
  * ---------------------------------------------------------------------------*/
 
 #ifndef TRACE_H
 #define TRACE_H
 

+#include "rts/EventLogFormat.h"
+#include "Capability.h"
+

 #pragma GCC visibility push(hidden)
 
 // -----------------------------------------------------------------------------
 #pragma GCC visibility push(hidden)
 
 // -----------------------------------------------------------------------------

-// Tracing functions
+// Posting events

 // -----------------------------------------------------------------------------
 
 // -----------------------------------------------------------------------------
 

+INLINE_HEADER void trace (StgWord32 class, char *msg, ...);
+

 #ifdef DEBUG
 #ifdef DEBUG

+INLINE_HEADER void debugTrace (StgWord32 class, char *msg, ...);
+#endif

 
 

-void initTracing (void);
+INLINE_HEADER void traceSchedEvent (Capability *cap, EventTypeNum tag, 
+                                    StgTSO *tso, StgWord64 other);

 
 

-// The simple way:
-void trace (StgWord32 class, const char *str, ...)
-    GNUC3_ATTRIBUTE(format (printf, 2, 3));
-
-// The harder way: sometimes we want to generate a trace message that
-// consists of multiple components generated by different functions.
-// So we provide the functionality of trace() split into 3 parts: 
-//   - traceClass(): a check that the required class is enabled
-//   - traceBegin(): print the beginning of the trace message
-//   - traceEnd(): complete the trace message (release the lock too).
-// 
-INLINE_HEADER rtsBool traceClass (StgWord32 class);
+INLINE_HEADER void traceCap (StgWord32 class, Capability *cap,
+                             char *msg, ...);

 
 

-void traceBegin (const char *str, ...)
-    GNUC3_ATTRIBUTE(format (printf, 1, 2));
+INLINE_HEADER void traceThreadStatus (StgWord32 class, StgTSO *tso);

 
 

+INLINE_HEADER rtsBool traceClass (StgWord32 class);
+
+#ifdef DEBUG
+void traceBegin (const char *str, ...);

 void traceEnd (void);
 void traceEnd (void);

+#endif

 
 

-#define debugTrace(class, str, ...) trace(class,str, ## __VA_ARGS__)
-// variable arg macros are C99, and supported by gcc.
-#define debugTraceBegin(str, ...) traceBegin(str, ## __VA_ARGS__)
-#define debugTraceEnd() traceEnd()
+// -----------------------------------------------------------------------------
+// EventLog API
+// -----------------------------------------------------------------------------

 
 

-#else /* !DEBUG */
+#if defined(TRACING)

 
 

-#define debugTrace(class, str, ...) /* nothing */
-#define debugTraceBegin(str, ...) /* nothing */
-#define debugTraceEnd() /* nothing */
+void initTracing (void);
+void endTracing  (void);
+void freeTracing (void);

 
 

-#endif
+#endif /* TRACING */

 
 // -----------------------------------------------------------------------------
 // Message classes, these may be OR-ed together
 
 // -----------------------------------------------------------------------------
 // Message classes, these may be OR-ed together

@@ -77,18 +71,120 @@ void traceEnd (void);
 #define DEBUG_linker              (1<<12)
 #define DEBUG_squeeze              (1<<13)
 #define DEBUG_hpc                  (1<<14)
 #define DEBUG_linker              (1<<12)
 #define DEBUG_squeeze              (1<<13)
 #define DEBUG_hpc                  (1<<14)

-#define DEBUG_eventlog            (1<<15)
+#define DEBUG_sparks              (1<<15)
+
+// events
+#define TRACE_sched                (1<<16)

 
 // -----------------------------------------------------------------------------
 // PRIVATE below here
 // -----------------------------------------------------------------------------
 
 
 // -----------------------------------------------------------------------------
 // PRIVATE below here
 // -----------------------------------------------------------------------------
 

+#ifdef TRACING
+

 extern StgWord32 classes_enabled;
 
 extern StgWord32 classes_enabled;
 

-INLINE_HEADER rtsBool
-traceClass (StgWord32 class) { return (classes_enabled & class); }
+INLINE_HEADER rtsBool traceClass (StgWord32 class) 
+{ return (classes_enabled & class); }
+
+void traceSchedEvent_ (Capability *cap, EventTypeNum tag, 
+                       StgTSO *tso, StgWord64 other);
+
+/* 
+ * Trace an event to the capability's event buffer.
+ */
+INLINE_HEADER void traceSchedEvent(Capability *cap, EventTypeNum tag, 
+                                   StgTSO *tso, StgWord64 other)
+{
+    if (traceClass(TRACE_sched)) {
+        traceSchedEvent_(cap, tag, tso, other);
+    }
+}
+
+void traceCap_(Capability *cap, char *msg, va_list ap);
+
+/* 
+ * Trace a log message
+ */
+INLINE_HEADER void traceCap (StgWord32 class, Capability *cap, char *msg, ...)
+{
+    va_list ap;
+    va_start(ap,msg);
+    if (traceClass(class)) {
+        traceCap_(cap, msg, ap);
+    }
+    va_end(ap);
+}
+
+void trace_(char *msg, va_list ap);
+
+/* 
+ * Trace a log message
+ */
+INLINE_HEADER void trace (StgWord32 class, char *msg, ...)
+{
+    va_list ap;
+    va_start(ap,msg);
+    if (traceClass(class)) {
+        trace_(msg, ap);
+    }
+    va_end(ap);
+}

 
 

-// -----------------------------------------------------------------------------
+#ifdef DEBUG
+INLINE_HEADER void debugTrace (StgWord32 class, char *msg, ...)
+{
+    va_list ap;
+    va_start(ap,msg);
+    if (traceClass(class)) {
+        trace_(msg, ap);
+    }
+    va_end(ap);
+}
+#else
+
+#define debugTrace(class, str, ...) /* nothing */
+// variable arg macros are C99, and supported by gcc.
+
+#endif
+
+void traceThreadStatus_ (StgTSO *tso);
+
+INLINE_HEADER void traceThreadStatus (StgWord32 class, StgTSO *tso)
+{
+    if (traceClass(class)) {
+        traceThreadStatus_(tso);
+    }
+}    
+
+#else /* !TRACING */
+
+INLINE_HEADER rtsBool traceClass (StgWord32 class STG_UNUSED) 
+{ return rtsFalse; }
+
+INLINE_HEADER void traceSchedEvent (Capability *cap STG_UNUSED,
+                                    EventTypeNum tag STG_UNUSED, 
+                                    StgTSO *tso STG_UNUSED,
+                                    StgWord64 other STG_UNUSED)
+{ /* nothing */ }
+
+INLINE_HEADER void traceCap (StgWord32 class STG_UNUSED,
+                             Capability *cap STG_UNUSED,
+                             char *msg STG_UNUSED, ...)
+{ /* nothing */ }
+
+INLINE_HEADER void trace (StgWord32 class STG_UNUSED, 
+                          char *msg STG_UNUSED, ...)
+{ /* nothing */ }
+
+#define debugTrace(class, str, ...) /* nothing */
+// variable arg macros are C99, and supported by gcc.
+
+INLINE_HEADER void traceThreadStatus (StgWord32 class STG_UNUSED, 
+                                      StgTSO *tso STG_UNUSED)
+{ /* nothing */ }
+
+#endif /* TRACING */

 
 #pragma GCC visibility pop
 
 
 #pragma GCC visibility pop
 

diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c
index bd887af..4486116 100644 (file)
--- a/rts/eventlog/EventLog.c
+++ b/rts/eventlog/EventLog.c
@@ -6,16 +6,17 @@
  *
  * ---------------------------------------------------------------------------*/
 
  *
  * ---------------------------------------------------------------------------*/
 

-#ifdef EVENTLOG
-

 #include "PosixSource.h"
 #include "Rts.h"
 
 #include "PosixSource.h"
 #include "Rts.h"
 

-#include "EventLog.h"
+#ifdef TRACING
+
+#include "Trace.h"

 #include "Capability.h"
 #include "Trace.h"
 #include "RtsUtils.h"
 #include "Stats.h"
 #include "Capability.h"
 #include "Trace.h"
 #include "RtsUtils.h"
 #include "Stats.h"

+#include "EventLog.h"

 
 #include <string.h> 
 #include <stdio.h>
 
 #include <string.h> 
 #include <stdio.h>

@@ -36,7 +37,12 @@ typedef struct _EventsBuf {
   StgWord64 size;
 } EventsBuf;
 
   StgWord64 size;
 } EventsBuf;
 

-EventsBuf *eventsBuf;
+EventsBuf *capEventBuf; // one EventsBuf for each Capability
+
+EventsBuf eventBuf; // an EventsBuf not associated with any Capability
+#ifdef THREADED_RTS
+Mutex eventBufMutex; // protected by this mutex
+#endif

 
 char *EventDesc[] = {
   [EVENT_CREATE_THREAD]       = "Create thread",
 
 char *EventDesc[] = {
   [EVENT_CREATE_THREAD]       = "Create thread",

@@ -52,9 +58,10 @@ char *EventDesc[] = {
   [EVENT_GC_END]              = "Finished GC",
   [EVENT_REQUEST_SEQ_GC]      = "Request sequential GC",
   [EVENT_REQUEST_PAR_GC]      = "Request parallel GC",
   [EVENT_GC_END]              = "Finished GC",
   [EVENT_REQUEST_SEQ_GC]      = "Request sequential GC",
   [EVENT_REQUEST_PAR_GC]      = "Request parallel GC",

-  [EVENT_CREATE_SPARK]        = "Create spark",
-  [EVENT_SPARK_TO_THREAD]     = "Spark to thread", /* DEPRECATED! */
-  [EVENT_CREATE_SPARK_THREAD] = "Create spark thread"
+  [EVENT_CREATE_SPARK_THREAD] = "Create spark thread",
+  [EVENT_LOG_CAP_MSG]         = "Log Capability message",
+  [EVENT_LOG_MSG]             = "Log message",
+  [EVENT_STARTUP]             = "Startup"

 };
 
 // Event type. 
 };
 
 // Event type. 

@@ -83,6 +90,7 @@ static void endEventTypes(EventsBuf *eb);
 static void postEventType(EventsBuf *eb, EventType *et);
 
 static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum);
 static void postEventType(EventsBuf *eb, EventType *et);
 
 static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum);

+static StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes);

 
 static inline void postWord8(EventsBuf *eb, StgWord8 i)
 {
 
 static inline void postWord8(EventsBuf *eb, StgWord8 i)
 {

@@ -107,6 +115,12 @@ static inline void postWord64(EventsBuf *eb, StgWord64 i)
     postWord32(eb, (StgWord32)i);
 }
 
     postWord32(eb, (StgWord32)i);
 }
 

+static inline void postBuf(EventsBuf *eb, StgWord8 *buf, nat size)
+{
+    memcpy(eb->pos, buf, size);
+    eb->pos += size;
+}
+

 static inline void postEventTypeNum(EventsBuf *eb, EventTypeNum etNum)
 { postWord16(eb, etNum); }
 
 static inline void postEventTypeNum(EventsBuf *eb, EventTypeNum etNum)
 { postWord16(eb, etNum); }
 

@@ -119,6 +133,9 @@ static inline void postThreadID(EventsBuf *eb, EventThreadID id)
 static inline void postCapNo(EventsBuf *eb, EventCapNo no)
 { postWord16(eb,no); }
 
 static inline void postCapNo(EventsBuf *eb, EventCapNo no)
 { postWord16(eb,no); }
 

+static inline void postPayloadSize(EventsBuf *eb, EventPayloadSize size)
+{ postWord16(eb,size); }
+

 static inline void postInt8(EventsBuf *eb, StgInt8 i)
 { postWord8(eb, (StgWord8)i); }
 
 static inline void postInt8(EventsBuf *eb, StgInt8 i)
 { postWord8(eb, (StgWord8)i); }
 

@@ -136,8 +153,7 @@ void
 initEventLogging(void)
 {
     StgWord8 t, c;
 initEventLogging(void)
 {
     StgWord8 t, c;

-
-    debugTrace(DEBUG_eventlog, "intiEventLog: start");
+    nat n_caps;

 
     event_log_filename = stgMallocBytes(strlen(prog_name) + 10,
                                         "initEventLogging");
 
     event_log_filename = stgMallocBytes(strlen(prog_name) + 10,
                                         "initEventLogging");

@@ -164,18 +180,25 @@ initEventLogging(void)
      * Use a single buffer to store the header with event types, then flush 
      * the buffer so all buffers are empty for writing events.
      */
      * Use a single buffer to store the header with event types, then flush 
      * the buffer so all buffers are empty for writing events.
      */

-    eventsBuf = stgMallocBytes(n_capabilities * sizeof(EventsBuf),"initEventLogging");
-
-    for (c = 0; c < n_capabilities; ++c) {
+#ifdef THREADED_RTS
+    // XXX n_capabilities hasn't been initislised yet
+    n_caps = RtsFlags.ParFlags.nNodes;
+#else
+    n_caps = 1;
+#endif
+    capEventBuf = stgMallocBytes(n_caps * sizeof(EventsBuf),"initEventLogging");
+
+    for (c = 0; c < n_caps; ++c) {

         // Init buffer for events.
         // Init buffer for events.

-        initEventsBuf(&eventsBuf[c], EVENT_LOG_SIZE);
+        initEventsBuf(&capEventBuf[c], EVENT_LOG_SIZE);

     }
     }

+    initEventsBuf(&eventBuf, EVENT_LOG_SIZE);

 
     // Write in buffer: the header begin marker.
 
     // Write in buffer: the header begin marker.

-    beginHeader(&eventsBuf[0]);
+    beginHeader(&eventBuf);

 
     // Mark beginning of event types in the header.
 
     // Mark beginning of event types in the header.

-    beginEventTypes(&eventsBuf[0]);
+    beginEventTypes(&eventBuf);

     for (t = 0; t < NUM_EVENT_TAGS; ++t) {
 
         eventTypes[t].etNum = t;
     for (t = 0; t < NUM_EVENT_TAGS; ++t) {
 
         eventTypes[t].etNum = t;

@@ -185,7 +208,6 @@ initEventLogging(void)
         case EVENT_CREATE_THREAD:   // (cap, thread)
         case EVENT_RUN_THREAD:      // (cap, thread)
         case EVENT_THREAD_RUNNABLE: // (cap, thread)
         case EVENT_CREATE_THREAD:   // (cap, thread)
         case EVENT_RUN_THREAD:      // (cap, thread)
         case EVENT_THREAD_RUNNABLE: // (cap, thread)

-        case EVENT_CREATE_SPARK:    // (cap, thread)

         case EVENT_RUN_SPARK:       // (cap, thread)
         case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
             eventTypes[t].size = sizeof(EventCapNo) + sizeof(EventThreadID);
         case EVENT_RUN_SPARK:       // (cap, thread)
         case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
             eventTypes[t].size = sizeof(EventCapNo) + sizeof(EventThreadID);

@@ -210,29 +232,35 @@ initEventLogging(void)
         case EVENT_GC_END:          // (cap)
             eventTypes[t].size = sizeof(EventCapNo);
             break;
         case EVENT_GC_END:          // (cap)
             eventTypes[t].size = sizeof(EventCapNo);
             break;

+
+        case EVENT_LOG_MSG:          // (msg)
+        case EVENT_LOG_CAP_MSG:      // (cap,msg)
+            eventTypes[t].size = 0xffff;
+            break;
+
+        default:
+            continue; /* ignore deprecated events */

         }
 
         // Write in buffer: the start event type.
         }
 
         // Write in buffer: the start event type.

-        postEventType(&eventsBuf[0], &eventTypes[t]);
+        postEventType(&eventBuf, &eventTypes[t]);

     }
 
     // Mark end of event types in the header.
     }
 
     // Mark end of event types in the header.

-    endEventTypes(&eventsBuf[0]);
+    endEventTypes(&eventBuf);

     
     // Write in buffer: the header end marker.
     
     // Write in buffer: the header end marker.

-    endHeader(&eventsBuf[0]);
+    endHeader(&eventBuf);

     
     // Prepare event buffer for events (data).
     
     // Prepare event buffer for events (data).

-    beginData(&eventsBuf[0]);
+    beginData(&eventBuf);

     
     

-    // Flush eventsBuf with header.
+    // Flush capEventBuf with header.

     /*
      * Flush header and data begin marker to the file, thus preparing the
      * file to have events written to it.
      */
     /*
      * Flush header and data begin marker to the file, thus preparing the
      * file to have events written to it.
      */

-    printAndClearEventBuf(&eventsBuf[0]);
-
-    debugTrace(DEBUG_eventlog, "initEventLog: finish"); 
+    printAndClearEventBuf(&eventBuf);

 }
 
 void
 }
 
 void

@@ -240,46 +268,39 @@ endEventLogging(void)
 {
     nat c;
 
 {
     nat c;
 

-    debugTrace(DEBUG_eventlog,"endEventLog: start");
-    

     // Flush all events remaining in the buffers.
     for (c = 0; c < n_capabilities; ++c) {
     // Flush all events remaining in the buffers.
     for (c = 0; c < n_capabilities; ++c) {

-        printAndClearEventBuf(&eventsBuf[c]);
+        printAndClearEventBuf(&capEventBuf[c]);

     }
     }

+    printAndClearEventBuf(&eventBuf);

 
     // Mark end of events (data).
 
     // Mark end of events (data).

-    endData(&eventsBuf[0]);
+    endData(&eventBuf);

 
     // Flush the end of data marker.
 
     // Flush the end of data marker.

-    printAndClearEventBuf(&eventsBuf[0]);
+    printAndClearEventBuf(&eventBuf);

 
     if (event_log_file != NULL) {
         fclose(event_log_file);
     }
 
     if (event_log_file != NULL) {
         fclose(event_log_file);
     }

-    
-    debugTrace(DEBUG_eventlog,"endEventLog: finish");

 }
 
 void 
 freeEventLogging(void)
 {
     StgWord8 c;
 }
 
 void 
 freeEventLogging(void)
 {
     StgWord8 c;

-
-    debugTrace(DEBUG_eventlog,"freeEventLog: start"); 

     
     // Free events buffer.
     for (c = 0; c < n_capabilities; ++c) {
     
     // Free events buffer.
     for (c = 0; c < n_capabilities; ++c) {

-        if (eventsBuf[c].begin != NULL) 
-            stgFree(eventsBuf[c].begin);
+        if (capEventBuf[c].begin != NULL) 
+            stgFree(capEventBuf[c].begin);

     }
     }

-    if (eventsBuf != NULL)  {
-        stgFree(eventsBuf);
+    if (capEventBuf != NULL)  {
+        stgFree(capEventBuf);

     }
     if (event_log_filename != NULL) {
         stgFree(event_log_filename);
     }
     }
     if (event_log_filename != NULL) {
         stgFree(event_log_filename);
     }

-    
-    debugTrace(DEBUG_eventlog,"freeEventLog: finish"); 

 }
 
 /*
 }
 
 /*

@@ -287,13 +308,14 @@ freeEventLogging(void)
  * If the buffer is full, prints out the buffer and clears it.
  */
 void
  * If the buffer is full, prints out the buffer and clears it.
  */
 void

-postEvent_(Capability *cap, EventTypeNum tag, StgThreadID thread, StgWord64 other)
+postSchedEvent (Capability *cap, 
+                EventTypeNum tag, 
+                StgThreadID thread, 
+                StgWord64 other)

 {
     EventsBuf *eb;
 
 {
     EventsBuf *eb;
 

-    debugTrace(DEBUG_eventlog,"postEvent: start");
-    
-    eb = &eventsBuf[cap->no];
+    eb = &capEventBuf[cap->no];

 
     if (!hasRoomForEvent(eb, tag)) {
         // Flush event buffer to make room for new event.
 
     if (!hasRoomForEvent(eb, tag)) {
         // Flush event buffer to make room for new event.

@@ -308,7 +330,6 @@ postEvent_(Capability *cap, EventTypeNum tag, StgThreadID thread, StgWord64 othe
     case EVENT_CREATE_THREAD:   // (cap, thread)
     case EVENT_RUN_THREAD:      // (cap, thread)
     case EVENT_THREAD_RUNNABLE: // (cap, thread)
     case EVENT_CREATE_THREAD:   // (cap, thread)
     case EVENT_RUN_THREAD:      // (cap, thread)
     case EVENT_THREAD_RUNNABLE: // (cap, thread)

-    case EVENT_CREATE_SPARK:    // (cap, thread)

     case EVENT_RUN_SPARK:       // (cap, thread)
     {
         postThreadID(eb,thread);
     case EVENT_RUN_SPARK:       // (cap, thread)
     {
         postThreadID(eb,thread);

@@ -328,7 +349,7 @@ postEvent_(Capability *cap, EventTypeNum tag, StgThreadID thread, StgWord64 othe
         postThreadID(eb,thread);
         postCapNo(eb,other /* new_cap | victim_cap | other_cap */);
         break;
         postThreadID(eb,thread);
         postCapNo(eb,other /* new_cap | victim_cap | other_cap */);
         break;

-    }
+   }

 
     case EVENT_STOP_THREAD:     // (cap, thread, status)
     {
 
     case EVENT_STOP_THREAD:     // (cap, thread, status)
     {

@@ -349,24 +370,73 @@ postEvent_(Capability *cap, EventTypeNum tag, StgThreadID thread, StgWord64 othe
     default:
         barf("postEvent: unknown event tag %d", tag);
     }
     default:
         barf("postEvent: unknown event tag %d", tag);
     }

+}
+
+#define BUF 512
+
+void postMsg(char *msg, va_list ap)
+{
+    EventsBuf *eb;
+    char buf[BUF];
+    nat size;
+
+    size = vsnprintf(buf,BUF,msg,ap);
+    if (size > BUF) {
+        buf[BUF-1] = '\0';
+        size = BUF;
+    }
+
+    ACQUIRE_LOCK(&eventBufMutex);
+    eb = &eventBuf;
+
+    if (!hasRoomForVariableEvent(eb, size)) {
+        // Flush event buffer to make room for new event.
+        printAndClearEventBuf(eb);
+    }
+
+    postEventTypeNum(eb, EVENT_LOG_MSG);
+    postTimestamp(eb, stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND));
+    postPayloadSize(eb, size);
+    postBuf(eb,(StgWord8*)buf,size);
+
+    RELEASE_LOCK(&eventBufMutex);
+}
+
+void postCapMsg(Capability *cap, char *msg, va_list ap)
+{
+    EventsBuf *eb;
+    char buf[BUF];
+    nat size;
+
+    size = vsnprintf(buf,BUF,msg,ap);
+    if (size > BUF) {
+        buf[BUF-1] = '\0';
+        size = BUF;
+    }
+
+    eb = &capEventBuf[cap->no];
+
+    if (!hasRoomForVariableEvent(eb, size)) {
+        // Flush event buffer to make room for new event.
+        printAndClearEventBuf(eb);
+    }

 
 

-    debugTrace(DEBUG_eventlog,"postEvent: finish");
+    postEventTypeNum(eb, EVENT_LOG_MSG);
+    postTimestamp(eb, stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND));
+    postPayloadSize(eb, size + sizeof(EventCapNo));
+    postCapNo(eb, cap->no);
+    postBuf(eb,(StgWord8*)buf,size);

 }
 
 }
 

-static void printAndClearEventBuf (EventsBuf *eventsBuf)
+static void printAndClearEventBuf (EventsBuf *ebuf)

 {
     StgWord64 numBytes = 0, written = 0;
 
 {
     StgWord64 numBytes = 0, written = 0;
 

-    if (eventsBuf->begin != NULL && eventsBuf->pos != eventsBuf->begin)
+    if (ebuf->begin != NULL && ebuf->pos != ebuf->begin)

     {
     {

-        numBytes = eventsBuf->pos - eventsBuf->begin;
-        
-        debugTrace(DEBUG_eventlog, 
-                   "printAndEventLog: numbytes %" FMT_Word64
-                   " bytes to fwrite()",
-                   numBytes);
+        numBytes = ebuf->pos - ebuf->begin;

         
         

-        written = fwrite(eventsBuf->begin, 1, numBytes, event_log_file);
+        written = fwrite(ebuf->begin, 1, numBytes, event_log_file);

         if (written != numBytes) {
             debugBelch(
                 "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64
         if (written != numBytes) {
             debugBelch(
                 "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64

@@ -374,11 +444,7 @@ static void printAndClearEventBuf (EventsBuf *eventsBuf)
             return;
         }
         
             return;
         }
         

-        debugTrace(DEBUG_eventlog,
-                   "printAndClearEventLog: fwrite(): %" FMT_Word64 
-                   " bytes written", written);
-        
-        resetEventsBuf(eventsBuf);
+        resetEventsBuf(ebuf);

         flushCount++;
     }
 }
         flushCount++;
     }
 }

@@ -386,11 +452,7 @@ static void printAndClearEventBuf (EventsBuf *eventsBuf)
 void
 printAndClearEventLog(Capability *cap)
 {
 void
 printAndClearEventLog(Capability *cap)
 {

-    debugTrace(DEBUG_eventlog,"printAndClearEventLog: start");
-    
-    printAndClearEventBuf(&eventsBuf[cap->no]);
-    
-    debugTrace(DEBUG_eventlog,"printAndClearEventLog: finish");
+    printAndClearEventBuf(&capEventBuf[cap->no]);

 }
 
 /* -----------------------------------------------------------------------------
 }
 
 /* -----------------------------------------------------------------------------

@@ -442,9 +504,9 @@ void endEventTypes(EventsBuf *eb)
 
 StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
 {
 
 StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
 {

-  nat size = 0;
+  nat size;

 
 

-  size += sizeof(EventTypeNum) + sizeof(EventTimestamp) + eventTypes[eNum].size;
+  size = sizeof(EventTypeNum) + sizeof(EventTimestamp) + eventTypes[eNum].size;

 
   if (eb->pos + size > eb->begin + eb->size) {
       return 0; // Not enough space.
 
   if (eb->pos + size > eb->begin + eb->size) {
       return 0; // Not enough space.

@@ -453,6 +515,20 @@ StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
   }
 }
 
   }
 }
 

+StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes)
+{
+  nat size;
+
+  size = sizeof(EventTypeNum) + sizeof(EventTimestamp) +
+      sizeof(EventPayloadSize) + payload_bytes;
+
+  if (eb->pos + size > eb->begin + eb->size) {
+      return 0; // Not enough space.
+  } else  {
+      return 1; // Buf has enough space for the event.
+  }
+}    
+

 static void postEventType(EventsBuf *eb, EventType *et)
 {
     StgWord8 d;
 static void postEventType(EventsBuf *eb, EventType *et)
 {
     StgWord8 d;

@@ -470,4 +546,4 @@ static void postEventType(EventsBuf *eb, EventType *et)
     postInt32(eb, EVENT_ET_END);
 }
 
     postInt32(eb, EVENT_ET_END);
 }
 

-#endif /* EVENTLOG */
+#endif /* TRACING */

diff --git a/rts/eventlog/EventLog.h b/rts/eventlog/EventLog.h
index 0358256..9f3388e 100644 (file)
--- a/rts/eventlog/EventLog.h
+++ b/rts/eventlog/EventLog.h
@@ -14,7 +14,7 @@
 
 #pragma GCC visibility push(hidden)
 
 
 #pragma GCC visibility push(hidden)
 

-#ifdef EVENTLOG
+#ifdef TRACING

 
 /*
  * Descriptions of EventTags for events.
 
 /*
  * Descriptions of EventTags for events.

@@ -25,32 +25,37 @@ void initEventLogging(void);
 void endEventLogging(void);
 void freeEventLogging(void);
 
 void endEventLogging(void);
 void freeEventLogging(void);
 

-void postEvent_(Capability *cap, EventTypeNum tag, StgThreadID id, StgWord64 other);
-

 /* 
  * Post an event to the capability's event buffer.
  */
 /* 
  * Post an event to the capability's event buffer.
  */

-INLINE_HEADER void postEvent(Capability *cap, EventTypeNum tag, StgThreadID id, StgWord64 other)
-{
-    if (RtsFlags.EventLogFlags.doEventLogging) {
-        postEvent_(cap, tag, id, other);
-    }
-}
+void postSchedEvent(Capability *cap, EventTypeNum tag, 
+                    StgThreadID id, StgWord64 other);
+
+void postMsg(char *msg, va_list ap);
+
+void postCapMsg(Capability *cap, char *msg, va_list ap);

 
 void printAndClearEventLog(Capability *cap);
 
 
 void printAndClearEventLog(Capability *cap);
 

-#else /* !EVENTLOG */
+#else /* !TRACING */
+
+INLINE_HEADER void postSchedEvent (Capability *cap  STG_UNUSED,
+                                   EventTypeNum tag STG_UNUSED,
+                                   StgThreadID id   STG_UNUSED,
+                                   StgWord64 other  STG_UNUSED)
+{ /* nothing */ }
+
+INLINE_HEADER void postMsg (char *msg STG_UNUSED, 
+                            va_list ap STG_UNUSED)
+{ /* nothing */ }

 
 

-INLINE_HEADER void postEvent(Capability *cap  STG_UNUSED,
-                             EventTypeNum tag STG_UNUSED,
-                             StgThreadID id   STG_UNUSED,
-                             StgWord64 other  STG_UNUSED)
-{
-    /* nothing */
-}
+INLINE_HEADER void postCapMsg (Capability *cap,
+                               char *msg STG_UNUSED, 
+                               va_list ap STG_UNUSED)
+{ /* nothing */ }

 
 #endif
 
 #pragma GCC visibility pop
 
 
 #endif
 
 #pragma GCC visibility pop
 

-#endif /* EVENTLOG_H */
+#endif /* TRACING_H */