From a5288c551349a0adab0d931a429b10a096d9444d Mon Sep 17 00:00:00 2001 From: Simon Marlow Date: Sat, 29 Aug 2009 09:47:27 +0000 Subject: [PATCH] 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. --- compiler/main/StaticFlags.hs | 4 +- includes/rts/Config.h | 6 ++ includes/rts/EventLogFormat.h | 13 ++- includes/rts/Flags.h | 16 ++- mk/config.mk.in | 59 +---------- rts/Capability.c | 20 ++-- rts/Printer.c | 9 ++ rts/Printer.h | 2 + rts/RaiseAsync.c | 7 +- rts/RtsFlags.c | 72 +++++++++----- rts/RtsStartup.c | 17 +--- rts/Schedule.c | 89 ++++------------- rts/Schedule.h | 4 +- rts/Sparks.c | 12 +-- rts/Threads.c | 12 +-- rts/Trace.c | 215 ++++++++++++++++++++++++++++++++++++----- rts/Trace.h | 172 +++++++++++++++++++++++++-------- rts/eventlog/EventLog.c | 212 +++++++++++++++++++++++++++------------- rts/eventlog/EventLog.h | 41 ++++---- 19 files changed, 617 insertions(+), 365 deletions(-) diff --git a/compiler/main/StaticFlags.hs b/compiler/main/StaticFlags.hs index ffa1584..8035211 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 9e4d683..b8aa246 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 363c1ca..a860822 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 d9e3be9..3d0230a 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 a516e6d..e1d79cf 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 4264f0f..0e4d5a6 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 91bc6c8..1b6e57e 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 33fe6a8..fd89aa0 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 4ca1cba..3078cf9 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 1204c59..d200bf2 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 Minimum % of heap which must be available (default 3%)", " -G Number of generations (default: 2)", " -T Number of steps in younger generations (default: 2)", -" -c Auto-enable compaction of the oldest generation when live data is", -" at least % of the maximum heap size set with -M (default: 30%)", -" -c Enable compaction for all major collections", +" -c Use in-place compaction instead of copying in the oldest generation", +" when live data is at least % 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 Perform full GC after 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 .eventlog)", +" -v Log events to stderr", +" -l Log events in binary format to the file .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 f0b2170..1c39cf8 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 05315a5..9b261cf 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 c83b6fd..1214fd8 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 ff4beb7..a17b78c 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 8318e28..3b209ea 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 0a47ea3..eee3554 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 8820075..3ab6df4 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 bd887af..4486116 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 #include @@ -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 0358256..9f3388e 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 */ -- 1.7.10.4