820e95cef1b022c62c26c3797c29cd26223eec90
[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 #ifdef EVENTLOG
10
11 #include "Rts.h"
12 #include "EventLog.h"
13 #include "Capability.h"
14 #include "Trace.h"
15 #include "RtsUtils.h"
16 #include "Stats.h"
17 #include <string.h>
18 #include <stdio.h>
19
20 static char *event_log_filename = NULL;
21
22 // File for logging events
23 FILE *event_log_file = NULL;
24
25 #define EVENT_LOG_SIZE 2 * (1024 * 1024) // 2MB
26
27 static int flushCount;
28
29 // Struct for record keeping of buffer to store event types and events.
30 typedef struct _EventsBuf {
31 StgInt8 *begin;
32 StgInt8 *pos;
33 StgWord64 size;
34 } EventsBuf;
35
36 EventsBuf *eventsBuf;
37
38 char *EventDesc[] = {
39 "Create thread",
40 "Run thread",
41 "Stop thread",
42 "Thread runnable",
43 "Migrate thread",
44 "Run spark",
45 "Steal spark",
46 "Shutdown",
47 "Wakeup thread",
48 "Request sequential GC",
49 "Request parallel GC",
50 "Starting GC",
51 "Finished GC"
52 };
53
54 // Event type.
55
56 typedef struct _EventType {
57 EventTypeNum etNum; // Event Type number.
58 nat size; // size of the payload in bytes
59 char *desc; // Description
60 } EventType;
61
62 EventType eventTypes[NUM_EVENT_TAGS];
63
64 static void printAndClearEventBuf (EventsBuf *eventsBuf);
65 static void initEventsBuf(EventsBuf* eb, StgWord64 size);
66 static void resetEventsBuf(EventsBuf* eb);
67
68 static void beginHeader(EventsBuf *eb);
69 static void endHeader(EventsBuf *eb);
70
71 static void beginData(EventsBuf *eb);
72 static void endData(EventsBuf *eb);
73
74 static void beginEventTypes(EventsBuf *eb);
75 static void endEventTypes(EventsBuf *eb);
76
77 static void postEventType(EventsBuf *eb, EventType *et);
78
79 static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum);
80
81 static inline void postWord8(EventsBuf *eb, StgWord8 i)
82 {
83 *(eb->pos++) = i;
84 }
85
86 static inline void postWord16(EventsBuf *eb, StgWord16 i)
87 {
88 postWord8(eb, (StgWord8)(i >> 8));
89 postWord8(eb, (StgWord8)i);
90 }
91
92 static inline void postWord32(EventsBuf *eb, StgWord32 i)
93 {
94 postWord16(eb, (StgWord16)(i >> 16));
95 postWord16(eb, (StgWord16)i);
96 }
97
98 static inline void postWord64(EventsBuf *eb, StgWord64 i)
99 {
100 postWord32(eb, (StgWord32)(i >> 32));
101 postWord32(eb, (StgWord32)i);
102 }
103
104 static inline void postEventTypeNum(EventsBuf *eb, EventTypeNum etNum)
105 { postWord16(eb, etNum); }
106
107 static inline void postEventTypeID(EventsBuf *eb, StgWord16 etID)
108 { postWord16(eb, etID); }
109
110 static inline void postTimestamp(EventsBuf *eb, Timestamp t)
111 { postWord64(eb,t); }
112
113 static inline void postInt8(EventsBuf *eb, StgInt8 i)
114 { postWord8(eb, (StgWord8)i); }
115
116 static inline void postInt16(EventsBuf *eb, StgInt16 i)
117 { postWord16(eb, (StgWord16)i); }
118
119 static inline void postInt32(EventsBuf *eb, StgInt32 i)
120 { postWord32(eb, (StgWord32)i); }
121
122 static inline void postInt64(EventsBuf *eb, StgInt64 i)
123 { postWord64(eb, (StgWord64)i); }
124
125
126 void
127 initEventLogging(void)
128 {
129 StgWord8 t, c;
130
131 debugTrace(DEBUG_eventlog, "intiEventLog: start");
132
133 event_log_filename = stgMallocBytes(strlen(prog_name) + 9,
134 "initEventLogging");
135
136 if (sizeof(EventDesc) / sizeof(char*) != NUM_EVENT_TAGS) {
137 barf("EventDesc array has the wrong number of elements");
138 }
139
140 sprintf(event_log_filename, "%s.eventlog", prog_name);
141
142 /* Open event log file for writing. */
143 if ((event_log_file = fopen(event_log_filename, "wb")) == NULL) {
144 sysErrorBelch("initEventLoggin: can't open %s", event_log_filename);
145 stg_exit(EXIT_FAILURE);
146 }
147
148 /*
149 * Allocate buffer(s) to store events.
150 * Create buffer large enough for the header begin marker, all event
151 * types, and header end marker to prevent checking if buffer has room
152 * for each of these steps, and remove the need to flush the buffer to
153 * disk during initialization.
154 *
155 * Use a single buffer to store the header with event types, then flush
156 * the buffer so all buffers are empty for writing events.
157 */
158 eventsBuf = stgMallocBytes(n_capabilities * sizeof(EventsBuf),"initEventLogging");
159
160 for (c = 0; c < n_capabilities; ++c) {
161 // Init buffer for events.
162 initEventsBuf(&eventsBuf[c], EVENT_LOG_SIZE);
163 }
164
165 // Write in buffer: the header begin marker.
166 beginHeader(&eventsBuf[0]);
167
168 // Mark beginning of event types in the header.
169 beginEventTypes(&eventsBuf[0]);
170 for (t = 0; t < NUM_EVENT_TAGS; ++t) {
171
172 eventTypes[t].etNum = t;
173 eventTypes[t].desc = EventDesc[t];
174
175 switch (t) {
176 case EVENT_CREATE_THREAD: // (cap, thread)
177 case EVENT_RUN_THREAD: // (cap, thread)
178 case EVENT_THREAD_RUNNABLE: // (cap, thread)
179 case EVENT_RUN_SPARK: // (cap, thread)
180 eventTypes[t].size = sizeof(CapabilityNum) + sizeof(ThreadID);
181 break;
182
183 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
184 case EVENT_STEAL_SPARK: // (cap, thread, victim_cap)
185 case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap)
186 eventTypes[t].size =
187 sizeof(CapabilityNum) + sizeof(ThreadID) +
188 sizeof(CapabilityNum);
189 break;
190
191 case EVENT_STOP_THREAD: // (cap, thread, status)
192 eventTypes[t].size =
193 sizeof(CapabilityNum) + sizeof(ThreadID) + sizeof(StgWord16);
194 break;
195
196 case EVENT_SHUTDOWN: // (cap)
197 case EVENT_REQUEST_SEQ_GC: // (cap)
198 case EVENT_REQUEST_PAR_GC: // (cap)
199 case EVENT_GC_START: // (cap)
200 case EVENT_GC_END: // (cap)
201 eventTypes[t].size = sizeof(CapabilityNum);
202 break;
203 }
204
205 // Write in buffer: the start event type.
206 postEventType(&eventsBuf[0], &eventTypes[t]);
207 }
208
209 // Mark end of event types in the header.
210 endEventTypes(&eventsBuf[0]);
211
212 // Write in buffer: the header end marker.
213 endHeader(&eventsBuf[0]);
214
215 // Prepare event buffer for events (data).
216 beginData(&eventsBuf[0]);
217
218 // Flush eventsBuf with header.
219 /*
220 * Flush header and data begin marker to the file, thus preparing the
221 * file to have events written to it.
222 */
223 printAndClearEventBuf(&eventsBuf[0]);
224
225 debugTrace(DEBUG_eventlog, "initEventLog: finish");
226 }
227
228 void
229 endEventLogging(void)
230 {
231 nat c;
232
233 debugTrace(DEBUG_eventlog,"endEventLog: start");
234
235 // Flush all events remaining in the buffers.
236 for (c = 0; c < n_capabilities; ++c) {
237 printAndClearEventBuf(&eventsBuf[c]);
238 }
239
240 // Mark end of events (data).
241 endData(&eventsBuf[0]);
242
243 // Flush the end of data marker.
244 printAndClearEventBuf(&eventsBuf[0]);
245
246 if (event_log_file != NULL) {
247 fclose(event_log_file);
248 }
249
250 debugTrace(DEBUG_eventlog,"endEventLog: finish");
251 }
252
253 void
254 freeEventLogging(void)
255 {
256 StgWord8 c;
257
258 debugTrace(DEBUG_eventlog,"freeEventLog: start");
259
260 // Free events buffer.
261 for (c = 0; c < n_capabilities; ++c) {
262 if (eventsBuf[c].begin != NULL)
263 stgFree(eventsBuf[c].begin);
264 }
265 if (eventsBuf != NULL) {
266 stgFree(eventsBuf);
267 }
268 if (event_log_filename != NULL) {
269 stgFree(event_log_filename);
270 }
271
272 debugTrace(DEBUG_eventlog,"freeEventLog: finish");
273 }
274
275 /*
276 * Post an event message to the capability's eventlog buffer.
277 * If the buffer is full, prints out the buffer and clears it.
278 */
279 void
280 postEvent_(Capability *cap, EventTypeNum tag, StgThreadID thread, nat other_cap)
281 {
282 EventsBuf *eb;
283
284 debugTrace(DEBUG_eventlog,"postEvent: start");
285
286 eb = &eventsBuf[cap->no];
287
288 if (!hasRoomForEvent(eb, tag)) {
289 // Flush event buffer to make room for new event.
290 printAndClearEventBuf(eb);
291 }
292
293 postEventTypeNum(eb, tag);
294 postTimestamp(eb, stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND));
295 postWord16(eb, cap->no);
296
297 switch (tag) {
298 case EVENT_CREATE_THREAD: // (cap, thread)
299 case EVENT_RUN_THREAD: // (cap, thread)
300 case EVENT_THREAD_RUNNABLE: // (cap, thread)
301 case EVENT_RUN_SPARK: // (cap, thread)
302 {
303 postWord64(eb,thread);
304 break;
305 }
306
307 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
308 case EVENT_STEAL_SPARK: // (cap, thread, victim_cap)
309 case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap)
310 {
311 postWord64(eb,thread);
312 postWord16(eb,other_cap);
313 break;
314 }
315
316 case EVENT_STOP_THREAD: // (cap, thread, status)
317 {
318 postWord64(eb,thread);
319 postWord16(eb,other_cap);
320 break;
321 }
322
323 case EVENT_SHUTDOWN: // (cap)
324 case EVENT_REQUEST_SEQ_GC: // (cap)
325 case EVENT_REQUEST_PAR_GC: // (cap)
326 case EVENT_GC_START: // (cap)
327 case EVENT_GC_END: // (cap)
328 {
329 break;
330 }
331
332 default:
333 barf("postEvent: unknown event tag %d", tag);
334 }
335
336 debugTrace(DEBUG_eventlog,"postEvent: finish");
337 }
338
339 static void printAndClearEventBuf (EventsBuf *eventsBuf)
340 {
341 StgWord64 numBytes = 0, written = 0;
342
343 if (eventsBuf->begin != NULL && eventsBuf->pos != eventsBuf->begin)
344 {
345 numBytes = eventsBuf->pos - eventsBuf->begin;
346
347 debugTrace(DEBUG_eventlog,
348 "printAndEventLog: numbytes %" FMT_Word64
349 " bytes to fwrite()",
350 numBytes);
351
352 written = fwrite(eventsBuf->begin, 1, numBytes, event_log_file);
353 if (written != numBytes) {
354 debugBelch(
355 "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64
356 " doesn't match numBytes=%" FMT_Word64, written, numBytes);
357 return;
358 }
359
360 debugTrace(DEBUG_eventlog,
361 "printAndClearEventLog: fwrite(): %" FMT_Word64
362 " bytes written", written);
363
364 resetEventsBuf(eventsBuf);
365 flushCount++;
366 }
367 }
368
369 void
370 printAndClearEventLog(Capability *cap)
371 {
372 debugTrace(DEBUG_eventlog,"printAndClearEventLog: start");
373
374 printAndClearEventBuf(&eventsBuf[cap->no]);
375
376 debugTrace(DEBUG_eventlog,"printAndClearEventLog: finish");
377 }
378
379 /* -----------------------------------------------------------------------------
380 Actual event generation below here
381 -------------------------------------------------------------------------- */
382
383 void initEventsBuf(EventsBuf* eb, StgWord64 size)
384 {
385 eb->begin = eb->pos = malloc(size);
386 eb->size = size;
387 }
388
389 void resetEventsBuf(EventsBuf* eb)
390 {
391 eb->pos = eb->begin;
392 }
393
394 // N.B.: Assuming buffer contains enough space for the header begin marker.
395 void beginHeader(EventsBuf *eb)
396 {
397 postInt32(eb, EVENT_HEADER_BEGIN);
398 }
399
400 // N.B.: Assuming buffer contains enough space for the header end marker.
401 void endHeader(EventsBuf *eb)
402 {
403 postInt32(eb, EVENT_HEADER_END);
404 }
405
406 void beginData(EventsBuf *eb)
407 {
408 postInt32(eb, EVENT_DATA_BEGIN);
409 }
410
411 void endData(EventsBuf *eb)
412 {
413 postEventTypeNum(eb, EVENT_DATA_END);
414 }
415
416 void beginEventTypes(EventsBuf *eb)
417 {
418 postInt32(eb, EVENT_HET_BEGIN);
419 }
420
421 void endEventTypes(EventsBuf *eb)
422 {
423 postInt32(eb, EVENT_HET_END);
424 }
425
426 StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
427 {
428 nat size = 0;
429
430 size += sizeof(EventTypeNum) + sizeof(Timestamp) + eventTypes[eNum].size;
431
432 if (eb->pos + size > eb->begin + eb->size) {
433 return 0; // Not enough space.
434 } else {
435 return 1; // Buf has enough space for the event.
436 }
437 }
438
439 static void postEventType(EventsBuf *eb, EventType *et)
440 {
441 StgWord8 d;
442 nat desclen;
443
444 postInt32(eb, EVENT_ET_BEGIN);
445 postEventTypeNum(eb, et->etNum);
446 postWord16(eb, (StgWord16)et->size);
447 desclen = strlen(et->desc);
448 postWord32(eb, desclen);
449 for (d = 0; d < desclen; ++d) {
450 postInt8(eb, (StgInt8)et->desc[d]);
451 }
452 postWord32(eb, 0); // no extensions yet
453 postInt32(eb, EVENT_ET_END);
454 }
455
456 #endif /* EVENTLOG */