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