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