Add capability sets to the tracing/events system
[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 "Stats.h"
19 #include "eventlog/EventLog.h"
20 #include "Threads.h"
21 #include "Printer.h"
22
23 #ifdef DEBUG
24 // debugging flags, set with +RTS -D<something>
25 int DEBUG_sched;
26 int DEBUG_interp;
27 int DEBUG_weak;
28 int DEBUG_gccafs;
29 int DEBUG_gc;
30 int DEBUG_block_alloc;
31 int DEBUG_sanity;
32 int DEBUG_stable;
33 int DEBUG_stm;
34 int DEBUG_prof;
35 int DEBUG_gran;
36 int DEBUG_par;
37 int DEBUG_linker;
38 int DEBUG_squeeze;
39 int DEBUG_hpc;
40 int DEBUG_sparks;
41 #endif
42
43 // events
44 int TRACE_sched;
45
46 #ifdef THREADED_RTS
47 static Mutex trace_utx;
48 #endif
49
50 static rtsBool eventlog_enabled;
51
52 /* ---------------------------------------------------------------------------
53 Starting up / shuttting down the tracing facilities
54 --------------------------------------------------------------------------- */
55
56 void initTracing (void)
57 {
58 #ifdef THREADED_RTS
59 initMutex(&trace_utx);
60 #endif
61
62 #ifdef DEBUG
63 #define DEBUG_FLAG(name, class) \
64 class = RtsFlags.DebugFlags.name ? 1 : 0;
65
66 DEBUG_FLAG(scheduler, DEBUG_sched);
67
68 DEBUG_FLAG(interpreter, DEBUG_interp);
69 DEBUG_FLAG(weak, DEBUG_weak);
70 DEBUG_FLAG(gccafs, DEBUG_gccafs);
71 DEBUG_FLAG(gc, DEBUG_gc);
72 DEBUG_FLAG(block_alloc, DEBUG_block_alloc);
73 DEBUG_FLAG(sanity, DEBUG_sanity);
74 DEBUG_FLAG(stable, DEBUG_stable);
75 DEBUG_FLAG(stm, DEBUG_stm);
76 DEBUG_FLAG(prof, DEBUG_prof);
77 DEBUG_FLAG(linker, DEBUG_linker);
78 DEBUG_FLAG(squeeze, DEBUG_squeeze);
79 DEBUG_FLAG(hpc, DEBUG_hpc);
80 DEBUG_FLAG(sparks, DEBUG_sparks);
81 #endif
82
83 // -Ds turns on scheduler tracing too
84 TRACE_sched =
85 RtsFlags.TraceFlags.scheduler ||
86 RtsFlags.DebugFlags.scheduler;
87
88 eventlog_enabled = RtsFlags.TraceFlags.tracing == TRACE_EVENTLOG;
89
90 if (eventlog_enabled) {
91 initEventLogging();
92 }
93 }
94
95 void endTracing (void)
96 {
97 if (eventlog_enabled) {
98 endEventLogging();
99 }
100 }
101
102 void freeTracing (void)
103 {
104 if (eventlog_enabled) {
105 freeEventLogging();
106 }
107 }
108
109 void resetTracing (void)
110 {
111 if (eventlog_enabled) {
112 abortEventLogging(); // abort eventlog inherited from parent
113 initEventLogging(); // child starts its own eventlog
114 }
115 }
116
117 /* ---------------------------------------------------------------------------
118 Emitting trace messages/events
119 --------------------------------------------------------------------------- */
120
121 #ifdef DEBUG
122 static void tracePreface (void)
123 {
124 #ifdef THREADED_RTS
125 debugBelch("%12lx: ", (unsigned long)osThreadId());
126 #endif
127 if (RtsFlags.TraceFlags.timestamp) {
128 debugBelch("%9" FMT_Word64 ": ", stat_getElapsedTime());
129 }
130 }
131 #endif
132
133 #ifdef DEBUG
134 static char *thread_stop_reasons[] = {
135 [HeapOverflow] = "heap overflow",
136 [StackOverflow] = "stack overflow",
137 [ThreadYielding] = "yielding",
138 [ThreadBlocked] = "blocked",
139 [ThreadFinished] = "finished",
140 [THREAD_SUSPENDED_FOREIGN_CALL] = "suspended while making a foreign call",
141 [6 + BlockedOnMVar] = "blocked on an MVar",
142 [6 + BlockedOnBlackHole] = "blocked on a black hole",
143 [6 + BlockedOnRead] = "blocked on a read operation",
144 [6 + BlockedOnWrite] = "blocked on a write operation",
145 [6 + BlockedOnDelay] = "blocked on a delay operation",
146 [6 + BlockedOnSTM] = "blocked on STM",
147 [6 + BlockedOnDoProc] = "blocked on asyncDoProc",
148 [6 + BlockedOnCCall] = "blocked on a foreign call",
149 [6 + BlockedOnCCall_Interruptible] = "blocked on a foreign call (interruptible)",
150 [6 + BlockedOnMsgThrowTo] = "blocked on throwTo",
151 [6 + ThreadMigrating] = "migrating"
152 };
153 #endif
154
155 #ifdef DEBUG
156 static void traceSchedEvent_stderr (Capability *cap, EventTypeNum tag,
157 StgTSO *tso,
158 StgWord info1 STG_UNUSED,
159 StgWord info2 STG_UNUSED)
160 {
161 ACQUIRE_LOCK(&trace_utx);
162
163 tracePreface();
164 switch (tag) {
165 case EVENT_CREATE_THREAD: // (cap, thread)
166 debugBelch("cap %d: created thread %lu\n",
167 cap->no, (lnat)tso->id);
168 break;
169 case EVENT_RUN_THREAD: // (cap, thread)
170 debugBelch("cap %d: running thread %lu (%s)\n",
171 cap->no, (lnat)tso->id, what_next_strs[tso->what_next]);
172 break;
173 case EVENT_THREAD_RUNNABLE: // (cap, thread)
174 debugBelch("cap %d: thread %lu appended to run queue\n",
175 cap->no, (lnat)tso->id);
176 break;
177 case EVENT_RUN_SPARK: // (cap, thread)
178 debugBelch("cap %d: thread %lu running a spark\n",
179 cap->no, (lnat)tso->id);
180 break;
181 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
182 debugBelch("cap %d: creating spark thread %lu\n",
183 cap->no, (long)info1);
184 break;
185 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
186 debugBelch("cap %d: thread %lu migrating to cap %d\n",
187 cap->no, (lnat)tso->id, (int)info1);
188 break;
189 case EVENT_STEAL_SPARK: // (cap, thread, victim_cap)
190 debugBelch("cap %d: thread %lu stealing a spark from cap %d\n",
191 cap->no, (lnat)tso->id, (int)info1);
192 break;
193 case EVENT_THREAD_WAKEUP: // (cap, thread, info1_cap)
194 debugBelch("cap %d: waking up thread %lu on cap %d\n",
195 cap->no, (lnat)tso->id, (int)info1);
196 break;
197
198 case EVENT_STOP_THREAD: // (cap, thread, status)
199 if (info1 == 6 + BlockedOnBlackHole) {
200 debugBelch("cap %d: thread %lu stopped (blocked on black hole owned by thread %lu)\n",
201 cap->no, (lnat)tso->id, (long)info2);
202 } else {
203 debugBelch("cap %d: thread %lu stopped (%s)\n",
204 cap->no, (lnat)tso->id, thread_stop_reasons[info1]);
205 }
206 break;
207 case EVENT_SHUTDOWN: // (cap)
208 debugBelch("cap %d: shutting down\n", cap->no);
209 break;
210 case EVENT_REQUEST_SEQ_GC: // (cap)
211 debugBelch("cap %d: requesting sequential GC\n", cap->no);
212 break;
213 case EVENT_REQUEST_PAR_GC: // (cap)
214 debugBelch("cap %d: requesting parallel GC\n", cap->no);
215 break;
216 case EVENT_GC_START: // (cap)
217 debugBelch("cap %d: starting GC\n", cap->no);
218 break;
219 case EVENT_GC_END: // (cap)
220 debugBelch("cap %d: finished GC\n", cap->no);
221 break;
222 case EVENT_GC_IDLE: // (cap)
223 debugBelch("cap %d: GC idle\n", cap->no);
224 break;
225 case EVENT_GC_WORK: // (cap)
226 debugBelch("cap %d: GC working\n", cap->no);
227 break;
228 case EVENT_GC_DONE: // (cap)
229 debugBelch("cap %d: GC done\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 void traceCapsetModify_ (EventTypeNum tag,
255 CapsetID capset,
256 StgWord32 other)
257 {
258 #ifdef DEBUG
259 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
260 ACQUIRE_LOCK(&trace_utx);
261
262 tracePreface();
263 switch (tag) {
264 case EVENT_CAPSET_CREATE: // (capset, capset_type)
265 debugBelch("created capset %d of type %d\n", capset, other);
266 break;
267 case EVENT_CAPSET_DELETE: // (capset)
268 debugBelch("deleted capset %d\n", capset);
269 break;
270 case EVENT_CAPSET_ASSIGN_CAP: // (capset, capno)
271 debugBelch("assigned cap %d to capset %d\n", other, capset);
272 break;
273 case EVENT_CAPSET_REMOVE_CAP: // (capset, capno)
274 debugBelch("removed cap %d from capset %d\n", other, capset);
275 break;
276 }
277 RELEASE_LOCK(&trace_utx);
278 } else
279 #endif
280 {
281 if (eventlog_enabled) {
282 postCapsetModifyEvent(tag, capset, other);
283 }
284 }
285 }
286
287 void traceEvent_ (Capability *cap, EventTypeNum tag)
288 {
289 #ifdef DEBUG
290 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
291 traceSchedEvent_stderr(cap, tag, 0, 0, 0);
292 } else
293 #endif
294 {
295 postEvent(cap,tag);
296 }
297 }
298
299 #ifdef DEBUG
300 static void traceCap_stderr(Capability *cap, char *msg, va_list ap)
301 {
302 ACQUIRE_LOCK(&trace_utx);
303
304 tracePreface();
305 debugBelch("cap %d: ", cap->no);
306 vdebugBelch(msg,ap);
307 debugBelch("\n");
308
309 RELEASE_LOCK(&trace_utx);
310 }
311 #endif
312
313 void traceCap_(Capability *cap, char *msg, ...)
314 {
315 va_list ap;
316 va_start(ap,msg);
317
318 #ifdef DEBUG
319 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
320 traceCap_stderr(cap, msg, ap);
321 } else
322 #endif
323 {
324 postCapMsg(cap, msg, ap);
325 }
326
327 va_end(ap);
328 }
329
330 #ifdef DEBUG
331 static void trace_stderr(char *msg, va_list ap)
332 {
333 ACQUIRE_LOCK(&trace_utx);
334
335 tracePreface();
336 vdebugBelch(msg,ap);
337 debugBelch("\n");
338
339 RELEASE_LOCK(&trace_utx);
340 }
341 #endif
342
343 void trace_(char *msg, ...)
344 {
345 va_list ap;
346 va_start(ap,msg);
347
348 #ifdef DEBUG
349 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
350 trace_stderr(msg, ap);
351 } else
352 #endif
353 {
354 postMsg(msg, ap);
355 }
356
357 va_end(ap);
358 }
359
360 static void traceFormatUserMsg(Capability *cap, char *msg, ...)
361 {
362 va_list ap;
363 va_start(ap,msg);
364
365 #ifdef DEBUG
366 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
367 traceCap_stderr(cap, msg, ap);
368 } else
369 #endif
370 {
371 if (eventlog_enabled) {
372 postUserMsg(cap, msg, ap);
373 }
374 }
375 dtraceUserMsg(cap->no, msg);
376 }
377
378 void traceUserMsg(Capability *cap, char *msg)
379 {
380 traceFormatUserMsg(cap, "%s", msg);
381 }
382
383 void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
384 {
385 #ifdef DEBUG
386 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
387 printThreadStatus(tso);
388 } else
389 #endif
390 {
391 /* nothing - no event for this one yet */
392 }
393 }
394
395 void traceEventStartup_(int nocaps)
396 {
397 if (eventlog_enabled) {
398 postEventStartup(nocaps);
399 }
400 }
401
402 #ifdef DEBUG
403 void traceBegin (const char *str, ...)
404 {
405 va_list ap;
406 va_start(ap,str);
407
408 ACQUIRE_LOCK(&trace_utx);
409
410 tracePreface();
411 vdebugBelch(str,ap);
412 }
413
414 void traceEnd (void)
415 {
416 debugBelch("\n");
417 RELEASE_LOCK(&trace_utx);
418 }
419 #endif /* DEBUG */
420
421 #endif /* TRACING */
422
423 // If DTRACE is enabled, but neither DEBUG nor TRACING, we need a C land
424 // wrapper for the user-msg probe (as we can't expand that in PrimOps.cmm)
425 //
426 #if !defined(DEBUG) && !defined(TRACING) && defined(DTRACE)
427
428 void dtraceUserMsgWrapper(Capability *cap, char *msg)
429 {
430 dtraceUserMsg(cap->no, msg);
431 }
432
433 #endif /* !defined(DEBUG) && !defined(TRACING) && defined(DTRACE) */