Add events to show when GC threads are idle/working
[ghc.git] / rts / eventlog / EventLog.c
1 /* -----------------------------------------------------------------------------
2 *
3 * (c) The GHC Team, 2008-2009
4 *
5 * Support for fast binary event logging.
6 *
7 * ---------------------------------------------------------------------------*/
8
9 #include "PosixSource.h"
10 #include "Rts.h"
11
12 #ifdef TRACING
13
14 #include "Trace.h"
15 #include "Capability.h"
16 #include "Trace.h"
17 #include "RtsUtils.h"
18 #include "Stats.h"
19 #include "EventLog.h"
20
21 #include <string.h>
22 #include <stdio.h>
23
24 static char *event_log_filename = NULL;
25
26 // File for logging events
27 FILE *event_log_file = NULL;
28
29 #define EVENT_LOG_SIZE 2 * (1024 * 1024) // 2MB
30
31 static int flushCount;
32
33 // Struct for record keeping of buffer to store event types and events.
34 typedef struct _EventsBuf {
35 StgInt8 *begin;
36 StgInt8 *pos;
37 StgInt8 *marker;
38 StgWord64 size;
39 EventCapNo capno; // which capability this buffer belongs to, or -1
40 } EventsBuf;
41
42 EventsBuf *capEventBuf; // one EventsBuf for each Capability
43
44 EventsBuf eventBuf; // an EventsBuf not associated with any Capability
45 #ifdef THREADED_RTS
46 Mutex eventBufMutex; // protected by this mutex
47 #endif
48
49 char *EventDesc[] = {
50 [EVENT_CREATE_THREAD] = "Create thread",
51 [EVENT_RUN_THREAD] = "Run thread",
52 [EVENT_STOP_THREAD] = "Stop thread",
53 [EVENT_THREAD_RUNNABLE] = "Thread runnable",
54 [EVENT_MIGRATE_THREAD] = "Migrate thread",
55 [EVENT_RUN_SPARK] = "Run spark",
56 [EVENT_STEAL_SPARK] = "Steal spark",
57 [EVENT_SHUTDOWN] = "Shutdown",
58 [EVENT_THREAD_WAKEUP] = "Wakeup thread",
59 [EVENT_GC_START] = "Starting GC",
60 [EVENT_GC_END] = "Finished GC",
61 [EVENT_REQUEST_SEQ_GC] = "Request sequential GC",
62 [EVENT_REQUEST_PAR_GC] = "Request parallel GC",
63 [EVENT_CREATE_SPARK_THREAD] = "Create spark thread",
64 [EVENT_LOG_MSG] = "Log message",
65 [EVENT_USER_MSG] = "User message",
66 [EVENT_STARTUP] = "Startup",
67 [EVENT_GC_IDLE] = "GC idle",
68 [EVENT_GC_WORK] = "GC working",
69 [EVENT_GC_DONE] = "GC done",
70 [EVENT_BLOCK_MARKER] = "Block marker"
71 };
72
73 // Event type.
74
75 typedef struct _EventType {
76 EventTypeNum etNum; // Event Type number.
77 nat size; // size of the payload in bytes
78 char *desc; // Description
79 } EventType;
80
81 EventType eventTypes[NUM_EVENT_TAGS];
82
83 static void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno);
84 static void resetEventsBuf(EventsBuf* eb);
85 static void printAndClearEventBuf (EventsBuf *eventsBuf);
86
87 static void postEventType(EventsBuf *eb, EventType *et);
88
89 static void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap);
90
91 static void postBlockMarker(EventsBuf *eb);
92 static void closeBlockMarker(EventsBuf *ebuf);
93
94 static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum);
95 static StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes);
96
97 static inline void postWord8(EventsBuf *eb, StgWord8 i)
98 {
99 *(eb->pos++) = i;
100 }
101
102 static inline void postWord16(EventsBuf *eb, StgWord16 i)
103 {
104 postWord8(eb, (StgWord8)(i >> 8));
105 postWord8(eb, (StgWord8)i);
106 }
107
108 static inline void postWord32(EventsBuf *eb, StgWord32 i)
109 {
110 postWord16(eb, (StgWord16)(i >> 16));
111 postWord16(eb, (StgWord16)i);
112 }
113
114 static inline void postWord64(EventsBuf *eb, StgWord64 i)
115 {
116 postWord32(eb, (StgWord32)(i >> 32));
117 postWord32(eb, (StgWord32)i);
118 }
119
120 static inline void postBuf(EventsBuf *eb, StgWord8 *buf, nat size)
121 {
122 memcpy(eb->pos, buf, size);
123 eb->pos += size;
124 }
125
126 static inline StgWord64 time_ns(void)
127 { return stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND); }
128
129 static inline void postEventTypeNum(EventsBuf *eb, EventTypeNum etNum)
130 { postWord16(eb, etNum); }
131
132 static inline void postTimestamp(EventsBuf *eb)
133 { postWord64(eb, time_ns()); }
134
135 static inline void postThreadID(EventsBuf *eb, EventThreadID id)
136 { postWord32(eb,id); }
137
138 static inline void postCapNo(EventsBuf *eb, EventCapNo no)
139 { postWord16(eb,no); }
140
141 static inline void postPayloadSize(EventsBuf *eb, EventPayloadSize size)
142 { postWord16(eb,size); }
143
144 static inline void postEventHeader(EventsBuf *eb, EventTypeNum type)
145 {
146 postEventTypeNum(eb, type);
147 postTimestamp(eb);
148 }
149
150 static inline void postInt8(EventsBuf *eb, StgInt8 i)
151 { postWord8(eb, (StgWord8)i); }
152
153 static inline void postInt16(EventsBuf *eb, StgInt16 i)
154 { postWord16(eb, (StgWord16)i); }
155
156 static inline void postInt32(EventsBuf *eb, StgInt32 i)
157 { postWord32(eb, (StgWord32)i); }
158
159 static inline void postInt64(EventsBuf *eb, StgInt64 i)
160 { postWord64(eb, (StgWord64)i); }
161
162
163 void
164 initEventLogging(void)
165 {
166 StgWord8 t, c;
167 nat n_caps;
168
169 event_log_filename = stgMallocBytes(strlen(prog_name) + 10,
170 "initEventLogging");
171
172 if (sizeof(EventDesc) / sizeof(char*) != NUM_EVENT_TAGS) {
173 barf("EventDesc array has the wrong number of elements");
174 }
175
176 sprintf(event_log_filename, "%s.eventlog", prog_name);
177
178 /* Open event log file for writing. */
179 if ((event_log_file = fopen(event_log_filename, "wb")) == NULL) {
180 sysErrorBelch("initEventLogging: can't open %s", event_log_filename);
181 stg_exit(EXIT_FAILURE);
182 }
183
184 /*
185 * Allocate buffer(s) to store events.
186 * Create buffer large enough for the header begin marker, all event
187 * types, and header end marker to prevent checking if buffer has room
188 * for each of these steps, and remove the need to flush the buffer to
189 * disk during initialization.
190 *
191 * Use a single buffer to store the header with event types, then flush
192 * the buffer so all buffers are empty for writing events.
193 */
194 #ifdef THREADED_RTS
195 // XXX n_capabilities hasn't been initislised yet
196 n_caps = RtsFlags.ParFlags.nNodes;
197 #else
198 n_caps = 1;
199 #endif
200 capEventBuf = stgMallocBytes(n_caps * sizeof(EventsBuf),"initEventLogging");
201
202 for (c = 0; c < n_caps; ++c) {
203 // Init buffer for events.
204 initEventsBuf(&capEventBuf[c], EVENT_LOG_SIZE, c);
205 }
206 initEventsBuf(&eventBuf, EVENT_LOG_SIZE, (EventCapNo)(-1));
207
208 // Write in buffer: the header begin marker.
209 postInt32(&eventBuf, EVENT_HEADER_BEGIN);
210
211 // Mark beginning of event types in the header.
212 postInt32(&eventBuf, EVENT_HET_BEGIN);
213 for (t = 0; t < NUM_EVENT_TAGS; ++t) {
214
215 eventTypes[t].etNum = t;
216 eventTypes[t].desc = EventDesc[t];
217
218 switch (t) {
219 case EVENT_CREATE_THREAD: // (cap, thread)
220 case EVENT_RUN_THREAD: // (cap, thread)
221 case EVENT_THREAD_RUNNABLE: // (cap, thread)
222 case EVENT_RUN_SPARK: // (cap, thread)
223 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
224 eventTypes[t].size = sizeof(EventThreadID);
225 break;
226
227 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
228 case EVENT_STEAL_SPARK: // (cap, thread, victim_cap)
229 case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap)
230 eventTypes[t].size =
231 sizeof(EventThreadID) + sizeof(EventCapNo);
232 break;
233
234 case EVENT_STOP_THREAD: // (cap, thread, status)
235 eventTypes[t].size =
236 sizeof(EventThreadID) + sizeof(StgWord16);
237 break;
238
239 case EVENT_SHUTDOWN: // (cap)
240 case EVENT_REQUEST_SEQ_GC: // (cap)
241 case EVENT_REQUEST_PAR_GC: // (cap)
242 case EVENT_GC_START: // (cap)
243 case EVENT_GC_END: // (cap)
244 case EVENT_STARTUP:
245 case EVENT_GC_IDLE:
246 case EVENT_GC_WORK:
247 case EVENT_GC_DONE:
248 eventTypes[t].size = 0;
249 break;
250
251 case EVENT_LOG_MSG: // (msg)
252 case EVENT_USER_MSG: // (msg)
253 eventTypes[t].size = 0xffff;
254 break;
255
256 case EVENT_BLOCK_MARKER:
257 eventTypes[t].size = sizeof(StgWord32) + sizeof(EventTimestamp) +
258 sizeof(EventCapNo);
259 break;
260
261 default:
262 continue; /* ignore deprecated events */
263 }
264
265 // Write in buffer: the start event type.
266 postEventType(&eventBuf, &eventTypes[t]);
267 }
268
269 // Mark end of event types in the header.
270 postInt32(&eventBuf, EVENT_HET_END);
271
272 // Write in buffer: the header end marker.
273 postInt32(&eventBuf, EVENT_HEADER_END);
274
275 // Prepare event buffer for events (data).
276 postInt32(&eventBuf, EVENT_DATA_BEGIN);
277
278 // Post a STARTUP event with the number of capabilities
279 postEventHeader(&eventBuf, EVENT_STARTUP);
280 postCapNo(&eventBuf, n_caps);
281
282 // Flush capEventBuf with header.
283 /*
284 * Flush header and data begin marker to the file, thus preparing the
285 * file to have events written to it.
286 */
287 printAndClearEventBuf(&eventBuf);
288
289 for (c = 0; c < n_caps; ++c) {
290 postBlockMarker(&capEventBuf[c]);
291 }
292 }
293
294 void
295 endEventLogging(void)
296 {
297 nat c;
298
299 // Flush all events remaining in the buffers.
300 for (c = 0; c < n_capabilities; ++c) {
301 printAndClearEventBuf(&capEventBuf[c]);
302 }
303 printAndClearEventBuf(&eventBuf);
304 resetEventsBuf(&eventBuf); // we don't want the block marker
305
306 // Mark end of events (data).
307 postEventTypeNum(&eventBuf, EVENT_DATA_END);
308
309 // Flush the end of data marker.
310 printAndClearEventBuf(&eventBuf);
311
312 if (event_log_file != NULL) {
313 fclose(event_log_file);
314 }
315 }
316
317 void
318 freeEventLogging(void)
319 {
320 StgWord8 c;
321
322 // Free events buffer.
323 for (c = 0; c < n_capabilities; ++c) {
324 if (capEventBuf[c].begin != NULL)
325 stgFree(capEventBuf[c].begin);
326 }
327 if (capEventBuf != NULL) {
328 stgFree(capEventBuf);
329 }
330 if (event_log_filename != NULL) {
331 stgFree(event_log_filename);
332 }
333 }
334
335 /*
336 * Post an event message to the capability's eventlog buffer.
337 * If the buffer is full, prints out the buffer and clears it.
338 */
339 void
340 postSchedEvent (Capability *cap,
341 EventTypeNum tag,
342 StgThreadID thread,
343 StgWord64 other)
344 {
345 EventsBuf *eb;
346
347 eb = &capEventBuf[cap->no];
348
349 if (!hasRoomForEvent(eb, tag)) {
350 // Flush event buffer to make room for new event.
351 printAndClearEventBuf(eb);
352 }
353
354 postEventHeader(eb, tag);
355
356 switch (tag) {
357 case EVENT_CREATE_THREAD: // (cap, thread)
358 case EVENT_RUN_THREAD: // (cap, thread)
359 case EVENT_THREAD_RUNNABLE: // (cap, thread)
360 case EVENT_RUN_SPARK: // (cap, thread)
361 {
362 postThreadID(eb,thread);
363 break;
364 }
365
366 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
367 {
368 postThreadID(eb,other /* spark_thread */);
369 break;
370 }
371
372 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
373 case EVENT_STEAL_SPARK: // (cap, thread, victim_cap)
374 case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap)
375 {
376 postThreadID(eb,thread);
377 postCapNo(eb,other /* new_cap | victim_cap | other_cap */);
378 break;
379 }
380
381 case EVENT_STOP_THREAD: // (cap, thread, status)
382 {
383 postThreadID(eb,thread);
384 postWord16(eb,other /* status */);
385 break;
386 }
387
388 case EVENT_SHUTDOWN: // (cap)
389 case EVENT_REQUEST_SEQ_GC: // (cap)
390 case EVENT_REQUEST_PAR_GC: // (cap)
391 case EVENT_GC_START: // (cap)
392 case EVENT_GC_END: // (cap)
393 {
394 break;
395 }
396
397 default:
398 barf("postEvent: unknown event tag %d", tag);
399 }
400 }
401
402 void
403 postEvent (Capability *cap, EventTypeNum tag)
404 {
405 EventsBuf *eb;
406
407 eb = &capEventBuf[cap->no];
408
409 if (!hasRoomForEvent(eb, tag)) {
410 // Flush event buffer to make room for new event.
411 printAndClearEventBuf(eb);
412 }
413
414 postEventHeader(eb, tag);
415 }
416
417 #define BUF 512
418
419 void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap)
420 {
421 char buf[BUF];
422 nat size;
423
424 size = vsnprintf(buf,BUF,msg,ap);
425 if (size > BUF) {
426 buf[BUF-1] = '\0';
427 size = BUF;
428 }
429
430 if (!hasRoomForVariableEvent(eb, size)) {
431 // Flush event buffer to make room for new event.
432 printAndClearEventBuf(eb);
433 }
434
435 postEventHeader(eb, type);
436 postPayloadSize(eb, size);
437 postBuf(eb,(StgWord8*)buf,size);
438 }
439
440 void postMsg(char *msg, va_list ap)
441 {
442 ACQUIRE_LOCK(&eventBufMutex);
443 postLogMsg(&eventBuf, EVENT_LOG_MSG, msg, ap);
444 RELEASE_LOCK(&eventBufMutex);
445 }
446
447 void postCapMsg(Capability *cap, char *msg, va_list ap)
448 {
449 postLogMsg(&capEventBuf[cap->no], EVENT_LOG_MSG, msg, ap);
450 }
451
452 void postUserMsg(Capability *cap, char *msg)
453 {
454 postLogMsg(&capEventBuf[cap->no], EVENT_USER_MSG, msg, NULL);
455 }
456
457 void closeBlockMarker (EventsBuf *ebuf)
458 {
459 StgInt8* save_pos;
460
461 if (ebuf->marker)
462 {
463 // (type:16, time:64, size:32, end_time:64)
464
465 save_pos = ebuf->pos;
466 ebuf->pos = ebuf->marker + sizeof(EventTypeNum) +
467 sizeof(EventTimestamp);
468 postWord32(ebuf, save_pos - ebuf->marker);
469 postTimestamp(ebuf);
470 ebuf->pos = save_pos;
471 ebuf->marker = NULL;
472 }
473 }
474
475
476 void postBlockMarker (EventsBuf *eb)
477 {
478 if (!hasRoomForEvent(eb, EVENT_BLOCK_MARKER)) {
479 printAndClearEventBuf(eb);
480 }
481
482 closeBlockMarker(eb);
483
484 eb->marker = eb->pos;
485 postEventHeader(eb, EVENT_BLOCK_MARKER);
486 postWord32(eb,0); // these get filled in later by closeBlockMarker();
487 postWord64(eb,0);
488 postCapNo(eb, eb->capno);
489 }
490
491 void printAndClearEventBuf (EventsBuf *ebuf)
492 {
493 StgWord64 numBytes = 0, written = 0;
494
495 closeBlockMarker(ebuf);
496
497 if (ebuf->begin != NULL && ebuf->pos != ebuf->begin)
498 {
499 numBytes = ebuf->pos - ebuf->begin;
500
501 written = fwrite(ebuf->begin, 1, numBytes, event_log_file);
502 if (written != numBytes) {
503 debugBelch(
504 "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64
505 " doesn't match numBytes=%" FMT_Word64, written, numBytes);
506 return;
507 }
508
509 resetEventsBuf(ebuf);
510 flushCount++;
511
512 postBlockMarker(ebuf);
513 }
514 }
515
516 void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno)
517 {
518 eb->begin = eb->pos = stgMallocBytes(size, "initEventsBuf");
519 eb->size = size;
520 eb->marker = NULL;
521 eb->capno = capno;
522 }
523
524 void resetEventsBuf(EventsBuf* eb)
525 {
526 eb->pos = eb->begin;
527 eb->marker = NULL;
528 }
529
530 StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
531 {
532 nat size;
533
534 size = sizeof(EventTypeNum) + sizeof(EventTimestamp) + eventTypes[eNum].size;
535
536 if (eb->pos + size > eb->begin + eb->size) {
537 return 0; // Not enough space.
538 } else {
539 return 1; // Buf has enough space for the event.
540 }
541 }
542
543 StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes)
544 {
545 nat size;
546
547 size = sizeof(EventTypeNum) + sizeof(EventTimestamp) +
548 sizeof(EventPayloadSize) + payload_bytes;
549
550 if (eb->pos + size > eb->begin + eb->size) {
551 return 0; // Not enough space.
552 } else {
553 return 1; // Buf has enough space for the event.
554 }
555 }
556
557 void postEventType(EventsBuf *eb, EventType *et)
558 {
559 StgWord8 d;
560 nat desclen;
561
562 postInt32(eb, EVENT_ET_BEGIN);
563 postEventTypeNum(eb, et->etNum);
564 postWord16(eb, (StgWord16)et->size);
565 desclen = strlen(et->desc);
566 postWord32(eb, desclen);
567 for (d = 0; d < desclen; ++d) {
568 postInt8(eb, (StgInt8)et->desc[d]);
569 }
570 postWord32(eb, 0); // no extensions yet
571 postInt32(eb, EVENT_ET_END);
572 }
573
574 #endif /* TRACING */