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 // internal headers
  13 #include "Trace.h"
  14
  15 #ifdef TRACING
  16
  17 #include "GetTime.h"
  18 #include "Stats.h"
  19 #include "eventlog/EventLog.h"
  20 #include "Threads.h"
  21 #include "Printer.h"
  22
  23 #ifdef DEBUG
  24 // debugging flags, set with +RTS -D<something>
  25 int DEBUG_sched;
  26 int DEBUG_interp;
  27 int DEBUG_weak;
  28 int DEBUG_gccafs;
  29 int DEBUG_gc;
  30 int DEBUG_block_alloc;
  31 int DEBUG_sanity;
  32 int DEBUG_stable;
  33 int DEBUG_stm;
  34 int DEBUG_prof;
  35 int DEBUG_gran;
  36 int DEBUG_par;
  37 int DEBUG_linker;
  38 int DEBUG_squeeze;
  39 int DEBUG_hpc;
  40 int DEBUG_sparks;
  41 #endif
  42
  43 // events
  44 int TRACE_sched;
  45
  46 #ifdef THREADED_RTS
  47 static Mutex trace_utx;
  48 #endif
  49
  50 static rtsBool eventlog_enabled;
  51
  52 /* ---------------------------------------------------------------------------
  53    Starting up / shuttting down the tracing facilities
  54  --------------------------------------------------------------------------- */
  55
  56 void initTracing (void)
  57 {
  58 #ifdef THREADED_RTS
  59     initMutex(&trace_utx);
  60 #endif
  61
  62 #ifdef DEBUG
  63 #define DEBUG_FLAG(name, class) \
  64     class = RtsFlags.DebugFlags.name ? 1 : 0;
  65
  66     DEBUG_FLAG(scheduler,    DEBUG_sched);
  67
  68     DEBUG_FLAG(interpreter,  DEBUG_interp);
  69     DEBUG_FLAG(weak,         DEBUG_weak);
  70     DEBUG_FLAG(gccafs,       DEBUG_gccafs);
  71     DEBUG_FLAG(gc,           DEBUG_gc);
  72     DEBUG_FLAG(block_alloc,  DEBUG_block_alloc);
  73     DEBUG_FLAG(sanity,       DEBUG_sanity);
  74     DEBUG_FLAG(stable,       DEBUG_stable);
  75     DEBUG_FLAG(stm,          DEBUG_stm);
  76     DEBUG_FLAG(prof,         DEBUG_prof);
  77     DEBUG_FLAG(linker,       DEBUG_linker);
  78     DEBUG_FLAG(squeeze,      DEBUG_squeeze);
  79     DEBUG_FLAG(hpc,          DEBUG_hpc);
  80     DEBUG_FLAG(sparks,       DEBUG_sparks);
  81 #endif
  82
  83     // -Ds turns on scheduler tracing too
  84     TRACE_sched =
  85         RtsFlags.TraceFlags.scheduler ||
  86         RtsFlags.DebugFlags.scheduler;
  87
  88     eventlog_enabled = RtsFlags.TraceFlags.tracing == TRACE_EVENTLOG;
  89
  90     if (eventlog_enabled) {
  91         initEventLogging();
  92     }
  93 }
  94
  95 void endTracing (void)
  96 {
  97     if (eventlog_enabled) {
  98         endEventLogging();
  99     }
 100 }
 101
 102 void freeTracing (void)
 103 {
 104     if (eventlog_enabled) {
 105         freeEventLogging();
 106     }
 107 }
 108
 109 void resetTracing (void)
 110 {
 111     if (eventlog_enabled) {
 112         abortEventLogging(); // abort eventlog inherited from parent
 113         initEventLogging(); // child starts its own eventlog
 114     }
 115 }
 116
 117 /* ---------------------------------------------------------------------------
 118    Emitting trace messages/events
 119  --------------------------------------------------------------------------- */
 120
 121 #ifdef DEBUG
 122 static void tracePreface (void)
 123 {
 124 #ifdef THREADED_RTS
 125     debugBelch("%12lx: ", (unsigned long)osThreadId());
 126 #endif
 127     if (RtsFlags.TraceFlags.timestamp) {
 128         debugBelch("%9" FMT_Word64 ": ", stat_getElapsedTime());
 129     }
 130 }
 131 #endif
 132
 133 #ifdef DEBUG
 134 static char *thread_stop_reasons[] = {
 135     [HeapOverflow] = "heap overflow",
 136     [StackOverflow] = "stack overflow",
 137     [ThreadYielding] = "yielding",
 138     [ThreadBlocked] = "blocked",
 139     [ThreadFinished] = "finished",
 140     [THREAD_SUSPENDED_FOREIGN_CALL] = "suspended while making a foreign call",
 141     [6 + BlockedOnMVar]         = "blocked on an MVar",
 142     [6 + BlockedOnBlackHole]    = "blocked on a black hole",
 143     [6 + BlockedOnRead]         = "blocked on a read operation",
 144     [6 + BlockedOnWrite]        = "blocked on a write operation",
 145     [6 + BlockedOnDelay]        = "blocked on a delay operation",
 146     [6 + BlockedOnSTM]          = "blocked on STM",
 147     [6 + BlockedOnDoProc]       = "blocked on asyncDoProc",
 148     [6 + BlockedOnCCall]        = "blocked on a foreign call",
 149     [6 + BlockedOnCCall_Interruptible] = "blocked on a foreign call (interruptible)",
 150     [6 + BlockedOnMsgThrowTo]   =  "blocked on throwTo",
 151     [6 + ThreadMigrating]       =  "migrating"
 152 };
 153 #endif
 154
 155 #ifdef DEBUG
 156 static void traceSchedEvent_stderr (Capability *cap, EventTypeNum tag,
 157                                     StgTSO *tso,
 158                                     StgWord info1 STG_UNUSED,
 159                                     StgWord info2 STG_UNUSED)
 160 {
 161     ACQUIRE_LOCK(&trace_utx);
 162
 163     tracePreface();
 164     switch (tag) {
 165     case EVENT_CREATE_THREAD:   // (cap, thread)
 166         debugBelch("cap %d: created thread %lu\n",
 167                    cap->no, (lnat)tso->id);
 168         break;
 169     case EVENT_RUN_THREAD:      //  (cap, thread)
 170         debugBelch("cap %d: running thread %lu (%s)\n",
 171                    cap->no, (lnat)tso->id, what_next_strs[tso->what_next]);
 172         break;
 173     case EVENT_THREAD_RUNNABLE: // (cap, thread)
 174         debugBelch("cap %d: thread %lu appended to run queue\n",
 175                    cap->no, (lnat)tso->id);
 176         break;
 177     case EVENT_RUN_SPARK:       // (cap, thread)
 178         debugBelch("cap %d: thread %lu running a spark\n",
 179                    cap->no, (lnat)tso->id);
 180         break;
 181     case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
 182         debugBelch("cap %d: creating spark thread %lu\n",
 183                    cap->no, (long)info1);
 184         break;
 185     case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
 186         debugBelch("cap %d: thread %lu migrating to cap %d\n",
 187                    cap->no, (lnat)tso->id, (int)info1);
 188         break;
 189     case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
 190         debugBelch("cap %d: thread %lu stealing a spark from cap %d\n",
 191                    cap->no, (lnat)tso->id, (int)info1);
 192         break;
 193     case EVENT_THREAD_WAKEUP:   // (cap, thread, info1_cap)
 194         debugBelch("cap %d: waking up thread %lu on cap %d\n",
 195                    cap->no, (lnat)tso->id, (int)info1);
 196         break;
 197
 198     case EVENT_STOP_THREAD:     // (cap, thread, status)
 199         if (info1 == 6 + BlockedOnBlackHole) {
 200             debugBelch("cap %d: thread %lu stopped (blocked on black hole owned by thread %lu)\n",
 201                        cap->no, (lnat)tso->id, (long)info2);
 202         } else {
 203             debugBelch("cap %d: thread %lu stopped (%s)\n",
 204                        cap->no, (lnat)tso->id, thread_stop_reasons[info1]);
 205         }
 206         break;
 207     case EVENT_SHUTDOWN:        // (cap)
 208         debugBelch("cap %d: shutting down\n", cap->no);
 209         break;
 210     case EVENT_REQUEST_SEQ_GC:  // (cap)
 211         debugBelch("cap %d: requesting sequential GC\n", cap->no);
 212         break;
 213     case EVENT_REQUEST_PAR_GC:  // (cap)
 214         debugBelch("cap %d: requesting parallel GC\n", cap->no);
 215         break;
 216     case EVENT_GC_START:        // (cap)
 217         debugBelch("cap %d: starting GC\n", cap->no);
 218         break;
 219     case EVENT_GC_END:          // (cap)
 220         debugBelch("cap %d: finished GC\n", cap->no);
 221         break;
 222     case EVENT_GC_IDLE:        // (cap)
 223         debugBelch("cap %d: GC idle\n", cap->no);
 224         break;
 225     case EVENT_GC_WORK:          // (cap)
 226         debugBelch("cap %d: GC working\n", cap->no);
 227         break;
 228     case EVENT_GC_DONE:          // (cap)
 229         debugBelch("cap %d: GC done\n", cap->no);
 230         break;
 231     default:
 232         debugBelch("cap %d: thread %lu: event %d\n\n",
 233                    cap->no, (lnat)tso->id, tag);
 234         break;
 235     }
 236
 237     RELEASE_LOCK(&trace_utx);
 238 }
 239 #endif
 240
 241 void traceSchedEvent_ (Capability *cap, EventTypeNum tag,
 242                        StgTSO *tso, StgWord info1, StgWord info2)
 243 {
 244 #ifdef DEBUG
 245     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 246         traceSchedEvent_stderr(cap, tag, tso, info1, info2);
 247     } else
 248 #endif
 249     {
 250         postSchedEvent(cap,tag,tso ? tso->id : 0, info1, info2);
 251     }
 252 }
 253
 254 void traceEvent_ (Capability *cap, EventTypeNum tag)
 255 {
 256 #ifdef DEBUG
 257     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 258         traceSchedEvent_stderr(cap, tag, 0, 0, 0);
 259     } else
 260 #endif
 261     {
 262         postEvent(cap,tag);
 263     }
 264 }
 265
 266 #ifdef DEBUG
 267 static void traceCap_stderr(Capability *cap, char *msg, va_list ap)
 268 {
 269     ACQUIRE_LOCK(&trace_utx);
 270
 271     tracePreface();
 272     debugBelch("cap %d: ", cap->no);
 273     vdebugBelch(msg,ap);
 274     debugBelch("\n");
 275
 276     RELEASE_LOCK(&trace_utx);
 277 }
 278 #endif
 279
 280 void traceCap_(Capability *cap, char *msg, ...)
 281 {
 282     va_list ap;
 283     va_start(ap,msg);
 284
 285 #ifdef DEBUG
 286     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 287         traceCap_stderr(cap, msg, ap);
 288     } else
 289 #endif
 290     {
 291         postCapMsg(cap, msg, ap);
 292     }
 293
 294     va_end(ap);
 295 }
 296
 297 #ifdef DEBUG
 298 static void trace_stderr(char *msg, va_list ap)
 299 {
 300     ACQUIRE_LOCK(&trace_utx);
 301
 302     tracePreface();
 303     vdebugBelch(msg,ap);
 304     debugBelch("\n");
 305
 306     RELEASE_LOCK(&trace_utx);
 307 }
 308 #endif
 309
 310 void trace_(char *msg, ...)
 311 {
 312     va_list ap;
 313     va_start(ap,msg);
 314
 315 #ifdef DEBUG
 316     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 317         trace_stderr(msg, ap);
 318     } else
 319 #endif
 320     {
 321         postMsg(msg, ap);
 322     }
 323
 324     va_end(ap);
 325 }
 326
 327 static void traceFormatUserMsg(Capability *cap, char *msg, ...)
 328 {
 329     va_list ap;
 330     va_start(ap,msg);
 331
 332 #ifdef DEBUG
 333     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 334         traceCap_stderr(cap, msg, ap);
 335     } else
 336 #endif
 337     {
 338         if (eventlog_enabled) {
 339             postUserMsg(cap, msg, ap);
 340         }
 341     }
 342     dtraceUserMsg(cap->no, msg);
 343 }
 344
 345 void traceUserMsg(Capability *cap, char *msg)
 346 {
 347     traceFormatUserMsg(cap, "%s", msg);
 348 }
 349
 350 void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
 351 {
 352 #ifdef DEBUG
 353     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 354         printThreadStatus(tso);
 355     } else
 356 #endif
 357     {
 358         /* nothing - no event for this one yet */
 359     }
 360 }
 361
 362 void traceEventStartup_(int nocaps)
 363 {
 364     if (eventlog_enabled) {
 365         postEventStartup(nocaps);
 366     }
 367 }
 368
 369 #ifdef DEBUG
 370 void traceBegin (const char *str, ...)
 371 {
 372     va_list ap;
 373     va_start(ap,str);
 374
 375     ACQUIRE_LOCK(&trace_utx);
 376
 377     tracePreface();
 378     vdebugBelch(str,ap);
 379 }
 380
 381 void traceEnd (void)
 382 {
 383     debugBelch("\n");
 384     RELEASE_LOCK(&trace_utx);
 385 }
 386 #endif /* DEBUG */
 387
 388 #endif /* TRACING */
 389
 390 // If DTRACE is enabled, but neither DEBUG nor TRACING, we need a C land
 391 // wrapper for the user-msg probe (as we can't expand that in PrimOps.cmm)
 392 //
 393 #if !defined(DEBUG) && !defined(TRACING) && defined(DTRACE)
 394
 395 void dtraceUserMsgWrapper(Capability *cap, char *msg)
 396 {
 397     dtraceUserMsg(cap->no, msg);
 398 }
 399
 400 #endif /* !defined(DEBUG) && !defined(TRACING) && defined(DTRACE) */