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