Skip to content

Commit

Permalink
Add fast event logging
Browse files Browse the repository at this point in the history
Generate binary log files from the RTS containing a log of runtime
events with timestamps.  The log file can be visualised in various
ways, for investigating runtime behaviour and debugging performance
problems.  See for example the forthcoming ThreadScope viewer.

New GHC option:

  -eventlog   (link-time option) Enables event logging.

  +RTS -l     (runtime option) Generates <prog>.eventlog with
              the binary event information.

This replaces some of the tracing machinery we already had in the RTS:
e.g. +RTS -vg  for GC tracing (we should do this using the new event
logging instead).

Event logging has almost no runtime cost when it isn't enabled, though
in the future we might add more fine-grained events and this might
change; hence having a link-time option and compiling a separate
version of the RTS for event logging.  There's a small runtime cost
for enabling event-logging, for most programs it shouldn't make much
difference.

(Todo: docs)
  • Loading branch information
simonmar committed Mar 17, 2009
1 parent f8f4cb3 commit 8b18fae
Show file tree
Hide file tree
Showing 20 changed files with 809 additions and 119 deletions.
1 change: 1 addition & 0 deletions compiler/main/StaticFlagParser.hs
Original file line number Diff line number Diff line change
Expand Up @@ -106,6 +106,7 @@ static_flags = [

------- ways --------------------------------------------------------
, Flag "prof" (NoArg (addWay WayProf)) Supported
, Flag "eventlog" (NoArg (addWay WayEventLog)) Supported
, Flag "ticky" (NoArg (addWay WayTicky)) Supported
, Flag "parallel" (NoArg (addWay WayPar)) Supported
, Flag "gransim" (NoArg (addWay WayGran)) Supported
Expand Down
6 changes: 6 additions & 0 deletions compiler/main/StaticFlags.hs
Original file line number Diff line number Diff line change
Expand Up @@ -320,6 +320,7 @@ data WayName
= WayThreaded
| WayDebug
| WayProf
| WayEventLog
| WayTicky
| WayPar
| WayGran
Expand Down Expand Up @@ -359,6 +360,7 @@ allowed_combination way = and [ x `allowedWith` y

WayProf `allowedWith` WayNDP = True
WayThreaded `allowedWith` WayProf = True
WayThreaded `allowedWith` WayEventLog = True
_ `allowedWith` _ = False


Expand Down Expand Up @@ -425,6 +427,10 @@ way_details =
, "-DPROFILING"
, "-optc-DPROFILING" ]),

(WayEventLog, Way "l" True "RTS Event Logging"
[ "-DEVENTLOG"
, "-optc-DEVENTLOG" ]),

(WayTicky, Way "t" True "Ticky-ticky Profiling"
[ "-DTICKY_TICKY"
, "-optc-DTICKY_TICKY" ]),
Expand Down
135 changes: 135 additions & 0 deletions includes/EventLogFormat.h
Original file line number Diff line number Diff line change
@@ -0,0 +1,135 @@
/* -----------------------------------------------------------------------------
*
* (c) The GHC Team, 2008-2009
*
* Event log format
*
* The log format is designed to be extensible: old tools should be
* able to parse (but not necessarily understand all of) new versions
* of the format, and new tools will be able to understand old log
* files.
*
* Each event has a specific format. If you add new events, give them
* new numbers: we never re-use old event numbers.
*
* - The format is endian-independent: all values are represented in
* bigendian order.
*
* - The format is extensible:
*
* - The header describes each event type and its length. Tools
* that don't recognise a particular event type can skip those events.
*
* - There is room for extra information in the event type
* specification, which can be ignored by older tools.
*
* - Events can have extra information added, but existing fields
* cannot be changed. Tools should ignore extra fields at the
* end of the event record.
*
* - Old event type ids are never re-used; just take a new identifier.
*
*
* The format
* ----------
*
* log : EVENT_HEADER_BEGIN
* EventType*
* EVENT_HEADER_END
* EVENT_DATA_BEGIN
* Event*
* EVENT_DATA_END
*
* EventType :
* EVENT_ET_BEGIN
* Word16 -- unique identifier for this event
* Int16 -- >=0 size of the event in bytes (minus the header)
* -- -1 variable size
* Word32 -- length of the next field in bytes
* Word8* -- string describing the event
* Word32 -- length of the next field in bytes
* Word8* -- extra info (for future extensions)
* EVENT_ET_END
*
* Event :
* Word16 -- event_type
* Word64 -- time (nanosecs)
* [Word16] -- length of the rest (for variable-sized events only)
* ... extra event-specific info ...
*
*
* To add a new event
* ------------------
*
* - In this file:
* - give it a new number, add a new #define EVENT_XXX below
* - In EventLog.c
* - add it to the EventDesc array
* - emit the event type in initEventLogging()
* - emit the new event in postEvent_()
* - generate the event itself by calling postEvent() somewhere
* - In the Haskell code to parse the event log file:
* - add types and code to read the new event
*
* -------------------------------------------------------------------------- */

/*
* Markers for begin/end of the Header.
*/
#define EVENT_HEADER_BEGIN 0x68647262 /* 'h' 'd' 'r' 'b' */
#define EVENT_HEADER_END 0x68647265 /* 'h' 'd' 'r' 'e' */

#define EVENT_DATA_BEGIN 0x64617462 /* 'd' 'a' 't' 'b' */
#define EVENT_DATA_END 0xffff

/*
* Markers for begin/end of the list of Event Types in the Header.
* Header, Event Type, Begin = hetb
* Header, Event Type, End = hete
*/
#define EVENT_HET_BEGIN 0x68657462 /* 'h' 'e' 't' 'b' */
#define EVENT_HET_END 0x68657465 /* 'h' 'e' 't' 'e' */

#define EVENT_ET_BEGIN 0x65746200 /* 'e' 't' 'b' 0 */
#define EVENT_ET_END 0x65746500 /* 'e' 't' 'e' 0 */

/*
* Types of event
*/
#define EVENT_CREATE_THREAD 0 /* (cap, thread) */
#define EVENT_RUN_THREAD 1 /* (cap, thread) */
#define EVENT_STOP_THREAD 2 /* (cap, thread, status) */
#define EVENT_THREAD_RUNNABLE 3 /* (cap, thread) */
#define EVENT_MIGRATE_THREAD 4 /* (cap, thread, new_cap) */
#define EVENT_RUN_SPARK 5 /* (cap, thread) */
#define EVENT_STEAL_SPARK 6 /* (cap, thread, victim_cap) */
#define EVENT_SHUTDOWN 7 /* (cap) */
#define EVENT_THREAD_WAKEUP 8 /* (cap, thread, other_cap) */
#define EVENT_GC_START 9 /* (cap) */
#define EVENT_GC_END 10 /* (cap) */
#define EVENT_REQUEST_SEQ_GC 11 /* (cap) */
#define EVENT_REQUEST_PAR_GC 12 /* (cap) */

#define NUM_EVENT_TAGS 13

/*
* Status values for EVENT_STOP_THREAD
*
* 1-5 are the StgRun return values (from includes/Constants.h):
*
* #define HeapOverflow 1
* #define StackOverflow 2
* #define ThreadYielding 3
* #define ThreadBlocked 4
* #define ThreadFinished 5
*/
#define THREAD_SUSPENDED_FOREIGN_CALL 6

#ifndef EVENTLOG_CONSTANTS_ONLY

typedef StgWord16 EventTypeNum;
typedef StgWord64 Timestamp; // in nanoseconds
typedef StgWord64 ThreadID;
typedef StgWord16 CapabilityNum;

#endif
18 changes: 11 additions & 7 deletions includes/RtsFlags.h
Original file line number Diff line number Diff line change
Expand Up @@ -60,13 +60,15 @@ struct DEBUG_FLAGS {
rtsBool sanity; /* 'S' warning: might be expensive! */
rtsBool stable; /* 't' */
rtsBool prof; /* 'p' */
rtsBool eventlog; /* 'e' */
rtsBool gran; /* 'r' */
rtsBool par; /* 'P' */
rtsBool linker; /* 'l' the object linker */
rtsBool apply; /* 'a' */
rtsBool stm; /* 'm' */
rtsBool squeeze; /* 'z' stack squeezing & lazy blackholing */
rtsBool hpc; /* 'c' coverage */
rtsBool timestamp; /* add timestamps to traces */
};

struct COST_CENTRE_FLAGS {
Expand Down Expand Up @@ -113,6 +115,12 @@ struct PROFILING_FLAGS {

};

#ifdef EVENTLOG
struct EVENTLOG_FLAGS {
rtsBool doEventLogging;
};
#endif

struct CONCURRENT_FLAGS {
int ctxtSwitchTime; /* in milliseconds */
int ctxtSwitchTicks; /* derived */
Expand Down Expand Up @@ -307,12 +315,6 @@ struct TICKY_FLAGS {
FILE *tickyFile;
};

struct TRACE_FLAGS {
rtsBool sched; /* trace scheduler events for profiling */
rtsBool gc; /* trace GC events */
rtsBool timestamp; /* add timestamps to traces */
};

#ifdef USE_PAPI
#define MAX_PAPI_USER_EVENTS 8

Expand Down Expand Up @@ -341,8 +343,10 @@ typedef struct _RTS_FLAGS {
struct DEBUG_FLAGS DebugFlags;
struct COST_CENTRE_FLAGS CcFlags;
struct PROFILING_FLAGS ProfFlags;
#ifdef EVENTLOG
struct EVENTLOG_FLAGS EventLogFlags;
#endif
struct TICKY_FLAGS TickyFlags;
struct TRACE_FLAGS TraceFlags;

#if defined(THREADED_RTS) || defined(PAR)
struct PAR_FLAGS ParFlags;
Expand Down
20 changes: 18 additions & 2 deletions mk/config.mk.in
Original file line number Diff line number Diff line change
Expand Up @@ -385,8 +385,11 @@ endif
# thr_debug_p : debugging threaded profiled
# t : ticky-ticky profiling
# debug_t : debugging ticky-ticky profiling
# l : event logging
# thr_l : threaded and event logging
# thr_debug_l : threaded and debugging and event logging
#
GhcRTSWays=
GhcRTSWays=l

# Usually want the debug version
ifeq "$(BootingFromHc)" "NO"
Expand All @@ -400,7 +403,8 @@ endif
# Want the threaded versions unless we're unregisterised
# Defer the check until later by using $(if..), because GhcUnregisterised might
# be set in build.mk, which hasn't been read yet.
GhcRTSWays += $(if $(findstring NO, $(GhcUnregisterised)),thr thr_p thr_debug,)
GhcRTSWays += $(if $(findstring NO, $(GhcUnregisterised)),thr thr_debug thr_l,)
GhcRTSWays += $(if $(findstring p, $(GhcLibWays)),thr_p,)

# We can only build GHCi threaded if we have a threaded RTS:
GhcThreaded = $(if $(findstring thr,$(GhcRTSWays)),YES,NO)
Expand Down Expand Up @@ -1248,6 +1252,10 @@ WAY_p_HC_OPTS= -prof
WAY_t_NAME=ticky-ticky profiling
WAY_t_HC_OPTS= -ticky

# Way 'l':
WAY_l_NAME=event logging
WAY_l_HC_OPTS= -eventlog

# Way `mp':
WAY_mp_NAME=parallel
WAY_mp_HC_OPTS=-parallel
Expand All @@ -1268,6 +1276,10 @@ WAY_thr_HC_OPTS=-optc-DTHREADED_RTS
WAY_thr_p_NAME=threaded profiled
WAY_thr_p_HC_OPTS=-optc-DTHREADED_RTS -prof

# Way 'thr_l':
WAY_thr_l_NAME=threaded event logging
WAY_thr_l_HC_OPTS=-optc-DTHREADED_RTS -eventlog

# Way 'debug':
WAY_debug_NAME=debug
WAY_debug_HC_OPTS=-optc-DDEBUG
Expand All @@ -1288,6 +1300,10 @@ WAY_thr_debug_HC_OPTS=-optc-DTHREADED_RTS -optc-DDEBUG
WAY_thr_debug_p_NAME=threaded debug profiling
WAY_thr_debug_p_HC_OPTS=-optc-DTHREADED_RTS -optc-DDEBUG -prof

# Way 'thr_debug_l':
WAY_thr_debug_l_NAME=threaded debug event logging
WAY_thr_debug_l_HC_OPTS=-optc-DTHREADED_RTS -optc-DDEBUG -eventlog

# Way 'dyn': build dynamic shared libraries
WAY_dyn_NAME=dyn
WAY_dyn_HC_OPTS=-fPIC -dynamic
Expand Down
20 changes: 10 additions & 10 deletions rts/Capability.c
Original file line number Diff line number Diff line change
Expand Up @@ -320,10 +320,9 @@ giveCapabilityToTask (Capability *cap USED_IF_DEBUG, Task *task)
{
ASSERT_LOCK_HELD(&cap->lock);
ASSERT(task->cap == cap);
trace(TRACE_sched | DEBUG_sched,
"passing capability %d to %s %p",
cap->no, task->tso ? "bound task" : "worker",
(void *)task->id);
debugTrace(DEBUG_sched, "passing capability %d to %s %p",
cap->no, task->tso ? "bound task" : "worker",
(void *)task->id);
ACQUIRE_LOCK(&task->lock);
task->wakeup = rtsTrue;
// the wakeup flag is needed because signalCondition() doesn't
Expand Down Expand Up @@ -365,8 +364,7 @@ releaseCapability_ (Capability* cap,

if (waiting_for_gc == PENDING_GC_SEQ) {
last_free_capability = cap; // needed?
trace(TRACE_sched | DEBUG_sched,
"GC pending, set capability %d free", cap->no);
debugTrace(DEBUG_sched, "GC pending, set capability %d free", cap->no);
return;
}

Expand Down Expand Up @@ -407,7 +405,7 @@ releaseCapability_ (Capability* cap,
}

last_free_capability = cap;
trace(TRACE_sched | DEBUG_sched, "freeing capability %d", cap->no);
debugTrace(DEBUG_sched, "freeing capability %d", cap->no);
}

void
Expand Down Expand Up @@ -542,7 +540,7 @@ waitForReturnCapability (Capability **pCap, Task *task)

ASSERT_FULL_CAPABILITY_INVARIANTS(cap,task);

trace(TRACE_sched | DEBUG_sched, "resuming capability %d", cap->no);
debugTrace(DEBUG_sched, "resuming capability %d", cap->no);

*pCap = cap;
#endif
Expand All @@ -560,7 +558,9 @@ yieldCapability (Capability** pCap, Task *task)

if (waiting_for_gc == PENDING_GC_PAR) {
debugTrace(DEBUG_sched, "capability %d: becoming a GC thread", cap->no);
postEvent(cap, EVENT_GC_START, 0, 0);
gcWorkerThread(cap);
postEvent(cap, EVENT_GC_END, 0, 0);
return;
}

Expand Down Expand Up @@ -606,7 +606,7 @@ yieldCapability (Capability** pCap, Task *task)
break;
}

trace(TRACE_sched | DEBUG_sched, "resuming capability %d", cap->no);
debugTrace(DEBUG_sched, "resuming capability %d", cap->no);
ASSERT(cap->running_task == task);

*pCap = cap;
Expand Down Expand Up @@ -648,7 +648,6 @@ wakeupThreadOnCapability (Capability *my_cap,

appendToRunQueue(other_cap,tso);

trace(TRACE_sched, "resuming capability %d", other_cap->no);
releaseCapability_(other_cap,rtsFalse);
} else {
appendToWakeupQueue(my_cap,other_cap,tso);
Expand Down Expand Up @@ -768,6 +767,7 @@ shutdownCapability (Capability *cap, Task *task, rtsBool safe)
continue;
}

postEvent(cap, EVENT_SHUTDOWN, 0, 0);
debugTrace(DEBUG_sched, "capability %d is stopped.", cap->no);
RELEASE_LOCK(&cap->lock);
break;
Expand Down
7 changes: 4 additions & 3 deletions rts/Makefile
Original file line number Diff line number Diff line change
Expand Up @@ -57,7 +57,7 @@ override HADDOCK_DOCS = NO
NON_HS_PACKAGE = YES

# grab sources from these subdirectories
ALL_DIRS = hooks parallel sm
ALL_DIRS = hooks parallel sm eventlog

ifeq "$(HOSTPLATFORM)" "i386-unknown-mingw32"
ALL_DIRS += win32
Expand Down Expand Up @@ -137,7 +137,8 @@ WARNING_OPTS += -Waggregate-return
#WARNING_OPTS += -Wredundant-decls
#WARNING_OPTS += -Wconversion

STANDARD_OPTS += -I../includes -I. -Iparallel -Ism
STANDARD_OPTS += -I../includes -I. -Iparallel -Ism -Ieventlog

# COMPILING_RTS is only used when building Win32 DLL support.
STANDARD_OPTS += -DCOMPILING_RTS

Expand Down Expand Up @@ -322,7 +323,7 @@ SRC_MKDEPENDC_OPTS += -I. -I../includes
# a superset of the dependencies. To do this properly, we should generate
# a different set of dependencies for each way. Further hack: PROFILING and
# TICKY_TICKY can't be used together, so we omit TICKY_TICKY for now.
SRC_MKDEPENDC_OPTS += -DPROFILING -DTHREADED_RTS -DDEBUG
SRC_MKDEPENDC_OPTS += -DPROFILING -DTHREADED_RTS -DDEBUG -DEVENTLOG

# -----------------------------------------------------------------------------
# The auto-generated apply code
Expand Down
1 change: 1 addition & 0 deletions rts/RaiseAsync.c
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@
#include "STM.h"
#include "Sanity.h"
#include "Profiling.h"
#include "EventLog.h"
#if defined(mingw32_HOST_OS)
#include "win32/IOManager.h"
#endif
Expand Down
Loading

0 comments on commit 8b18fae

Please sign in to comment.