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 };
 142 #endif
 143
 144 #ifdef DEBUG
 145 static void traceSchedEvent_stderr (Capability *cap, EventTypeNum tag,
 146                                     StgTSO *tso,
 147                                     StgWord64 other STG_UNUSED)
 148 {
 149     ACQUIRE_LOCK(&trace_utx);
 150
 151     tracePreface();
 152     switch (tag) {
 153     case EVENT_CREATE_THREAD:   // (cap, thread)
 154         debugBelch("cap %d: created thread %lu\n",
 155                    cap->no, (lnat)tso->id);
 156         break;
 157     case EVENT_RUN_THREAD:      //  (cap, thread)
 158         debugBelch("cap %d: running thread %lu (%s)\n",
 159                    cap->no, (lnat)tso->id, what_next_strs[tso->what_next]);
 160         break;
 161     case EVENT_THREAD_RUNNABLE: // (cap, thread)
 162         debugBelch("cap %d: thread %lu appended to run queue\n",
 163                    cap->no, (lnat)tso->id);
 164         break;
 165     case EVENT_RUN_SPARK:       // (cap, thread)
 166         debugBelch("cap %d: thread %lu running a spark\n",
 167                    cap->no, (lnat)tso->id);
 168         break;
 169     case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
 170         debugBelch("cap %d: creating spark thread %lu\n",
 171                    cap->no, (long)other);
 172         break;
 173     case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
 174         debugBelch("cap %d: thread %lu migrating to cap %d\n",
 175                    cap->no, (lnat)tso->id, (int)other);
 176         break;
 177     case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
 178         debugBelch("cap %d: thread %lu stealing a spark from cap %d\n",
 179                    cap->no, (lnat)tso->id, (int)other);
 180         break;
 181     case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
 182         debugBelch("cap %d: waking up thread %lu on cap %d\n",
 183                    cap->no, (lnat)tso->id, (int)other);
 184         break;
 185
 186     case EVENT_STOP_THREAD:     // (cap, thread, status)
 187         debugBelch("cap %d: thread %lu stopped (%s)\n",
 188                    cap->no, (lnat)tso->id, thread_stop_reasons[other]);
 189         break;
 190     case EVENT_SHUTDOWN:        // (cap)
 191         debugBelch("cap %d: shutting down\n", cap->no);
 192         break;
 193     case EVENT_REQUEST_SEQ_GC:  // (cap)
 194         debugBelch("cap %d: requesting sequential GC\n", cap->no);
 195         break;
 196     case EVENT_REQUEST_PAR_GC:  // (cap)
 197         debugBelch("cap %d: requesting parallel GC\n", cap->no);
 198         break;
 199     case EVENT_GC_START:        // (cap)
 200         debugBelch("cap %d: starting GC\n", cap->no);
 201         break;
 202     case EVENT_GC_END:          // (cap)
 203         debugBelch("cap %d: finished GC\n", cap->no);
 204         break;
 205     case EVENT_GC_IDLE:        // (cap)
 206         debugBelch("cap %d: GC idle\n", cap->no);
 207         break;
 208     case EVENT_GC_WORK:          // (cap)
 209         debugBelch("cap %d: GC working\n", cap->no);
 210         break;
 211     case EVENT_GC_DONE:          // (cap)
 212         debugBelch("cap %d: GC done\n", cap->no);
 213         break;
 214     default:
 215         debugBelch("cap %d: thread %lu: event %d\n\n",
 216                    cap->no, (lnat)tso->id, tag);
 217         break;
 218     }
 219
 220     RELEASE_LOCK(&trace_utx);
 221 }
 222 #endif
 223
 224 void traceSchedEvent_ (Capability *cap, EventTypeNum tag,
 225                       StgTSO *tso, StgWord64 other)
 226 {
 227 #ifdef DEBUG
 228     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 229         traceSchedEvent_stderr(cap, tag, tso, other);
 230     } else
 231 #endif
 232     {
 233         postSchedEvent(cap,tag,tso ? tso->id : 0,other);
 234     }
 235 }
 236
 237 void traceEvent_ (Capability *cap, EventTypeNum tag)
 238 {
 239 #ifdef DEBUG
 240     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 241         traceSchedEvent_stderr(cap, tag, 0, 0);
 242     } else
 243 #endif
 244     {
 245         postEvent(cap,tag);
 246     }
 247 }
 248
 249 #ifdef DEBUG
 250 static void traceCap_stderr(Capability *cap, char *msg, va_list ap)
 251 {
 252     ACQUIRE_LOCK(&trace_utx);
 253
 254     tracePreface();
 255     debugBelch("cap %d: ", cap->no);
 256     vdebugBelch(msg,ap);
 257     debugBelch("\n");
 258
 259     RELEASE_LOCK(&trace_utx);
 260 }
 261 #endif
 262
 263 void traceCap_(Capability *cap, char *msg, ...)
 264 {
 265     va_list ap;
 266     va_start(ap,msg);
 267
 268 #ifdef DEBUG
 269     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 270         traceCap_stderr(cap, msg, ap);
 271     } else
 272 #endif
 273     {
 274         postCapMsg(cap, msg, ap);
 275     }
 276
 277     va_end(ap);
 278 }
 279
 280 #ifdef DEBUG
 281 static void trace_stderr(char *msg, va_list ap)
 282 {
 283     ACQUIRE_LOCK(&trace_utx);
 284
 285     tracePreface();
 286     vdebugBelch(msg,ap);
 287     debugBelch("\n");
 288
 289     RELEASE_LOCK(&trace_utx);
 290 }
 291 #endif
 292
 293 void trace_(char *msg, ...)
 294 {
 295     va_list ap;
 296     va_start(ap,msg);
 297
 298 #ifdef DEBUG
 299     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 300         trace_stderr(msg, ap);
 301     } else
 302 #endif
 303     {
 304         postMsg(msg, ap);
 305     }
 306
 307     va_end(ap);
 308 }
 309
 310 static void traceFormatUserMsg(Capability *cap, char *msg, ...)
 311 {
 312     va_list ap;
 313     va_start(ap,msg);
 314
 315 #ifdef DEBUG
 316     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 317         traceCap_stderr(cap, msg, ap);
 318     } else
 319 #endif
 320     {
 321         if (eventlog_enabled) {
 322             postUserMsg(cap, msg, ap);
 323         }
 324     }
 325     dtraceUserMsg(cap->no, msg);
 326 }
 327
 328 void traceUserMsg(Capability *cap, char *msg)
 329 {
 330     traceFormatUserMsg(cap, "%s", msg);
 331 }
 332
 333 void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
 334 {
 335 #ifdef DEBUG
 336     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 337         printThreadStatus(tso);
 338     } else
 339 #endif
 340     {
 341         /* nothing - no event for this one yet */
 342     }
 343 }
 344
 345
 346 #ifdef DEBUG
 347 void traceBegin (const char *str, ...)
 348 {
 349     va_list ap;
 350     va_start(ap,str);
 351
 352     ACQUIRE_LOCK(&trace_utx);
 353
 354     tracePreface();
 355     vdebugBelch(str,ap);
 356 }
 357
 358 void traceEnd (void)
 359 {
 360     debugBelch("\n");
 361     RELEASE_LOCK(&trace_utx);
 362 }
 363 #endif /* DEBUG */
 364
 365 #endif /* TRACING */
 366
 367 // If DTRACE is enabled, but neither DEBUG nor TRACING, we need a C land
 368 // wrapper for the user-msg probe (as we can't expand that in PrimOps.cmm)
 369 //
 370 #if !defined(DEBUG) && !defined(TRACING) && defined(DTRACE)
 371
 372 void dtraceUserMsgWrapper(Capability *cap, char *msg)
 373 {
 374     dtraceUserMsg(cap->no, msg);
 375 }
 376
 377 #endif /* !defined(DEBUG) && !defined(TRACING) && defined(DTRACE) */