Commit 4856d15a authored by Duncan Coutts's avatar Duncan Coutts

Add new eventlog EVENT_WALL_CLOCK_TIME for time matching

Eventlog timestamps are elapsed times (in nanoseconds) relative to the
process start. To be able to merge eventlogs from multiple processes we
need to be able to align their timelines. If they share a clock domain
(or a user judges that their clocks are sufficiently closely
synchronised) then it is sufficient to know how the eventlog timestamps
match up with the clock.

The EVENT_WALL_CLOCK_TIME contains the clock time with (up to)
nanosecond precision. It is otherwise an ordinary event and so contains
the usual timestamp for the same moment in time. It therefore enables
us to match up all the eventlog timestamps with clock time.
parent ece21ea0
......@@ -141,9 +141,10 @@
#define EVENT_SPARK_FIZZLE 40 /* () */
#define EVENT_SPARK_GC 41 /* () */
#define EVENT_INTERN_STRING 42 /* (string, id) {not used by ghc} */
#define EVENT_WALL_CLOCK_TIME 43 /* (capset, unix_epoch_seconds, nanoseconds) */
/* Range 43 - 59 is available for new GHC and common events */
/* Range 44 - 59 is available for new GHC and common events */
/* Range 60 - 80 is used by eden for parallel tracing
* see http://www.mathematik.uni-marburg.de/~eden/
......@@ -156,7 +157,7 @@
* ranges higher than this are reserved but not currently emitted by ghc.
* This must match the size of the EventDesc[] array in EventLog.c
*/
#define NUM_GHC_EVENT_TAGS 42
#define NUM_GHC_EVENT_TAGS 44
#if 0 /* DEPRECATED EVENTS: */
/* we don't actually need to record the thread, it's implicit */
......
......@@ -328,6 +328,12 @@ void traceCapsetEvent_ (EventTypeNum tag,
}
}
void traceWallClockTime_(void) {
if (eventlog_enabled) {
postWallClockTime(CAPSET_CLOCKDOMAIN_DEFAULT);
}
}
void traceOSProcessInfo_(void) {
if (eventlog_enabled) {
postCapsetEvent(EVENT_OSPROCESS_PID,
......
......@@ -37,6 +37,7 @@ enum CapsetType { CapsetTypeCustom = CAPSET_TYPE_CUSTOM,
CapsetTypeOsProcess = CAPSET_TYPE_OSPROCESS,
CapsetTypeClockdomain = CAPSET_TYPE_CLOCKDOMAIN };
#define CAPSET_OSPROCESS_DEFAULT 0
#define CAPSET_CLOCKDOMAIN_DEFAULT 1
// -----------------------------------------------------------------------------
// Message classes
......@@ -199,6 +200,8 @@ void traceCapsetEvent_ (EventTypeNum tag,
CapsetID capset,
StgWord info);
void traceWallClockTime_(void);
void traceOSProcessInfo_ (void);
void traceSparkCounters_ (Capability *cap,
......@@ -219,6 +222,7 @@ void traceSparkCounters_ (Capability *cap,
#define traceThreadStatus(class, tso) /* nothing */
INLINE_HEADER void traceEventStartup_ (int n_caps STG_UNUSED) {};
#define traceCapsetEvent_(tag, capset, info) /* nothing */
#define traceWallClockTime_() /* nothing */
#define traceOSProcessInfo_() /* nothing */
#define traceSparkCounters_(cap, counters, remaining) /* nothing */
......@@ -492,6 +496,12 @@ INLINE_HEADER void traceCapsetRemoveCap(CapsetID capset STG_UNUSED,
dtraceCapsetRemoveCap(capset, capno);
}
INLINE_HEADER void traceWallClockTime(void)
{
traceWallClockTime_();
/* Note: no DTrace equivalent because it is available to DTrace directly */
}
INLINE_HEADER void traceOSProcessInfo(void)
{
traceOSProcessInfo_();
......
......@@ -83,6 +83,7 @@ char *EventDesc[] = {
[EVENT_PROGRAM_ENV] = "Program environment variables",
[EVENT_OSPROCESS_PID] = "Process ID",
[EVENT_OSPROCESS_PPID] = "Parent process ID",
[EVENT_WALL_CLOCK_TIME] = "Wall clock time",
[EVENT_SPARK_COUNTERS] = "Spark counters",
[EVENT_SPARK_CREATE] = "Spark create",
[EVENT_SPARK_DUD] = "Spark dud",
......@@ -299,6 +300,11 @@ initEventLogging(void)
sizeof(EventCapsetID) + sizeof(StgWord32);
break;
case EVENT_WALL_CLOCK_TIME: // (capset, unix_epoch_seconds, nanoseconds)
eventTypes[t].size =
sizeof(EventCapsetID) + sizeof(StgWord64) + sizeof(StgWord32);
break;
case EVENT_SPARK_STEAL: // (cap, victim_cap)
eventTypes[t].size =
sizeof(EventCapNo);
......@@ -668,6 +674,52 @@ void postCapsetVecEvent (EventTypeNum tag,
RELEASE_LOCK(&eventBufMutex);
}
void postWallClockTime (EventCapsetID capset)
{
StgWord64 ts;
StgWord64 sec;
StgWord32 nsec;
ACQUIRE_LOCK(&eventBufMutex);
/* The EVENT_WALL_CLOCK_TIME event is intended to allow programs
reading the eventlog to match up the event timestamps with wall
clock time. The normal event timestamps measure time since the
start of the program. To align eventlogs from concurrent
processes we need to be able to match up the timestamps. One way
to do this is if we know how the timestamps and wall clock time
match up (and of course if both processes have sufficiently
synchronised clocks).
So we want to make sure that the timestamp that we generate for
this event matches up very closely with the wall clock time.
Unfortunately we currently have to use two different APIs to get
the elapsed time vs the wall clock time. So to minimise the
difference we just call them very close together.
*/
getUnixEpochTime(&sec, &nsec); /* Get the wall clock time */
ts = time_ns(); /* Get the eventlog timestamp */
if (!hasRoomForEvent(&eventBuf, EVENT_WALL_CLOCK_TIME)) {
// Flush event buffer to make room for new event.
printAndClearEventBuf(&eventBuf);
}
/* Normally we'd call postEventHeader(), but that generates its own
timestamp, so we go one level lower so we can write out the
timestamp we already generated above. */
postEventTypeNum(&eventBuf, EVENT_WALL_CLOCK_TIME);
postWord64(&eventBuf, ts);
/* EVENT_WALL_CLOCK_TIME (capset, unix_epoch_seconds, nanoseconds) */
postCapsetID(&eventBuf, capset);
postWord64(&eventBuf, sec);
postWord32(&eventBuf, nsec);
RELEASE_LOCK(&eventBufMutex);
}
void
postEvent (Capability *cap, EventTypeNum tag)
{
......
......@@ -69,6 +69,8 @@ void postCapsetVecEvent (EventTypeNum tag,
int argc,
char *msg[]);
void postWallClockTime (EventCapsetID capset);
/*
* Post a `par` spark event
*/
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment