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