summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorSimon Marlow <marlowsd@gmail.com>2009-08-29 09:47:27 +0000
committerSimon Marlow <marlowsd@gmail.com>2009-08-29 09:47:27 +0000
commita5288c551349a0adab0d931a429b10a096d9444d (patch)
tree245dd2dfd2b4e23f3fc8ae474b709289b60e5f15
parentc51229b2bfd3b1a61d3966db894210ef848f0a6d (diff)
downloadhaskell-a5288c551349a0adab0d931a429b10a096d9444d.tar.gz
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.
-rw-r--r--compiler/main/StaticFlags.hs4
-rw-r--r--includes/rts/Config.h6
-rw-r--r--includes/rts/EventLogFormat.h13
-rw-r--r--includes/rts/Flags.h16
-rw-r--r--mk/config.mk.in59
-rw-r--r--rts/Capability.c20
-rw-r--r--rts/Printer.c9
-rw-r--r--rts/Printer.h2
-rw-r--r--rts/RaiseAsync.c7
-rw-r--r--rts/RtsFlags.c72
-rw-r--r--rts/RtsStartup.c17
-rw-r--r--rts/Schedule.c89
-rw-r--r--rts/Schedule.h4
-rw-r--r--rts/Sparks.c12
-rw-r--r--rts/Threads.c12
-rw-r--r--rts/Trace.c215
-rw-r--r--rts/Trace.h172
-rw-r--r--rts/eventlog/EventLog.c212
-rw-r--r--rts/eventlog/EventLog.h41
19 files changed, 617 insertions, 365 deletions
diff --git a/compiler/main/StaticFlags.hs b/compiler/main/StaticFlags.hs
index ffa15841ad..8035211a7c 100644
--- 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"
- [ "-DEVENTLOG"
- , "-optc-DEVENTLOG" ],
+ [ "-DTRACING"
+ , "-optc-DTRACING" ],
Way WayTicky "t" True "Ticky-ticky Profiling"
[ "-DTICKY_TICKY"
diff --git a/includes/rts/Config.h b/includes/rts/Config.h
index 9e4d683857..b8aa24634c 100644
--- a/includes/rts/Config.h
+++ b/includes/rts/Config.h
@@ -27,6 +27,12 @@
#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.
-------------------------------------------------------------------------- */
diff --git a/includes/rts/EventLogFormat.h b/includes/rts/EventLogFormat.h
index 363c1ca1cf..a860822ab9 100644
--- 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_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_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
@@ -137,6 +143,7 @@ typedef StgWord16 EventTypeNum;
typedef StgWord64 EventTimestamp; // in nanoseconds
typedef StgWord64 EventThreadID;
typedef StgWord16 EventCapNo;
+typedef StgWord16 EventPayloadSize; // variable-size events
#endif
diff --git a/includes/rts/Flags.h b/includes/rts/Flags.h
index d9e3be97de..3d0230a376 100644
--- 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 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 timestamp; /* add timestamps to traces */
+ rtsBool sparks; /* 'r' */
};
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 */
@@ -184,9 +184,7 @@ typedef struct _RTS_FLAGS {
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)
diff --git a/mk/config.mk.in b/mk/config.mk.in
index a516e6da77..e1d79cfcf4 100644
--- 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
-# thr_debug_l : threaded and debugging and event logging
#
GhcRTSWays=l
@@ -775,8 +774,7 @@ endif
#
# 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,
@@ -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_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
@@ -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
-#
-# 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
diff --git a/rts/Capability.c b/rts/Capability.c
index 4264f0ff57..0e4d5a6a30 100644
--- 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.
- postEvent(cap, EVENT_RUN_SPARK, cap->r.rCurrentTSO->id, 0);
+ traceSchedEvent(cap, EVENT_RUN_SPARK, cap->r.rCurrentTSO, 0);
return spark;
}
@@ -127,14 +127,10 @@ findSpark (Capability *cap)
}
if (spark != NULL) {
- debugTrace(DEBUG_sched,
- "cap %d: Stole a spark from capability %d",
- cap->no, robbed->no);
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;
}
@@ -580,10 +576,9 @@ yieldCapability (Capability** pCap, Task *task)
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);
- postEvent(cap, EVENT_GC_END, 0, 0);
+ traceSchedEvent(cap, EVENT_GC_END, 0, 0);
return;
}
@@ -790,8 +785,7 @@ shutdownCapability (Capability *cap, Task *task, rtsBool safe)
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;
}
@@ -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) {
- debugTrace(DEBUG_sched,
- "evac'ing suspended TSO %lu", (unsigned long)task->suspended_tso->id);
evac(user, (StgClosure **)(void *)&task->suspended_tso);
}
diff --git a/rts/Printer.c b/rts/Printer.c
index 91bc6c8cd4..1b6e57eae6 100644
--- 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 )
{
diff --git a/rts/Printer.h b/rts/Printer.h
index 33fe6a8316..fd89aa073a 100644
--- 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 char *what_next_strs[];
#endif
#pragma GCC visibility pop
diff --git a/rts/RaiseAsync.c b/rts/RaiseAsync.c
index 4ca1cba28d..3078cf90ad 100644
--- a/rts/RaiseAsync.c
+++ b/rts/RaiseAsync.c
@@ -18,7 +18,6 @@
#include "STM.h"
#include "Sanity.h"
#include "Profiling.h"
-#include "eventlog/EventLog.h"
#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
- if (traceClass(DEBUG_sched)) {
- debugTraceBegin("throwTo: target");
- printThreadStatus(target);
- debugTraceEnd();
- }
+ traceThreadStatus(DEBUG_sched, target);
#endif
goto check_target;
diff --git a/rts/RtsFlags.c b/rts/RtsFlags.c
index 1204c59356..d200bf2560 100644
--- 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.eventlog = 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)
@@ -135,8 +134,10 @@ void initRtsFlagsDefaults(void)
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 */
@@ -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)",
-" -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)",
@@ -252,9 +255,13 @@ usage_text[] = {
# 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
@@ -275,8 +282,6 @@ usage_text[] = {
" 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",
@@ -293,6 +298,10 @@ usage_text[] = {
" -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)
@@ -472,10 +481,10 @@ errorBelch("not built for: -prof"); \
error = rtsTrue;
#endif
-#ifdef EVENTLOG
-# define EVENTLOG_BUILD_ONLY(x) x
+#ifdef TRACING
+# define TRACING_BUILD_ONLY(x) x
#else
-# define EVENTLOG_BUILD_ONLY(x) \
+# define TRACING_BUILD_ONLY(x) \
errorBelch("not built for: -par-prof"); \
error = rtsTrue;
#endif
@@ -617,9 +626,6 @@ error = rtsTrue;
case 'p':
RtsFlags.DebugFlags.prof = rtsTrue;
break;
- case 'e':
- RtsFlags.DebugFlags.eventlog = rtsTrue;
- break;
case 'l':
RtsFlags.DebugFlags.linker = rtsTrue;
break;
@@ -635,10 +641,16 @@ error = rtsTrue;
case 'c':
RtsFlags.DebugFlags.hpc = rtsTrue;
break;
+ case 'r':
+ RtsFlags.DebugFlags.sparks = rtsTrue;
+ break;
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
@@ -743,8 +755,19 @@ error = rtsTrue;
/* =========== 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
@@ -1049,13 +1072,14 @@ error = rtsTrue;
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':
- RtsFlags.DebugFlags.timestamp = rtsTrue;
+ RtsFlags.TraceFlags.timestamp = rtsTrue;
break;
+#endif
case 's':
case 'g':
// ignored for backwards-compat
diff --git a/rts/RtsStartup.c b/rts/RtsStartup.c
index f0b2170bad..1c39cf8422 100644
--- a/rts/RtsStartup.c
+++ b/rts/RtsStartup.c
@@ -29,7 +29,6 @@
#include "sm/BlockAlloc.h"
#include "Trace.h"
#include "Stable.h"
-#include "eventlog/EventLog.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() */
-#ifdef DEBUG
+#ifdef TRACING
initTracing();
#endif
@@ -190,12 +189,6 @@ hs_init(int *argc, char **argv[])
initProfiling1();
-#ifdef EVENTLOG
- if (RtsFlags.EventLogFlags.doEventLogging) {
- initEventLogging();
- }
-#endif
-
/* start the virtual timer 'subsystem'. */
initTimer();
startTimer();
@@ -421,11 +414,9 @@ hs_exit_(rtsBool wait_foreign)
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)
diff --git a/rts/Schedule.c b/rts/Schedule.c
index 05315a59d9..9b261cf660 100644
--- a/rts/Schedule.c
+++ b/rts/Schedule.c
@@ -26,7 +26,6 @@
#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"
@@ -172,17 +171,6 @@ static void deleteAllThreads (Capability *cap);
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
* -------------------------------------------------------------------------- */
@@ -249,9 +237,7 @@ schedule (Capability *initialCapability, Task *task)
// 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();
@@ -396,12 +382,11 @@ schedule (Capability *initialCapability, Task *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,
- "### 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;
@@ -410,7 +395,8 @@ schedule (Capability *initialCapability, Task *task)
// 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);
@@ -445,9 +431,6 @@ run_thread:
// 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
@@ -485,7 +468,7 @@ run_thread:
}
#endif
- postEvent(cap, EVENT_RUN_THREAD, t->id, 0);
+ traceSchedEvent(cap, EVENT_RUN_THREAD, t, 0);
switch (prev_what_next) {
@@ -535,7 +518,7 @@ run_thread:
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
@@ -545,9 +528,6 @@ run_thread:
// 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;
}
@@ -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);
- 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];
@@ -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);
- 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);
}
@@ -1106,7 +1086,7 @@ scheduleHandleHeapOverflow( Capability *cap, StgTSO *t )
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 ||
@@ -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
@@ -1185,10 +1161,6 @@ scheduleHandleHeapOverflow( Capability *cap, 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.
*/
@@ -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",
- (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
@@ -1281,12 +1249,7 @@ scheduleHandleThreadBlocked( StgTSO *t
// 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
}
@@ -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.
*/
- 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
@@ -1456,7 +1417,7 @@ scheduleDoGC (Capability *cap, Task *task USED_IF_THREADS, rtsBool force_major)
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);
@@ -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.
- 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);
@@ -1505,8 +1466,7 @@ delete_threads_and_gc:
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;
@@ -1514,7 +1474,7 @@ delete_threads_and_gc:
#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)
{
@@ -1829,10 +1789,7 @@ suspendThread (StgRegTable *reg)
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;
@@ -1858,13 +1815,6 @@ suspendThread (StgRegTable *reg)
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);
@@ -1902,8 +1852,7 @@ resumeThread (void *task_)
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
@@ -1959,7 +1908,7 @@ scheduleThreadOn(Capability *cap, StgWord cpu USED_IF_THREADS, StgTSO *tso)
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
diff --git a/rts/Schedule.h b/rts/Schedule.h
index c83b6fdcb6..1214fd8784 100644
--- a/rts/Schedule.h
+++ b/rts/Schedule.h
@@ -12,7 +12,7 @@
#include "rts/OSThreads.h"
#include "Capability.h"
-#include "eventlog/EventLog.h"
+#include "Trace.h"
#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;
- 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.
diff --git a/rts/Sparks.c b/rts/Sparks.c
index ff4beb7fd5..a17b78ce57 100644
--- 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);
- postEvent(cap, EVENT_CREATE_SPARK_THREAD, 0, tso->id);
+ traceSchedEvent(cap, EVENT_CREATE_SPARK_THREAD, 0, tso->id);
appendToRunQueue(cap,tso);
}
@@ -75,8 +75,6 @@ newSpark (StgRegTable *reg, StgClosure *p)
cap->sparks_created++;
- postEvent(cap, EVENT_CREATE_SPARK, cap->r.rCurrentTSO->id, 0);
-
return 1;
}
@@ -140,7 +138,7 @@ pruneSparkQueue (evac_fn evac, void *user, Capability *cap)
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);
@@ -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)
- 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);
@@ -274,7 +272,7 @@ traverseSparkQueue (evac_fn evac, void *user, Capability *cap)
top++;
}
- debugTrace(DEBUG_sched,
+ debugTrace(DEBUG_sparks,
"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 8318e28ca9..3b209ea95b 100644
--- a/rts/Threads.c
+++ b/rts/Threads.c
@@ -106,11 +106,9 @@ createThread(Capability *cap, nat size)
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;
}
@@ -256,10 +254,7 @@ unblockOne_ (Capability *cap, StgTSO *tso,
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;
}
@@ -357,6 +352,7 @@ printThreadBlockage(StgTSO *tso)
}
}
+
void
printThreadStatus(StgTSO *t)
{
diff --git a/rts/Trace.c b/rts/Trace.c
index 0a47ea3860..eee3554ca1 100644
--- a/rts/Trace.c
+++ b/rts/Trace.c
@@ -6,25 +6,18 @@
*
* ---------------------------------------------------------------------------*/
-#ifdef DEBUG
-
// external headers
#include "Rts.h"
-#include "rts/Flags.h"
+
+#ifdef TRACING
// 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
@@ -32,8 +25,9 @@ StgWord32 classes_enabled; // not static due to inline funcs
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)
{
@@ -41,7 +35,13 @@ void initTracing (void)
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, TRACE_sched); // -Ds enabled all sched events
+
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(eventlog, DEBUG_eventlog);
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
- if (RtsFlags.DebugFlags.timestamp) {
+ if (RtsFlags.TraceFlags.timestamp) {
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);
- 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);
+}
+#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;
@@ -101,5 +265,6 @@ void traceEnd (void)
debugBelch("\n");
RELEASE_LOCK(&trace_utx);
}
+#endif /* DEBUG */
-#endif
+#endif /* TRACING */
diff --git a/rts/Trace.h b/rts/Trace.h
index 8820075bea..3ab6df456c 100644
--- 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
+#include "rts/EventLogFormat.h"
+#include "Capability.h"
+
#pragma GCC visibility push(hidden)
// -----------------------------------------------------------------------------
-// Tracing functions
+// Posting events
// -----------------------------------------------------------------------------
+INLINE_HEADER void trace (StgWord32 class, char *msg, ...);
+
#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);
+#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
@@ -77,18 +71,120 @@ void traceEnd (void);
#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
// -----------------------------------------------------------------------------
+#ifdef TRACING
+
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
diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c
index bd887afa8e..448611675a 100644
--- a/rts/eventlog/EventLog.c
+++ b/rts/eventlog/EventLog.c
@@ -6,16 +6,17 @@
*
* ---------------------------------------------------------------------------*/
-#ifdef EVENTLOG
-
#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 "EventLog.h"
#include <string.h>
#include <stdio.h>
@@ -36,7 +37,12 @@ typedef struct _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",
@@ -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_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.
@@ -83,6 +90,7 @@ static void endEventTypes(EventsBuf *eb);
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)
{
@@ -107,6 +115,12 @@ static inline void postWord64(EventsBuf *eb, StgWord64 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); }
@@ -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 postPayloadSize(EventsBuf *eb, EventPayloadSize size)
+{ postWord16(eb,size); }
+
static inline void postInt8(EventsBuf *eb, StgInt8 i)
{ postWord8(eb, (StgWord8)i); }
@@ -136,8 +153,7 @@ void
initEventLogging(void)
{
StgWord8 t, c;
-
- debugTrace(DEBUG_eventlog, "intiEventLog: start");
+ nat n_caps;
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.
*/
- 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.
- initEventsBuf(&eventsBuf[c], EVENT_LOG_SIZE);
+ initEventsBuf(&capEventBuf[c], EVENT_LOG_SIZE);
}
+ initEventsBuf(&eventBuf, EVENT_LOG_SIZE);
// Write in buffer: the header begin marker.
- beginHeader(&eventsBuf[0]);
+ beginHeader(&eventBuf);
// 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;
@@ -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_SPARK: // (cap, thread)
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_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.
- postEventType(&eventsBuf[0], &eventTypes[t]);
+ postEventType(&eventBuf, &eventTypes[t]);
}
// Mark end of event types in the header.
- endEventTypes(&eventsBuf[0]);
+ endEventTypes(&eventBuf);
// Write in buffer: the header end marker.
- endHeader(&eventsBuf[0]);
+ endHeader(&eventBuf);
// 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.
*/
- printAndClearEventBuf(&eventsBuf[0]);
-
- debugTrace(DEBUG_eventlog, "initEventLog: finish");
+ printAndClearEventBuf(&eventBuf);
}
void
@@ -240,46 +268,39 @@ endEventLogging(void)
{
nat c;
- debugTrace(DEBUG_eventlog,"endEventLog: start");
-
// 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).
- endData(&eventsBuf[0]);
+ endData(&eventBuf);
// Flush the end of data marker.
- printAndClearEventBuf(&eventsBuf[0]);
+ printAndClearEventBuf(&eventBuf);
if (event_log_file != NULL) {
fclose(event_log_file);
}
-
- debugTrace(DEBUG_eventlog,"endEventLog: finish");
}
void
freeEventLogging(void)
{
StgWord8 c;
-
- debugTrace(DEBUG_eventlog,"freeEventLog: start");
// 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);
}
-
- debugTrace(DEBUG_eventlog,"freeEventLog: finish");
}
/*
@@ -287,13 +308,14 @@ freeEventLogging(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;
- 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.
@@ -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_SPARK: // (cap, 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;
- }
+ }
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);
}
+}
+
+#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;
- 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
@@ -374,11 +444,7 @@ static void printAndClearEventBuf (EventsBuf *eventsBuf)
return;
}
- debugTrace(DEBUG_eventlog,
- "printAndClearEventLog: fwrite(): %" FMT_Word64
- " bytes written", written);
-
- resetEventsBuf(eventsBuf);
+ resetEventsBuf(ebuf);
flushCount++;
}
}
@@ -386,11 +452,7 @@ static void printAndClearEventBuf (EventsBuf *eventsBuf)
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)
{
- 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.
@@ -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;
@@ -470,4 +546,4 @@ static void postEventType(EventsBuf *eb, EventType *et)
postInt32(eb, EVENT_ET_END);
}
-#endif /* EVENTLOG */
+#endif /* TRACING */
diff --git a/rts/eventlog/EventLog.h b/rts/eventlog/EventLog.h
index 0358256357..9f3388e421 100644
--- a/rts/eventlog/EventLog.h
+++ b/rts/eventlog/EventLog.h
@@ -14,7 +14,7 @@
#pragma GCC visibility push(hidden)
-#ifdef EVENTLOG
+#ifdef TRACING
/*
* Descriptions of EventTags for events.
@@ -25,32 +25,37 @@ void initEventLogging(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.
*/
-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);
-#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 /* EVENTLOG_H */
+#endif /* TRACING_H */