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 #define TRACE_FLAG(name, class) \
  62     class = RtsFlags.TraceFlags.name ? 1 : 0;
  63
  64     TRACE_FLAG(scheduler, TRACE_sched);
  65
  66 #ifdef DEBUG
  67 #define DEBUG_FLAG(name, class) \
  68     class = RtsFlags.DebugFlags.name ? 1 : 0;
  69
  70     DEBUG_FLAG(scheduler,    DEBUG_sched);
  71     DEBUG_FLAG(scheduler,    TRACE_sched); // -Ds enabled all sched events
  72
  73     DEBUG_FLAG(interpreter,  DEBUG_interp);
  74     DEBUG_FLAG(weak,         DEBUG_weak);
  75     DEBUG_FLAG(gccafs,       DEBUG_gccafs);
  76     DEBUG_FLAG(gc,           DEBUG_gc);
  77     DEBUG_FLAG(block_alloc,  DEBUG_block_alloc);
  78     DEBUG_FLAG(sanity,       DEBUG_sanity);
  79     DEBUG_FLAG(stable,       DEBUG_stable);
  80     DEBUG_FLAG(stm,          DEBUG_stm);
  81     DEBUG_FLAG(prof,         DEBUG_prof);
  82     DEBUG_FLAG(linker,       DEBUG_linker);
  83     DEBUG_FLAG(squeeze,      DEBUG_squeeze);
  84     DEBUG_FLAG(hpc,          DEBUG_hpc);
  85     DEBUG_FLAG(sparks,       DEBUG_sparks);
  86 #endif
  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     default:
 198         debugBelch("cap %2d: thread %lu: event %d\n\n",
 199                    cap->no, (lnat)tso->id, tag);
 200         break;
 201     }
 202
 203     RELEASE_LOCK(&trace_utx);
 204 }
 205 #endif
 206
 207 void traceSchedEvent_ (Capability *cap, EventTypeNum tag,
 208                       StgTSO *tso, StgWord64 other)
 209 {
 210 #ifdef DEBUG
 211     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 212         traceSchedEvent_stderr(cap, tag, tso, other);
 213     } else
 214 #endif
 215     {
 216         postSchedEvent(cap,tag,tso ? tso->id : 0,other);
 217     }
 218 }
 219
 220 #ifdef DEBUG
 221 static void traceCap_stderr(Capability *cap, char *msg, va_list ap)
 222 {
 223     ACQUIRE_LOCK(&trace_utx);
 224
 225     tracePreface();
 226     debugBelch("cap %2d: ", cap->no);
 227     vdebugBelch(msg,ap);
 228     debugBelch("\n");
 229
 230     RELEASE_LOCK(&trace_utx);
 231 }
 232 #endif
 233
 234 void traceCap_(Capability *cap, char *msg, ...)
 235 {
 236     va_list ap;
 237     va_start(ap,msg);
 238
 239 #ifdef DEBUG
 240     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 241         traceCap_stderr(cap, msg, ap);
 242     } else
 243 #endif
 244     {
 245         postCapMsg(cap, msg, ap);
 246     }
 247
 248     va_end(ap);
 249 }
 250
 251 #ifdef DEBUG
 252 static void trace_stderr(char *msg, va_list ap)
 253 {
 254     ACQUIRE_LOCK(&trace_utx);
 255
 256     tracePreface();
 257     vdebugBelch(msg,ap);
 258     debugBelch("\n");
 259
 260     RELEASE_LOCK(&trace_utx);
 261 }
 262 #endif
 263
 264 void trace_(char *msg, ...)
 265 {
 266     va_list ap;
 267     va_start(ap,msg);
 268
 269 #ifdef DEBUG
 270     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 271         trace_stderr(msg, ap);
 272     } else
 273 #endif
 274     {
 275         postMsg(msg, ap);
 276     }
 277
 278     va_end(ap);
 279 }
 280
 281 void traceUserMsg(Capability *cap, char *msg)
 282 {
 283 #ifdef DEBUG
 284     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 285         traceCap_stderr(cap, msg, NULL);
 286     } else
 287 #endif
 288     {
 289         if (eventlog_enabled) {
 290             postUserMsg(cap, msg);
 291         }
 292     }
 293 }
 294
 295 void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
 296 {
 297 #ifdef DEBUG
 298     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 299         printThreadStatus(tso);
 300     } else
 301 #endif
 302     {
 303         /* nothing - no event for this one yet */
 304     }
 305 }
 306
 307
 308 #ifdef DEBUG
 309 void traceBegin (const char *str, ...)
 310 {
 311     va_list ap;
 312     va_start(ap,str);
 313
 314     ACQUIRE_LOCK(&trace_utx);
 315
 316     tracePreface();
 317     vdebugBelch(str,ap);
 318 }
 319
 320 void traceEnd (void)
 321 {
 322     debugBelch("\n");
 323     RELEASE_LOCK(&trace_utx);
 324 }
 325 #endif /* DEBUG */
 326
 327 #endif /* TRACING */