rts/Trace.c

   1 /* -----------------------------------------------------------------------------
   2  *
   3  * (c) The GHC Team 2006-2009
   4  *
   5  * Debug and performance tracing
   6  *
   7  * ---------------------------------------------------------------------------*/
   8
   9 // external headers
  10 #include "Rts.h"
  11
  12 #ifdef TRACING
  13
  14 // internal headers
  15 #include "Trace.h"
  16 #include "GetTime.h"
  17 #include "Stats.h"
  18 #include "eventlog/EventLog.h"
  19 #include "Threads.h"
  20 #include "Printer.h"
  21
  22 #ifdef DEBUG
  23 // debugging flags, set with +RTS -D<something>
  24 int DEBUG_sched;
  25 int DEBUG_interp;
  26 int DEBUG_weak;
  27 int DEBUG_gccafs;
  28 int DEBUG_gc;
  29 int DEBUG_block_alloc;
  30 int DEBUG_sanity;
  31 int DEBUG_stable;
  32 int DEBUG_stm;
  33 int DEBUG_prof;
  34 int DEBUG_gran;
  35 int DEBUG_par;
  36 int DEBUG_linker;
  37 int DEBUG_squeeze;
  38 int DEBUG_hpc;
  39 int DEBUG_sparks;
  40 #endif
  41
  42 // events
  43 int TRACE_sched;
  44
  45 #ifdef THREADED_RTS
  46 static Mutex trace_utx;
  47 #endif
  48
  49 static rtsBool eventlog_enabled;
  50
  51 /* ---------------------------------------------------------------------------
  52    Starting up / shuttting down the tracing facilities
  53  --------------------------------------------------------------------------- */
  54
  55 void initTracing (void)
  56 {
  57 #ifdef THREADED_RTS
  58     initMutex(&trace_utx);
  59 #endif
  60
  61 #ifdef DEBUG
  62 #define DEBUG_FLAG(name, class) \
  63     class = RtsFlags.DebugFlags.name ? 1 : 0;
  64
  65     DEBUG_FLAG(scheduler,    DEBUG_sched);
  66
  67     DEBUG_FLAG(interpreter,  DEBUG_interp);
  68     DEBUG_FLAG(weak,         DEBUG_weak);
  69     DEBUG_FLAG(gccafs,       DEBUG_gccafs);
  70     DEBUG_FLAG(gc,           DEBUG_gc);
  71     DEBUG_FLAG(block_alloc,  DEBUG_block_alloc);
  72     DEBUG_FLAG(sanity,       DEBUG_sanity);
  73     DEBUG_FLAG(stable,       DEBUG_stable);
  74     DEBUG_FLAG(stm,          DEBUG_stm);
  75     DEBUG_FLAG(prof,         DEBUG_prof);
  76     DEBUG_FLAG(linker,       DEBUG_linker);
  77     DEBUG_FLAG(squeeze,      DEBUG_squeeze);
  78     DEBUG_FLAG(hpc,          DEBUG_hpc);
  79     DEBUG_FLAG(sparks,       DEBUG_sparks);
  80 #endif
  81
  82     // -Ds turns on scheduler tracing too
  83     TRACE_sched =
  84         RtsFlags.TraceFlags.scheduler ||
  85         RtsFlags.DebugFlags.scheduler;
  86
  87     eventlog_enabled = RtsFlags.TraceFlags.tracing == TRACE_EVENTLOG;
  88
  89     if (eventlog_enabled) {
  90         initEventLogging();
  91     }
  92 }
  93
  94 void endTracing (void)
  95 {
  96     if (eventlog_enabled) {
  97         endEventLogging();
  98     }
  99 }
 100
 101 void freeTracing (void)
 102 {
 103     if (eventlog_enabled) {
 104         freeEventLogging();
 105     }
 106 }
 107
 108 /* ---------------------------------------------------------------------------
 109    Emitting trace messages/events
 110  --------------------------------------------------------------------------- */
 111
 112 #ifdef DEBUG
 113 static void tracePreface (void)
 114 {
 115 #ifdef THREADED_RTS
 116     debugBelch("%12lx: ", (unsigned long)osThreadId());
 117 #endif
 118     if (RtsFlags.TraceFlags.timestamp) {
 119         debugBelch("%9" FMT_Word64 ": ", stat_getElapsedTime());
 120     }
 121 }
 122 #endif
 123
 124 #ifdef DEBUG
 125 static char *thread_stop_reasons[] = {
 126     [HeapOverflow] = "heap overflow",
 127     [StackOverflow] = "stack overflow",
 128     [ThreadYielding] = "yielding",
 129     [ThreadBlocked] = "blocked",
 130     [ThreadFinished] = "finished",
 131     [THREAD_SUSPENDED_FOREIGN_CALL] = "suspended while making a foreign call"
 132 };
 133 #endif
 134
 135 #ifdef DEBUG
 136 static void traceSchedEvent_stderr (Capability *cap, EventTypeNum tag,
 137                                     StgTSO *tso,
 138                                     StgWord64 other STG_UNUSED)
 139 {
 140     ACQUIRE_LOCK(&trace_utx);
 141
 142     tracePreface();
 143     switch (tag) {
 144     case EVENT_CREATE_THREAD:   // (cap, thread)
 145         debugBelch("cap %d: created thread %lu\n",
 146                    cap->no, (lnat)tso->id);
 147         break;
 148     case EVENT_RUN_THREAD:      //  (cap, thread)
 149         debugBelch("cap %d: running thread %lu (%s)\n",
 150                    cap->no, (lnat)tso->id, what_next_strs[tso->what_next]);
 151         break;
 152     case EVENT_THREAD_RUNNABLE: // (cap, thread)
 153         debugBelch("cap %d: thread %lu appended to run queue\n",
 154                    cap->no, (lnat)tso->id);
 155         break;
 156     case EVENT_RUN_SPARK:       // (cap, thread)
 157         debugBelch("cap %d: thread %lu running a spark\n",
 158                    cap->no, (lnat)tso->id);
 159         break;
 160     case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
 161         debugBelch("cap %d: creating spark thread %lu\n",
 162                    cap->no, (long)other);
 163         break;
 164     case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
 165         debugBelch("cap %d: thread %lu migrating to cap %d\n",
 166                    cap->no, (lnat)tso->id, (int)other);
 167         break;
 168     case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
 169         debugBelch("cap %d: thread %lu stealing a spark from cap %d\n",
 170                    cap->no, (lnat)tso->id, (int)other);
 171         break;
 172     case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
 173         debugBelch("cap %d: waking up thread %lu on cap %d\n",
 174                    cap->no, (lnat)tso->id, (int)other);
 175         break;
 176
 177     case EVENT_STOP_THREAD:     // (cap, thread, status)
 178         debugBelch("cap %d: thread %lu stopped (%s)\n",
 179                    cap->no, (lnat)tso->id, thread_stop_reasons[other]);
 180         break;
 181     case EVENT_SHUTDOWN:        // (cap)
 182         debugBelch("cap %d: shutting down\n", cap->no);
 183         break;
 184     case EVENT_REQUEST_SEQ_GC:  // (cap)
 185         debugBelch("cap %d: requesting sequential GC\n", cap->no);
 186         break;
 187     case EVENT_REQUEST_PAR_GC:  // (cap)
 188         debugBelch("cap %d: requesting parallel GC\n", cap->no);
 189         break;
 190     case EVENT_GC_START:        // (cap)
 191         debugBelch("cap %d: starting GC\n", cap->no);
 192         break;
 193     case EVENT_GC_END:          // (cap)
 194         debugBelch("cap %d: finished GC\n", cap->no);
 195         break;
 196     default:
 197         debugBelch("cap %2d: thread %lu: event %d\n\n",
 198                    cap->no, (lnat)tso->id, tag);
 199         break;
 200     }
 201
 202     RELEASE_LOCK(&trace_utx);
 203 }
 204 #endif
 205
 206 void traceSchedEvent_ (Capability *cap, EventTypeNum tag,
 207                       StgTSO *tso, StgWord64 other)
 208 {
 209 #ifdef DEBUG
 210     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 211         traceSchedEvent_stderr(cap, tag, tso, other);
 212     } else
 213 #endif
 214     {
 215         postSchedEvent(cap,tag,tso ? tso->id : 0,other);
 216     }
 217 }
 218
 219 #ifdef DEBUG
 220 static void traceCap_stderr(Capability *cap, char *msg, va_list ap)
 221 {
 222     ACQUIRE_LOCK(&trace_utx);
 223
 224     tracePreface();
 225     debugBelch("cap %2d: ", cap->no);
 226     vdebugBelch(msg,ap);
 227     debugBelch("\n");
 228
 229     RELEASE_LOCK(&trace_utx);
 230 }
 231 #endif
 232
 233 void traceCap_(Capability *cap, char *msg, ...)
 234 {
 235     va_list ap;
 236     va_start(ap,msg);
 237
 238 #ifdef DEBUG
 239     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 240         traceCap_stderr(cap, msg, ap);
 241     } else
 242 #endif
 243     {
 244         postCapMsg(cap, msg, ap);
 245     }
 246
 247     va_end(ap);
 248 }
 249
 250 #ifdef DEBUG
 251 static void trace_stderr(char *msg, va_list ap)
 252 {
 253     ACQUIRE_LOCK(&trace_utx);
 254
 255     tracePreface();
 256     vdebugBelch(msg,ap);
 257     debugBelch("\n");
 258
 259     RELEASE_LOCK(&trace_utx);
 260 }
 261 #endif
 262
 263 void trace_(char *msg, ...)
 264 {
 265     va_list ap;
 266     va_start(ap,msg);
 267
 268 #ifdef DEBUG
 269     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 270         trace_stderr(msg, ap);
 271     } else
 272 #endif
 273     {
 274         postMsg(msg, ap);
 275     }
 276
 277     va_end(ap);
 278 }
 279
 280 void traceUserMsg(Capability *cap, char *msg)
 281 {
 282 #ifdef DEBUG
 283     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 284         traceCap_stderr(cap, msg, NULL);
 285     } else
 286 #endif
 287     {
 288         if (eventlog_enabled) {
 289             postUserMsg(cap, msg);
 290         }
 291     }
 292 }
 293
 294 void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
 295 {
 296 #ifdef DEBUG
 297     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 298         printThreadStatus(tso);
 299     } else
 300 #endif
 301     {
 302         /* nothing - no event for this one yet */
 303     }
 304 }
 305
 306
 307 #ifdef DEBUG
 308 void traceBegin (const char *str, ...)
 309 {
 310     va_list ap;
 311     va_start(ap,str);
 312
 313     ACQUIRE_LOCK(&trace_utx);
 314
 315     tracePreface();
 316     vdebugBelch(str,ap);
 317 }
 318
 319 void traceEnd (void)
 320 {
 321     debugBelch("\n");
 322     RELEASE_LOCK(&trace_utx);
 323 }
 324 #endif /* DEBUG */
 325
 326 #endif /* TRACING */