X-Git-Url: http://git.megacz.com/?p=ghc-hetmet.git;a=blobdiff_plain;f=rts%2FTrace.c;h=70f4a397422dfd108869fcac2ac171700184550e;hp=042de6d8d4c5ecf8ab8d1f0015816e7705af9908;hb=HEAD;hpb=5a2769f0273dd389977e8283375e7920d183bdd4 diff --git a/rts/Trace.c b/rts/Trace.c index 042de6d..70f4a39 100644 --- a/rts/Trace.c +++ b/rts/Trace.c @@ -1,60 +1,62 @@ /* ----------------------------------------------------------------------------- * - * (c) The GHC Team 2006 + * (c) The GHC Team 2006-2009 * * Debug and performance tracing * * ---------------------------------------------------------------------------*/ +// external headers #include "Rts.h" -#include "OSThreads.h" + +// internal headers #include "Trace.h" -#include "RtsFlags.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? -*/ +#ifdef TRACING -StgWord32 classes_enabled; // not static due to inline funcs +#include "GetTime.h" +#include "GetEnv.h" +#include "Stats.h" +#include "eventlog/EventLog.h" +#include "Threads.h" +#include "Printer.h" -#ifdef THREADED_RTS -static Mutex trace_utx; +#ifdef HAVE_UNISTD_H +#include #endif #ifdef DEBUG -#define DEBUG_FLAG(name, class) \ - if (RtsFlags.DebugFlags.name) classes_enabled |= class; -#else -#define DEBUG_FLAG(name, class) \ - /* nothing */ +// debugging flags, set with +RTS -D +int DEBUG_sched; +int DEBUG_interp; +int DEBUG_weak; +int DEBUG_gccafs; +int DEBUG_gc; +int DEBUG_block_alloc; +int DEBUG_sanity; +int DEBUG_stable; +int DEBUG_stm; +int DEBUG_prof; +int DEBUG_gran; +int DEBUG_par; +int DEBUG_linker; +int DEBUG_squeeze; +int DEBUG_hpc; +int DEBUG_sparks; #endif -#ifdef PAR -#define PAR_FLAG(name, class) \ - if (RtsFlags.ParFlags.Debug.name) classes_enabled |= class; -#else -#define PAR_FLAG(name, class) \ - /* nothing */ -#endif +// events +int TRACE_sched; -#ifdef GRAN -#define GRAN_FLAG(name, class) \ - if (RtsFlags.GranFlags.Debug.name) classes_enabled |= class; -#else -#define GRAN_FLAG(name, class) \ - /* nothing */ +#ifdef THREADED_RTS +static Mutex trace_utx; #endif -#define TRACE_FLAG(name, class) \ - if (RtsFlags.TraceFlags.name) classes_enabled |= class; +static rtsBool eventlog_enabled; +/* --------------------------------------------------------------------------- + Starting up / shuttting down the tracing facilities + --------------------------------------------------------------------------- */ void initTracing (void) { @@ -62,7 +64,12 @@ void initTracing (void) initMutex(&trace_utx); #endif +#ifdef DEBUG +#define DEBUG_FLAG(name, class) \ + class = RtsFlags.DebugFlags.name ? 1 : 0; + DEBUG_FLAG(scheduler, DEBUG_sched); + DEBUG_FLAG(interpreter, DEBUG_interp); DEBUG_FLAG(weak, DEBUG_weak); DEBUG_FLAG(gccafs, DEBUG_gccafs); @@ -72,43 +79,51 @@ void initTracing (void) DEBUG_FLAG(stable, DEBUG_stable); DEBUG_FLAG(stm, DEBUG_stm); DEBUG_FLAG(prof, DEBUG_prof); - DEBUG_FLAG(gran, DEBUG_gran); - DEBUG_FLAG(par, DEBUG_par); DEBUG_FLAG(linker, DEBUG_linker); DEBUG_FLAG(squeeze, DEBUG_squeeze); + DEBUG_FLAG(hpc, DEBUG_hpc); + DEBUG_FLAG(sparks, DEBUG_sparks); +#endif - PAR_FLAG(verbose, PAR_DEBUG_verbose); - PAR_FLAG(bq, PAR_DEBUG_bq); - PAR_FLAG(schedule, PAR_DEBUG_schedule); - PAR_FLAG(free, PAR_DEBUG_free); - PAR_FLAG(resume, PAR_DEBUG_resume); - PAR_FLAG(weight, PAR_DEBUG_weight); - PAR_FLAG(fetch, PAR_DEBUG_fetch); - PAR_FLAG(fish, PAR_DEBUG_fish); - PAR_FLAG(tables, PAR_DEBUG_tables); - PAR_FLAG(packet, PAR_DEBUG_packet); - PAR_FLAG(pack, PAR_DEBUG_pack); - PAR_FLAG(paranoia, PAR_DEBUG_paranoia); - - GRAN_FLAG(event_trace, GRAN_DEBUG_event_trace); - GRAN_FLAG(event_stats, GRAN_DEBUG_event_stats); - GRAN_FLAG(bq, GRAN_DEBUG_bq); - GRAN_FLAG(pack, GRAN_DEBUG_pack); - GRAN_FLAG(checkSparkQ, GRAN_DEBUG_checkSparkQ); - GRAN_FLAG(thunkStealing, GRAN_DEBUG_thunkStealing); - GRAN_FLAG(randomSteal, GRAN_DEBUG_randomSteal); - GRAN_FLAG(findWork, GRAN_DEBUG_findWork); - GRAN_FLAG(unused, GRAN_DEBUG_unused); - GRAN_FLAG(pri, GRAN_DEBUG_pri); - GRAN_FLAG(checkLight, GRAN_DEBUG_checkLight); - GRAN_FLAG(sortedQ, GRAN_DEBUG_sortedQ); - GRAN_FLAG(blockOnFetch, GRAN_DEBUG_blockOnFetch); - GRAN_FLAG(packBuffer, GRAN_DEBUG_packBuffer); - GRAN_FLAG(blockedOnFetch_sanity, GRAN_DEBUG_BOF_sanity); - - TRACE_FLAG(sched, TRACE_sched); + // -Ds turns on scheduler tracing too + TRACE_sched = + RtsFlags.TraceFlags.scheduler || + RtsFlags.DebugFlags.scheduler; + + eventlog_enabled = RtsFlags.TraceFlags.tracing == TRACE_EVENTLOG; + + if (eventlog_enabled) { + initEventLogging(); + } } +void endTracing (void) +{ + if (eventlog_enabled) { + endEventLogging(); + } +} + +void freeTracing (void) +{ + if (eventlog_enabled) { + freeEventLogging(); + } +} + +void resetTracing (void) +{ + if (eventlog_enabled) { + abortEventLogging(); // abort eventlog inherited from parent + initEventLogging(); // child starts its own eventlog + } +} + +/* --------------------------------------------------------------------------- + Emitting trace messages/events + --------------------------------------------------------------------------- */ + +#ifdef DEBUG static void tracePreface (void) { #ifdef THREADED_RTS @@ -118,25 +133,324 @@ static void tracePreface (void) debugBelch("%9" FMT_Word64 ": ", stat_getElapsedTime()); } } +#endif -void trace (StgWord32 class, const char *str, ...) +#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", + [6 + BlockedOnMVar] = "blocked on an MVar", + [6 + BlockedOnBlackHole] = "blocked on a black hole", + [6 + BlockedOnRead] = "blocked on a read operation", + [6 + BlockedOnWrite] = "blocked on a write operation", + [6 + BlockedOnDelay] = "blocked on a delay operation", + [6 + BlockedOnSTM] = "blocked on STM", + [6 + BlockedOnDoProc] = "blocked on asyncDoProc", + [6 + BlockedOnCCall] = "blocked on a foreign call", + [6 + BlockedOnCCall_Interruptible] = "blocked on a foreign call (interruptible)", + [6 + BlockedOnMsgThrowTo] = "blocked on throwTo", + [6 + ThreadMigrating] = "migrating" +}; +#endif + +#ifdef DEBUG +static void traceSchedEvent_stderr (Capability *cap, EventTypeNum tag, + StgTSO *tso, + StgWord info1 STG_UNUSED, + StgWord info2 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 %lu\n", + cap->no, (lnat)tso->id); + break; + case EVENT_RUN_THREAD: // (cap, thread) + debugBelch("cap %d: running thread %lu (%s)\n", + cap->no, (lnat)tso->id, what_next_strs[tso->what_next]); + break; + case EVENT_THREAD_RUNNABLE: // (cap, thread) + debugBelch("cap %d: thread %lu appended to run queue\n", + cap->no, (lnat)tso->id); + break; + case EVENT_RUN_SPARK: // (cap, thread) + debugBelch("cap %d: thread %lu running a spark\n", + cap->no, (lnat)tso->id); + break; + case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread) + debugBelch("cap %d: creating spark thread %lu\n", + cap->no, (long)info1); + break; + case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap) + debugBelch("cap %d: thread %lu migrating to cap %d\n", + cap->no, (lnat)tso->id, (int)info1); + break; + case EVENT_STEAL_SPARK: // (cap, thread, victim_cap) + debugBelch("cap %d: thread %lu stealing a spark from cap %d\n", + cap->no, (lnat)tso->id, (int)info1); + break; + case EVENT_THREAD_WAKEUP: // (cap, thread, info1_cap) + debugBelch("cap %d: waking up thread %lu on cap %d\n", + cap->no, (lnat)tso->id, (int)info1); + break; + + case EVENT_STOP_THREAD: // (cap, thread, status) + if (info1 == 6 + BlockedOnBlackHole) { + debugBelch("cap %d: thread %lu stopped (blocked on black hole owned by thread %lu)\n", + cap->no, (lnat)tso->id, (long)info2); + } else { + debugBelch("cap %d: thread %lu stopped (%s)\n", + cap->no, (lnat)tso->id, thread_stop_reasons[info1]); + } + 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; + case EVENT_GC_IDLE: // (cap) + debugBelch("cap %d: GC idle\n", cap->no); + break; + case EVENT_GC_WORK: // (cap) + debugBelch("cap %d: GC working\n", cap->no); + break; + case EVENT_GC_DONE: // (cap) + debugBelch("cap %d: GC done\n", cap->no); + break; + default: + debugBelch("cap %d: thread %lu: event %d\n\n", + cap->no, (lnat)tso->id, tag); + break; + } + + RELEASE_LOCK(&trace_utx); +} +#endif + +void traceSchedEvent_ (Capability *cap, EventTypeNum tag, + StgTSO *tso, StgWord info1, StgWord info2) +{ +#ifdef DEBUG + if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) { + traceSchedEvent_stderr(cap, tag, tso, info1, info2); + } else +#endif + { + postSchedEvent(cap,tag,tso ? tso->id : 0, info1, info2); + } +} + +void traceCapsetModify_ (EventTypeNum tag, + CapsetID capset, + StgWord32 other) +{ +#ifdef DEBUG + if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) { + ACQUIRE_LOCK(&trace_utx); + + tracePreface(); + switch (tag) { + case EVENT_CAPSET_CREATE: // (capset, capset_type) + debugBelch("created capset %lu of type %d\n", (lnat)capset, (int)other); + break; + case EVENT_CAPSET_DELETE: // (capset) + debugBelch("deleted capset %lu\n", (lnat)capset); + break; + case EVENT_CAPSET_ASSIGN_CAP: // (capset, capno) + debugBelch("assigned cap %lu to capset %lu\n", + (lnat)other, (lnat)capset); + break; + case EVENT_CAPSET_REMOVE_CAP: // (capset, capno) + debugBelch("removed cap %lu from capset %lu\n", + (lnat)other, (lnat)capset); + break; + } + RELEASE_LOCK(&trace_utx); + } else +#endif + { + if (eventlog_enabled) { + postCapsetModifyEvent(tag, capset, other); + } + } +} + +void traceOSProcessInfo_(void) { + if (eventlog_enabled) { + postCapsetModifyEvent(EVENT_OSPROCESS_PID, + CAPSET_OSPROCESS_DEFAULT, + getpid()); + +#if !defined(cygwin32_HOST_OS) && !defined (mingw32_HOST_OS) +/* Windows has no strong concept of process heirarchy, so no getppid(). + * In any case, this trace event is mainly useful for tracing programs + * that use 'forkProcess' which Windows doesn't support anyway. + */ + postCapsetModifyEvent(EVENT_OSPROCESS_PPID, + CAPSET_OSPROCESS_DEFAULT, + getppid()); +#endif + { + char buf[256]; + snprintf(buf, sizeof(buf), "GHC-%s %s", ProjectVersion, RtsWay); + postCapsetStrEvent(EVENT_RTS_IDENTIFIER, + CAPSET_OSPROCESS_DEFAULT, + buf); + } + { + int argc = 0; char **argv; + getFullProgArgv(&argc, &argv); + if (argc != 0) { + postCapsetVecEvent(EVENT_PROGRAM_ARGS, + CAPSET_OSPROCESS_DEFAULT, + argc, argv); + } + } + { + int envc = 0; char **envv; + getProgEnvv(&envc, &envv); + if (envc != 0) { + postCapsetVecEvent(EVENT_PROGRAM_ENV, + CAPSET_OSPROCESS_DEFAULT, + envc, envv); + } + freeProgEnvv(envc, envv); + } + } +} +void traceEvent_ (Capability *cap, EventTypeNum tag) +{ +#ifdef DEBUG + if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) { + traceSchedEvent_stderr(cap, tag, 0, 0, 0); + } else +#endif + { + postEvent(cap,tag); + } +} + +#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 %d: ", cap->no); + vdebugBelch(msg,ap); + debugBelch("\n"); + + RELEASE_LOCK(&trace_utx); +} +#endif + +void traceCap_(Capability *cap, char *msg, ...) +{ + va_list ap; + va_start(ap,msg); + +#ifdef DEBUG + if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) { + traceCap_stderr(cap, msg, ap); + } else +#endif + { + postCapMsg(cap, msg, ap); } + va_end(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 + +void trace_(char *msg, ...) +{ + va_list ap; + va_start(ap,msg); + +#ifdef DEBUG + if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) { + trace_stderr(msg, ap); + } else +#endif + { + postMsg(msg, ap); + } va_end(ap); } +static void traceFormatUserMsg(Capability *cap, char *msg, ...) +{ + va_list ap; + va_start(ap,msg); + +#ifdef DEBUG + if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) { + traceCap_stderr(cap, msg, ap); + } else +#endif + { + if (eventlog_enabled) { + postUserMsg(cap, msg, ap); + } + } + dtraceUserMsg(cap->no, msg); +} + +void traceUserMsg(Capability *cap, char *msg) +{ + traceFormatUserMsg(cap, "%s", msg); +} + +void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG) +{ +#ifdef DEBUG + if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) { + printThreadStatus(tso); + } else +#endif + { + /* nothing - no event for this one yet */ + } +} + +void traceEventStartup_(int nocaps) +{ + if (eventlog_enabled) { + postEventStartup(nocaps); + } +} + +#ifdef DEBUG void traceBegin (const char *str, ...) { va_list ap; @@ -153,3 +467,18 @@ void traceEnd (void) debugBelch("\n"); RELEASE_LOCK(&trace_utx); } +#endif /* DEBUG */ + +#endif /* TRACING */ + +// If DTRACE is enabled, but neither DEBUG nor TRACING, we need a C land +// wrapper for the user-msg probe (as we can't expand that in PrimOps.cmm) +// +#if !defined(DEBUG) && !defined(TRACING) && defined(DTRACE) + +void dtraceUserMsgWrapper(Capability *cap, char *msg) +{ + dtraceUserMsg(cap->no, msg); +} + +#endif /* !defined(DEBUG) && !defined(TRACING) && defined(DTRACE) */