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