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     case EVENT_GC_IDLE:        // (cap)
 197         debugBelch("cap %d: GC idle\n", cap->no);
 198         break;
 199     case EVENT_GC_WORK:          // (cap)
 200         debugBelch("cap %d: GC working\n", cap->no);
 201         break;
 202     case EVENT_GC_DONE:          // (cap)
 203         debugBelch("cap %d: GC done\n", cap->no);
 204         break;
 205     default:
 206         debugBelch("cap %2d: thread %lu: event %d\n\n",
 207                    cap->no, (lnat)tso->id, tag);
 208         break;
 209     }
 210
 211     RELEASE_LOCK(&trace_utx);
 212 }
 213 #endif
 214
 215 void traceSchedEvent_ (Capability *cap, EventTypeNum tag,
 216                       StgTSO *tso, StgWord64 other)
 217 {
 218 #ifdef DEBUG
 219     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 220         traceSchedEvent_stderr(cap, tag, tso, other);
 221     } else
 222 #endif
 223     {
 224         postSchedEvent(cap,tag,tso ? tso->id : 0,other);
 225     }
 226 }
 227
 228 void traceEvent_ (Capability *cap, EventTypeNum tag)
 229 {
 230 #ifdef DEBUG
 231     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 232         traceSchedEvent_stderr(cap, tag, 0, 0);
 233     } else
 234 #endif
 235     {
 236         postEvent(cap,tag);
 237     }
 238 }
 239
 240 #ifdef DEBUG
 241 static void traceCap_stderr(Capability *cap, char *msg, va_list ap)
 242 {
 243     ACQUIRE_LOCK(&trace_utx);
 244
 245     tracePreface();
 246     debugBelch("cap %2d: ", cap->no);
 247     vdebugBelch(msg,ap);
 248     debugBelch("\n");
 249
 250     RELEASE_LOCK(&trace_utx);
 251 }
 252 #endif
 253
 254 void traceCap_(Capability *cap, char *msg, ...)
 255 {
 256     va_list ap;
 257     va_start(ap,msg);
 258
 259 #ifdef DEBUG
 260     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 261         traceCap_stderr(cap, msg, ap);
 262     } else
 263 #endif
 264     {
 265         postCapMsg(cap, msg, ap);
 266     }
 267
 268     va_end(ap);
 269 }
 270
 271 #ifdef DEBUG
 272 static void trace_stderr(char *msg, va_list ap)
 273 {
 274     ACQUIRE_LOCK(&trace_utx);
 275
 276     tracePreface();
 277     vdebugBelch(msg,ap);
 278     debugBelch("\n");
 279
 280     RELEASE_LOCK(&trace_utx);
 281 }
 282 #endif
 283
 284 void trace_(char *msg, ...)
 285 {
 286     va_list ap;
 287     va_start(ap,msg);
 288
 289 #ifdef DEBUG
 290     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 291         trace_stderr(msg, ap);
 292     } else
 293 #endif
 294     {
 295         postMsg(msg, ap);
 296     }
 297
 298     va_end(ap);
 299 }
 300
 301 void traceUserMsg(Capability *cap, char *msg)
 302 {
 303 #ifdef DEBUG
 304     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 305         traceCap_stderr(cap, msg, NULL);
 306     } else
 307 #endif
 308     {
 309         if (eventlog_enabled) {
 310             postUserMsg(cap, msg);
 311         }
 312     }
 313 }
 314
 315 void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
 316 {
 317 #ifdef DEBUG
 318     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 319         printThreadStatus(tso);
 320     } else
 321 #endif
 322     {
 323         /* nothing - no event for this one yet */
 324     }
 325 }
 326
 327
 328 #ifdef DEBUG
 329 void traceBegin (const char *str, ...)
 330 {
 331     va_list ap;
 332     va_start(ap,str);
 333
 334     ACQUIRE_LOCK(&trace_utx);
 335
 336     tracePreface();
 337     vdebugBelch(str,ap);
 338 }
 339
 340 void traceEnd (void)
 341 {
 342     debugBelch("\n");
 343     RELEASE_LOCK(&trace_utx);
 344 }
 345 #endif /* DEBUG */
 346
 347 #endif /* TRACING */