Add the GC_GLOBAL_SYNC event marking that all caps are stopped for GC
[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 /* no stderr equivalent for these ones */
329 postHeapEvent(cap, tag, heap_capset, info1);
330 }
331
332 void traceEventHeapInfo_ (CapsetID heap_capset,
333 nat gens,
334 lnat maxHeapSize,
335 lnat allocAreaSize,
336 lnat mblockSize,
337 lnat blockSize)
338 {
339 /* no stderr equivalent for this one */
340 postEventHeapInfo(heap_capset, gens,
341 maxHeapSize, allocAreaSize,
342 mblockSize, blockSize);
343 }
344
345 void traceEventGcStats_ (Capability *cap,
346 CapsetID heap_capset,
347 nat gen,
348 lnat copied,
349 lnat slop,
350 lnat fragmentation,
351 nat par_n_threads,
352 lnat par_max_copied,
353 lnat par_tot_copied)
354 {
355 /* no stderr equivalent for this one */
356 postEventGcStats(cap, heap_capset, gen,
357 copied, slop, fragmentation,
358 par_n_threads, par_max_copied, par_tot_copied);
359 }
360
361 void traceCapEvent (Capability *cap,
362 EventTypeNum tag)
363 {
364 #ifdef DEBUG
365 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
366 ACQUIRE_LOCK(&trace_utx);
367
368 tracePreface();
369 switch (tag) {
370 case EVENT_CAP_CREATE: // (cap)
371 debugBelch("cap %d: initialised\n", cap->no);
372 break;
373 case EVENT_CAP_DELETE: // (cap)
374 debugBelch("cap %d: shutting down\n", cap->no);
375 break;
376 case EVENT_CAP_ENABLE: // (cap)
377 debugBelch("cap %d: enabling capability\n", cap->no);
378 break;
379 case EVENT_CAP_DISABLE: // (cap)
380 debugBelch("cap %d: disabling capability\n", cap->no);
381 break;
382 }
383 RELEASE_LOCK(&trace_utx);
384 } else
385 #endif
386 {
387 if (eventlog_enabled) {
388 postCapEvent(tag, (EventCapNo)cap->no);
389 }
390 }
391 }
392
393 void traceCapsetEvent (EventTypeNum tag,
394 CapsetID capset,
395 StgWord info)
396 {
397 #ifdef DEBUG
398 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR && TRACE_sched)
399 // When events go to stderr, it is annoying to see the capset
400 // events every time, so we only emit them with -Ds.
401 {
402 ACQUIRE_LOCK(&trace_utx);
403
404 tracePreface();
405 switch (tag) {
406 case EVENT_CAPSET_CREATE: // (capset, capset_type)
407 debugBelch("created capset %lu of type %d\n", (lnat)capset, (int)info);
408 break;
409 case EVENT_CAPSET_DELETE: // (capset)
410 debugBelch("deleted capset %lu\n", (lnat)capset);
411 break;
412 case EVENT_CAPSET_ASSIGN_CAP: // (capset, capno)
413 debugBelch("assigned cap %lu to capset %lu\n",
414 (lnat)info, (lnat)capset);
415 break;
416 case EVENT_CAPSET_REMOVE_CAP: // (capset, capno)
417 debugBelch("removed cap %lu from capset %lu\n",
418 (lnat)info, (lnat)capset);
419 break;
420 }
421 RELEASE_LOCK(&trace_utx);
422 } else
423 #endif
424 {
425 if (eventlog_enabled) {
426 postCapsetEvent(tag, capset, info);
427 }
428 }
429 }
430
431 void traceWallClockTime_(void) {
432 if (eventlog_enabled) {
433 postWallClockTime(CAPSET_CLOCKDOMAIN_DEFAULT);
434 }
435 }
436
437 void traceOSProcessInfo_(void) {
438 if (eventlog_enabled) {
439 postCapsetEvent(EVENT_OSPROCESS_PID,
440 CAPSET_OSPROCESS_DEFAULT,
441 getpid());
442
443 #if !defined(cygwin32_HOST_OS) && !defined (mingw32_HOST_OS)
444 /* Windows has no strong concept of process heirarchy, so no getppid().
445 * In any case, this trace event is mainly useful for tracing programs
446 * that use 'forkProcess' which Windows doesn't support anyway.
447 */
448 postCapsetEvent(EVENT_OSPROCESS_PPID,
449 CAPSET_OSPROCESS_DEFAULT,
450 getppid());
451 #endif
452 {
453 char buf[256];
454 snprintf(buf, sizeof(buf), "GHC-%s %s", ProjectVersion, RtsWay);
455 postCapsetStrEvent(EVENT_RTS_IDENTIFIER,
456 CAPSET_OSPROCESS_DEFAULT,
457 buf);
458 }
459 {
460 int argc = 0; char **argv;
461 getFullProgArgv(&argc, &argv);
462 if (argc != 0) {
463 postCapsetVecEvent(EVENT_PROGRAM_ARGS,
464 CAPSET_OSPROCESS_DEFAULT,
465 argc, argv);
466 }
467 }
468 {
469 int envc = 0; char **envv;
470 getProgEnvv(&envc, &envv);
471 if (envc != 0) {
472 postCapsetVecEvent(EVENT_PROGRAM_ENV,
473 CAPSET_OSPROCESS_DEFAULT,
474 envc, envv);
475 }
476 freeProgEnvv(envc, envv);
477 }
478 }
479 }
480
481 #ifdef DEBUG
482 static void traceSparkEvent_stderr (Capability *cap, EventTypeNum tag,
483 StgWord info1)
484 {
485 ACQUIRE_LOCK(&trace_utx);
486
487 tracePreface();
488 switch (tag) {
489
490 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
491 debugBelch("cap %d: creating spark thread %lu\n",
492 cap->no, (long)info1);
493 break;
494 case EVENT_SPARK_CREATE: // (cap)
495 debugBelch("cap %d: added spark to pool\n",
496 cap->no);
497 break;
498 case EVENT_SPARK_DUD: // (cap)
499 debugBelch("cap %d: discarded dud spark\n",
500 cap->no);
501 break;
502 case EVENT_SPARK_OVERFLOW: // (cap)
503 debugBelch("cap %d: discarded overflowed spark\n",
504 cap->no);
505 break;
506 case EVENT_SPARK_RUN: // (cap)
507 debugBelch("cap %d: running a spark\n",
508 cap->no);
509 break;
510 case EVENT_SPARK_STEAL: // (cap, victim_cap)
511 debugBelch("cap %d: stealing a spark from cap %d\n",
512 cap->no, (int)info1);
513 break;
514 case EVENT_SPARK_FIZZLE: // (cap)
515 debugBelch("cap %d: fizzled spark removed from pool\n",
516 cap->no);
517 break;
518 case EVENT_SPARK_GC: // (cap)
519 debugBelch("cap %d: GCd spark removed from pool\n",
520 cap->no);
521 break;
522 default:
523 barf("traceSparkEvent: unknown event tag %d", tag);
524 break;
525 }
526
527 RELEASE_LOCK(&trace_utx);
528 }
529 #endif
530
531 void traceSparkEvent_ (Capability *cap, EventTypeNum tag, StgWord info1)
532 {
533 #ifdef DEBUG
534 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
535 traceSparkEvent_stderr(cap, tag, info1);
536 } else
537 #endif
538 {
539 postSparkEvent(cap,tag,info1);
540 }
541 }
542
543 void traceSparkCounters_ (Capability *cap,
544 SparkCounters counters,
545 StgWord remaining)
546 {
547 #ifdef DEBUG
548 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
549 /* we currently don't do debug tracing of spark stats but we must
550 test for TRACE_STDERR because of the !eventlog_enabled case. */
551 } else
552 #endif
553 {
554 postSparkCountersEvent(cap, counters, remaining);
555 }
556 }
557
558 #ifdef DEBUG
559 static void traceCap_stderr(Capability *cap, char *msg, va_list ap)
560 {
561 ACQUIRE_LOCK(&trace_utx);
562
563 tracePreface();
564 debugBelch("cap %d: ", cap->no);
565 vdebugBelch(msg,ap);
566 debugBelch("\n");
567
568 RELEASE_LOCK(&trace_utx);
569 }
570 #endif
571
572 void traceCap_(Capability *cap, char *msg, ...)
573 {
574 va_list ap;
575 va_start(ap,msg);
576
577 #ifdef DEBUG
578 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
579 traceCap_stderr(cap, msg, ap);
580 } else
581 #endif
582 {
583 postCapMsg(cap, msg, ap);
584 }
585
586 va_end(ap);
587 }
588
589 #ifdef DEBUG
590 static void trace_stderr(char *msg, va_list ap)
591 {
592 ACQUIRE_LOCK(&trace_utx);
593
594 tracePreface();
595 vdebugBelch(msg,ap);
596 debugBelch("\n");
597
598 RELEASE_LOCK(&trace_utx);
599 }
600 #endif
601
602 void trace_(char *msg, ...)
603 {
604 va_list ap;
605 va_start(ap,msg);
606
607 #ifdef DEBUG
608 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
609 trace_stderr(msg, ap);
610 } else
611 #endif
612 {
613 postMsg(msg, ap);
614 }
615
616 va_end(ap);
617 }
618
619 static void traceFormatUserMsg(Capability *cap, char *msg, ...)
620 {
621 va_list ap;
622 va_start(ap,msg);
623
624 /* Note: normally we don't check the TRACE_* flags here as they're checked
625 by the wrappers in Trace.h. But traceUserMsg is special since it has no
626 wrapper (it's called from cmm code), so we check TRACE_user here
627 */
628 #ifdef DEBUG
629 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR && TRACE_user) {
630 traceCap_stderr(cap, msg, ap);
631 } else
632 #endif
633 {
634 if (eventlog_enabled && TRACE_user) {
635 postUserMsg(cap, msg, ap);
636 }
637 }
638 dtraceUserMsg(cap->no, msg);
639 }
640
641 void traceUserMsg(Capability *cap, char *msg)
642 {
643 traceFormatUserMsg(cap, "%s", msg);
644 }
645
646 void traceThreadLabel_(Capability *cap,
647 StgTSO *tso,
648 char *label)
649 {
650 #ifdef DEBUG
651 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
652 ACQUIRE_LOCK(&trace_utx);
653 tracePreface();
654 debugBelch("cap %d: thread %lu has label %s\n",
655 cap->no, (lnat)tso->id, label);
656 RELEASE_LOCK(&trace_utx);
657 } else
658 #endif
659 {
660 postThreadLabel(cap, tso->id, label);
661 }
662 }
663
664 void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
665 {
666 #ifdef DEBUG
667 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
668 printThreadStatus(tso);
669 } else
670 #endif
671 {
672 /* nothing - no event for this one yet */
673 }
674 }
675
676 void traceEventStartup_(int nocaps)
677 {
678 if (eventlog_enabled) {
679 postEventStartup(nocaps);
680 }
681 }
682
683 #ifdef DEBUG
684 void traceBegin (const char *str, ...)
685 {
686 va_list ap;
687 va_start(ap,str);
688
689 ACQUIRE_LOCK(&trace_utx);
690
691 tracePreface();
692 vdebugBelch(str,ap);
693 }
694
695 void traceEnd (void)
696 {
697 debugBelch("\n");
698 RELEASE_LOCK(&trace_utx);
699 }
700 #endif /* DEBUG */
701
702 #endif /* TRACING */
703
704 // If DTRACE is enabled, but neither DEBUG nor TRACING, we need a C land
705 // wrapper for the user-msg probe (as we can't expand that in PrimOps.cmm)
706 //
707 #if !defined(DEBUG) && !defined(TRACING) && defined(DTRACE)
708
709 void dtraceUserMsgWrapper(Capability *cap, char *msg)
710 {
711 dtraceUserMsg(cap->no, msg);
712 }
713
714 #endif /* !defined(DEBUG) && !defined(TRACING) && defined(DTRACE) */