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