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