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