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