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 %lu of type %d\n", (lnat)capset, (int)other);
 271             break;
 272         case EVENT_CAPSET_DELETE:   // (capset)
 273             debugBelch("deleted capset %lu\n", (lnat)capset);
 274             break;
 275         case EVENT_CAPSET_ASSIGN_CAP:  // (capset, capno)
 276             debugBelch("assigned cap %lu to capset %lu\n",
 277                        (lnat)other, (lnat)capset);
 278             break;
 279         case EVENT_CAPSET_REMOVE_CAP:  // (capset, capno)
 280             debugBelch("removed cap %lu from capset %lu\n",
 281                        (lnat)other, (lnat)capset);
 282             break;
 283         }
 284         RELEASE_LOCK(&trace_utx);
 285     } else
 286 #endif
 287     {
 288         if (eventlog_enabled) {
 289             postCapsetModifyEvent(tag, capset, other);
 290         }
 291     }
 292 }
 293
 294 void traceOSProcessInfo_(void) {
 295     if (eventlog_enabled) {
 296         postCapsetModifyEvent(EVENT_OSPROCESS_PID,
 297                               CAPSET_OSPROCESS_DEFAULT,
 298                               getpid());
 299
 300 #if !defined(cygwin32_HOST_OS) && !defined (mingw32_HOST_OS)
 301 /* Windows has no strong concept of process heirarchy, so no getppid().
 302  * In any case, this trace event is mainly useful for tracing programs
 303  * that use 'forkProcess' which Windows doesn't support anyway.
 304  */
 305         postCapsetModifyEvent(EVENT_OSPROCESS_PPID,
 306                               CAPSET_OSPROCESS_DEFAULT,
 307                               getppid());
 308 #endif
 309         {
 310             char buf[256];
 311             snprintf(buf, sizeof(buf), "GHC-%s %s", ProjectVersion, RtsWay);
 312             postCapsetStrEvent(EVENT_RTS_IDENTIFIER,
 313                                CAPSET_OSPROCESS_DEFAULT,
 314                                buf);
 315         }
 316         {
 317             int argc = 0; char **argv;
 318             getFullProgArgv(&argc, &argv);
 319             if (argc != 0) {
 320                 postCapsetVecEvent(EVENT_PROGRAM_ARGS,
 321                                    CAPSET_OSPROCESS_DEFAULT,
 322                                    argc, argv);
 323             }
 324         }
 325         {
 326             int envc = 0; char **envv;
 327             getProgEnvv(&envc, &envv);
 328             if (envc != 0) {
 329                 postCapsetVecEvent(EVENT_PROGRAM_ENV,
 330                                    CAPSET_OSPROCESS_DEFAULT,
 331                                    envc, envv);
 332             }
 333             freeProgEnvv(envc, envv);
 334         }
 335     }
 336 }
 337
 338 void traceEvent_ (Capability *cap, EventTypeNum tag)
 339 {
 340 #ifdef DEBUG
 341     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 342         traceSchedEvent_stderr(cap, tag, 0, 0, 0);
 343     } else
 344 #endif
 345     {
 346         postEvent(cap,tag);
 347     }
 348 }
 349
 350 #ifdef DEBUG
 351 static void traceCap_stderr(Capability *cap, char *msg, va_list ap)
 352 {
 353     ACQUIRE_LOCK(&trace_utx);
 354
 355     tracePreface();
 356     debugBelch("cap %d: ", cap->no);
 357     vdebugBelch(msg,ap);
 358     debugBelch("\n");
 359
 360     RELEASE_LOCK(&trace_utx);
 361 }
 362 #endif
 363
 364 void traceCap_(Capability *cap, char *msg, ...)
 365 {
 366     va_list ap;
 367     va_start(ap,msg);
 368
 369 #ifdef DEBUG
 370     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 371         traceCap_stderr(cap, msg, ap);
 372     } else
 373 #endif
 374     {
 375         postCapMsg(cap, msg, ap);
 376     }
 377
 378     va_end(ap);
 379 }
 380
 381 #ifdef DEBUG
 382 static void trace_stderr(char *msg, va_list ap)
 383 {
 384     ACQUIRE_LOCK(&trace_utx);
 385
 386     tracePreface();
 387     vdebugBelch(msg,ap);
 388     debugBelch("\n");
 389
 390     RELEASE_LOCK(&trace_utx);
 391 }
 392 #endif
 393
 394 void trace_(char *msg, ...)
 395 {
 396     va_list ap;
 397     va_start(ap,msg);
 398
 399 #ifdef DEBUG
 400     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 401         trace_stderr(msg, ap);
 402     } else
 403 #endif
 404     {
 405         postMsg(msg, ap);
 406     }
 407
 408     va_end(ap);
 409 }
 410
 411 static void traceFormatUserMsg(Capability *cap, char *msg, ...)
 412 {
 413     va_list ap;
 414     va_start(ap,msg);
 415
 416 #ifdef DEBUG
 417     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 418         traceCap_stderr(cap, msg, ap);
 419     } else
 420 #endif
 421     {
 422         if (eventlog_enabled) {
 423             postUserMsg(cap, msg, ap);
 424         }
 425     }
 426     dtraceUserMsg(cap->no, msg);
 427 }
 428
 429 void traceUserMsg(Capability *cap, char *msg)
 430 {
 431     traceFormatUserMsg(cap, "%s", msg);
 432 }
 433
 434 void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
 435 {
 436 #ifdef DEBUG
 437     if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
 438         printThreadStatus(tso);
 439     } else
 440 #endif
 441     {
 442         /* nothing - no event for this one yet */
 443     }
 444 }
 445
 446 void traceEventStartup_(int nocaps)
 447 {
 448     if (eventlog_enabled) {
 449         postEventStartup(nocaps);
 450     }
 451 }
 452
 453 #ifdef DEBUG
 454 void traceBegin (const char *str, ...)
 455 {
 456     va_list ap;
 457     va_start(ap,str);
 458
 459     ACQUIRE_LOCK(&trace_utx);
 460
 461     tracePreface();
 462     vdebugBelch(str,ap);
 463 }
 464
 465 void traceEnd (void)
 466 {
 467     debugBelch("\n");
 468     RELEASE_LOCK(&trace_utx);
 469 }
 470 #endif /* DEBUG */
 471
 472 #endif /* TRACING */
 473
 474 // If DTRACE is enabled, but neither DEBUG nor TRACING, we need a C land
 475 // wrapper for the user-msg probe (as we can't expand that in PrimOps.cmm)
 476 //
 477 #if !defined(DEBUG) && !defined(TRACING) && defined(DTRACE)
 478
 479 void dtraceUserMsgWrapper(Capability *cap, char *msg)
 480 {
 481     dtraceUserMsg(cap->no, msg);
 482 }
 483
 484 #endif /* !defined(DEBUG) && !defined(TRACING) && defined(DTRACE) */