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     DEBUG_FLAG(scheduler,    TRACE_sched); // -Ds enabled all sched events
  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 #define TRACE_FLAG(name, class) \
  84     class = RtsFlags.TraceFlags.name ? 1 : 0;
  85
  86     TRACE_FLAG(scheduler, TRACE_sched);
  87
  88     eventlog_enabled = !RtsFlags.TraceFlags.trace_stderr && (
  89                        TRACE_sched
  90 #ifdef DEBUG
  91                        | DEBUG_sched
  92                        | DEBUG_interp
  93                        | DEBUG_weak
  94                        | DEBUG_gccafs
  95                        | DEBUG_gc
  96                        | DEBUG_block_alloc
  97                        | DEBUG_sanity
  98                        | DEBUG_stable
  99                        | DEBUG_stm
 100                        | DEBUG_prof
 101                        | DEBUG_linker
 102                        | DEBUG_squeeze
 103                        | DEBUG_hpc
 104 #endif
 105         );
 106
 107     if (eventlog_enabled) {
 108         initEventLogging();
 109     }
 110 }
 111
 112 void endTracing (void)
 113 {
 114     if (eventlog_enabled) {
 115         endEventLogging();
 116     }
 117 }
 118
 119 void freeTracing (void)
 120 {
 121     if (eventlog_enabled) {
 122         freeEventLogging();
 123     }
 124 }
 125
 126 /* ---------------------------------------------------------------------------
 127    Emitting trace messages/events
 128  --------------------------------------------------------------------------- */
 129
 130 #ifdef DEBUG
 131 static void tracePreface (void)
 132 {
 133 #ifdef THREADED_RTS
 134     debugBelch("%12lx: ", (unsigned long)osThreadId());
 135 #endif
 136     if (RtsFlags.TraceFlags.timestamp) {
 137         debugBelch("%9" FMT_Word64 ": ", stat_getElapsedTime());
 138     }
 139 }
 140 #endif
 141
 142 #ifdef DEBUG
 143 static char *thread_stop_reasons[] = {
 144     [HeapOverflow] = "heap overflow",
 145     [StackOverflow] = "stack overflow",
 146     [ThreadYielding] = "yielding",
 147     [ThreadBlocked] = "blocked",
 148     [ThreadFinished] = "finished",
 149     [THREAD_SUSPENDED_FOREIGN_CALL] = "suspended while making a foreign call"
 150 };
 151 #endif
 152
 153 #ifdef DEBUG
 154 static void traceSchedEvent_stderr (Capability *cap, EventTypeNum tag,
 155                                     StgTSO *tso,
 156                                     StgWord64 other STG_UNUSED)
 157 {
 158     ACQUIRE_LOCK(&trace_utx);
 159
 160     tracePreface();
 161     switch (tag) {
 162     case EVENT_CREATE_THREAD:   // (cap, thread)
 163         debugBelch("cap %d: created thread %lu\n",
 164                    cap->no, (lnat)tso->id);
 165         break;
 166     case EVENT_RUN_THREAD:      //  (cap, thread)
 167         debugBelch("cap %d: running thread %lu (%s)\n",
 168                    cap->no, (lnat)tso->id, what_next_strs[tso->what_next]);
 169         break;
 170     case EVENT_THREAD_RUNNABLE: // (cap, thread)
 171         debugBelch("cap %d: thread %lu appended to run queue\n",
 172                    cap->no, (lnat)tso->id);
 173         break;
 174     case EVENT_RUN_SPARK:       // (cap, thread)
 175         debugBelch("cap %d: thread %lu running a spark\n",
 176                    cap->no, (lnat)tso->id);
 177         break;
 178     case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
 179         debugBelch("cap %d: creating spark thread %lu\n",
 180                    cap->no, (long)other);
 181         break;
 182     case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
 183         debugBelch("cap %d: thread %lu migrating to cap %d\n",
 184                    cap->no, (lnat)tso->id, (int)other);
 185         break;
 186     case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
 187         debugBelch("cap %d: thread %lu stealing a spark from cap %d\n",
 188                    cap->no, (lnat)tso->id, (int)other);
 189         break;
 190     case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
 191         debugBelch("cap %d: waking up thread %lu on cap %d\n",
 192                    cap->no, (lnat)tso->id, (int)other);
 193         break;
 194
 195     case EVENT_STOP_THREAD:     // (cap, thread, status)
 196         debugBelch("cap %d: thread %lu stopped (%s)\n",
 197                    cap->no, (lnat)tso->id, thread_stop_reasons[other]);
 198         break;
 199     case EVENT_SHUTDOWN:        // (cap)
 200         debugBelch("cap %d: shutting down\n", cap->no);
 201         break;
 202     case EVENT_REQUEST_SEQ_GC:  // (cap)
 203         debugBelch("cap %d: requesting sequential GC\n", cap->no);
 204         break;
 205     case EVENT_REQUEST_PAR_GC:  // (cap)
 206         debugBelch("cap %d: requesting parallel GC\n", cap->no);
 207         break;
 208     case EVENT_GC_START:        // (cap)
 209         debugBelch("cap %d: starting GC\n", cap->no);
 210         break;
 211     case EVENT_GC_END:          // (cap)
 212         debugBelch("cap %d: finished GC\n", cap->no);
 213         break;
 214     default:
 215         debugBelch("cap %2d: 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.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 #ifdef DEBUG
 238 static void traceCap_stderr(Capability *cap, char *msg, va_list ap)
 239 {
 240     ACQUIRE_LOCK(&trace_utx);
 241
 242     tracePreface();
 243     debugBelch("cap %2d: ", cap->no);
 244     vdebugBelch(msg,ap);
 245     debugBelch("\n");
 246
 247     RELEASE_LOCK(&trace_utx);
 248 }
 249 #endif
 250
 251 void traceCap_(Capability *cap, char *msg, ...)
 252 {
 253     va_list ap;
 254     va_start(ap,msg);
 255
 256 #ifdef DEBUG
 257     if (RtsFlags.TraceFlags.trace_stderr) {
 258         traceCap_stderr(cap, msg, ap);
 259     } else
 260 #endif
 261     {
 262         postCapMsg(cap, msg, ap);
 263     }
 264
 265     va_end(ap);
 266 }
 267
 268 #ifdef DEBUG
 269 static void trace_stderr(char *msg, va_list ap)
 270 {
 271     ACQUIRE_LOCK(&trace_utx);
 272
 273     tracePreface();
 274     vdebugBelch(msg,ap);
 275     debugBelch("\n");
 276
 277     RELEASE_LOCK(&trace_utx);
 278 }
 279 #endif
 280
 281 void trace_(char *msg, ...)
 282 {
 283     va_list ap;
 284     va_start(ap,msg);
 285
 286 #ifdef DEBUG
 287     if (RtsFlags.TraceFlags.trace_stderr) {
 288         trace_stderr(msg, ap);
 289     } else
 290 #endif
 291     {
 292         postMsg(msg, ap);
 293     }
 294
 295     va_end(ap);
 296 }
 297
 298 void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
 299 {
 300 #ifdef DEBUG
 301     if (RtsFlags.TraceFlags.trace_stderr) {
 302         printThreadStatus(tso);
 303     } else
 304 #endif
 305     {
 306         /* nothing - no event for this one yet */
 307     }
 308 }
 309
 310
 311 #ifdef DEBUG
 312 void traceBegin (const char *str, ...)
 313 {
 314     va_list ap;
 315     va_start(ap,str);
 316
 317     ACQUIRE_LOCK(&trace_utx);
 318
 319     tracePreface();
 320     vdebugBelch(str,ap);
 321 }
 322
 323 void traceEnd (void)
 324 {
 325     debugBelch("\n");
 326     RELEASE_LOCK(&trace_utx);
 327 }
 328 #endif /* DEBUG */
 329
 330 #endif /* TRACING */