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