Add events to show when GC threads are idle/working
[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 #ifdef TRACING
13
14 // internal headers
15 #include "Trace.h"
16 #include "GetTime.h"
17 #include "Stats.h"
18 #include "eventlog/EventLog.h"
19 #include "Threads.h"
20 #include "Printer.h"
21
22 #ifdef DEBUG
23 // debugging flags, set with +RTS -D<something>
24 int DEBUG_sched;
25 int DEBUG_interp;
26 int DEBUG_weak;
27 int DEBUG_gccafs;
28 int DEBUG_gc;
29 int DEBUG_block_alloc;
30 int DEBUG_sanity;
31 int DEBUG_stable;
32 int DEBUG_stm;
33 int DEBUG_prof;
34 int DEBUG_gran;
35 int DEBUG_par;
36 int DEBUG_linker;
37 int DEBUG_squeeze;
38 int DEBUG_hpc;
39 int DEBUG_sparks;
40 #endif
41
42 // events
43 int TRACE_sched;
44
45 #ifdef THREADED_RTS
46 static Mutex trace_utx;
47 #endif
48
49 static rtsBool eventlog_enabled;
50
51 /* ---------------------------------------------------------------------------
52 Starting up / shuttting down the tracing facilities
53 --------------------------------------------------------------------------- */
54
55 void initTracing (void)
56 {
57 #ifdef THREADED_RTS
58 initMutex(&trace_utx);
59 #endif
60
61 #ifdef DEBUG
62 #define DEBUG_FLAG(name, class) \
63 class = RtsFlags.DebugFlags.name ? 1 : 0;
64
65 DEBUG_FLAG(scheduler, DEBUG_sched);
66
67 DEBUG_FLAG(interpreter, DEBUG_interp);
68 DEBUG_FLAG(weak, DEBUG_weak);
69 DEBUG_FLAG(gccafs, DEBUG_gccafs);
70 DEBUG_FLAG(gc, DEBUG_gc);
71 DEBUG_FLAG(block_alloc, DEBUG_block_alloc);
72 DEBUG_FLAG(sanity, DEBUG_sanity);
73 DEBUG_FLAG(stable, DEBUG_stable);
74 DEBUG_FLAG(stm, DEBUG_stm);
75 DEBUG_FLAG(prof, DEBUG_prof);
76 DEBUG_FLAG(linker, DEBUG_linker);
77 DEBUG_FLAG(squeeze, DEBUG_squeeze);
78 DEBUG_FLAG(hpc, DEBUG_hpc);
79 DEBUG_FLAG(sparks, DEBUG_sparks);
80 #endif
81
82 // -Ds turns on scheduler tracing too
83 TRACE_sched =
84 RtsFlags.TraceFlags.scheduler ||
85 RtsFlags.DebugFlags.scheduler;
86
87 eventlog_enabled = RtsFlags.TraceFlags.tracing == TRACE_EVENTLOG;
88
89 if (eventlog_enabled) {
90 initEventLogging();
91 }
92 }
93
94 void endTracing (void)
95 {
96 if (eventlog_enabled) {
97 endEventLogging();
98 }
99 }
100
101 void freeTracing (void)
102 {
103 if (eventlog_enabled) {
104 freeEventLogging();
105 }
106 }
107
108 /* ---------------------------------------------------------------------------
109 Emitting trace messages/events
110 --------------------------------------------------------------------------- */
111
112 #ifdef DEBUG
113 static void tracePreface (void)
114 {
115 #ifdef THREADED_RTS
116 debugBelch("%12lx: ", (unsigned long)osThreadId());
117 #endif
118 if (RtsFlags.TraceFlags.timestamp) {
119 debugBelch("%9" FMT_Word64 ": ", stat_getElapsedTime());
120 }
121 }
122 #endif
123
124 #ifdef DEBUG
125 static char *thread_stop_reasons[] = {
126 [HeapOverflow] = "heap overflow",
127 [StackOverflow] = "stack overflow",
128 [ThreadYielding] = "yielding",
129 [ThreadBlocked] = "blocked",
130 [ThreadFinished] = "finished",
131 [THREAD_SUSPENDED_FOREIGN_CALL] = "suspended while making a foreign call"
132 };
133 #endif
134
135 #ifdef DEBUG
136 static void traceSchedEvent_stderr (Capability *cap, EventTypeNum tag,
137 StgTSO *tso,
138 StgWord64 other STG_UNUSED)
139 {
140 ACQUIRE_LOCK(&trace_utx);
141
142 tracePreface();
143 switch (tag) {
144 case EVENT_CREATE_THREAD: // (cap, thread)
145 debugBelch("cap %d: created thread %lu\n",
146 cap->no, (lnat)tso->id);
147 break;
148 case EVENT_RUN_THREAD: // (cap, thread)
149 debugBelch("cap %d: running thread %lu (%s)\n",
150 cap->no, (lnat)tso->id, what_next_strs[tso->what_next]);
151 break;
152 case EVENT_THREAD_RUNNABLE: // (cap, thread)
153 debugBelch("cap %d: thread %lu appended to run queue\n",
154 cap->no, (lnat)tso->id);
155 break;
156 case EVENT_RUN_SPARK: // (cap, thread)
157 debugBelch("cap %d: thread %lu running a spark\n",
158 cap->no, (lnat)tso->id);
159 break;
160 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
161 debugBelch("cap %d: creating spark thread %lu\n",
162 cap->no, (long)other);
163 break;
164 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
165 debugBelch("cap %d: thread %lu migrating to cap %d\n",
166 cap->no, (lnat)tso->id, (int)other);
167 break;
168 case EVENT_STEAL_SPARK: // (cap, thread, victim_cap)
169 debugBelch("cap %d: thread %lu stealing a spark from cap %d\n",
170 cap->no, (lnat)tso->id, (int)other);
171 break;
172 case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap)
173 debugBelch("cap %d: waking up thread %lu on cap %d\n",
174 cap->no, (lnat)tso->id, (int)other);
175 break;
176
177 case EVENT_STOP_THREAD: // (cap, thread, status)
178 debugBelch("cap %d: thread %lu stopped (%s)\n",
179 cap->no, (lnat)tso->id, thread_stop_reasons[other]);
180 break;
181 case EVENT_SHUTDOWN: // (cap)
182 debugBelch("cap %d: shutting down\n", cap->no);
183 break;
184 case EVENT_REQUEST_SEQ_GC: // (cap)
185 debugBelch("cap %d: requesting sequential GC\n", cap->no);
186 break;
187 case EVENT_REQUEST_PAR_GC: // (cap)
188 debugBelch("cap %d: requesting parallel GC\n", cap->no);
189 break;
190 case EVENT_GC_START: // (cap)
191 debugBelch("cap %d: starting GC\n", cap->no);
192 break;
193 case EVENT_GC_END: // (cap)
194 debugBelch("cap %d: finished GC\n", cap->no);
195 break;
196 case EVENT_GC_IDLE: // (cap)
197 debugBelch("cap %d: GC idle\n", cap->no);
198 break;
199 case EVENT_GC_WORK: // (cap)
200 debugBelch("cap %d: GC working\n", cap->no);
201 break;
202 case EVENT_GC_DONE: // (cap)
203 debugBelch("cap %d: GC done\n", cap->no);
204 break;
205 default:
206 debugBelch("cap %2d: thread %lu: event %d\n\n",
207 cap->no, (lnat)tso->id, tag);
208 break;
209 }
210
211 RELEASE_LOCK(&trace_utx);
212 }
213 #endif
214
215 void traceSchedEvent_ (Capability *cap, EventTypeNum tag,
216 StgTSO *tso, StgWord64 other)
217 {
218 #ifdef DEBUG
219 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
220 traceSchedEvent_stderr(cap, tag, tso, other);
221 } else
222 #endif
223 {
224 postSchedEvent(cap,tag,tso ? tso->id : 0,other);
225 }
226 }
227
228 void traceEvent_ (Capability *cap, EventTypeNum tag)
229 {
230 #ifdef DEBUG
231 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
232 traceSchedEvent_stderr(cap, tag, 0, 0);
233 } else
234 #endif
235 {
236 postEvent(cap,tag);
237 }
238 }
239
240 #ifdef DEBUG
241 static void traceCap_stderr(Capability *cap, char *msg, va_list ap)
242 {
243 ACQUIRE_LOCK(&trace_utx);
244
245 tracePreface();
246 debugBelch("cap %2d: ", cap->no);
247 vdebugBelch(msg,ap);
248 debugBelch("\n");
249
250 RELEASE_LOCK(&trace_utx);
251 }
252 #endif
253
254 void traceCap_(Capability *cap, char *msg, ...)
255 {
256 va_list ap;
257 va_start(ap,msg);
258
259 #ifdef DEBUG
260 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
261 traceCap_stderr(cap, msg, ap);
262 } else
263 #endif
264 {
265 postCapMsg(cap, msg, ap);
266 }
267
268 va_end(ap);
269 }
270
271 #ifdef DEBUG
272 static void trace_stderr(char *msg, va_list ap)
273 {
274 ACQUIRE_LOCK(&trace_utx);
275
276 tracePreface();
277 vdebugBelch(msg,ap);
278 debugBelch("\n");
279
280 RELEASE_LOCK(&trace_utx);
281 }
282 #endif
283
284 void trace_(char *msg, ...)
285 {
286 va_list ap;
287 va_start(ap,msg);
288
289 #ifdef DEBUG
290 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
291 trace_stderr(msg, ap);
292 } else
293 #endif
294 {
295 postMsg(msg, ap);
296 }
297
298 va_end(ap);
299 }
300
301 void traceUserMsg(Capability *cap, char *msg)
302 {
303 #ifdef DEBUG
304 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
305 traceCap_stderr(cap, msg, NULL);
306 } else
307 #endif
308 {
309 if (eventlog_enabled) {
310 postUserMsg(cap, msg);
311 }
312 }
313 }
314
315 void traceThreadStatus_ (StgTSO *tso USED_IF_DEBUG)
316 {
317 #ifdef DEBUG
318 if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) {
319 printThreadStatus(tso);
320 } else
321 #endif
322 {
323 /* nothing - no event for this one yet */
324 }
325 }
326
327
328 #ifdef DEBUG
329 void traceBegin (const char *str, ...)
330 {
331 va_list ap;
332 va_start(ap,str);
333
334 ACQUIRE_LOCK(&trace_utx);
335
336 tracePreface();
337 vdebugBelch(str,ap);
338 }
339
340 void traceEnd (void)
341 {
342 debugBelch("\n");
343 RELEASE_LOCK(&trace_utx);
344 }
345 #endif /* DEBUG */
346
347 #endif /* TRACING */