Fix crash with debug tracing and the new heap events
[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 if (TRACE_gc && RtsFlags.GcFlags.giveStats == NO_GC_STATS) {
102 RtsFlags.GcFlags.giveStats = COLLECT_GC_STATS;
103 }
104
105 TRACE_spark_sampled =
106 RtsFlags.TraceFlags.sparks_sampled;
107
108 // -Dr turns on full spark tracing
109 TRACE_spark_full =
110 RtsFlags.TraceFlags.sparks_full ||
111 RtsFlags.DebugFlags.sparks;
112
113 TRACE_user =
114 RtsFlags.TraceFlags.user;
115
116 eventlog_enabled = RtsFlags.TraceFlags.tracing == TRACE_EVENTLOG;
117
118 /* Note: we can have any of the TRACE_* flags turned on even when
119 eventlog_enabled is off. In the DEBUG way we may be tracing to stderr.
120 */
121
122 if (eventlog_enabled) {
123 initEventLogging();
124 }
125 }
126
127 void endTracing (void)
128 {
129 if (eventlog_enabled) {
130 endEventLogging();
131 }
132 }
133
134 void freeTracing (void)
135 {
136 if (eventlog_enabled) {
137 freeEventLogging();
138 }
139 }
140
141 void resetTracing (void)
142 {
143 if (eventlog_enabled) {
144 abortEventLogging(); // abort eventlog inherited from parent
145 initEventLogging(); // child starts its own eventlog
146 }
147 }
148
149 void tracingAddCapapilities (nat from, nat to)
150 {
151 if (eventlog_enabled) {
152 moreCapEventBufs(from,to);
153 }
154 }
155
156 /* ---------------------------------------------------------------------------
157 Emitting trace messages/events
158 --------------------------------------------------------------------------- */
159
160 #ifdef DEBUG
161 static void tracePreface (void)
162 {
163 #ifdef THREADED_RTS
164 debugBelch("%12lx: ", (unsigned long)osThreadId());
165 #endif
166 if (RtsFlags.TraceFlags.timestamp) {
167 debugBelch("%9" FMT_Word64 ": ", stat_getElapsedTime());
168 }
169 }
170 #endif
171
172 #ifdef DEBUG
173 static char *thread_stop_reasons[] = {
174 [HeapOverflow] = "heap overflow",
175 [StackOverflow] = "stack overflow",
176 [ThreadYielding] = "yielding",
177 [ThreadBlocked] = "blocked",
178 [ThreadFinished] = "finished",
179 [THREAD_SUSPENDED_FOREIGN_CALL] = "suspended while making a foreign call",
180 [6 + BlockedOnMVar] = "blocked on an MVar",
181 [6 + BlockedOnBlackHole] = "blocked on a black hole",
182 [6 + BlockedOnRead] = "blocked on a read operation",
183 [6 + BlockedOnWrite] = "blocked on a write operation",
184 [6 + BlockedOnDelay] = "blocked on a delay operation",
185 [6 + BlockedOnSTM] = "blocked on STM",
186 [6 + BlockedOnDoProc] = "blocked on asyncDoProc",
187 [6 + BlockedOnCCall] = "blocked on a foreign call",
188 [6 + BlockedOnCCall_Interruptible] = "blocked on a foreign call (interruptible)",
189 [6 + BlockedOnMsgThrowTo] = "blocked on throwTo",
190 [6 + ThreadMigrating] = "migrating"
191 };
192 #endif
193
194 #ifdef DEBUG
195 static void traceSchedEvent_stderr (Capability *cap, EventTypeNum tag,
196 StgTSO *tso,
197 StgWord info1 STG_UNUSED,
198 StgWord info2 STG_UNUSED)
199 {
200 ACQUIRE_LOCK(&trace_utx);
201
202 tracePreface();
203 switch (tag) {
204 case EVENT_CREATE_THREAD: // (cap, thread)
205 debugBelch("cap %d: created thread %lu\n",
206 cap->no, (lnat)tso->id);
207 break;
208 case EVENT_RUN_THREAD: // (cap, thread)
209 debugBelch("cap %d: running thread %lu (%s)\n",
210 cap->no, (lnat)tso->id, what_next_strs[tso->what_next]);
211 break;
212 case EVENT_THREAD_RUNNABLE: // (cap, thread)
213 debugBelch("cap %d: thread %lu appended to run queue\n",
214 cap->no, (lnat)tso->id);
215 break;
216 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
217 debugBelch("cap %d: thread %lu migrating to cap %d\n",
218 cap->no, (lnat)tso->id, (int)info1);
219 break;
220 case EVENT_THREAD_WAKEUP: // (cap, thread, info1_cap)
221 debugBelch("cap %d: waking up thread %lu on cap %d\n",
222 cap->no, (lnat)tso->id, (int)info1);
223 break;
224
225 case EVENT_STOP_THREAD: // (cap, thread, status)
226 if (info1 == 6 + BlockedOnBlackHole) {
227 debugBelch("cap %d: thread %lu stopped (blocked on black hole owned by thread %lu)\n",
228 cap->no, (lnat)tso->id, (long)info2);
229 } else {
230 debugBelch("cap %d: thread %lu stopped (%s)\n",
231 cap->no, (lnat)tso->id, thread_stop_reasons[info1]);
232 }
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 case EVENT_GC_GLOBAL_SYNC: // (cap)
286 debugBelch("cap %d: all caps stopped for GC\n", cap->no);
287 break;
288 default:
289 barf("traceGcEvent: unknown event tag %d", tag);
290 break;
291 }
292
293 RELEASE_LOCK(&trace_utx);
294 }
295 #endif
296
297 void traceGcEvent_ (Capability *cap, EventTypeNum tag)
298 {
299 #ifdef DEBUG
300 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
301 traceGcEvent_stderr(cap, tag);
302 } else
303 #endif
304 {
305 /* currently all GC events are nullary events */
306 postEvent(cap, tag);
307 }
308 }
309
310 void traceGcEventAtT_ (Capability *cap, StgWord64 ts, EventTypeNum tag)
311 {
312 #ifdef DEBUG
313 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
314 traceGcEvent_stderr(cap, tag);
315 } else
316 #endif
317 {
318 /* assuming nullary events and explicitly inserting a timestamp */
319 postEventAtTimestamp(cap, ts, tag);
320 }
321 }
322
323 void traceHeapEvent_ (Capability *cap,
324 EventTypeNum tag,
325 CapsetID heap_capset,
326 lnat info1)
327 {
328 #ifdef DEBUG
329 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
330 /* no stderr equivalent for these ones */
331 } else
332 #endif
333 {
334 postHeapEvent(cap, tag, heap_capset, info1);
335 }
336 }
337
338 void traceEventHeapInfo_ (CapsetID heap_capset,
339 nat gens,
340 lnat maxHeapSize,
341 lnat allocAreaSize,
342 lnat mblockSize,
343 lnat blockSize)
344 {
345 #ifdef DEBUG
346 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
347 /* no stderr equivalent for these ones */
348 } else
349 #endif
350 {
351 postEventHeapInfo(heap_capset, gens,
352 maxHeapSize, allocAreaSize,
353 mblockSize, blockSize);
354 }
355 }
356
357 void traceEventGcStats_ (Capability *cap,
358 CapsetID heap_capset,
359 nat gen,
360 lnat copied,
361 lnat slop,
362 lnat fragmentation,
363 nat par_n_threads,
364 lnat par_max_copied,
365 lnat par_tot_copied)
366 {
367 #ifdef DEBUG
368 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
369 /* no stderr equivalent for these ones */
370 } else
371 #endif
372 {
373 postEventGcStats(cap, heap_capset, gen,
374 copied, slop, fragmentation,
375 par_n_threads, par_max_copied, par_tot_copied);
376 }
377 }
378
379 void traceCapEvent (Capability *cap,
380 EventTypeNum tag)
381 {
382 #ifdef DEBUG
383 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
384 ACQUIRE_LOCK(&trace_utx);
385
386 tracePreface();
387 switch (tag) {
388 case EVENT_CAP_CREATE: // (cap)
389 debugBelch("cap %d: initialised\n", cap->no);
390 break;
391 case EVENT_CAP_DELETE: // (cap)
392 debugBelch("cap %d: shutting down\n", cap->no);
393 break;
394 case EVENT_CAP_ENABLE: // (cap)
395 debugBelch("cap %d: enabling capability\n", cap->no);
396 break;
397 case EVENT_CAP_DISABLE: // (cap)
398 debugBelch("cap %d: disabling capability\n", cap->no);
399 break;
400 }
401 RELEASE_LOCK(&trace_utx);
402 } else
403 #endif
404 {
405 if (eventlog_enabled) {
406 postCapEvent(tag, (EventCapNo)cap->no);
407 }
408 }
409 }
410
411 void traceCapsetEvent (EventTypeNum tag,
412 CapsetID capset,
413 StgWord info)
414 {
415 #ifdef DEBUG
416 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR && TRACE_sched)
417 // When events go to stderr, it is annoying to see the capset
418 // events every time, so we only emit them with -Ds.
419 {
420 ACQUIRE_LOCK(&trace_utx);
421
422 tracePreface();
423 switch (tag) {
424 case EVENT_CAPSET_CREATE: // (capset, capset_type)
425 debugBelch("created capset %lu of type %d\n", (lnat)capset, (int)info);
426 break;
427 case EVENT_CAPSET_DELETE: // (capset)
428 debugBelch("deleted capset %lu\n", (lnat)capset);
429 break;
430 case EVENT_CAPSET_ASSIGN_CAP: // (capset, capno)
431 debugBelch("assigned cap %lu to capset %lu\n",
432 (lnat)info, (lnat)capset);
433 break;
434 case EVENT_CAPSET_REMOVE_CAP: // (capset, capno)
435 debugBelch("removed cap %lu from capset %lu\n",
436 (lnat)info, (lnat)capset);
437 break;
438 }
439 RELEASE_LOCK(&trace_utx);
440 } else
441 #endif
442 {
443 if (eventlog_enabled) {
444 postCapsetEvent(tag, capset, info);
445 }
446 }
447 }
448
449 void traceWallClockTime_(void) {
450 if (eventlog_enabled) {
451 postWallClockTime(CAPSET_CLOCKDOMAIN_DEFAULT);
452 }
453 }
454
455 void traceOSProcessInfo_(void) {
456 if (eventlog_enabled) {
457 postCapsetEvent(EVENT_OSPROCESS_PID,
458 CAPSET_OSPROCESS_DEFAULT,
459 getpid());
460
461 #if !defined(cygwin32_HOST_OS) && !defined (mingw32_HOST_OS)
462 /* Windows has no strong concept of process heirarchy, so no getppid().
463 * In any case, this trace event is mainly useful for tracing programs
464 * that use 'forkProcess' which Windows doesn't support anyway.
465 */
466 postCapsetEvent(EVENT_OSPROCESS_PPID,
467 CAPSET_OSPROCESS_DEFAULT,
468 getppid());
469 #endif
470 {
471 char buf[256];
472 snprintf(buf, sizeof(buf), "GHC-%s %s", ProjectVersion, RtsWay);
473 postCapsetStrEvent(EVENT_RTS_IDENTIFIER,
474 CAPSET_OSPROCESS_DEFAULT,
475 buf);
476 }
477 {
478 int argc = 0; char **argv;
479 getFullProgArgv(&argc, &argv);
480 if (argc != 0) {
481 postCapsetVecEvent(EVENT_PROGRAM_ARGS,
482 CAPSET_OSPROCESS_DEFAULT,
483 argc, argv);
484 }
485 }
486 {
487 int envc = 0; char **envv;
488 getProgEnvv(&envc, &envv);
489 if (envc != 0) {
490 postCapsetVecEvent(EVENT_PROGRAM_ENV,
491 CAPSET_OSPROCESS_DEFAULT,
492 envc, envv);
493 }
494 freeProgEnvv(envc, envv);
495 }
496 }
497 }
498
499 #ifdef DEBUG
500 static void traceSparkEvent_stderr (Capability *cap, EventTypeNum tag,
501 StgWord info1)
502 {
503 ACQUIRE_LOCK(&trace_utx);
504
505 tracePreface();
506 switch (tag) {
507
508 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
509 debugBelch("cap %d: creating spark thread %lu\n",
510 cap->no, (long)info1);
511 break;
512 case EVENT_SPARK_CREATE: // (cap)
513 debugBelch("cap %d: added spark to pool\n",
514 cap->no);
515 break;
516 case EVENT_SPARK_DUD: // (cap)
517 debugBelch("cap %d: discarded dud spark\n",
518 cap->no);
519 break;
520 case EVENT_SPARK_OVERFLOW: // (cap)
521 debugBelch("cap %d: discarded overflowed spark\n",
522 cap->no);
523 break;
524 case EVENT_SPARK_RUN: // (cap)
525 debugBelch("cap %d: running a spark\n",
526 cap->no);
527 break;
528 case EVENT_SPARK_STEAL: // (cap, victim_cap)
529 debugBelch("cap %d: stealing a spark from cap %d\n",
530 cap->no, (int)info1);
531 break;
532 case EVENT_SPARK_FIZZLE: // (cap)
533 debugBelch("cap %d: fizzled spark removed from pool\n",
534 cap->no);
535 break;
536 case EVENT_SPARK_GC: // (cap)
537 debugBelch("cap %d: GCd spark removed from pool\n",
538 cap->no);
539 break;
540 default:
541 barf("traceSparkEvent: unknown event tag %d", tag);
542 break;
543 }
544
545 RELEASE_LOCK(&trace_utx);
546 }
547 #endif
548
549 void traceSparkEvent_ (Capability *cap, EventTypeNum tag, StgWord info1)
550 {
551 #ifdef DEBUG
552 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
553 traceSparkEvent_stderr(cap, tag, info1);
554 } else
555 #endif
556 {
557 postSparkEvent(cap,tag,info1);
558 }
559 }
560
561 void traceSparkCounters_ (Capability *cap,
562 SparkCounters counters,
563 StgWord remaining)
564 {
565 #ifdef DEBUG
566 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
567 /* we currently don't do debug tracing of spark stats but we must
568 test for TRACE_STDERR because of the !eventlog_enabled case. */
569 } else
570 #endif
571 {
572 postSparkCountersEvent(cap, counters, remaining);
573 }
574 }
575
576 #ifdef DEBUG
577 static void traceCap_stderr(Capability *cap, char *msg, va_list ap)
578 {
579 ACQUIRE_LOCK(&trace_utx);
580
581 tracePreface();
582 debugBelch("cap %d: ", cap->no);
583 vdebugBelch(msg,ap);
584 debugBelch("\n");
585
586 RELEASE_LOCK(&trace_utx);
587 }
588 #endif
589
590 void traceCap_(Capability *cap, char *msg, ...)
591 {
592 va_list ap;
593 va_start(ap,msg);
594
595 #ifdef DEBUG
596 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
597 traceCap_stderr(cap, msg, ap);
598 } else
599 #endif
600 {
601 postCapMsg(cap, msg, ap);
602 }
603
604 va_end(ap);
605 }
606
607 #ifdef DEBUG
608 static void trace_stderr(char *msg, va_list ap)
609 {
610 ACQUIRE_LOCK(&trace_utx);
611
612 tracePreface();
613 vdebugBelch(msg,ap);
614 debugBelch("\n");
615
616 RELEASE_LOCK(&trace_utx);
617 }
618 #endif
619
620 void trace_(char *msg, ...)
621 {
622 va_list ap;
623 va_start(ap,msg);
624
625 #ifdef DEBUG
626 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
627 trace_stderr(msg, ap);
628 } else
629 #endif
630 {
631 postMsg(msg, ap);
632 }
633
634 va_end(ap);
635 }
636
637 static void traceFormatUserMsg(Capability *cap, char *msg, ...)
638 {
639 va_list ap;
640 va_start(ap,msg);
641
642 /* Note: normally we don't check the TRACE_* flags here as they're checked
643 by the wrappers in Trace.h. But traceUserMsg is special since it has no
644 wrapper (it's called from cmm code), so we check TRACE_user here
645 */
646 #ifdef DEBUG
647 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR && TRACE_user) {
648 traceCap_stderr(cap, msg, ap);
649 } else
650 #endif
651 {
652 if (eventlog_enabled && TRACE_user) {
653 postUserMsg(cap, msg, ap);
654 }
655 }
656 dtraceUserMsg(cap->no, msg);
657 }
658
659 void traceUserMsg(Capability *cap, char *msg)
660 {
661 traceFormatUserMsg(cap, "%s", msg);
662 }
663
664 void traceThreadLabel_(Capability *cap,
665 StgTSO *tso,
666 char *label)
667 {
668 #ifdef DEBUG
669 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
670 ACQUIRE_LOCK(&trace_utx);
671 tracePreface();
672 debugBelch("cap %d: thread %lu has label %s\n",
673 cap->no, (lnat)tso->id, label);
674 RELEASE_LOCK(&trace_utx);
675 } else
676 #endif
677 {
678 postThreadLabel(cap, tso->id, label);
679 }
680 }
681
682 void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
683 {
684 #ifdef DEBUG
685 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
686 printThreadStatus(tso);
687 } else
688 #endif
689 {
690 /* nothing - no event for this one yet */
691 }
692 }
693
694 void traceEventStartup_(int nocaps)
695 {
696 if (eventlog_enabled) {
697 postEventStartup(nocaps);
698 }
699 }
700
701 #ifdef DEBUG
702 void traceBegin (const char *str, ...)
703 {
704 va_list ap;
705 va_start(ap,str);
706
707 ACQUIRE_LOCK(&trace_utx);
708
709 tracePreface();
710 vdebugBelch(str,ap);
711 }
712
713 void traceEnd (void)
714 {
715 debugBelch("\n");
716 RELEASE_LOCK(&trace_utx);
717 }
718 #endif /* DEBUG */
719
720 #endif /* TRACING */
721
722 // If DTRACE is enabled, but neither DEBUG nor TRACING, we need a C land
723 // wrapper for the user-msg probe (as we can't expand that in PrimOps.cmm)
724 //
725 #if !defined(DEBUG) && !defined(TRACING) && defined(DTRACE)
726
727 void dtraceUserMsgWrapper(Capability *cap, char *msg)
728 {
729 dtraceUserMsg(cap->no, msg);
730 }
731
732 #endif /* !defined(DEBUG) && !defined(TRACING) && defined(DTRACE) */