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