Add capability sets to the tracing/events system
[ghc-hetmet.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 "RtsUtils.h"
17 #include "Stats.h"
18 #include "EventLog.h"
19
20 #include <string.h>
21 #include <stdio.h>
22 #ifdef HAVE_SYS_TYPES_H
23 #include <sys/types.h>
24 #endif
25 #ifdef HAVE_UNISTD_H
26 #include <unistd.h>
27 #endif
28
29 // PID of the process that writes to event_log_filename (#4512)
30 static pid_t event_log_pid = -1;
31
32 static char *event_log_filename = NULL;
33
34 // File for logging events
35 FILE *event_log_file = NULL;
36
37 #define EVENT_LOG_SIZE 2 * (1024 * 1024) // 2MB
38
39 static int flushCount;
40
41 // Struct for record keeping of buffer to store event types and events.
42 typedef struct _EventsBuf {
43   StgInt8 *begin;
44   StgInt8 *pos;
45   StgInt8 *marker;
46   StgWord64 size;
47   EventCapNo capno; // which capability this buffer belongs to, or -1
48 } EventsBuf;
49
50 EventsBuf *capEventBuf; // one EventsBuf for each Capability
51
52 EventsBuf eventBuf; // an EventsBuf not associated with any Capability
53 #ifdef THREADED_RTS
54 Mutex eventBufMutex; // protected by this mutex
55 #endif
56
57 char *EventDesc[] = {
58   [EVENT_CREATE_THREAD]       = "Create thread",
59   [EVENT_RUN_THREAD]          = "Run thread",
60   [EVENT_STOP_THREAD]         = "Stop thread",
61   [EVENT_THREAD_RUNNABLE]     = "Thread runnable",
62   [EVENT_MIGRATE_THREAD]      = "Migrate thread",
63   [EVENT_RUN_SPARK]           = "Run spark",
64   [EVENT_STEAL_SPARK]         = "Steal spark",
65   [EVENT_SHUTDOWN]            = "Shutdown",
66   [EVENT_THREAD_WAKEUP]       = "Wakeup thread",
67   [EVENT_GC_START]            = "Starting GC",
68   [EVENT_GC_END]              = "Finished GC",
69   [EVENT_REQUEST_SEQ_GC]      = "Request sequential GC",
70   [EVENT_REQUEST_PAR_GC]      = "Request parallel GC",
71   [EVENT_CREATE_SPARK_THREAD] = "Create spark thread",
72   [EVENT_LOG_MSG]             = "Log message",
73   [EVENT_USER_MSG]            = "User message",
74   [EVENT_STARTUP]             = "Startup",
75   [EVENT_GC_IDLE]             = "GC idle",
76   [EVENT_GC_WORK]             = "GC working",
77   [EVENT_GC_DONE]             = "GC done",
78   [EVENT_BLOCK_MARKER]        = "Block marker",
79   [EVENT_CAPSET_CREATE]       = "Create capability set",
80   [EVENT_CAPSET_DELETE]       = "Delete capability set",
81   [EVENT_CAPSET_ASSIGN_CAP]   = "Add capability to capability set",
82   [EVENT_CAPSET_REMOVE_CAP]   = "Remove capability from capability set"
83 };
84
85 // Event type. 
86
87 typedef struct _EventType {
88   EventTypeNum etNum;  // Event Type number.
89   nat   size;     // size of the payload in bytes
90   char *desc;     // Description
91 } EventType;
92
93 EventType eventTypes[NUM_EVENT_TAGS];
94
95 static void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno);
96 static void resetEventsBuf(EventsBuf* eb);
97 static void printAndClearEventBuf (EventsBuf *eventsBuf);
98
99 static void postEventType(EventsBuf *eb, EventType *et);
100
101 static void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap);
102
103 static void postBlockMarker(EventsBuf *eb);
104 static void closeBlockMarker(EventsBuf *ebuf);
105
106 static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum);
107 static StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes);
108
109 static inline void postWord8(EventsBuf *eb, StgWord8 i)
110 {
111     *(eb->pos++) = i; 
112 }
113
114 static inline void postWord16(EventsBuf *eb, StgWord16 i)
115 {
116     postWord8(eb, (StgWord8)(i >> 8));
117     postWord8(eb, (StgWord8)i);
118 }
119
120 static inline void postWord32(EventsBuf *eb, StgWord32 i)
121 {
122     postWord16(eb, (StgWord16)(i >> 16));
123     postWord16(eb, (StgWord16)i);
124 }
125
126 static inline void postWord64(EventsBuf *eb, StgWord64 i)
127 {
128     postWord32(eb, (StgWord32)(i >> 32));
129     postWord32(eb, (StgWord32)i);
130 }
131
132 static inline void postBuf(EventsBuf *eb, StgWord8 *buf, nat size)
133 {
134     memcpy(eb->pos, buf, size);
135     eb->pos += size;
136 }
137
138 static inline StgWord64 time_ns(void)
139 { return stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND); }
140
141 static inline void postEventTypeNum(EventsBuf *eb, EventTypeNum etNum)
142 { postWord16(eb, etNum); }
143
144 static inline void postTimestamp(EventsBuf *eb)
145 { postWord64(eb, time_ns()); }
146
147 static inline void postThreadID(EventsBuf *eb, EventThreadID id)
148 { postWord32(eb,id); }
149
150 static inline void postCapNo(EventsBuf *eb, EventCapNo no)
151 { postWord16(eb,no); }
152
153 static inline void postCapsetID(EventsBuf *eb, EventCapsetID id)
154 { postWord32(eb,id); }
155
156 static inline void postCapsetType(EventsBuf *eb, EventCapsetType type)
157 { postWord16(eb,type); }
158
159 static inline void postPayloadSize(EventsBuf *eb, EventPayloadSize size)
160 { postWord16(eb,size); }
161
162 static inline void postEventHeader(EventsBuf *eb, EventTypeNum type)
163 {
164     postEventTypeNum(eb, type);
165     postTimestamp(eb);
166 }    
167
168 static inline void postInt8(EventsBuf *eb, StgInt8 i)
169 { postWord8(eb, (StgWord8)i); }
170
171 static inline void postInt16(EventsBuf *eb, StgInt16 i)
172 { postWord16(eb, (StgWord16)i); }
173
174 static inline void postInt32(EventsBuf *eb, StgInt32 i)
175 { postWord32(eb, (StgWord32)i); }
176
177 static inline void postInt64(EventsBuf *eb, StgInt64 i)
178 { postWord64(eb, (StgWord64)i); }
179
180
181 void
182 initEventLogging(void)
183 {
184     StgWord8 t, c;
185     nat n_caps;
186
187     event_log_filename = stgMallocBytes(strlen(prog_name)
188                                         + 10 /* .%d */
189                                         + 10 /* .eventlog */,
190                                         "initEventLogging");
191
192     if (sizeof(EventDesc) / sizeof(char*) != NUM_EVENT_TAGS) {
193         barf("EventDesc array has the wrong number of elements");
194     }
195
196     if (event_log_pid == -1) { // #4512
197         // Single process
198         sprintf(event_log_filename, "%s.eventlog", prog_name);
199         event_log_pid = getpid();
200     } else {
201         // Forked process, eventlog already started by the parent
202         // before fork
203         event_log_pid = getpid();
204         sprintf(event_log_filename, "%s.%d.eventlog", prog_name, event_log_pid);
205     }
206
207     /* Open event log file for writing. */
208     if ((event_log_file = fopen(event_log_filename, "wb")) == NULL) {
209         sysErrorBelch("initEventLogging: can't open %s", event_log_filename);
210         stg_exit(EXIT_FAILURE);    
211     }
212
213     /* 
214      * Allocate buffer(s) to store events.
215      * Create buffer large enough for the header begin marker, all event
216      * types, and header end marker to prevent checking if buffer has room
217      * for each of these steps, and remove the need to flush the buffer to
218      * disk during initialization.
219      *
220      * Use a single buffer to store the header with event types, then flush 
221      * the buffer so all buffers are empty for writing events.
222      */
223 #ifdef THREADED_RTS
224     // XXX n_capabilities hasn't been initislised yet
225     n_caps = RtsFlags.ParFlags.nNodes;
226 #else
227     n_caps = 1;
228 #endif
229     capEventBuf = stgMallocBytes(n_caps * sizeof(EventsBuf),"initEventLogging");
230
231     for (c = 0; c < n_caps; ++c) {
232         // Init buffer for events.
233         initEventsBuf(&capEventBuf[c], EVENT_LOG_SIZE, c);
234     }
235     initEventsBuf(&eventBuf, EVENT_LOG_SIZE, (EventCapNo)(-1));
236
237     // Write in buffer: the header begin marker.
238     postInt32(&eventBuf, EVENT_HEADER_BEGIN);
239
240     // Mark beginning of event types in the header.
241     postInt32(&eventBuf, EVENT_HET_BEGIN);
242     for (t = 0; t < NUM_EVENT_TAGS; ++t) {
243
244         eventTypes[t].etNum = t;
245         eventTypes[t].desc = EventDesc[t];
246
247         switch (t) {
248         case EVENT_CREATE_THREAD:   // (cap, thread)
249         case EVENT_RUN_THREAD:      // (cap, thread)
250         case EVENT_THREAD_RUNNABLE: // (cap, thread)
251         case EVENT_RUN_SPARK:       // (cap, thread)
252         case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
253             eventTypes[t].size = sizeof(EventThreadID);
254             break;
255
256         case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
257         case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
258         case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
259             eventTypes[t].size =
260                 sizeof(EventThreadID) + sizeof(EventCapNo);
261             break;
262
263         case EVENT_STOP_THREAD:     // (cap, thread, status)
264             eventTypes[t].size =
265                 sizeof(EventThreadID) + sizeof(StgWord16) + sizeof(EventThreadID);
266             break;
267
268         case EVENT_STARTUP:         // (cap count)
269             eventTypes[t].size = sizeof(EventCapNo);
270             break;
271
272         case EVENT_CAPSET_CREATE:   // (capset, capset_type)
273             eventTypes[t].size =
274                 sizeof(EventCapsetID) + sizeof(EventCapsetType);
275             break;
276
277         case EVENT_CAPSET_DELETE:   // (capset)
278             eventTypes[t].size = sizeof(EventCapsetID);
279             break;
280
281         case EVENT_CAPSET_ASSIGN_CAP:  // (capset, cap)
282         case EVENT_CAPSET_REMOVE_CAP:
283             eventTypes[t].size =
284                 sizeof(EventCapsetID) + sizeof(EventCapNo);
285             break;
286
287         case EVENT_SHUTDOWN:        // (cap)
288         case EVENT_REQUEST_SEQ_GC:  // (cap)
289         case EVENT_REQUEST_PAR_GC:  // (cap)
290         case EVENT_GC_START:        // (cap)
291         case EVENT_GC_END:          // (cap)
292         case EVENT_GC_IDLE:
293         case EVENT_GC_WORK:
294         case EVENT_GC_DONE:
295             eventTypes[t].size = 0;
296             break;
297
298         case EVENT_LOG_MSG:          // (msg)
299         case EVENT_USER_MSG:         // (msg)
300             eventTypes[t].size = 0xffff;
301             break;
302
303         case EVENT_BLOCK_MARKER:
304             eventTypes[t].size = sizeof(StgWord32) + sizeof(EventTimestamp) + 
305                 sizeof(EventCapNo);
306             break;
307
308         default:
309             continue; /* ignore deprecated events */
310         }
311
312         // Write in buffer: the start event type.
313         postEventType(&eventBuf, &eventTypes[t]);
314     }
315
316     // Mark end of event types in the header.
317     postInt32(&eventBuf, EVENT_HET_END);
318     
319     // Write in buffer: the header end marker.
320     postInt32(&eventBuf, EVENT_HEADER_END);
321     
322     // Prepare event buffer for events (data).
323     postInt32(&eventBuf, EVENT_DATA_BEGIN);
324
325     // Flush capEventBuf with header.
326     /*
327      * Flush header and data begin marker to the file, thus preparing the
328      * file to have events written to it.
329      */
330     printAndClearEventBuf(&eventBuf);
331
332     for (c = 0; c < n_caps; ++c) {
333         postBlockMarker(&capEventBuf[c]);
334     }
335
336 #ifdef THREADED_RTS
337     initMutex(&eventBufMutex);
338 #endif
339 }
340
341 void
342 endEventLogging(void)
343 {
344     nat c;
345
346     // Flush all events remaining in the buffers.
347     for (c = 0; c < n_capabilities; ++c) {
348         printAndClearEventBuf(&capEventBuf[c]);
349     }
350     printAndClearEventBuf(&eventBuf);
351     resetEventsBuf(&eventBuf); // we don't want the block marker
352
353     // Mark end of events (data).
354     postEventTypeNum(&eventBuf, EVENT_DATA_END);
355
356     // Flush the end of data marker.
357     printAndClearEventBuf(&eventBuf);
358
359     if (event_log_file != NULL) {
360         fclose(event_log_file);
361     }
362 }
363
364 void 
365 freeEventLogging(void)
366 {
367     StgWord8 c;
368     
369     // Free events buffer.
370     for (c = 0; c < n_capabilities; ++c) {
371         if (capEventBuf[c].begin != NULL) 
372             stgFree(capEventBuf[c].begin);
373     }
374     if (capEventBuf != NULL)  {
375         stgFree(capEventBuf);
376     }
377     if (event_log_filename != NULL) {
378         stgFree(event_log_filename);
379     }
380 }
381
382 void 
383 flushEventLog(void)
384 {
385     if (event_log_file != NULL) {
386         fflush(event_log_file);
387     }
388 }
389
390 void 
391 abortEventLogging(void)
392 {
393     freeEventLogging();
394     if (event_log_file != NULL) {
395         fclose(event_log_file);
396     }
397 }
398 /*
399  * Post an event message to the capability's eventlog buffer.
400  * If the buffer is full, prints out the buffer and clears it.
401  */
402 void
403 postSchedEvent (Capability *cap, 
404                 EventTypeNum tag, 
405                 StgThreadID thread, 
406                 StgWord info1,
407                 StgWord info2)
408 {
409     EventsBuf *eb;
410
411     eb = &capEventBuf[cap->no];
412
413     if (!hasRoomForEvent(eb, tag)) {
414         // Flush event buffer to make room for new event.
415         printAndClearEventBuf(eb);
416     }
417     
418     postEventHeader(eb, tag);
419
420     switch (tag) {
421     case EVENT_CREATE_THREAD:   // (cap, thread)
422     case EVENT_RUN_THREAD:      // (cap, thread)
423     case EVENT_THREAD_RUNNABLE: // (cap, thread)
424     case EVENT_RUN_SPARK:       // (cap, thread)
425     {
426         postThreadID(eb,thread);
427         break;
428     }
429
430     case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
431     {
432         postThreadID(eb,info1 /* spark_thread */);
433         break;
434     }
435
436     case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
437     case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
438     case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
439     {
440         postThreadID(eb,thread);
441         postCapNo(eb,info1 /* new_cap | victim_cap | other_cap */);
442         break;
443    }
444
445     case EVENT_STOP_THREAD:     // (cap, thread, status)
446     {
447         postThreadID(eb,thread);
448         postWord16(eb,info1 /* status */);
449         postThreadID(eb,info2 /* blocked on thread */);
450         break;
451     }
452
453     case EVENT_SHUTDOWN:        // (cap)
454     case EVENT_REQUEST_SEQ_GC:  // (cap)
455     case EVENT_REQUEST_PAR_GC:  // (cap)
456     case EVENT_GC_START:        // (cap)
457     case EVENT_GC_END:          // (cap)
458     {
459         break;
460     }
461
462     default:
463         barf("postEvent: unknown event tag %d", tag);
464     }
465 }
466
467 void postCapsetModifyEvent (EventTypeNum tag,
468                             EventCapsetID capset,
469                             StgWord32 other)
470 {
471     ACQUIRE_LOCK(&eventBufMutex);
472
473     if (!hasRoomForEvent(&eventBuf, tag)) {
474         // Flush event buffer to make room for new event.
475         printAndClearEventBuf(&eventBuf);
476     }
477
478     postEventHeader(&eventBuf, tag);
479     postCapsetID(&eventBuf, capset);
480
481     switch (tag) {
482     case EVENT_CAPSET_CREATE:   // (capset, capset_type)
483     {
484         postCapsetType(&eventBuf, other /* capset_type */);
485         break;
486     }
487
488     case EVENT_CAPSET_DELETE:   // (capset)
489     {
490         break;
491     }
492
493     case EVENT_CAPSET_ASSIGN_CAP:  // (capset, capno)
494     case EVENT_CAPSET_REMOVE_CAP:  // (capset, capno)
495     {
496         postCapNo(&eventBuf, other /* capno */);
497         break;
498     }
499     default:
500         barf("postCapsetModifyEvent: unknown event tag %d", tag);
501     }
502
503     RELEASE_LOCK(&eventBufMutex);
504 }
505
506 void
507 postEvent (Capability *cap, EventTypeNum tag)
508 {
509     EventsBuf *eb;
510
511     eb = &capEventBuf[cap->no];
512
513     if (!hasRoomForEvent(eb, tag)) {
514         // Flush event buffer to make room for new event.
515         printAndClearEventBuf(eb);
516     }
517
518     postEventHeader(eb, tag);
519 }
520
521 #define BUF 512
522
523 void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap)
524 {
525     char buf[BUF];
526     nat size;
527
528     size = vsnprintf(buf,BUF,msg,ap);
529     if (size > BUF) {
530         buf[BUF-1] = '\0';
531         size = BUF;
532     }
533
534     if (!hasRoomForVariableEvent(eb, size)) {
535         // Flush event buffer to make room for new event.
536         printAndClearEventBuf(eb);
537     }
538
539     postEventHeader(eb, type);
540     postPayloadSize(eb, size);
541     postBuf(eb,(StgWord8*)buf,size);
542 }
543
544 void postMsg(char *msg, va_list ap)
545 {
546     ACQUIRE_LOCK(&eventBufMutex);
547     postLogMsg(&eventBuf, EVENT_LOG_MSG, msg, ap);
548     RELEASE_LOCK(&eventBufMutex);
549 }
550
551 void postCapMsg(Capability *cap, char *msg, va_list ap)
552 {
553     postLogMsg(&capEventBuf[cap->no], EVENT_LOG_MSG, msg, ap);
554 }
555
556 void postUserMsg(Capability *cap, char *msg, va_list ap)
557 {
558     postLogMsg(&capEventBuf[cap->no], EVENT_USER_MSG, msg, ap);
559 }    
560
561 void postEventStartup(EventCapNo n_caps)
562 {
563     ACQUIRE_LOCK(&eventBufMutex);
564
565     if (!hasRoomForEvent(&eventBuf, EVENT_STARTUP)) {
566         // Flush event buffer to make room for new event.
567         printAndClearEventBuf(&eventBuf);
568     }
569
570     // Post a STARTUP event with the number of capabilities
571     postEventHeader(&eventBuf, EVENT_STARTUP);
572     postCapNo(&eventBuf, n_caps);
573
574     RELEASE_LOCK(&eventBufMutex);
575 }
576
577 void closeBlockMarker (EventsBuf *ebuf)
578 {
579     StgInt8* save_pos;
580
581     if (ebuf->marker)
582     {
583         // (type:16, time:64, size:32, end_time:64)
584
585         save_pos = ebuf->pos;
586         ebuf->pos = ebuf->marker + sizeof(EventTypeNum) +
587                     sizeof(EventTimestamp);
588         postWord32(ebuf, save_pos - ebuf->marker);
589         postTimestamp(ebuf);
590         ebuf->pos = save_pos;
591         ebuf->marker = NULL;
592     }
593 }
594
595
596 void postBlockMarker (EventsBuf *eb)
597 {
598     if (!hasRoomForEvent(eb, EVENT_BLOCK_MARKER)) {
599         printAndClearEventBuf(eb);
600     }
601
602     closeBlockMarker(eb);
603
604     eb->marker = eb->pos;
605     postEventHeader(eb, EVENT_BLOCK_MARKER);
606     postWord32(eb,0); // these get filled in later by closeBlockMarker();
607     postWord64(eb,0);
608     postCapNo(eb, eb->capno);
609 }
610
611 void printAndClearEventBuf (EventsBuf *ebuf)
612 {
613     StgWord64 numBytes = 0, written = 0;
614
615     closeBlockMarker(ebuf);
616
617     if (ebuf->begin != NULL && ebuf->pos != ebuf->begin)
618     {
619         numBytes = ebuf->pos - ebuf->begin;
620         
621         written = fwrite(ebuf->begin, 1, numBytes, event_log_file);
622         if (written != numBytes) {
623             debugBelch(
624                 "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64
625                 " doesn't match numBytes=%" FMT_Word64, written, numBytes);
626             return;
627         }
628         
629         resetEventsBuf(ebuf);
630         flushCount++;
631
632         postBlockMarker(ebuf);
633     }
634 }
635
636 void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno)
637 {
638     eb->begin = eb->pos = stgMallocBytes(size, "initEventsBuf");
639     eb->size = size;
640     eb->marker = NULL;
641     eb->capno = capno;
642 }
643
644 void resetEventsBuf(EventsBuf* eb)
645 {
646     eb->pos = eb->begin;
647     eb->marker = NULL;
648 }
649
650 StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
651 {
652   nat size;
653
654   size = sizeof(EventTypeNum) + sizeof(EventTimestamp) + eventTypes[eNum].size;
655
656   if (eb->pos + size > eb->begin + eb->size) {
657       return 0; // Not enough space.
658   } else  {
659       return 1; // Buf has enough space for the event.
660   }
661 }
662
663 StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes)
664 {
665   nat size;
666
667   size = sizeof(EventTypeNum) + sizeof(EventTimestamp) +
668       sizeof(EventPayloadSize) + payload_bytes;
669
670   if (eb->pos + size > eb->begin + eb->size) {
671       return 0; // Not enough space.
672   } else  {
673       return 1; // Buf has enough space for the event.
674   }
675 }    
676
677 void postEventType(EventsBuf *eb, EventType *et)
678 {
679     StgWord8 d;
680     nat desclen;
681
682     postInt32(eb, EVENT_ET_BEGIN);
683     postEventTypeNum(eb, et->etNum);
684     postWord16(eb, (StgWord16)et->size);
685     desclen = strlen(et->desc);
686     postWord32(eb, desclen);
687     for (d = 0; d < desclen; ++d) {
688         postInt8(eb, (StgInt8)et->desc[d]);
689     }
690     postWord32(eb, 0); // no extensions yet
691     postInt32(eb, EVENT_ET_END);
692 }
693
694 #endif /* TRACING */