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 "GetEnv.h"
  19 #include "Stats.h"
  20 #include "eventlog/EventLog.h"
  21 #include "Threads.h"
  22 #include "Printer.h"
  23
  24 #ifdef HAVE_UNISTD_H
  25 #include <unistd.h>
  26 #endif
  27
  28 #ifdef DEBUG
  29 // debugging flags, set with +RTS -D<something>
  30 int DEBUG_sched;
  31 int DEBUG_interp;
  32 int DEBUG_weak;
  33 int DEBUG_gccafs;
  34 int DEBUG_gc;
  35 int DEBUG_block_alloc;
  36 int DEBUG_sanity;
  37 int DEBUG_stable;
  38 int DEBUG_stm;
  39 int DEBUG_prof;
  40 int DEBUG_gran;
  41 int DEBUG_par;
  42 int DEBUG_linker;
  43 int DEBUG_squeeze;
  44 int DEBUG_hpc;
  45 int DEBUG_sparks;
  46 #endif
  47
  48 // events
  49 int TRACE_sched;
  50
  51 #ifdef THREADED_RTS
  52 static Mutex trace_utx;
  53 #endif
  54
  55 static rtsBool eventlog_enabled;
  56
  57 /* ---------------------------------------------------------------------------
  58    Starting up / shuttting down the tracing facilities
  59  --------------------------------------------------------------------------- */
  60
  61 void initTracing (void)
  62 {
  63 #ifdef THREADED_RTS
  64     initMutex(&trace_utx);
  65 #endif
  66
  67 #ifdef DEBUG
  68 #define DEBUG_FLAG(name, class) \
  69     class = RtsFlags.DebugFlags.name ? 1 : 0;
  70
  71     DEBUG_FLAG(scheduler,    DEBUG_sched);
  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     // -Ds turns on scheduler tracing too
  89     TRACE_sched =
  90         RtsFlags.TraceFlags.scheduler ||
  91         RtsFlags.DebugFlags.scheduler;
  92
  93     eventlog_enabled = RtsFlags.TraceFlags.tracing == TRACE_EVENTLOG;
  94
  95     if (eventlog_enabled) {
  96         initEventLogging();
  97     }
  98 }
  99
 100 void endTracing (void)
 101 {
 102     if (eventlog_enabled) {
 103         endEventLogging();
 104     }
 105 }
 106
 107 void freeTracing (void)
 108 {
 109     if (eventlog_enabled) {
 110         freeEventLogging();
 111     }
 112 }
 113
 114 void resetTracing (void)
 115 {
 116     if (eventlog_enabled) {
 117         abortEventLogging(); // abort eventlog inherited from parent
 118         initEventLogging(); // child starts its own eventlog
 119     }
 120 }
 121
 122 /* ---------------------------------------------------------------------------
 123    Emitting trace messages/events
 124  --------------------------------------------------------------------------- */
 125
 126 #ifdef DEBUG
 127 static void tracePreface (void)
 128 {
 129 #ifdef THREADED_RTS
 130     debugBelch("%12lx: ", (unsigned long)osThreadId());
 131 #endif
 132     if (RtsFlags.TraceFlags.timestamp) {
 133         debugBelch("%9" FMT_Word64 ": ", stat_getElapsedTime());
 134     }
 135 }
 136 #endif
 137
 138 #ifdef DEBUG
 139 static char *thread_stop_reasons[] = {
 140     [HeapOverflow] = "heap overflow",
 141     [StackOverflow] = "stack overflow",
 142     [ThreadYielding] = "yielding",
 143     [ThreadBlocked] = "blocked",
 144     [ThreadFinished] = "finished",
 145     [THREAD_SUSPENDED_FOREIGN_CALL] = "suspended while making a foreign call",
 146     [6 + BlockedOnMVar]         = "blocked on an MVar",
 147     [6 + BlockedOnBlackHole]    = "blocked on a black hole",
 148     [6 + BlockedOnRead]         = "blocked on a read operation",
 149     [6 + BlockedOnWrite]        = "blocked on a write operation",
 150     [6 + BlockedOnDelay]        = "blocked on a delay operation",
 151     [6 + BlockedOnSTM]          = "blocked on STM",
 152     [6 + BlockedOnDoProc]       = "blocked on asyncDoProc",
 153     [6 + BlockedOnCCall]        = "blocked on a foreign call",
 154     [6 + BlockedOnCCall_Interruptible] = "blocked on a foreign call (interruptible)",
 155     [6 + BlockedOnMsgThrowTo]   =  "blocked on throwTo",
 156     [6 + ThreadMigrating]       =  "migrating"
 157 };
 158 #endif
 159
 160 #ifdef DEBUG
 161 static void traceSchedEvent_stderr (Capability *cap, EventTypeNum tag,
 162                                     StgTSO *tso,
 163                                     StgWord info1 STG_UNUSED,
 164                                     StgWord info2 STG_UNUSED)
 165 {
 166     ACQUIRE_LOCK(&trace_utx);
 167
 168     tracePreface();
 169     switch (tag) {
 170     case EVENT_CREATE_THREAD:   // (cap, thread)
 171         debugBelch("cap %d: created thread %lu\n",
 172                    cap->no, (lnat)tso->id);
 173         break;
 174     case EVENT_RUN_THREAD:      //  (cap, thread)
 175         debugBelch("cap %d: running thread %lu (%s)\n",
 176                    cap->no, (lnat)tso->id, what_next_strs[tso->what_next]);
 177         break;
 178     case EVENT_THREAD_RUNNABLE: // (cap, thread)
 179         debugBelch("cap %d: thread %lu appended to run queue\n",
 180                    cap->no, (lnat)tso->id);
 181         break;
 182     case EVENT_RUN_SPARK:       // (cap, thread)
 183         debugBelch("cap %d: thread %lu running a spark\n",
 184                    cap->no, (lnat)tso->id);
 185         break;
 186     case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
 187         debugBelch("cap %d: creating spark thread %lu\n",
 188                    cap->no, (long)info1);
 189         break;
 190     case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
 191         debugBelch("cap %d: thread %lu migrating to cap %d\n",
 192                    cap->no, (lnat)tso->id, (int)info1);
 193         break;
 194     case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
 195         debugBelch("cap %d: thread %lu stealing a spark from cap %d\n",
 196                    cap->no, (lnat)tso->id, (int)info1);
 197         break;
 198     case EVENT_THREAD_WAKEUP:   // (cap, thread, info1_cap)
 199         debugBelch("cap %d: waking up thread %lu on cap %d\n",
 200                    cap->no, (lnat)tso->id, (int)info1);
 201         break;
 202
 203     case EVENT_STOP_THREAD:     // (cap, thread, status)
 204         if (info1 == 6 + BlockedOnBlackHole) {
 205             debugBelch("cap %d: thread %lu stopped (blocked on black hole owned by thread %lu)\n",
 206                        cap->no, (lnat)tso->id, (long)info2);
 207         } else {
 208             debugBelch("cap %d: thread %lu stopped (%s)\n",
 209                        cap->no, (lnat)tso->id, thread_stop_reasons[info1]);
 210         }
 211         break;
 212     case EVENT_SHUTDOWN:        // (cap)
 213         debugBelch("cap %d: shutting down\n", cap->no);
 214         break;
 215     case EVENT_REQUEST_SEQ_GC:  // (cap)
 216         debugBelch("cap %d: requesting sequential GC\n", cap->no);
 217         break;
 218     case EVENT_REQUEST_PAR_GC:  // (cap)
 219         debugBelch("cap %d: requesting parallel GC\n", cap->no);
 220         break;
 221     case EVENT_GC_START:        // (cap)
 222         debugBelch("cap %d: starting GC\n", cap->no);
 223         break;
 224     case EVENT_GC_END:          // (cap)
 225         debugBelch("cap %d: finished GC\n", cap->no);
 226         break;
 227     case EVENT_GC_IDLE:        // (cap)
 228         debugBelch("cap %d: GC idle\n", cap->no);
 229         break;
 230     case EVENT_GC_WORK:          // (cap)
 231         debugBelch("cap %d: GC working\n", cap->no);
 232         break;
 233     case EVENT_GC_DONE:          // (cap)
 234         debugBelch("cap %d: GC done\n", cap->no);
 235         break;
 236     default:
 237         debugBelch("cap %d: thread %lu: event %d\n\n",
 238                    cap->no, (lnat)tso->id, tag);
 239         break;
 240     }
 241
 242     RELEASE_LOCK(&trace_utx);
 243 }
 244 #endif
 245
 246 void traceSchedEvent_ (Capability *cap, EventTypeNum tag,
 247                        StgTSO *tso, StgWord info1, StgWord info2)
 248 {
 249 #ifdef DEBUG
 250     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 251         traceSchedEvent_stderr(cap, tag, tso, info1, info2);
 252     } else
 253 #endif
 254     {
 255         postSchedEvent(cap,tag,tso ? tso->id : 0, info1, info2);
 256     }
 257 }
 258
 259 void traceCapsetModify_ (EventTypeNum tag,
 260                          CapsetID capset,
 261                          StgWord32 other)
 262 {
 263 #ifdef DEBUG
 264     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 265         ACQUIRE_LOCK(&trace_utx);
 266
 267         tracePreface();
 268         switch (tag) {
 269         case EVENT_CAPSET_CREATE:   // (capset, capset_type)
 270             debugBelch("created capset %d of type %d\n", capset, other);
 271             break;
 272         case EVENT_CAPSET_DELETE:   // (capset)
 273             debugBelch("deleted capset %d\n", capset);
 274             break;
 275         case EVENT_CAPSET_ASSIGN_CAP:  // (capset, capno)
 276             debugBelch("assigned cap %d to capset %d\n", other, capset);
 277             break;
 278         case EVENT_CAPSET_REMOVE_CAP:  // (capset, capno)
 279             debugBelch("removed cap %d from capset %d\n", other, capset);
 280             break;
 281         }
 282         RELEASE_LOCK(&trace_utx);
 283     } else
 284 #endif
 285     {
 286         if (eventlog_enabled) {
 287             postCapsetModifyEvent(tag, capset, other);
 288         }
 289     }
 290 }
 291
 292 void traceOSProcessInfo_(void) {
 293     if (eventlog_enabled) {
 294         postCapsetModifyEvent(EVENT_OSPROCESS_PID,
 295                               CAPSET_OSPROCESS_DEFAULT,
 296                               getpid());
 297
 298 #if !defined(cygwin32_HOST_OS) && !defined (mingw32_HOST_OS)
 299 /* Windows has no strong concept of process heirarchy, so no getppid().
 300  * In any case, this trace event is mainly useful for tracing programs
 301  * that use 'forkProcess' which Windows doesn't support anyway.
 302  */
 303         postCapsetModifyEvent(EVENT_OSPROCESS_PPID,
 304                               CAPSET_OSPROCESS_DEFAULT,
 305                               getppid());
 306 #endif
 307         {
 308             char buf[256];
 309             snprintf(buf, sizeof(buf), "GHC-%s %s", ProjectVersion, RtsWay);
 310             postCapsetStrEvent(EVENT_RTS_IDENTIFIER,
 311                                CAPSET_OSPROCESS_DEFAULT,
 312                                buf);
 313         }
 314         {
 315             int argc = 0; char **argv;
 316             getFullProgArgv(&argc, &argv);
 317             if (argc != 0) {
 318                 postCapsetVecEvent(EVENT_PROGRAM_ARGS,
 319                                    CAPSET_OSPROCESS_DEFAULT,
 320                                    argc, argv);
 321             }
 322         }
 323         {
 324             int envc = 0; char **envv;
 325             getProgEnvv(&envc, &envv);
 326             if (envc != 0) {
 327                 postCapsetVecEvent(EVENT_PROGRAM_ENV,
 328                                    CAPSET_OSPROCESS_DEFAULT,
 329                                    envc, envv);
 330             }
 331             freeProgEnvv(envc, envv);
 332         }
 333     }
 334 }
 335
 336 void traceEvent_ (Capability *cap, EventTypeNum tag)
 337 {
 338 #ifdef DEBUG
 339     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 340         traceSchedEvent_stderr(cap, tag, 0, 0, 0);
 341     } else
 342 #endif
 343     {
 344         postEvent(cap,tag);
 345     }
 346 }
 347
 348 #ifdef DEBUG
 349 static void traceCap_stderr(Capability *cap, char *msg, va_list ap)
 350 {
 351     ACQUIRE_LOCK(&trace_utx);
 352
 353     tracePreface();
 354     debugBelch("cap %d: ", cap->no);
 355     vdebugBelch(msg,ap);
 356     debugBelch("\n");
 357
 358     RELEASE_LOCK(&trace_utx);
 359 }
 360 #endif
 361
 362 void traceCap_(Capability *cap, char *msg, ...)
 363 {
 364     va_list ap;
 365     va_start(ap,msg);
 366
 367 #ifdef DEBUG
 368     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 369         traceCap_stderr(cap, msg, ap);
 370     } else
 371 #endif
 372     {
 373         postCapMsg(cap, msg, ap);
 374     }
 375
 376     va_end(ap);
 377 }
 378
 379 #ifdef DEBUG
 380 static void trace_stderr(char *msg, va_list ap)
 381 {
 382     ACQUIRE_LOCK(&trace_utx);
 383
 384     tracePreface();
 385     vdebugBelch(msg,ap);
 386     debugBelch("\n");
 387
 388     RELEASE_LOCK(&trace_utx);
 389 }
 390 #endif
 391
 392 void trace_(char *msg, ...)
 393 {
 394     va_list ap;
 395     va_start(ap,msg);
 396
 397 #ifdef DEBUG
 398     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 399         trace_stderr(msg, ap);
 400     } else
 401 #endif
 402     {
 403         postMsg(msg, ap);
 404     }
 405
 406     va_end(ap);
 407 }
 408
 409 static void traceFormatUserMsg(Capability *cap, char *msg, ...)
 410 {
 411     va_list ap;
 412     va_start(ap,msg);
 413
 414 #ifdef DEBUG
 415     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 416         traceCap_stderr(cap, msg, ap);
 417     } else
 418 #endif
 419     {
 420         if (eventlog_enabled) {
 421             postUserMsg(cap, msg, ap);
 422         }
 423     }
 424     dtraceUserMsg(cap->no, msg);
 425 }
 426
 427 void traceUserMsg(Capability *cap, char *msg)
 428 {
 429     traceFormatUserMsg(cap, "%s", msg);
 430 }
 431
 432 void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
 433 {
 434 #ifdef DEBUG
 435     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 436         printThreadStatus(tso);
 437     } else
 438 #endif
 439     {
 440         /* nothing - no event for this one yet */
 441     }
 442 }
 443
 444 void traceEventStartup_(int nocaps)
 445 {
 446     if (eventlog_enabled) {
 447         postEventStartup(nocaps);
 448     }
 449 }
 450
 451 #ifdef DEBUG
 452 void traceBegin (const char *str, ...)
 453 {
 454     va_list ap;
 455     va_start(ap,str);
 456
 457     ACQUIRE_LOCK(&trace_utx);
 458
 459     tracePreface();
 460     vdebugBelch(str,ap);
 461 }
 462
 463 void traceEnd (void)
 464 {
 465     debugBelch("\n");
 466     RELEASE_LOCK(&trace_utx);
 467 }
 468 #endif /* DEBUG */
 469
 470 #endif /* TRACING */
 471
 472 // If DTRACE is enabled, but neither DEBUG nor TRACING, we need a C land
 473 // wrapper for the user-msg probe (as we can't expand that in PrimOps.cmm)
 474 //
 475 #if !defined(DEBUG) && !defined(TRACING) && defined(DTRACE)
 476
 477 void dtraceUserMsgWrapper(Capability *cap, char *msg)
 478 {
 479     dtraceUserMsg(cap->no, msg);
 480 }
 481
 482 #endif /* !defined(DEBUG) && !defined(TRACING) && defined(DTRACE) */