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