diff --git a/CHANGELOG.md b/CHANGELOG.md --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,8 @@ # Change Log -## Unreleased +## 0.7.0 - 2017-10-04 + +* Add support for heap profiling events ([#29](https://github.com/haskell/ghc-events/pull/29)) ## 0.6.0 - 2017-05-31 diff --git a/ghc-events.cabal b/ghc-events.cabal --- a/ghc-events.cabal +++ b/ghc-events.cabal @@ -1,5 +1,5 @@ name: ghc-events -version: 0.6.0 +version: 0.7.0 synopsis: Library and tool for parsing .eventlog files from GHC description: Parses .eventlog files emitted by GHC 6.12.1 and later. Includes the ghc-events tool permitting, in particular, @@ -21,7 +21,7 @@ bug-reports: https://github.com/haskell/ghc-events/issues build-type: Simple tested-with: GHC == 7.6.1, GHC == 7.6.3, GHC == 7.8.2, GHC == 7.8.3, GHC == 7.10.1, - GHC == 8.0.2 + GHC == 8.0.2, GHC == 8.2.1 cabal-version: >= 1.8 extra-source-files: include/EventLogFormat.h test/queens-ghc-6.12.1.eventlog @@ -38,6 +38,16 @@ test/782stop.eventlog.reference test/783stop.eventlog test/783stop.eventlog.reference + test/sleep.h.eventlog + test/sleep.h.eventlog.reference + test/sleep.hC.eventlog + test/sleep.hC.eventlog.reference + test/sleep.hd.eventlog + test/sleep.hd.eventlog.reference + test/sleep.hm.eventlog + test/sleep.hm.eventlog.reference + test/sleep.hy.eventlog + test/sleep.hy.eventlog.reference test/Utils.hs test/stop.hs README.md @@ -52,7 +62,9 @@ containers >= 0.5 && < 0.6, binary >= 0.7 && < 0.10, bytestring >= 0.10.4, - array >= 0.2 && < 0.6 + array >= 0.2 && < 0.6, + text >= 0.11.2.3 && < 1.3, + vector >= 0.7 && < 0.13 exposed-modules: GHC.RTS.Events, GHC.RTS.Events.Incremental GHC.RTS.Events.Merge diff --git a/include/EventLogFormat.h b/include/EventLogFormat.h --- a/include/EventLogFormat.h +++ b/include/EventLogFormat.h @@ -113,8 +113,7 @@ /* 13, 14 deprecated */ #define EVENT_CREATE_SPARK_THREAD 15 /* (spark_thread) */ #define EVENT_LOG_MSG 16 /* (message ...) */ -/* EVENT_STARTUP should be deprecated at some point */ -#define EVENT_STARTUP 17 /* (num_capabilities) */ +/* 17 deprecated */ #define EVENT_BLOCK_MARKER 18 /* (size, end_time, capability) */ #define EVENT_USER_MSG 19 /* (message ...) */ #define EVENT_GC_IDLE 20 /* () */ @@ -164,8 +163,6 @@ #define EVENT_USER_MARKER 58 /* (marker_name) */ #define EVENT_HACK_BUG_T9003 59 /* Hack: see trac #9003 */ -/* Range 59 - 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/ */ @@ -191,12 +188,20 @@ /* Range 140 - 159 is reserved for Perf events, see below. */ +/* Range 160 - 180 is reserved for cost-centre heap profiling events. */ + +#define EVENT_HEAP_PROF_BEGIN 160 +#define EVENT_HEAP_PROF_COST_CENTRE 161 +#define EVENT_HEAP_PROF_SAMPLE_BEGIN 162 +#define EVENT_HEAP_PROF_SAMPLE_COST_CENTRE 163 +#define EVENT_HEAP_PROF_SAMPLE_STRING 164 + /* * The highest event code +1 that ghc itself emits. Note that some event * 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 70 +#define NUM_GHC_EVENT_TAGS 165 /* DEPRECATED EVENTS: */ @@ -212,6 +217,7 @@ #define EVENT_CREATE_SPARK 13 /* (cap, thread) */ #define EVENT_SPARK_TO_THREAD 14 /* (cap, thread, spark_thread) */ #endif +#define EVENT_STARTUP 17 /* (num_capabilities) */ /* diff --git a/src/GHC/RTS/EventTypes.hs b/src/GHC/RTS/EventTypes.hs --- a/src/GHC/RTS/EventTypes.hs +++ b/src/GHC/RTS/EventTypes.hs @@ -1,7 +1,11 @@ +{-# LANGUAGE GeneralizedNewtypeDeriving #-} module GHC.RTS.EventTypes where import Control.Monad +import Data.Bits import Data.Binary +import Data.Text (Text) +import qualified Data.Vector.Unboxed as VU -- EventType. type EventTypeNum = Word16 @@ -373,7 +377,37 @@ | PerfTracepoint { perfNum :: {-# UNPACK #-}!PerfEventTypeNum , tid :: {-# UNPACK #-}!KernelThreadId } - + | HeapProfBegin { heapProfId :: !Word8 + , heapProfSamplingPeriod :: !Word64 + , heapProfBreakdown :: !HeapProfBreakdown + , heapProfModuleFilter :: !Text + , heapProfClosureDescrFilter :: !Text + , heapProfTypeDescrFilter :: !Text + , heapProfCostCentreFilter :: !Text + , heapProfCostCentreStackFilter :: !Text + , heapProfRetainerFilter :: !Text + , heapProfBiographyFilter :: !Text + } + | HeapProfCostCentre { heapProfCostCentreId :: !Word32 + , heapProfLabel :: !Text + , heapProfModule :: !Text + , heapProfSrcLoc :: !Text + , heapProfFlags :: !HeapProfFlags + } + | HeapProfSampleBegin + { heapProfSampleEra :: !Word64 + } + | HeapProfSampleCostCentre + { heapProfId :: !Word8 + , heapProfResidency :: !Word64 + , heapProfStackDepth :: !Word8 + , heapProfStack :: !(VU.Vector Word32) + } + | HeapProfSampleString + { heapProfId :: !Word8 + , heapProfResidency :: !Word64 + , heapProfLabel :: !Text + } deriving Show {- [Note: Stop status in GHC-7.8.2] @@ -519,6 +553,41 @@ fromMsgTag :: MessageTag -> RawMsgTag fromMsgTag = (+ offset) . fromIntegral . fromEnum + +-- | Sample break-down types in heap profiling +data HeapProfBreakdown + = HeapProfBreakdownCostCentre + | HeapProfBreakdownModule + | HeapProfBreakdownClosureDescr + | HeapProfBreakdownTypeDescr + | HeapProfBreakdownRetainer + | HeapProfBreakdownBiography + deriving Show + +instance Binary HeapProfBreakdown where + get = do + n <- get :: Get Word32 + case n of + 1 -> return HeapProfBreakdownCostCentre + 2 -> return HeapProfBreakdownModule + 3 -> return HeapProfBreakdownClosureDescr + 4 -> return HeapProfBreakdownTypeDescr + 5 -> return HeapProfBreakdownRetainer + 6 -> return HeapProfBreakdownBiography + _ -> fail $ "Unknown HeapProfBreakdown: " ++ show n + put breakdown = put $ case breakdown of + HeapProfBreakdownCostCentre -> (1 :: Word32) + HeapProfBreakdownModule -> 2 + HeapProfBreakdownClosureDescr -> 3 + HeapProfBreakdownTypeDescr -> 4 + HeapProfBreakdownRetainer -> 5 + HeapProfBreakdownBiography -> 6 + +newtype HeapProfFlags = HeapProfFlags Word8 + deriving (Show, Binary) + +isCaf :: HeapProfFlags -> Bool +isCaf (HeapProfFlags w8) = testBit w8 0 -- Checks if the capability is not -1 (which indicates a global eventblock), so -- has no associated capability diff --git a/src/GHC/RTS/Events.hs b/src/GHC/RTS/Events.hs --- a/src/GHC/RTS/Events.hs +++ b/src/GHC/RTS/Events.hs @@ -1,4 +1,3 @@ -{-# LANGUAGE CPP,BangPatterns #-} {-# LANGUAGE OverloadedStrings #-} {-# LANGUAGE MultiWayIf #-} {-# OPTIONS_GHC -fsimpl-tick-factor=150 #-} @@ -70,15 +69,21 @@ import Control.Concurrent hiding (ThreadId) import qualified Data.Binary.Put as P import qualified Data.ByteString as B -import qualified Data.ByteString.Builder as BB import qualified Data.ByteString.Lazy as BL -import qualified Data.ByteString.Lazy.Char8 as BL8 import Data.IntMap (IntMap) import qualified Data.IntMap as IM import Data.Foldable (foldMap) import Data.Function hiding (id) import Data.List import Data.Monoid ((<>)) +import Data.String (IsString) +import qualified Data.Text as T +import qualified Data.Text.Lazy as TL +import qualified Data.Text.Lazy.Builder as TB +import qualified Data.Text.Lazy.Builder.Int as TB +import qualified Data.Text.Lazy.IO as TL +import qualified Data.Vector.Unboxed as VU +import Data.Word import System.IO import Prelude hiding (gcd, rem, id) @@ -111,7 +116,7 @@ where go decoder = case decoder of Produce event decoder' -> do - BB.hPutBuilder stdout $ buildEvent' event <> "\n" + TL.hPutStrLn stdout $ TB.toLazyText $ buildEvent' event go decoder' Consume k -> do chunk <- B.hGetSome hdl 4096 @@ -185,39 +190,39 @@ -- Some pretty-printing support showEventInfo :: EventInfo -> String -showEventInfo = BL8.unpack . BB.toLazyByteString . buildEventInfo +showEventInfo = TL.unpack . TB.toLazyText . buildEventInfo -buildEventInfo :: EventInfo -> BB.Builder +buildEventInfo :: EventInfo -> TB.Builder buildEventInfo spec' = case spec' of EventBlock end_time cap _block_events -> - "event block: cap " <> BB.intDec cap - <> ", end time: " <> BB.word64Dec end_time <> "\n" + "event block: cap " <> TB.decimal cap + <> ", end time: " <> TB.decimal end_time <> "\n" Startup n_caps -> - "startup: " <> BB.intDec n_caps <> " capabilities" + "startup: " <> TB.decimal n_caps <> " capabilities" CreateThread thread -> - "creating thread " <> BB.word32Dec thread + "creating thread " <> TB.decimal thread RunThread thread -> - "running thread " <> BB.word32Dec thread + "running thread " <> TB.decimal thread StopThread thread status -> - "stopping thread " <> BB.word32Dec thread - <> " (" <> BB.stringUtf8 (showThreadStopStatus status) <> ")" + "stopping thread " <> TB.decimal thread + <> " (" <> TB.fromString (showThreadStopStatus status) <> ")" ThreadRunnable thread -> - "thread " <> BB.word32Dec thread <> " is runnable" + "thread " <> TB.decimal thread <> " is runnable" MigrateThread thread newCap -> - "migrating thread " <> BB.word32Dec thread - <> " to cap " <> BB.intDec newCap + "migrating thread " <> TB.decimal thread + <> " to cap " <> TB.decimal newCap CreateSparkThread sparkThread -> - "creating spark thread " <> BB.word32Dec sparkThread + "creating spark thread " <> TB.decimal sparkThread SparkCounters crt dud ovf cnv fiz gcd rem -> "spark stats: " - <> BB.word64Dec crt <> " created, " - <> BB.word64Dec cnv <> " converted, " - <> BB.word64Dec rem <> " remaining (" - <> BB.word64Dec ovf <> " overflowed, " - <> BB.word64Dec dud <> " dud, " - <> BB.word64Dec gcd <> " GC'd, " - <> BB.word64Dec fiz <> " fizzled)" + <> TB.decimal crt <> " created, " + <> TB.decimal cnv <> " converted, " + <> TB.decimal rem <> " remaining (" + <> TB.decimal ovf <> " overflowed, " + <> TB.decimal dud <> " dud, " + <> TB.decimal gcd <> " GC'd, " + <> TB.decimal fiz <> " fizzled)" SparkCreate -> "spark created" SparkDud -> @@ -227,29 +232,29 @@ SparkRun -> "running a local spark" SparkSteal victimCap -> - "stealing a spark from cap " <> BB.intDec victimCap + "stealing a spark from cap " <> TB.decimal victimCap SparkFizzle -> "spark fizzled" SparkGC -> "spark GCed" TaskCreate taskId cap tid -> - "task 0x" <> BB.word64Hex taskId - <> " created on cap " <> BB.intDec cap - <>" with OS kernel thread " <> BB.word64Dec (kernelThreadId tid) + "task 0x" <> TB.hexadecimal taskId + <> " created on cap " <> TB.decimal cap + <>" with OS kernel thread " <> TB.decimal (kernelThreadId tid) TaskMigrate taskId cap new_cap -> - "task 0x" <> BB.word64Hex taskId - <> " migrated from cap " <> BB.intDec cap - <> " to cap " <> BB.intDec new_cap + "task 0x" <> TB.hexadecimal taskId + <> " migrated from cap " <> TB.decimal cap + <> " to cap " <> TB.decimal new_cap TaskDelete taskId -> - "task 0x" <> BB.word64Hex taskId <> " deleted" + "task 0x" <> TB.hexadecimal taskId <> " deleted" Shutdown -> "shutting down" WakeupThread thread otherCap -> - "waking up thread " <> BB.word32Dec thread - <> " on cap " <> BB.intDec otherCap + "waking up thread " <> TB.decimal thread + <> " on cap " <> TB.decimal otherCap ThreadLabel thread label -> - "thread " <> BB.word32Dec thread - <> " has label \"" <> BB.stringUtf8 label <> "\"" + "thread " <> TB.decimal thread + <> " has label \"" <> TB.fromString label <> "\"" RequestSeqGC -> "requesting sequential GC" RequestParGC -> @@ -267,139 +272,139 @@ GlobalSyncGC -> "all caps stopped for GC" GCStatsGHC{..} -> - "GC stats for heap capset " <> BB.word32Dec heapCapset - <> ": generation " <> BB.intDec gen <> ", " - <> BB.word64Dec copied <> " bytes copied, " - <> BB.word64Dec slop <> " bytes slop, " - <> BB.word64Dec frag <> " bytes fragmentation, " - <> BB.intDec parNThreads <> " par threads, " - <> BB.word64Dec parMaxCopied <> " bytes max par copied, " - <> BB.word64Dec parTotCopied <> " bytes total par copied" + "GC stats for heap capset " <> TB.decimal heapCapset + <> ": generation " <> TB.decimal gen <> ", " + <> TB.decimal copied <> " bytes copied, " + <> TB.decimal slop <> " bytes slop, " + <> TB.decimal frag <> " bytes fragmentation, " + <> TB.decimal parNThreads <> " par threads, " + <> TB.decimal parMaxCopied <> " bytes max par copied, " + <> TB.decimal parTotCopied <> " bytes total par copied" HeapAllocated{..} -> - "allocated on heap capset " <> BB.word32Dec heapCapset - <> ": " <> BB.word64Dec allocBytes <> " total bytes till now" + "allocated on heap capset " <> TB.decimal heapCapset + <> ": " <> TB.decimal allocBytes <> " total bytes till now" HeapSize{..} -> - "size of heap capset " <> BB.word32Dec heapCapset - <> ": " <> BB.word64Dec sizeBytes <> " bytes" + "size of heap capset " <> TB.decimal heapCapset + <> ": " <> TB.decimal sizeBytes <> " bytes" HeapLive{..} -> - "live data in heap capset " <> BB.word32Dec heapCapset - <> ": " <> BB.word64Dec liveBytes <> " bytes" + "live data in heap capset " <> TB.decimal heapCapset + <> ": " <> TB.decimal liveBytes <> " bytes" HeapInfoGHC{..} -> - "heap stats for heap capset " <> BB.word32Dec heapCapset - <> ": generations " <> BB.intDec gens <> ", " - <> BB.word64Dec maxHeapSize <> " bytes max heap size, " - <> BB.word64Dec allocAreaSize <> " bytes alloc area size, " - <> BB.word64Dec mblockSize <> " bytes mblock size, " - <> BB.word64Dec blockSize <> " bytes block size" + "heap stats for heap capset " <> TB.decimal heapCapset + <> ": generations " <> TB.decimal gens <> ", " + <> TB.decimal maxHeapSize <> " bytes max heap size, " + <> TB.decimal allocAreaSize <> " bytes alloc area size, " + <> TB.decimal mblockSize <> " bytes mblock size, " + <> TB.decimal blockSize <> " bytes block size" CapCreate{cap} -> - "created cap " <> BB.intDec cap + "created cap " <> TB.decimal cap CapDelete{cap} -> - "deleted cap " <> BB.intDec cap + "deleted cap " <> TB.decimal cap CapDisable{cap} -> - "disabled cap " <> BB.intDec cap + "disabled cap " <> TB.decimal cap CapEnable{cap} -> - "enabled cap " <> BB.intDec cap + "enabled cap " <> TB.decimal cap Message msg -> - BB.stringUtf8 msg + TB.fromString msg UserMessage msg -> - BB.stringUtf8 msg + TB.fromString msg UserMarker markername -> - "marker: " <> BB.stringUtf8 markername + "marker: " <> TB.fromString markername CapsetCreate cs ct -> - "created capset " <> BB.word32Dec cs - <> " of type " <> BB.stringUtf8 (show ct) + "created capset " <> TB.decimal cs + <> " of type " <> TB.fromString (show ct) CapsetDelete cs -> - "deleted capset " <> BB.word32Dec cs + "deleted capset " <> TB.decimal cs CapsetAssignCap cs cp -> - "assigned cap " <> BB.intDec cp <> " to capset " <> BB.word32Dec cs + "assigned cap " <> TB.decimal cp <> " to capset " <> TB.decimal cs CapsetRemoveCap cs cp -> - "removed cap " <> BB.intDec cp <> " from capset " <> BB.word32Dec cs + "removed cap " <> TB.decimal cp <> " from capset " <> TB.decimal cs OsProcessPid cs pid -> - "capset " <> BB.word32Dec cs <> ": pid " <> BB.word32Dec pid + "capset " <> TB.decimal cs <> ": pid " <> TB.decimal pid OsProcessParentPid cs ppid -> - "capset " <> BB.word32Dec cs <> ": parent pid " <> BB.word32Dec ppid + "capset " <> TB.decimal cs <> ": parent pid " <> TB.decimal ppid WallClockTime cs sec nsec -> - "capset " <> BB.word32Dec cs <> ": wall clock time " - <> BB.word64Dec sec <> "s " - <> BB.word32Dec nsec <> "ns (unix epoch)" + "capset " <> TB.decimal cs <> ": wall clock time " + <> TB.decimal sec <> "s " + <> TB.decimal nsec <> "ns (unix epoch)" RtsIdentifier cs i -> - "capset " <> BB.word32Dec cs - <> ": RTS version \"" <> BB.stringUtf8 i <> "\"" + "capset " <> TB.decimal cs + <> ": RTS version \"" <> TB.fromString i <> "\"" ProgramArgs cs args -> - "capset " <> BB.word32Dec cs - <> ": args: " <> BB.stringUtf8 (show args) + "capset " <> TB.decimal cs + <> ": args: " <> TB.fromString (show args) ProgramEnv cs env -> - "capset " <> BB.word32Dec cs - <> ": env: " <> BB.stringUtf8 (show env) + "capset " <> TB.decimal cs + <> ": env: " <> TB.fromString (show env) UnknownEvent n -> - "Unknown event type " <> BB.word16Dec n + "Unknown event type " <> TB.decimal n InternString str sId -> - "Interned string: \"" <> BB.stringUtf8 str - <> "\" with id " <> BB.word32Dec sId + "Interned string: \"" <> TB.fromString str + <> "\" with id " <> TB.decimal sId -- events for the parallel RTS Version version -> - "compiler version is " <> BB.stringUtf8 version + "compiler version is " <> TB.fromString version ProgramInvocation commandline -> - "program invocation: " <> BB.stringUtf8 commandline + "program invocation: " <> TB.fromString commandline EdenStartReceive -> "starting to receive" EdenEndReceive -> "stop receiving" CreateProcess process -> - "creating process " <> BB.word32Dec process + "creating process " <> TB.decimal process KillProcess process -> - "killing process " <> BB.word32Dec process + "killing process " <> TB.decimal process AssignThreadToProcess thread process -> - "assigning thread " <> BB.word32Dec thread - <> " to process " <> BB.word32Dec process + "assigning thread " <> TB.decimal thread + <> " to process " <> TB.decimal process CreateMachine machine realtime -> - "creating machine " <> BB.word16Dec machine - <> " at " <> BB.word64Dec realtime + "creating machine " <> TB.decimal machine + <> " at " <> TB.decimal realtime KillMachine machine -> - "killing machine " <> BB.word16Dec machine + "killing machine " <> TB.decimal machine SendMessage mesTag senderProcess senderThread receiverMachine receiverProcess receiverInport -> - "sending message with tag " <> BB.stringUtf8 (show mesTag) - <> " from process " <> BB.word32Dec senderProcess - <> ", thread " <> BB.word32Dec senderThread - <> " to machine " <> BB.word16Dec receiverMachine - <> ", process " <> BB.word32Dec receiverProcess - <> " on inport " <> BB.word32Dec receiverInport + "sending message with tag " <> TB.fromString (show mesTag) + <> " from process " <> TB.decimal senderProcess + <> ", thread " <> TB.decimal senderThread + <> " to machine " <> TB.decimal receiverMachine + <> ", process " <> TB.decimal receiverProcess + <> " on inport " <> TB.decimal receiverInport ReceiveMessage mesTag receiverProcess receiverInport senderMachine senderProcess senderThread messageSize -> - "receiving message with tag " <> BB.stringUtf8 (show mesTag) - <> " at process " <> BB.word32Dec receiverProcess - <> ", inport " <> BB.word32Dec receiverInport - <> " from machine " <> BB.word16Dec senderMachine - <> ", process " <> BB.word32Dec senderProcess - <> ", thread " <> BB.word32Dec senderThread - <> " with size " <> BB.word32Dec messageSize + "receiving message with tag " <> TB.fromString (show mesTag) + <> " at process " <> TB.decimal receiverProcess + <> ", inport " <> TB.decimal receiverInport + <> " from machine " <> TB.decimal senderMachine + <> ", process " <> TB.decimal senderProcess + <> ", thread " <> TB.decimal senderThread + <> " with size " <> TB.decimal messageSize SendReceiveLocalMessage mesTag senderProcess senderThread receiverProcess receiverInport -> - "sending/receiving message with tag " <> BB.stringUtf8 (show mesTag) - <> " from process " <> BB.word32Dec senderProcess - <> ", thread " <> BB.word32Dec senderThread - <> " to process " <> BB.word32Dec receiverProcess - <> " on inport " <> BB.word32Dec receiverInport + "sending/receiving message with tag " <> TB.fromString (show mesTag) + <> " from process " <> TB.decimal senderProcess + <> ", thread " <> TB.decimal senderThread + <> " to process " <> TB.decimal receiverProcess + <> " on inport " <> TB.decimal receiverInport MerStartParConjunction dyn_id static_id -> - "Start a parallel conjunction 0x" <> BB.word64Hex dyn_id - <> ", static_id: " <> BB.word32Dec static_id + "Start a parallel conjunction 0x" <> TB.hexadecimal dyn_id + <> ", static_id: " <> TB.decimal static_id MerEndParConjunction dyn_id -> - "End par conjunction: 0x" <> BB.word64Hex dyn_id + "End par conjunction: 0x" <> TB.hexadecimal dyn_id MerEndParConjunct dyn_id -> - "End par conjunct: 0x" <> BB.word64Hex dyn_id + "End par conjunct: 0x" <> TB.hexadecimal dyn_id MerCreateSpark dyn_id spark_id -> - "Create spark for conjunction: 0x" <> BB.word64Hex dyn_id - <> " spark: 0x" <> BB.word32Hex spark_id + "Create spark for conjunction: 0x" <> TB.hexadecimal dyn_id + <> " spark: 0x" <> TB.hexadecimal spark_id MerFutureCreate future_id name_id -> - "Create future 0x" <> BB.word64Hex future_id - <> " named " <> BB.word32Dec name_id + "Create future 0x" <> TB.hexadecimal future_id + <> " named " <> TB.decimal name_id MerFutureWaitNosuspend future_id -> - "Wait didn't suspend for future: 0x" <> BB.word64Hex future_id + "Wait didn't suspend for future: 0x" <> TB.hexadecimal future_id MerFutureWaitSuspended future_id -> - "Wait suspended on future: 0x" <> BB.word64Hex future_id + "Wait suspended on future: 0x" <> TB.hexadecimal future_id MerFutureSignal future_id -> - "Signaled future 0x" <> BB.word64Hex future_id + "Signaled future 0x" <> TB.hexadecimal future_id MerLookingForGlobalThread -> "Looking for global thread to resume" MerWorkStealing -> @@ -407,22 +412,66 @@ MerLookingForLocalSpark -> "Looking for a local spark to execute" MerReleaseThread thread_id -> - "Releasing thread " <> BB.word32Dec thread_id <> " to the free pool" + "Releasing thread " <> TB.decimal thread_id <> " to the free pool" MerCapSleeping -> "Capability going to sleep" MerCallingMain -> "About to call the program entry point" PerfName{perfNum, name} -> - "perf event " <> BB.word32Dec perfNum - <> " named \"" <> BB.stringUtf8 name <> "\"" + "perf event " <> TB.decimal perfNum + <> " named \"" <> TB.fromString name <> "\"" PerfCounter{perfNum, tid, period} -> - "perf event counter " <> BB.word32Dec perfNum - <> " incremented by " <> BB.word64Dec (period + 1) - <> " in OS thread " <> BB.word64Dec (kernelThreadId tid) + "perf event counter " <> TB.decimal perfNum + <> " incremented by " <> TB.decimal (period + 1) + <> " in OS thread " <> TB.decimal (kernelThreadId tid) PerfTracepoint{perfNum, tid} -> - "perf event tracepoint " <> BB.word32Dec perfNum - <> " reached in OS thread " <> BB.word64Dec (kernelThreadId tid) + "perf event tracepoint " <> TB.decimal perfNum + <> " reached in OS thread " <> TB.decimal (kernelThreadId tid) + HeapProfBegin {..} -> + "start heap profiling " <> TB.decimal heapProfId + <> " at sampling period " <> TB.decimal heapProfSamplingPeriod + <> " broken down by " <> showHeapProfBreakdown heapProfBreakdown + <> maybe "" (" filtered by " <>) + (buildFilters + [ heapProfModuleFilter + , heapProfClosureDescrFilter + , heapProfTypeDescrFilter + , heapProfCostCentreFilter + , heapProfCostCentreStackFilter + , heapProfRetainerFilter + , heapProfBiographyFilter + ]) + HeapProfCostCentre {..} -> + "cost centre " <> TB.decimal heapProfCostCentreId + <> " " <> TB.fromText heapProfLabel + <> " in " <> TB.fromText heapProfModule + <> " at " <> TB.fromText heapProfSrcLoc + <> if isCaf heapProfFlags then " CAF" else "" + HeapProfSampleBegin {..} -> + "start heap prof sample " <> TB.decimal heapProfSampleEra + HeapProfSampleCostCentre {..} -> + "heap prof sample " <> TB.decimal heapProfId + <> ", residency " <> TB.decimal heapProfResidency + <> ", cost centre stack " <> buildCostCentreStack heapProfStack + HeapProfSampleString {..} -> + "heap prof sample " <> TB.decimal heapProfId + <> ", residency " <> TB.decimal heapProfResidency + <> ", label " <> TB.fromText heapProfLabel +buildFilters :: [T.Text] -> Maybe TB.Builder +buildFilters = foldr g Nothing + where + g f b + | T.null f = b + | otherwise = Just (TB.fromText f <> ", ") <> b + +buildCostCentreStack :: VU.Vector Word32 -> TB.Builder +buildCostCentreStack = VU.ifoldl' go "" + where + go b i cc + | i == 0 = TB.decimal cc + | otherwise = b <> ", " <> TB.decimal cc + showThreadStopStatus :: ThreadStopStatus -> String showThreadStopStatus HeapOverflow = "heap overflow" showThreadStopStatus StackOverflow = "stack overflow" @@ -447,10 +496,19 @@ "blocked on black hole owned by thread " ++ show target showThreadStopStatus NoStatus = "No stop thread status" +showHeapProfBreakdown :: IsString s => HeapProfBreakdown -> s +showHeapProfBreakdown breakdown = case breakdown of + HeapProfBreakdownCostCentre -> "cost centre" + HeapProfBreakdownModule -> "module" + HeapProfBreakdownClosureDescr -> "closure description" + HeapProfBreakdownTypeDescr -> "type description" + HeapProfBreakdownRetainer -> "retainer" + HeapProfBreakdownBiography -> "biography" + ppEventLog :: EventLog -> String -ppEventLog = BL8.unpack . BB.toLazyByteString . buildEventLog +ppEventLog = TL.unpack . TB.toLazyText . buildEventLog -buildEventLog :: EventLog -> BB.Builder +buildEventLog :: EventLog -> TB.Builder buildEventLog (EventLog (Header ets) (Data es)) = "Event Types:\n" <> foldMap (\evType -> buildEventType evType <> "\n") ets @@ -462,34 +520,34 @@ sorted = sortEvents es ppEventType :: EventType -> String -ppEventType = BL8.unpack . BB.toLazyByteString . buildEventType +ppEventType = TL.unpack . TB.toLazyText . buildEventType -buildEventType :: EventType -> BB.Builder +buildEventType :: EventType -> TB.Builder buildEventType (EventType num dsc msz) = - BB.word16Dec num <> ": " - <> BB.stringUtf8 dsc <> " (size " - <> maybe "variable" BB.word16Dec msz <> ")" + TB.decimal num <> ": " + <> TB.fromString dsc <> " (size " + <> maybe "variable" TB.decimal msz <> ")" -- | Pretty prints an 'Event', with clean handling for 'UnknownEvent' ppEvent :: IntMap EventType -> Event -> String -ppEvent imap = BL8.unpack . BB.toLazyByteString . buildEvent imap +ppEvent imap = TL.unpack . TB.toLazyText . buildEvent imap -buildEvent :: IntMap EventType -> Event -> BB.Builder +buildEvent :: IntMap EventType -> Event -> TB.Builder buildEvent imap Event {..} = - BB.word64Dec evTime + TB.decimal evTime <> ": " - <> maybe "" (\c -> "cap " <> BB.intDec c <> ": ") evCap + <> maybe "" (\c -> "cap " <> TB.decimal c <> ": ") evCap <> case evSpec of UnknownEvent{ ref=ref } -> - maybe "" (BB.stringUtf8 . desc) $ IM.lookup (fromIntegral ref) imap + maybe "" (TB.fromString . desc) $ IM.lookup (fromIntegral ref) imap _ -> buildEventInfo evSpec -buildEvent' :: Event -> BB.Builder +buildEvent' :: Event -> TB.Builder buildEvent' Event {..} = - BB.word64Dec evTime + TB.decimal evTime <> ": " - <> maybe "" (\c -> "cap " <> BB.intDec c <> ": ") evCap + <> maybe "" (\c -> "cap " <> TB.decimal c <> ": ") evCap <> case evSpec of UnknownEvent{ ref=ref } -> - "Unknown Event (ref: " <> BB.word16Dec ref <> ")" + "Unknown Event (ref: " <> TB.decimal ref <> ")" _ -> buildEventInfo evSpec diff --git a/src/GHC/RTS/Events/Binary.hs b/src/GHC/RTS/Events/Binary.hs --- a/src/GHC/RTS/Events/Binary.hs +++ b/src/GHC/RTS/Events/Binary.hs @@ -8,6 +8,7 @@ , ghc7Parsers , mercuryParsers , perfParsers + , heapProfParsers , pre77StopParsers , ghc782StopParser , post782StopParser @@ -24,6 +25,7 @@ , nEVENT_PERF_TRACEPOINT ) where +import Control.Exception (assert) import Control.Monad import Data.Maybe import Prelude hiding (gcd, rem, id) @@ -32,6 +34,12 @@ import Data.Binary import Data.Binary.Put import qualified Data.Binary.Get as G +import qualified Data.ByteString as B +import qualified Data.Text as T +import qualified Data.Text.Encoding as TE +import qualified Data.Text.Lazy as TL +import qualified Data.Text.Lazy.Encoding as TLE +import qualified Data.Vector.Unboxed as VU import GHC.RTS.EventTypes import GHC.RTS.EventParserUtils @@ -718,6 +726,90 @@ )) ] +heapProfParsers :: [EventParser EventInfo] +heapProfParsers = + [ VariableSizeParser EVENT_HEAP_PROF_BEGIN $ do + payloadLen <- get :: Get Word16 + heapProfId <- get + heapProfSamplingPeriod <- get + heapProfBreakdown <- get + heapProfModuleFilter <- getText + heapProfClosureDescrFilter <- getText + heapProfTypeDescrFilter <- getText + heapProfCostCentreFilter <- getText + heapProfCostCentreStackFilter <- getText + heapProfRetainerFilter <- getText + heapProfBiographyFilter <- getText + assert + (fromIntegral payloadLen == sum + [ 1 -- heapProfId + , 8 -- heapProfSamplingPeriod + , 4 -- heapProfBreakdown + , textByteLen heapProfModuleFilter + , textByteLen heapProfClosureDescrFilter + , textByteLen heapProfTypeDescrFilter + , textByteLen heapProfCostCentreFilter + , textByteLen heapProfCostCentreStackFilter + , textByteLen heapProfRetainerFilter + , textByteLen heapProfBiographyFilter + ]) + (return ()) + return $! HeapProfBegin {..} + , VariableSizeParser EVENT_HEAP_PROF_COST_CENTRE $ do + payloadLen <- get :: Get Word16 + heapProfCostCentreId <- get + heapProfLabel <- getText + heapProfModule <- getText + heapProfSrcLoc <- getText + heapProfFlags <- get + assert + (fromIntegral payloadLen == sum + [ 4 -- heapProfCostCentreId + , textByteLen heapProfLabel + , textByteLen heapProfModule + , textByteLen heapProfSrcLoc + , 1 -- heapProfFlags + ]) + (return ()) + return $! HeapProfCostCentre {..} + , FixedSizeParser EVENT_HEAP_PROF_SAMPLE_BEGIN 8 $ do + heapProfSampleEra <- get + return $! HeapProfSampleBegin {..} + , VariableSizeParser EVENT_HEAP_PROF_SAMPLE_COST_CENTRE $ do + payloadLen <- get :: Get Word16 + heapProfId <- get + heapProfResidency <- get + heapProfStackDepth <- get + heapProfStack <- VU.replicateM (fromIntegral heapProfStackDepth) get + assert + ((fromIntegral payloadLen :: Int) == sum + [ 1 -- heapProfId + , 8 -- heapProfResidency + , 1 -- heapProfStackDepth + , fromIntegral heapProfStackDepth * 4 + ]) + (return ()) + return $! HeapProfSampleCostCentre {..} + , VariableSizeParser EVENT_HEAP_PROF_SAMPLE_STRING $ do + payloadLen <- get :: Get Word16 + heapProfId <- get + heapProfResidency <- get + heapProfLabel <- getText + assert + (fromIntegral payloadLen == sum + [ 1 -- heapProfId + , 8 -- heapProfResidency + , textByteLen heapProfLabel + ]) + (return ()) + return $! HeapProfSampleString {..} + ] + +-- | String byte length in the eventlog format. It includes +-- 1 byte for NUL. +textByteLen :: T.Text -> Int +textByteLen = (+1) . B.length . TE.encodeUtf8 + ----------------------------------------------------------- putE :: Binary a => a -> PutM () @@ -849,6 +941,11 @@ PerfName {} -> nEVENT_PERF_NAME PerfCounter {} -> nEVENT_PERF_COUNTER PerfTracepoint {} -> nEVENT_PERF_TRACEPOINT + HeapProfBegin {} -> EVENT_HEAP_PROF_BEGIN + HeapProfCostCentre {} -> EVENT_HEAP_PROF_COST_CENTRE + HeapProfSampleBegin {} -> EVENT_HEAP_PROF_SAMPLE_BEGIN + HeapProfSampleCostCentre {} -> EVENT_HEAP_PROF_SAMPLE_COST_CENTRE + HeapProfSampleString {} -> EVENT_HEAP_PROF_SAMPLE_STRING nEVENT_PERF_NAME, nEVENT_PERF_COUNTER, nEVENT_PERF_TRACEPOINT :: EventTypeNum nEVENT_PERF_NAME = EVENT_PERF_NAME @@ -1216,6 +1313,41 @@ putE perfNum putE tid +putEventSpec HeapProfBegin {..} = do + putE heapProfId + putE heapProfSamplingPeriod + putE heapProfBreakdown + mapM_ (putE . T.unpack) + [ heapProfModuleFilter + , heapProfClosureDescrFilter + , heapProfTypeDescrFilter + , heapProfCostCentreFilter + , heapProfCostCentreStackFilter + , heapProfRetainerFilter + , heapProfBiographyFilter + ] + +putEventSpec HeapProfCostCentre {..} = do + putE heapProfCostCentreId + putE $ T.unpack heapProfLabel + putE $ T.unpack heapProfModule + putE $ T.unpack heapProfSrcLoc + putE heapProfFlags + +putEventSpec HeapProfSampleBegin {..} = + putE heapProfSampleEra + +putEventSpec HeapProfSampleCostCentre {..} = do + putE heapProfId + putE heapProfResidency + putE heapProfStackDepth + VU.mapM_ putE heapProfStack + +putEventSpec HeapProfSampleString {..} = do + putE heapProfId + putE heapProfResidency + putE $ T.unpack heapProfLabel + -- [] == [] -- [x] == x\0 -- [x, y, z] == x\0y\0 @@ -1226,3 +1358,10 @@ splitNull [] = [] splitNull xs = case span (/= '\0') xs of (x, xs') -> x : splitNull (drop 1 xs') + +getText :: Get T.Text +getText = do + chunks <- G.getLazyByteStringNul + case TLE.decodeUtf8' chunks of + Left err -> fail $ show err + Right text -> return $ TL.toStrict text diff --git a/src/GHC/RTS/Events/Incremental.hs b/src/GHC/RTS/Events/Incremental.hs --- a/src/GHC/RTS/Events/Incremental.hs +++ b/src/GHC/RTS/Events/Incremental.hs @@ -201,5 +201,6 @@ , parRTSParsers sz_tid , mercuryParsers , perfParsers + , heapProfParsers ] parsers = EventParsers $ mkEventTypeParsers imap event_parsers diff --git a/test/Utils.hs b/test/Utils.hs --- a/test/Utils.hs +++ b/test/Utils.hs @@ -6,7 +6,13 @@ , "queens-ghc-7.0.2.eventlog" , "mandelbrot-mmc-2011-06-14.eventlog" , "parallelTest.eventlog" - , "pre77stop.eventlog", "782stop.eventlog", "783stop.eventlog" ] + , "pre77stop.eventlog", "782stop.eventlog", "783stop.eventlog" + , "sleep.h.eventlog" + , "sleep.hC.eventlog" + , "sleep.hm.eventlog" + , "sleep.hd.eventlog" + , "sleep.hy.eventlog" + ] -- Code to help print the differences between a working test and a failing test. diff --git a/test/sleep.h.eventlog b/test/sleep.h.eventlog new file mode 100644 Binary files /dev/null and b/test/sleep.h.eventlog differ diff --git a/test/sleep.h.eventlog.reference b/test/sleep.h.eventlog.reference new file mode 100644 --- /dev/null +++ b/test/sleep.h.eventlog.reference @@ -0,0 +1,301 @@ +Event Types: +0: Create thread (size 4) +1: Run thread (size 4) +2: Stop thread (size 10) +3: Thread runnable (size 4) +4: Migrate thread (size 6) +8: Wakeup thread (size 6) +9: Starting GC (size 0) +10: Finished GC (size 0) +11: Request sequential GC (size 0) +12: Request parallel GC (size 0) +15: Create spark thread (size 4) +16: Log message (size variable) +18: Block marker (size 14) +19: User message (size variable) +20: GC idle (size 0) +21: GC working (size 0) +22: GC done (size 0) +25: Create capability set (size 6) +26: Delete capability set (size 4) +27: Add capability to capability set (size 6) +28: Remove capability from capability set (size 6) +29: RTS name and version (size variable) +30: Program arguments (size variable) +31: Program environment variables (size variable) +32: Process ID (size 8) +33: Parent process ID (size 8) +34: Spark counters (size 56) +35: Spark create (size 0) +36: Spark dud (size 0) +37: Spark overflow (size 0) +38: Spark run (size 0) +39: Spark steal (size 2) +40: Spark fizzle (size 0) +41: Spark GC (size 0) +43: Wall clock time (size 16) +44: Thread label (size variable) +45: Create capability (size 2) +46: Delete capability (size 2) +47: Disable capability (size 2) +48: Enable capability (size 2) +49: Total heap mem ever allocated (size 12) +50: Current heap size (size 12) +51: Current heap live data (size 12) +52: Heap static parameters (size 38) +53: GC statistics (size 50) +54: Synchronise stop-the-world GC (size 0) +55: Task create (size 18) +56: Task migrate (size 12) +57: Task delete (size 8) +58: User marker (size variable) +59: Empty event for bug #9003 (size 0) +160: Start of heap profile (size variable) +161: Cost center definition (size variable) +162: Start of heap profile sample (size 8) +163: Heap profile cost-centre sample (size variable) +164: Heap profile string sample (size variable) + +Events: +158325: created capset 0 of type CapsetOsProcess +160770: created capset 1 of type CapsetClockDomain +165658: created cap 0 +166776: assigned cap 0 to capset 0 +167754: assigned cap 0 to capset 1 +168941: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +175087: capset 1: wall clock time 1496042099s 522698000ns (unix epoch) +176065: capset 0: pid 30086 +178858: capset 0: parent pid 27111 +182699: capset 0: RTS version "GHC-8.2.0.20170507 rts_thr_p" +185702: capset 0: args: ["./sleep","+RTS","-l","-h"] +190451: capset 0: env: ["ADOTDIR=/home/maoe/.antigen","ANTIGEN_COMPDUMPFILE=/home/maoe/.zcompdump","ANTIGEN_DEFAULT_REPO_URL=https://github.com/robbyrussell/oh-my-zsh.git","AUTOJUMP_ERROR_PATH=/home/maoe/.local/share/autojump/errors.log","AUTOJUMP_SOURCED=1","CLUTTER_IM_MODULE=xim","DBUS_SESSION_BUS_ADDRESS=unix:abstract=/tmp/dbus-ioIEQwU7Ny","DEFAULTS_PATH=/usr/share/gconf/gnome.default.path","DERBY_HOME=/usr/lib/jvm/java-8-oracle/db","DESKTOP_SESSION=gnome","DISPLAY=:0","EDITOR=vim","GDMSESSION=gnome","GDM_LANG=en","GJS_DEBUG_OUTPUT=stderr","GJS_DEBUG_TOPICS=JS ERROR;JS LOG","GNOME_DESKTOP_SESSION_ID=this-is-deprecated","GNOME_KEYRING_CONTROL=","GNOME_KEYRING_PID=","GOPATH=/home/maoe/.go","GPG_AGENT_INFO=/home/maoe/.gnupg/S.gpg-agent:0:1","GTK_IM_MODULE=ibus","HOME=/home/maoe","IM_CONFIG_PHASE=1","INSTANCE=","J2REDIR=/usr/lib/jvm/java-8-oracle/jre","J2SDKDIR=/usr/lib/jvm/java-8-oracle","JAVA_HOME=/usr/lib/jvm/java-8-oracle","JOB=dbus","LANG=en_US.UTF-8","LANGUAGE=en","LC_ADDRESS=en_US.UTF-8","LC_CTYPE=en_US.UTF-8","LC_IDENTIFICATION=en_US.UTF-8","LC_MEASUREMENT=en_US.UTF-8","LC_MONETARY=en_US.UTF-8","LC_NAME=en_US.UTF-8","LC_NUMERIC=en_US.UTF-8","LC_PAPER=en_US.UTF-8","LC_TELEPHONE=en_US.UTF-8","LC_TIME=en_US.UTF-8","LESS=-R","LIBVIRT_DEFAULT_URI=qemu:///system","LOGNAME=maoe","LS_COLORS=di=34:ln=35:so=32:pi=33:ex=31:bd=46;34:cd=43;34:su=41;30:sg=46;30:tw=42;30:ow=43;30","MANDATORY_PATH=/usr/share/gconf/gnome.mandatory.path","NODE_PATH=/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript","OLDPWD=/home/maoe/src/github.com/haskell/ghc-events","PAGER=less","PAPERSIZE=letter","PATH=/usr/local/ghc/ghc-8.2.0-rc2/bin:/home/maoe/.npm-packages/bin:/home/maoe/Downloads/google-cloud-sdk/bin:/home/maoe/src/github.com/phacility/arcanist/bin:/home/maoe/.cargo/bin:/home/maoe/.local/bin:/home/maoe/.cabal/bin:/home/maoe/bin:/usr/local/bin:/usr/local/sbin:/home/maoe/.npm-packages/bin:/home/maoe/Downloads/google-cloud-sdk/bin:/home/maoe/src/github.com/phacility/arcanist/bin:/home/maoe/.cargo/bin:/home/maoe/.local/bin:/home/maoe/.cabal/bin:/home/maoe/bin:/usr/local/bin:/usr/local/sbin:/home/maoe/.cargo/bin:/home/maoe/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/usr/lib/jvm/java-8-oracle/bin:/usr/lib/jvm/java-8-oracle/db/bin:/usr/lib/jvm/java-8-oracle/jre/bin","PWD=/home/maoe/src/github.com/haskell/ghc-events","QT4_IM_MODULE=ibus","QT_ACCESSIBILITY=1","QT_IM_MODULE=ibus","QT_LINUX_ACCESSIBILITY_ALWAYS_ON=1","SESSION=gnome","SESSIONTYPE=gnome-session","SESSION_MANAGER=local/vangelis.tsuru.it:@/tmp/.ICE-unix/5489,unix/vangelis.tsuru.it:/tmp/.ICE-unix/5489","SHELL=/bin/zsh","SHLVL=2","SSH_AUTH_SOCK=/run/user/2016/keyring/ssh","TERM=screen-256color","TMUX=/tmp/tmux-2016/default,10542,3","TMUX_PANE=%93","UBUNTU_MENUPROXY=libappmenu.so","UPSTART_SESSION=unix:abstract=/com/ubuntu/upstart-session/2016/5282","USER=maoe","VTE_VERSION=4205","WINDOWID=71468690","XAUTHORITY=/home/maoe/.Xauthority","XDG_CONFIG_DIRS=/etc/xdg/xdg-gnome:/usr/share/upstart/xdg:/etc/xdg","XDG_CURRENT_DESKTOP=GNOME","XDG_DATA_DIRS=/usr/share/gnome:/usr/local/share/:/usr/share/","XDG_GREETER_DATA_DIR=/var/lib/lightdm-data/maoe","XDG_MENU_PREFIX=gnome-","XDG_RUNTIME_DIR=/run/user/2016","XDG_SEAT=seat0","XDG_SEAT_PATH=/org/freedesktop/DisplayManager/Seat0","XDG_SESSION_DESKTOP=gnome","XDG_SESSION_ID=c2","XDG_SESSION_PATH=/org/freedesktop/DisplayManager/Session0","XDG_SESSION_TYPE=x11","XDG_VTNR=7","XMODIFIERS=@im=ibus","ZSH=/home/maoe/.antigen/repos/https-COLON--SLASH--SLASH-github.com-SLASH-robbyrussell-SLASH-oh-my-zsh.git","ZSH_CACHE_DIR=/home/maoe/.antigen/repos/https-COLON--SLASH--SLASH-github.com-SLASH-robbyrussell-SLASH-oh-my-zsh.git/cache/","_=/home/maoe/src/github.com/haskell/ghc-events/./sleep","_ANTIGEN_BUNDLE_RECORD=\nhttps://github.com/robbyrussell/oh-my-zsh.git lib plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git plugins/git plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git plugins/pass plugin true \nhttps://github.com/zsh-users/zsh-syntax-highlighting.git / plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git themes/kphoen.zsh-theme theme true ","_ANTIGEN_LOG_PATH=/home/maoe/.antigen/antigen.log","_ZCACHE_BUNDLES_PATH=/home/maoe/.antigen/.cache/.zcache-bundles","_ZCACHE_CACHE_LOADED=true","_ZCACHE_CACHE_VERSION=v1.4.1","_ZCACHE_EXTENSION_BUNDLE=false","_ZCACHE_EXTENSION_CLEAN_FUNCTIONS=true","_ZCACHE_PATH=/home/maoe/.antigen/.cache","_ZCACHE_PAYLOAD_PATH=/home/maoe/.antigen/.cache/.zcache-payload","LSCOLORS=Gxfxcxdxbxegedabagacad","MANPATH=/home/maoe/.npm-packages/share/man:/home/maoe/.local/share/man:/home/maoe/.cabal/share/man:/usr/local/man:/usr/local/share/man:/usr/share/man:/usr/lib/jvm/java-8-oracle/man"] +259872: heap stats for heap capset 0: generations 2, 0 bytes max heap size, 1048576 bytes alloc area size, 1048576 bytes mblock size, 4096 bytes block size +445365: start heap profiling 0 at sampling period 100000000 broken down by cost centre +448088: cost centre 110 IDLE in IDLE at +449695: cost centre 109 PINNED in SYSTEM at +450882: cost centre 108 DONT_CARE in MAIN at +452069: cost centre 107 OVERHEAD_of in PROFILING at +453256: cost centre 106 GC in GC at +454374: cost centre 105 SYSTEM in SYSTEM at +455352: cost centre 104 MAIN in MAIN at +456539: cost centre 103 CAF in GHC.Types at CAF +457656: cost centre 102 CAF in GHC.Tuple at CAF +458844: cost centre 101 CAF in GHC.Classes at CAF +459961: cost centre 100 CAF in GHC.CString at CAF +461148: cost centre 99 CAF in GHC.Integer.Type at CAF +462266: cost centre 98 CAF in GHC.Integer.Logarithms.Internals at CAF +463593: cost centre 97 CAF in GHC.Integer.Logarithms at CAF +464780: cost centre 96 CAF in GHC.Event.Array at CAF +465897: cost centre 95 CAF in GHC.Event.Arr at CAF +466945: cost centre 94 CAF in Data.Proxy at CAF +468272: cost centre 93 CAF in GHC.Event.Poll at CAF +469389: cost centre 92 CAF in GHC.Event.PSQ at CAF +470646: cost centre 91 CAF in GHC.Event.Manager at CAF +471834: cost centre 90 CAF in GHC.Event.IntTable at CAF +473161: cost centre 89 CAF in GHC.Event.EPoll at CAF +474348: cost centre 88 CAF in GHC.Event.Control at CAF +475395: cost centre 87 CAF in System.Posix.Types at CAF +476513: cost centre 86 CAF in GHC.Storable at CAF +477491: cost centre 85 CAF in GHC.Natural at CAF +478748: cost centre 84 CAF in GHC.IO.FD at CAF +479935: cost centre 83 CAF in GHC.IO.Device at CAF +481052: cost centre 82 CAF in GHC.IO.BufferedIO at CAF +482030: cost centre 81 CAF in GHC.Generics at CAF +483357: cost centre 80 CAF in GHC.Float.RealFracMethods at CAF +484405: cost centre 79 CAF in GHC.Float.ConversionUtils at CAF +485382: cost centre 78 CAF in GHC.Float at CAF +486500: cost centre 77 CAF in GHC.Enum at CAF +487548: cost centre 76 CAF in GHC.Char at CAF +488735: cost centre 75 CAF in GHC.Arr at CAF +489922: cost centre 74 CAF in Foreign.Storable at CAF +491179: cost centre 73 CAF in Foreign.Marshal.Array at CAF +492297: cost centre 72 CAF in Foreign.Marshal.Alloc at CAF +493274: cost centre 71 CAF in Foreign.C.Types at CAF +494392: cost centre 70 CAF in Foreign.C.String at CAF +495649: cost centre 69 CAF in Foreign.C.Error at CAF +497115: cost centre 68 CAF in Data.Type.Equality at CAF +498233: cost centre 67 CAF in Data.Tuple at CAF +499211: cost centre 66 CAF in Data.Maybe at CAF +500328: cost centre 65 CAF in Data.Dynamic at CAF +501376: cost centre 64 CAF in Data.Bits at CAF +502353: cost centre 63 CAF in Control.Monad.Fail at CAF +503541: cost centre 62 CAF in GHC.Event.Unique at CAF +504728: cost centre 61 CAF in GHC.Event.TimerManager at CAF +505845: cost centre 60 CAF in GHC.Event.Thread at CAF +506963: cost centre 59 CAF in GHC.Event.Internal at CAF +508080: cost centre 58 CAF in Data.Typeable.Internal at CAF +509198: cost centre 57 CAF in Data.OldList at CAF +510245: cost centre 56 CAF in Text.Read.Lex at CAF +511363: cost centre 55 CAF in Text.ParserCombinators.ReadPrec at CAF +512340: cost centre 54 CAF in Text.ParserCombinators.ReadP at CAF +513458: cost centre 53 CAF in System.Posix.Internals at CAF +514505: cost centre 52 CAF in System.IO at CAF +515483: cost centre 51 CAF in Numeric at CAF +516670: cost centre 50 CAF in GHC.Word at CAF +517788: cost centre 49 CAF in GHC.Weak at CAF +518766: cost centre 48 CAF in GHC.Unicode at CAF +520023: cost centre 47 CAF in GHC.TopHandler at CAF +521070: cost centre 46 CAF in GHC.Stack.Types at CAF +525680: cost centre 45 CAF in GHC.Stack.CCS at CAF +526727: cost centre 44 CAF in GHC.Stable at CAF +527915: cost centre 43 CAF in GHC.Show at CAF +528962: cost centre 42 CAF in GHC.STRef at CAF +530149: cost centre 41 CAF in GHC.ST at CAF +531267: cost centre 40 CAF in GHC.Real at CAF +532314: cost centre 39 CAF in GHC.Read at CAF +533362: cost centre 38 CAF in GHC.Ptr at CAF +534410: cost centre 37 CAF in GHC.Pack at CAF +535597: cost centre 36 CAF in GHC.Num at CAF +536644: cost centre 35 CAF in GHC.MVar at CAF +537902: cost centre 34 CAF in GHC.List at CAF +539019: cost centre 33 CAF in GHC.Int at CAF +539997: cost centre 32 CAF in GHC.IORef at CAF +541044: cost centre 31 CAF in GHC.IO.Unsafe at CAF +542301: cost centre 30 CAF in GHC.IO.IOMode at CAF +543628: cost centre 29 CAF in GHC.IO.Handle.Types at CAF +544676: cost centre 28 CAF in GHC.IO.Handle.Text at CAF +545793: cost centre 27 CAF in GHC.IO.Handle.Internals at CAF +546841: cost centre 26 CAF in GHC.IO.Handle.FD at CAF +548028: cost centre 25 CAF in GHC.IO.Handle at CAF +549216: cost centre 24 CAF in GHC.IO.Exception at CAF +550403: cost centre 23 CAF in GHC.IO.Encoding.UTF8 at CAF +551590: cost centre 22 CAF in GHC.IO.Encoding.UTF32 at CAF +552638: cost centre 21 CAF in GHC.IO.Encoding.UTF16 at CAF +553755: cost centre 20 CAF in GHC.IO.Encoding.Types at CAF +554873: cost centre 19 CAF in GHC.IO.Encoding.Latin1 at CAF +555990: cost centre 18 CAF in GHC.IO.Encoding.Iconv at CAF +557107: cost centre 17 CAF in GHC.IO.Encoding.Failure at CAF +558225: cost centre 16 CAF in GHC.IO.Encoding at CAF +559272: cost centre 15 CAF in GHC.IO.Buffer at CAF +560390: cost centre 14 CAF in GHC.IO at CAF +561577: cost centre 13 CAF in GHC.ForeignPtr at CAF +562834: cost centre 12 CAF in GHC.Foreign at CAF +563882: cost centre 11 CAF in GHC.Fingerprint.Type at CAF +565279: cost centre 10 CAF in GHC.Fingerprint at CAF +566466: cost centre 9 CAF in GHC.Exception at CAF +567583: cost centre 8 CAF in GHC.Err at CAF +568701: cost centre 7 CAF in GHC.Conc.Sync at CAF +569748: cost centre 6 CAF in GHC.Conc.Signal at CAF +570936: cost centre 5 CAF in GHC.Conc.IO at CAF +572053: cost centre 4 CAF in GHC.Base at CAF +573101: cost centre 3 CAF in Data.Either at CAF +574148: cost centre 2 CAF in Control.Exception.Base at CAF +575196: cost centre 1 CAF in Main at CAF +672901: task 0x7ff358a2b740 created on cap 0 with OS kernel thread 30086 +680374: cap 0: creating thread 1 +685123: cap 0: running thread 1 +762644: cap 0: stopping thread 1 (stack overflow) +769698: cap 0: running thread 1 +798262: cap 0: creating thread 2 +812929: cap 0: stopping thread 1 (thread yielding) +926906: task 0x7ff3566e4700 created on cap 0 with OS kernel thread 30088 +928792: cap 0: running thread 2 +964270: cap 0: stopping thread 2 (thread yielding) +985641: cap 0: running thread 1 +1021189: cap 0: thread 2 has label "IOManager on cap 0" +1062883: cap 0: creating thread 3 +1068121: cap 0: stopping thread 1 (thread yielding) +1083416: cap 0: running thread 2 +1090190: cap 0: stopping thread 2 (making a foreign call) +1206892: task 0x7ff355ee3700 created on cap 0 with OS kernel thread 30089 +1210523: cap 0: running thread 3 +1281829: cap 0: stopping thread 3 (making a foreign call) +1350691: cap 0: running thread 1 +1362982: cap 0: thread 3 has label "TimerManager" +1365078: cap 0: stopping thread 1 (thread finished) +1445951: task 0x7ff358a2b740 deleted +1480941: task 0x7ff3556e2700 created on cap 0 with OS kernel thread 30090 +1494769: task 0x7ff358a2b740 created on cap 0 with OS kernel thread 30086 +1501194: cap 0: creating thread 4 +1503010: cap 0: running thread 4 +1557694: cap 0: stopping thread 4 (blocked on an MVar) +1580322: cap 0: running thread 3 +1600296: cap 0: stopping thread 3 (making a foreign call) +302857300: cap 0: running thread 3 +302880696: cap 0: stopping thread 3 (thread yielding) +302883699: cap 0: running thread 3 +302908772: cap 0: stopping thread 3 (making a foreign call) +302994464: cap 0: requesting parallel GC +303001379: cap 0: starting GC +303012553: cap 0: GC working +303222280: cap 0: GC idle +303223397: cap 0: GC done +303228566: cap 0: GC idle +303229473: cap 0: GC done +303231010: cap 0: GC idle +303231918: cap 0: GC done +303252381: cap 0: allocated on heap capset 0: 75736 total bytes till now +303255733: cap 0: finished GC +303256990: cap 0: all caps stopped for GC +303258247: cap 0: GC stats for heap capset 0: generation 1, 19984 bytes copied, 8728 bytes slop, 925696 bytes fragmentation, 1 par threads, 0 bytes max par copied, 19984 bytes total par copied +303259784: cap 0: live data in heap capset 0: 19944 bytes +303260831: cap 0: size of heap capset 0: 2097152 bytes +303263066: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5006669294: cap 0: running thread 3 +5006682773: cap 0: waking up thread 4 on cap 0 +5006690874: cap 0: stopping thread 3 (making a foreign call) +5006864425: cap 0: running thread 4 +5006866659: cap 0: stopping thread 4 (thread finished) +5006868824: task 0x7ff358a2b740 deleted +5006874831: task 0x7ff358a2b740 created on cap 0 with OS kernel thread 30086 +5006876926: cap 0: creating thread 5 +5006878183: cap 0: running thread 5 +5006909820: cap 0: stopping thread 5 (thread yielding) +5006914430: cap 0: requesting parallel GC +5006918131: cap 0: starting GC +5006924975: cap 0: GC working +5007150137: cap 0: GC idle +5007151464: cap 0: GC done +5007156841: cap 0: GC idle +5007157819: cap 0: GC done +5007159495: cap 0: GC idle +5007160403: cap 0: GC done +5007238414: start heap prof sample 0 +5007248191: heap prof sample 0, residency 48, cost centre stack 93 +5007251264: heap prof sample 0, residency 120, cost centre stack 18 +5007253429: heap prof sample 0, residency 640, cost centre stack 6 +5007255455: heap prof sample 0, residency 560, cost centre stack 60 +5007257340: heap prof sample 0, residency 128, cost centre stack 26 +5007259296: heap prof sample 0, residency 696, cost centre stack 16 +5007261531: heap prof sample 0, residency 9880, cost centre stack +5007334093: cap 0: allocated on heap capset 0: 81112 total bytes till now +5007335979: cap 0: finished GC +5007337306: cap 0: all caps stopped for GC +5007338563: cap 0: GC stats for heap capset 0: generation 1, 21824 bytes copied, 7432 bytes slop, 954368 bytes fragmentation, 1 par threads, 0 bytes max par copied, 21824 bytes total par copied +5007340100: cap 0: live data in heap capset 0: 21240 bytes +5007341077: cap 0: size of heap capset 0: 2097152 bytes +5007343592: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5007347014: cap 0: running thread 5 +5007392549: cap 0: stopping thread 5 (thread finished) +5007395063: task 0x7ff358a2b740 deleted +5007418529: cap 0: requesting sequential GC +5007422161: cap 0: starting GC +5007426561: cap 0: GC working +5007532926: cap 0: GC idle +5007533834: cap 0: GC done +5007537535: cap 0: GC idle +5007538373: cap 0: GC done +5007539072: cap 0: GC idle +5007540049: cap 0: GC done +5007551643: cap 0: allocated on heap capset 0: 119504 total bytes till now +5007553598: cap 0: finished GC +5007554506: cap 0: all caps stopped for GC +5007555414: cap 0: GC stats for heap capset 0: generation 1, 23152 bytes copied, 26368 bytes slop, 856064 bytes fragmentation, 1 par threads, 0 bytes max par copied, 23152 bytes total par copied +5007556392: cap 0: live data in heap capset 0: 55552 bytes +5007557230: cap 0: size of heap capset 0: 2097152 bytes +5007558766: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5007641735: cap 0: running thread 2 +5007667366: cap 0: stopping thread 2 (thread finished) +5007671627: task 0x7ff3566e4700 deleted +5007703892: cap 0: running thread 3 +5007719816: cap 0: stopping thread 3 (thread finished) +5007724355: task 0x7ff355ee3700 deleted +5007730152: task 0x7ff3556e2700 deleted +5007736298: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5008723894: cap 0: allocated on heap capset 0: 121184 total bytes till now +5008727177: removed cap 0 from capset 0 +5008728015: removed cap 0 from capset 1 +5008728783: deleted cap 0 +5008729551: deleted capset 0 +5008730320: deleted capset 1 + diff --git a/test/sleep.hC.eventlog b/test/sleep.hC.eventlog new file mode 100644 Binary files /dev/null and b/test/sleep.hC.eventlog differ diff --git a/test/sleep.hC.eventlog.reference b/test/sleep.hC.eventlog.reference new file mode 100644 --- /dev/null +++ b/test/sleep.hC.eventlog.reference @@ -0,0 +1,301 @@ +Event Types: +0: Create thread (size 4) +1: Run thread (size 4) +2: Stop thread (size 10) +3: Thread runnable (size 4) +4: Migrate thread (size 6) +8: Wakeup thread (size 6) +9: Starting GC (size 0) +10: Finished GC (size 0) +11: Request sequential GC (size 0) +12: Request parallel GC (size 0) +15: Create spark thread (size 4) +16: Log message (size variable) +18: Block marker (size 14) +19: User message (size variable) +20: GC idle (size 0) +21: GC working (size 0) +22: GC done (size 0) +25: Create capability set (size 6) +26: Delete capability set (size 4) +27: Add capability to capability set (size 6) +28: Remove capability from capability set (size 6) +29: RTS name and version (size variable) +30: Program arguments (size variable) +31: Program environment variables (size variable) +32: Process ID (size 8) +33: Parent process ID (size 8) +34: Spark counters (size 56) +35: Spark create (size 0) +36: Spark dud (size 0) +37: Spark overflow (size 0) +38: Spark run (size 0) +39: Spark steal (size 2) +40: Spark fizzle (size 0) +41: Spark GC (size 0) +43: Wall clock time (size 16) +44: Thread label (size variable) +45: Create capability (size 2) +46: Delete capability (size 2) +47: Disable capability (size 2) +48: Enable capability (size 2) +49: Total heap mem ever allocated (size 12) +50: Current heap size (size 12) +51: Current heap live data (size 12) +52: Heap static parameters (size 38) +53: GC statistics (size 50) +54: Synchronise stop-the-world GC (size 0) +55: Task create (size 18) +56: Task migrate (size 12) +57: Task delete (size 8) +58: User marker (size variable) +59: Empty event for bug #9003 (size 0) +160: Start of heap profile (size variable) +161: Cost center definition (size variable) +162: Start of heap profile sample (size 8) +163: Heap profile cost-centre sample (size variable) +164: Heap profile string sample (size variable) + +Events: +130320: created capset 0 of type CapsetOsProcess +132904: created capset 1 of type CapsetClockDomain +151342: created cap 0 +152389: assigned cap 0 to capset 0 +153367: assigned cap 0 to capset 1 +154624: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +160351: capset 1: wall clock time 1496042179s 794167000ns (unix epoch) +161817: capset 0: pid 30912 +164681: capset 0: parent pid 27111 +169290: capset 0: RTS version "GHC-8.2.0.20170507 rts_thr_p" +173690: capset 0: args: ["./sleep","+RTS","-l","-hC"] +178579: capset 0: env: ["ADOTDIR=/home/maoe/.antigen","ANTIGEN_COMPDUMPFILE=/home/maoe/.zcompdump","ANTIGEN_DEFAULT_REPO_URL=https://github.com/robbyrussell/oh-my-zsh.git","AUTOJUMP_ERROR_PATH=/home/maoe/.local/share/autojump/errors.log","AUTOJUMP_SOURCED=1","CLUTTER_IM_MODULE=xim","DBUS_SESSION_BUS_ADDRESS=unix:abstract=/tmp/dbus-ioIEQwU7Ny","DEFAULTS_PATH=/usr/share/gconf/gnome.default.path","DERBY_HOME=/usr/lib/jvm/java-8-oracle/db","DESKTOP_SESSION=gnome","DISPLAY=:0","EDITOR=vim","GDMSESSION=gnome","GDM_LANG=en","GJS_DEBUG_OUTPUT=stderr","GJS_DEBUG_TOPICS=JS ERROR;JS LOG","GNOME_DESKTOP_SESSION_ID=this-is-deprecated","GNOME_KEYRING_CONTROL=","GNOME_KEYRING_PID=","GOPATH=/home/maoe/.go","GPG_AGENT_INFO=/home/maoe/.gnupg/S.gpg-agent:0:1","GTK_IM_MODULE=ibus","HOME=/home/maoe","IM_CONFIG_PHASE=1","INSTANCE=","J2REDIR=/usr/lib/jvm/java-8-oracle/jre","J2SDKDIR=/usr/lib/jvm/java-8-oracle","JAVA_HOME=/usr/lib/jvm/java-8-oracle","JOB=dbus","LANG=en_US.UTF-8","LANGUAGE=en","LC_ADDRESS=en_US.UTF-8","LC_CTYPE=en_US.UTF-8","LC_IDENTIFICATION=en_US.UTF-8","LC_MEASUREMENT=en_US.UTF-8","LC_MONETARY=en_US.UTF-8","LC_NAME=en_US.UTF-8","LC_NUMERIC=en_US.UTF-8","LC_PAPER=en_US.UTF-8","LC_TELEPHONE=en_US.UTF-8","LC_TIME=en_US.UTF-8","LESS=-R","LIBVIRT_DEFAULT_URI=qemu:///system","LOGNAME=maoe","LS_COLORS=di=34:ln=35:so=32:pi=33:ex=31:bd=46;34:cd=43;34:su=41;30:sg=46;30:tw=42;30:ow=43;30","MANDATORY_PATH=/usr/share/gconf/gnome.mandatory.path","NODE_PATH=/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript","OLDPWD=/home/maoe/src/github.com/haskell/ghc-events","PAGER=less","PAPERSIZE=letter","PATH=/usr/local/ghc/ghc-8.2.0-rc2/bin:/home/maoe/.npm-packages/bin:/home/maoe/Downloads/google-cloud-sdk/bin:/home/maoe/src/github.com/phacility/arcanist/bin:/home/maoe/.cargo/bin:/home/maoe/.local/bin:/home/maoe/.cabal/bin:/home/maoe/bin:/usr/local/bin:/usr/local/sbin:/home/maoe/.npm-packages/bin:/home/maoe/Downloads/google-cloud-sdk/bin:/home/maoe/src/github.com/phacility/arcanist/bin:/home/maoe/.cargo/bin:/home/maoe/.local/bin:/home/maoe/.cabal/bin:/home/maoe/bin:/usr/local/bin:/usr/local/sbin:/home/maoe/.cargo/bin:/home/maoe/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/usr/lib/jvm/java-8-oracle/bin:/usr/lib/jvm/java-8-oracle/db/bin:/usr/lib/jvm/java-8-oracle/jre/bin","PWD=/home/maoe/src/github.com/haskell/ghc-events","QT4_IM_MODULE=ibus","QT_ACCESSIBILITY=1","QT_IM_MODULE=ibus","QT_LINUX_ACCESSIBILITY_ALWAYS_ON=1","SESSION=gnome","SESSIONTYPE=gnome-session","SESSION_MANAGER=local/vangelis.tsuru.it:@/tmp/.ICE-unix/5489,unix/vangelis.tsuru.it:/tmp/.ICE-unix/5489","SHELL=/bin/zsh","SHLVL=2","SSH_AUTH_SOCK=/run/user/2016/keyring/ssh","TERM=screen-256color","TMUX=/tmp/tmux-2016/default,10542,3","TMUX_PANE=%93","UBUNTU_MENUPROXY=libappmenu.so","UPSTART_SESSION=unix:abstract=/com/ubuntu/upstart-session/2016/5282","USER=maoe","VTE_VERSION=4205","WINDOWID=71468690","XAUTHORITY=/home/maoe/.Xauthority","XDG_CONFIG_DIRS=/etc/xdg/xdg-gnome:/usr/share/upstart/xdg:/etc/xdg","XDG_CURRENT_DESKTOP=GNOME","XDG_DATA_DIRS=/usr/share/gnome:/usr/local/share/:/usr/share/","XDG_GREETER_DATA_DIR=/var/lib/lightdm-data/maoe","XDG_MENU_PREFIX=gnome-","XDG_RUNTIME_DIR=/run/user/2016","XDG_SEAT=seat0","XDG_SEAT_PATH=/org/freedesktop/DisplayManager/Seat0","XDG_SESSION_DESKTOP=gnome","XDG_SESSION_ID=c2","XDG_SESSION_PATH=/org/freedesktop/DisplayManager/Session0","XDG_SESSION_TYPE=x11","XDG_VTNR=7","XMODIFIERS=@im=ibus","ZSH=/home/maoe/.antigen/repos/https-COLON--SLASH--SLASH-github.com-SLASH-robbyrussell-SLASH-oh-my-zsh.git","ZSH_CACHE_DIR=/home/maoe/.antigen/repos/https-COLON--SLASH--SLASH-github.com-SLASH-robbyrussell-SLASH-oh-my-zsh.git/cache/","_=/home/maoe/src/github.com/haskell/ghc-events/./sleep","_ANTIGEN_BUNDLE_RECORD=\nhttps://github.com/robbyrussell/oh-my-zsh.git lib plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git plugins/git plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git plugins/pass plugin true \nhttps://github.com/zsh-users/zsh-syntax-highlighting.git / plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git themes/kphoen.zsh-theme theme true ","_ANTIGEN_LOG_PATH=/home/maoe/.antigen/antigen.log","_ZCACHE_BUNDLES_PATH=/home/maoe/.antigen/.cache/.zcache-bundles","_ZCACHE_CACHE_LOADED=true","_ZCACHE_CACHE_VERSION=v1.4.1","_ZCACHE_EXTENSION_BUNDLE=false","_ZCACHE_EXTENSION_CLEAN_FUNCTIONS=true","_ZCACHE_PATH=/home/maoe/.antigen/.cache","_ZCACHE_PAYLOAD_PATH=/home/maoe/.antigen/.cache/.zcache-payload","LSCOLORS=Gxfxcxdxbxegedabagacad","MANPATH=/home/maoe/.npm-packages/share/man:/home/maoe/.local/share/man:/home/maoe/.cabal/share/man:/usr/local/man:/usr/local/share/man:/usr/share/man:/usr/lib/jvm/java-8-oracle/man"] +248837: heap stats for heap capset 0: generations 2, 0 bytes max heap size, 1048576 bytes alloc area size, 1048576 bytes mblock size, 4096 bytes block size +552708: start heap profiling 0 at sampling period 100000000 broken down by cost centre +555641: cost centre 110 IDLE in IDLE at +557457: cost centre 109 PINNED in SYSTEM at +558854: cost centre 108 DONT_CARE in MAIN at +560111: cost centre 107 OVERHEAD_of in PROFILING at +561298: cost centre 106 GC in GC at +562625: cost centre 105 SYSTEM in SYSTEM at +563742: cost centre 104 MAIN in MAIN at +565069: cost centre 103 CAF in GHC.Types at CAF +566326: cost centre 102 CAF in GHC.Tuple at CAF +567653: cost centre 101 CAF in GHC.Classes at CAF +568841: cost centre 100 CAF in GHC.CString at CAF +570237: cost centre 99 CAF in GHC.Integer.Type at CAF +571634: cost centre 98 CAF in GHC.Integer.Logarithms.Internals at CAF +572961: cost centre 97 CAF in GHC.Integer.Logarithms at CAF +574288: cost centre 96 CAF in GHC.Event.Array at CAF +575545: cost centre 95 CAF in GHC.Event.Arr at CAF +576663: cost centre 94 CAF in Data.Proxy at CAF +577989: cost centre 93 CAF in GHC.Event.Poll at CAF +579177: cost centre 92 CAF in GHC.Event.PSQ at CAF +580574: cost centre 91 CAF in GHC.Event.Manager at CAF +581970: cost centre 90 CAF in GHC.Event.IntTable at CAF +583227: cost centre 89 CAF in GHC.Event.EPoll at CAF +584485: cost centre 88 CAF in GHC.Event.Control at CAF +585672: cost centre 87 CAF in System.Posix.Types at CAF +586929: cost centre 86 CAF in GHC.Storable at CAF +588116: cost centre 85 CAF in GHC.Natural at CAF +589373: cost centre 84 CAF in GHC.IO.FD at CAF +590770: cost centre 83 CAF in GHC.IO.Device at CAF +592027: cost centre 82 CAF in GHC.IO.BufferedIO at CAF +593424: cost centre 81 CAF in GHC.Generics at CAF +594681: cost centre 80 CAF in GHC.Float.RealFracMethods at CAF +595938: cost centre 79 CAF in GHC.Float.ConversionUtils at CAF +597125: cost centre 78 CAF in GHC.Float at CAF +598522: cost centre 77 CAF in GHC.Enum at CAF +599849: cost centre 76 CAF in GHC.Char at CAF +601386: cost centre 75 CAF in GHC.Arr at CAF +602852: cost centre 74 CAF in Foreign.Storable at CAF +604389: cost centre 73 CAF in Foreign.Marshal.Array at CAF +605855: cost centre 72 CAF in Foreign.Marshal.Alloc at CAF +607112: cost centre 71 CAF in Foreign.C.Types at CAF +608509: cost centre 70 CAF in Foreign.C.String at CAF +609976: cost centre 69 CAF in Foreign.C.Error at CAF +611373: cost centre 68 CAF in Data.Type.Equality at CAF +612630: cost centre 67 CAF in Data.Tuple at CAF +613817: cost centre 66 CAF in Data.Maybe at CAF +615004: cost centre 65 CAF in Data.Dynamic at CAF +616122: cost centre 64 CAF in Data.Bits at CAF +617379: cost centre 63 CAF in Control.Monad.Fail at CAF +618776: cost centre 62 CAF in GHC.Event.Unique at CAF +620172: cost centre 61 CAF in GHC.Event.TimerManager at CAF +621569: cost centre 60 CAF in GHC.Event.Thread at CAF +622826: cost centre 59 CAF in GHC.Event.Internal at CAF +624153: cost centre 58 CAF in Data.Typeable.Internal at CAF +625410: cost centre 57 CAF in Data.OldList at CAF +626598: cost centre 56 CAF in Text.Read.Lex at CAF +627855: cost centre 55 CAF in Text.ParserCombinators.ReadPrec at CAF +629042: cost centre 54 CAF in Text.ParserCombinators.ReadP at CAF +630369: cost centre 53 CAF in System.Posix.Internals at CAF +631556: cost centre 52 CAF in System.IO at CAF +632743: cost centre 51 CAF in Numeric at CAF +634001: cost centre 50 CAF in GHC.Word at CAF +635258: cost centre 49 CAF in GHC.Weak at CAF +636585: cost centre 48 CAF in GHC.Unicode at CAF +637842: cost centre 47 CAF in GHC.TopHandler at CAF +639099: cost centre 46 CAF in GHC.Stack.Types at CAF +644756: cost centre 45 CAF in GHC.Stack.CCS at CAF +646013: cost centre 44 CAF in GHC.Stable at CAF +647340: cost centre 43 CAF in GHC.Show at CAF +648597: cost centre 42 CAF in GHC.STRef at CAF +649854: cost centre 41 CAF in GHC.ST at CAF +651251: cost centre 40 CAF in GHC.Real at CAF +652508: cost centre 39 CAF in GHC.Read at CAF +653835: cost centre 38 CAF in GHC.Ptr at CAF +655092: cost centre 37 CAF in GHC.Pack at CAF +656419: cost centre 36 CAF in GHC.Num at CAF +657746: cost centre 35 CAF in GHC.MVar at CAF +659003: cost centre 34 CAF in GHC.List at CAF +660260: cost centre 33 CAF in GHC.Int at CAF +661378: cost centre 32 CAF in GHC.IORef at CAF +662495: cost centre 31 CAF in GHC.IO.Unsafe at CAF +663892: cost centre 30 CAF in GHC.IO.IOMode at CAF +665289: cost centre 29 CAF in GHC.IO.Handle.Types at CAF +666685: cost centre 28 CAF in GHC.IO.Handle.Text at CAF +668152: cost centre 27 CAF in GHC.IO.Handle.Internals at CAF +669409: cost centre 26 CAF in GHC.IO.Handle.FD at CAF +670736: cost centre 25 CAF in GHC.IO.Handle at CAF +672203: cost centre 24 CAF in GHC.IO.Exception at CAF +673599: cost centre 23 CAF in GHC.IO.Encoding.UTF8 at CAF +674787: cost centre 22 CAF in GHC.IO.Encoding.UTF32 at CAF +676602: cost centre 21 CAF in GHC.IO.Encoding.UTF16 at CAF +677860: cost centre 20 CAF in GHC.IO.Encoding.Types at CAF +679117: cost centre 19 CAF in GHC.IO.Encoding.Latin1 at CAF +680513: cost centre 18 CAF in GHC.IO.Encoding.Iconv at CAF +681771: cost centre 17 CAF in GHC.IO.Encoding.Failure at CAF +683098: cost centre 16 CAF in GHC.IO.Encoding at CAF +684355: cost centre 15 CAF in GHC.IO.Buffer at CAF +685542: cost centre 14 CAF in GHC.IO at CAF +687009: cost centre 13 CAF in GHC.ForeignPtr at CAF +688335: cost centre 12 CAF in GHC.Foreign at CAF +689593: cost centre 11 CAF in GHC.Fingerprint.Type at CAF +690920: cost centre 10 CAF in GHC.Fingerprint at CAF +692316: cost centre 9 CAF in GHC.Exception at CAF +693643: cost centre 8 CAF in GHC.Err at CAF +694900: cost centre 7 CAF in GHC.Conc.Sync at CAF +696088: cost centre 6 CAF in GHC.Conc.Signal at CAF +697345: cost centre 5 CAF in GHC.Conc.IO at CAF +698602: cost centre 4 CAF in GHC.Base at CAF +699859: cost centre 3 CAF in Data.Either at CAF +701116: cost centre 2 CAF in Control.Exception.Base at CAF +702303: cost centre 1 CAF in Main at CAF +831855: task 0x7fe6bcade740 created on cap 0 with OS kernel thread 30912 +840166: cap 0: creating thread 1 +845683: cap 0: running thread 1 +938500: cap 0: stopping thread 1 (stack overflow) +949325: cap 0: running thread 1 +994022: cap 0: creating thread 2 +1015951: cap 0: stopping thread 1 (thread yielding) +1176651: task 0x7fe6ba797700 created on cap 0 with OS kernel thread 30914 +1179724: cap 0: running thread 2 +1203540: cap 0: stopping thread 2 (thread yielding) +1223304: cap 0: running thread 1 +1252217: cap 0: thread 2 has label "IOManager on cap 0" +1292864: cap 0: creating thread 3 +1298591: cap 0: stopping thread 1 (thread yielding) +1314374: cap 0: running thread 2 +1320520: cap 0: stopping thread 2 (making a foreign call) +1426327: task 0x7fe6b9f96700 created on cap 0 with OS kernel thread 30915 +1429330: cap 0: running thread 3 +1455310: cap 0: stopping thread 3 (making a foreign call) +1503080: cap 0: running thread 1 +1520400: cap 0: thread 3 has label "TimerManager" +1523473: cap 0: stopping thread 1 (thread finished) +1604487: task 0x7fe6bcade740 deleted +1650301: task 0x7fe6b9795700 created on cap 0 with OS kernel thread 30916 +1665666: task 0x7fe6bcade740 created on cap 0 with OS kernel thread 30912 +1672021: cap 0: creating thread 4 +1673977: cap 0: running thread 4 +1724750: cap 0: stopping thread 4 (blocked on an MVar) +1762533: cap 0: running thread 3 +1780761: cap 0: stopping thread 3 (making a foreign call) +302988109: cap 0: running thread 3 +303012204: cap 0: stopping thread 3 (thread yielding) +303015277: cap 0: running thread 3 +303042654: cap 0: stopping thread 3 (making a foreign call) +303166339: cap 0: requesting parallel GC +303173812: cap 0: starting GC +303187430: cap 0: GC working +303401488: cap 0: GC idle +303402675: cap 0: GC done +303408122: cap 0: GC idle +303409100: cap 0: GC done +303410706: cap 0: GC idle +303411614: cap 0: GC done +303433544: cap 0: allocated on heap capset 0: 75736 total bytes till now +303436687: cap 0: finished GC +303438153: cap 0: all caps stopped for GC +303439410: cap 0: GC stats for heap capset 0: generation 1, 19984 bytes copied, 8728 bytes slop, 925696 bytes fragmentation, 1 par threads, 0 bytes max par copied, 19984 bytes total par copied +303441436: cap 0: live data in heap capset 0: 19944 bytes +303442483: cap 0: size of heap capset 0: 2097152 bytes +303445137: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5006855904: cap 0: running thread 3 +5006884259: cap 0: waking up thread 4 on cap 0 +5006892291: cap 0: stopping thread 3 (making a foreign call) +5006945787: cap 0: running thread 4 +5006949140: cap 0: stopping thread 4 (thread finished) +5006952422: task 0x7fe6bcade740 deleted +5006961571: task 0x7fe6bcade740 created on cap 0 with OS kernel thread 30912 +5006964574: cap 0: creating thread 5 +5006966530: cap 0: running thread 5 +5006996211: cap 0: stopping thread 5 (thread yielding) +5007001868: cap 0: requesting parallel GC +5007006827: cap 0: starting GC +5007014719: cap 0: GC working +5007213411: cap 0: GC idle +5007214599: cap 0: GC done +5007219208: cap 0: GC idle +5007220116: cap 0: GC done +5007221722: cap 0: GC idle +5007222630: cap 0: GC done +5007294146: start heap prof sample 0 +5007302806: heap prof sample 0, residency 48, cost centre stack 93 +5007305809: heap prof sample 0, residency 120, cost centre stack 18 +5007307834: heap prof sample 0, residency 640, cost centre stack 6 +5007309790: heap prof sample 0, residency 560, cost centre stack 60 +5007311745: heap prof sample 0, residency 128, cost centre stack 26 +5007313631: heap prof sample 0, residency 696, cost centre stack 16 +5007315726: heap prof sample 0, residency 9880, cost centre stack +5007387730: cap 0: allocated on heap capset 0: 81112 total bytes till now +5007389616: cap 0: finished GC +5007390943: cap 0: all caps stopped for GC +5007392060: cap 0: GC stats for heap capset 0: generation 1, 21824 bytes copied, 7432 bytes slop, 954368 bytes fragmentation, 1 par threads, 0 bytes max par copied, 21824 bytes total par copied +5007393457: cap 0: live data in heap capset 0: 21240 bytes +5007394435: cap 0: size of heap capset 0: 2097152 bytes +5007396949: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5007399882: cap 0: running thread 5 +5007445348: cap 0: stopping thread 5 (thread finished) +5007447513: task 0x7fe6bcade740 deleted +5007466369: cap 0: requesting sequential GC +5007469931: cap 0: starting GC +5007474191: cap 0: GC working +5007602835: cap 0: GC idle +5007604162: cap 0: GC done +5007609260: cap 0: GC idle +5007610168: cap 0: GC done +5007611425: cap 0: GC idle +5007612613: cap 0: GC done +5007628885: cap 0: allocated on heap capset 0: 119504 total bytes till now +5007631469: cap 0: finished GC +5007632517: cap 0: all caps stopped for GC +5007633494: cap 0: GC stats for heap capset 0: generation 1, 23152 bytes copied, 26368 bytes slop, 856064 bytes fragmentation, 1 par threads, 0 bytes max par copied, 23152 bytes total par copied +5007634821: cap 0: live data in heap capset 0: 55552 bytes +5007635799: cap 0: size of heap capset 0: 2097152 bytes +5007637615: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5007654935: cap 0: running thread 2 +5007704730: cap 0: stopping thread 2 (thread finished) +5007713251: task 0x7fe6ba797700 deleted +5007724285: cap 0: running thread 3 +5007759135: cap 0: stopping thread 3 (thread finished) +5007769262: task 0x7fe6b9f96700 deleted +5007824156: task 0x7fe6b9795700 deleted +5007837146: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5007897766: cap 0: allocated on heap capset 0: 121184 total bytes till now +5007903283: removed cap 0 from capset 0 +5007904541: removed cap 0 from capset 1 +5007905658: deleted cap 0 +5007906775: deleted capset 0 +5007907823: deleted capset 1 + diff --git a/test/sleep.hd.eventlog b/test/sleep.hd.eventlog new file mode 100644 Binary files /dev/null and b/test/sleep.hd.eventlog differ diff --git a/test/sleep.hd.eventlog.reference b/test/sleep.hd.eventlog.reference new file mode 100644 --- /dev/null +++ b/test/sleep.hd.eventlog.reference @@ -0,0 +1,340 @@ +Event Types: +0: Create thread (size 4) +1: Run thread (size 4) +2: Stop thread (size 10) +3: Thread runnable (size 4) +4: Migrate thread (size 6) +8: Wakeup thread (size 6) +9: Starting GC (size 0) +10: Finished GC (size 0) +11: Request sequential GC (size 0) +12: Request parallel GC (size 0) +15: Create spark thread (size 4) +16: Log message (size variable) +18: Block marker (size 14) +19: User message (size variable) +20: GC idle (size 0) +21: GC working (size 0) +22: GC done (size 0) +25: Create capability set (size 6) +26: Delete capability set (size 4) +27: Add capability to capability set (size 6) +28: Remove capability from capability set (size 6) +29: RTS name and version (size variable) +30: Program arguments (size variable) +31: Program environment variables (size variable) +32: Process ID (size 8) +33: Parent process ID (size 8) +34: Spark counters (size 56) +35: Spark create (size 0) +36: Spark dud (size 0) +37: Spark overflow (size 0) +38: Spark run (size 0) +39: Spark steal (size 2) +40: Spark fizzle (size 0) +41: Spark GC (size 0) +43: Wall clock time (size 16) +44: Thread label (size variable) +45: Create capability (size 2) +46: Delete capability (size 2) +47: Disable capability (size 2) +48: Enable capability (size 2) +49: Total heap mem ever allocated (size 12) +50: Current heap size (size 12) +51: Current heap live data (size 12) +52: Heap static parameters (size 38) +53: GC statistics (size 50) +54: Synchronise stop-the-world GC (size 0) +55: Task create (size 18) +56: Task migrate (size 12) +57: Task delete (size 8) +58: User marker (size variable) +59: Empty event for bug #9003 (size 0) +160: Start of heap profile (size variable) +161: Cost center definition (size variable) +162: Start of heap profile sample (size 8) +163: Heap profile cost-centre sample (size variable) +164: Heap profile string sample (size variable) + +Events: +108251: created capset 0 of type CapsetOsProcess +110486: created capset 1 of type CapsetClockDomain +114676: created cap 0 +115654: assigned cap 0 to capset 0 +116492: assigned cap 0 to capset 1 +117540: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +122429: capset 1: wall clock time 1496042127s 89877000ns (unix epoch) +123336: capset 0: pid 30307 +125711: capset 0: parent pid 27111 +128924: capset 0: RTS version "GHC-8.2.0.20170507 rts_thr_p" +131577: capset 0: args: ["./sleep","+RTS","-l","-hd"] +135279: capset 0: env: ["ADOTDIR=/home/maoe/.antigen","ANTIGEN_COMPDUMPFILE=/home/maoe/.zcompdump","ANTIGEN_DEFAULT_REPO_URL=https://github.com/robbyrussell/oh-my-zsh.git","AUTOJUMP_ERROR_PATH=/home/maoe/.local/share/autojump/errors.log","AUTOJUMP_SOURCED=1","CLUTTER_IM_MODULE=xim","DBUS_SESSION_BUS_ADDRESS=unix:abstract=/tmp/dbus-ioIEQwU7Ny","DEFAULTS_PATH=/usr/share/gconf/gnome.default.path","DERBY_HOME=/usr/lib/jvm/java-8-oracle/db","DESKTOP_SESSION=gnome","DISPLAY=:0","EDITOR=vim","GDMSESSION=gnome","GDM_LANG=en","GJS_DEBUG_OUTPUT=stderr","GJS_DEBUG_TOPICS=JS ERROR;JS LOG","GNOME_DESKTOP_SESSION_ID=this-is-deprecated","GNOME_KEYRING_CONTROL=","GNOME_KEYRING_PID=","GOPATH=/home/maoe/.go","GPG_AGENT_INFO=/home/maoe/.gnupg/S.gpg-agent:0:1","GTK_IM_MODULE=ibus","HOME=/home/maoe","IM_CONFIG_PHASE=1","INSTANCE=","J2REDIR=/usr/lib/jvm/java-8-oracle/jre","J2SDKDIR=/usr/lib/jvm/java-8-oracle","JAVA_HOME=/usr/lib/jvm/java-8-oracle","JOB=dbus","LANG=en_US.UTF-8","LANGUAGE=en","LC_ADDRESS=en_US.UTF-8","LC_CTYPE=en_US.UTF-8","LC_IDENTIFICATION=en_US.UTF-8","LC_MEASUREMENT=en_US.UTF-8","LC_MONETARY=en_US.UTF-8","LC_NAME=en_US.UTF-8","LC_NUMERIC=en_US.UTF-8","LC_PAPER=en_US.UTF-8","LC_TELEPHONE=en_US.UTF-8","LC_TIME=en_US.UTF-8","LESS=-R","LIBVIRT_DEFAULT_URI=qemu:///system","LOGNAME=maoe","LS_COLORS=di=34:ln=35:so=32:pi=33:ex=31:bd=46;34:cd=43;34:su=41;30:sg=46;30:tw=42;30:ow=43;30","MANDATORY_PATH=/usr/share/gconf/gnome.mandatory.path","NODE_PATH=/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript","OLDPWD=/home/maoe/src/github.com/haskell/ghc-events","PAGER=less","PAPERSIZE=letter","PATH=/usr/local/ghc/ghc-8.2.0-rc2/bin:/home/maoe/.npm-packages/bin:/home/maoe/Downloads/google-cloud-sdk/bin:/home/maoe/src/github.com/phacility/arcanist/bin:/home/maoe/.cargo/bin:/home/maoe/.local/bin:/home/maoe/.cabal/bin:/home/maoe/bin:/usr/local/bin:/usr/local/sbin:/home/maoe/.npm-packages/bin:/home/maoe/Downloads/google-cloud-sdk/bin:/home/maoe/src/github.com/phacility/arcanist/bin:/home/maoe/.cargo/bin:/home/maoe/.local/bin:/home/maoe/.cabal/bin:/home/maoe/bin:/usr/local/bin:/usr/local/sbin:/home/maoe/.cargo/bin:/home/maoe/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/usr/lib/jvm/java-8-oracle/bin:/usr/lib/jvm/java-8-oracle/db/bin:/usr/lib/jvm/java-8-oracle/jre/bin","PWD=/home/maoe/src/github.com/haskell/ghc-events","QT4_IM_MODULE=ibus","QT_ACCESSIBILITY=1","QT_IM_MODULE=ibus","QT_LINUX_ACCESSIBILITY_ALWAYS_ON=1","SESSION=gnome","SESSIONTYPE=gnome-session","SESSION_MANAGER=local/vangelis.tsuru.it:@/tmp/.ICE-unix/5489,unix/vangelis.tsuru.it:/tmp/.ICE-unix/5489","SHELL=/bin/zsh","SHLVL=2","SSH_AUTH_SOCK=/run/user/2016/keyring/ssh","TERM=screen-256color","TMUX=/tmp/tmux-2016/default,10542,3","TMUX_PANE=%93","UBUNTU_MENUPROXY=libappmenu.so","UPSTART_SESSION=unix:abstract=/com/ubuntu/upstart-session/2016/5282","USER=maoe","VTE_VERSION=4205","WINDOWID=71468690","XAUTHORITY=/home/maoe/.Xauthority","XDG_CONFIG_DIRS=/etc/xdg/xdg-gnome:/usr/share/upstart/xdg:/etc/xdg","XDG_CURRENT_DESKTOP=GNOME","XDG_DATA_DIRS=/usr/share/gnome:/usr/local/share/:/usr/share/","XDG_GREETER_DATA_DIR=/var/lib/lightdm-data/maoe","XDG_MENU_PREFIX=gnome-","XDG_RUNTIME_DIR=/run/user/2016","XDG_SEAT=seat0","XDG_SEAT_PATH=/org/freedesktop/DisplayManager/Seat0","XDG_SESSION_DESKTOP=gnome","XDG_SESSION_ID=c2","XDG_SESSION_PATH=/org/freedesktop/DisplayManager/Session0","XDG_SESSION_TYPE=x11","XDG_VTNR=7","XMODIFIERS=@im=ibus","ZSH=/home/maoe/.antigen/repos/https-COLON--SLASH--SLASH-github.com-SLASH-robbyrussell-SLASH-oh-my-zsh.git","ZSH_CACHE_DIR=/home/maoe/.antigen/repos/https-COLON--SLASH--SLASH-github.com-SLASH-robbyrussell-SLASH-oh-my-zsh.git/cache/","_=/home/maoe/src/github.com/haskell/ghc-events/./sleep","_ANTIGEN_BUNDLE_RECORD=\nhttps://github.com/robbyrussell/oh-my-zsh.git lib plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git plugins/git plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git plugins/pass plugin true \nhttps://github.com/zsh-users/zsh-syntax-highlighting.git / plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git themes/kphoen.zsh-theme theme true ","_ANTIGEN_LOG_PATH=/home/maoe/.antigen/antigen.log","_ZCACHE_BUNDLES_PATH=/home/maoe/.antigen/.cache/.zcache-bundles","_ZCACHE_CACHE_LOADED=true","_ZCACHE_CACHE_VERSION=v1.4.1","_ZCACHE_EXTENSION_BUNDLE=false","_ZCACHE_EXTENSION_CLEAN_FUNCTIONS=true","_ZCACHE_PATH=/home/maoe/.antigen/.cache","_ZCACHE_PAYLOAD_PATH=/home/maoe/.antigen/.cache/.zcache-payload","LSCOLORS=Gxfxcxdxbxegedabagacad","MANPATH=/home/maoe/.npm-packages/share/man:/home/maoe/.local/share/man:/home/maoe/.cabal/share/man:/usr/local/man:/usr/local/share/man:/usr/share/man:/usr/lib/jvm/java-8-oracle/man"] +178789: heap stats for heap capset 0: generations 2, 0 bytes max heap size, 1048576 bytes alloc area size, 1048576 bytes mblock size, 4096 bytes block size +326848: start heap profiling 0 at sampling period 100000000 broken down by closure description +328664: cost centre 110 IDLE in IDLE at +329921: cost centre 109 PINNED in SYSTEM at +330829: cost centre 108 DONT_CARE in MAIN at +331667: cost centre 107 OVERHEAD_of in PROFILING at +332575: cost centre 106 GC in GC at +333413: cost centre 105 SYSTEM in SYSTEM at +334251: cost centre 104 MAIN in MAIN at +335159: cost centre 103 CAF in GHC.Types at CAF +336067: cost centre 102 CAF in GHC.Tuple at CAF +337045: cost centre 101 CAF in GHC.Classes at CAF +337952: cost centre 100 CAF in GHC.CString at CAF +338930: cost centre 99 CAF in GHC.Integer.Type at CAF +339768: cost centre 98 CAF in GHC.Integer.Logarithms.Internals at CAF +340746: cost centre 97 CAF in GHC.Integer.Logarithms at CAF +341654: cost centre 96 CAF in GHC.Event.Array at CAF +342562: cost centre 95 CAF in GHC.Event.Arr at CAF +343330: cost centre 94 CAF in Data.Proxy at CAF +344308: cost centre 93 CAF in GHC.Event.Poll at CAF +345146: cost centre 92 CAF in GHC.Event.PSQ at CAF +346054: cost centre 91 CAF in GHC.Event.Manager at CAF +347101: cost centre 90 CAF in GHC.Event.IntTable at CAF +348009: cost centre 89 CAF in GHC.Event.EPoll at CAF +348847: cost centre 88 CAF in GHC.Event.Control at CAF +349685: cost centre 87 CAF in System.Posix.Types at CAF +350733: cost centre 86 CAF in GHC.Storable at CAF +351571: cost centre 85 CAF in GHC.Natural at CAF +352479: cost centre 84 CAF in GHC.IO.FD at CAF +353387: cost centre 83 CAF in GHC.IO.Device at CAF +354295: cost centre 82 CAF in GHC.IO.BufferedIO at CAF +355063: cost centre 81 CAF in GHC.Generics at CAF +355971: cost centre 80 CAF in GHC.Float.RealFracMethods at CAF +356809: cost centre 79 CAF in GHC.Float.ConversionUtils at CAF +357647: cost centre 78 CAF in GHC.Float at CAF +358485: cost centre 77 CAF in GHC.Enum at CAF +359323: cost centre 76 CAF in GHC.Char at CAF +360231: cost centre 75 CAF in GHC.Arr at CAF +361139: cost centre 74 CAF in Foreign.Storable at CAF +362047: cost centre 73 CAF in Foreign.Marshal.Array at CAF +362955: cost centre 72 CAF in Foreign.Marshal.Alloc at CAF +363793: cost centre 71 CAF in Foreign.C.Types at CAF +364631: cost centre 70 CAF in Foreign.C.String at CAF +365539: cost centre 69 CAF in Foreign.C.Error at CAF +366517: cost centre 68 CAF in Data.Type.Equality at CAF +367285: cost centre 67 CAF in Data.Tuple at CAF +368123: cost centre 66 CAF in Data.Maybe at CAF +368961: cost centre 65 CAF in Data.Dynamic at CAF +369799: cost centre 64 CAF in Data.Bits at CAF +370567: cost centre 63 CAF in Control.Monad.Fail at CAF +371475: cost centre 62 CAF in GHC.Event.Unique at CAF +372383: cost centre 61 CAF in GHC.Event.TimerManager at CAF +373431: cost centre 60 CAF in GHC.Event.Thread at CAF +374269: cost centre 59 CAF in GHC.Event.Internal at CAF +375177: cost centre 58 CAF in Data.Typeable.Internal at CAF +376085: cost centre 57 CAF in Data.OldList at CAF +376853: cost centre 56 CAF in Text.Read.Lex at CAF +377900: cost centre 55 CAF in Text.ParserCombinators.ReadPrec at CAF +378739: cost centre 54 CAF in Text.ParserCombinators.ReadP at CAF +379577: cost centre 53 CAF in System.Posix.Internals at CAF +380415: cost centre 52 CAF in System.IO at CAF +381183: cost centre 51 CAF in Numeric at CAF +382230: cost centre 50 CAF in GHC.Word at CAF +383138: cost centre 49 CAF in GHC.Weak at CAF +383976: cost centre 48 CAF in GHC.Unicode at CAF +384884: cost centre 47 CAF in GHC.TopHandler at CAF +385722: cost centre 46 CAF in GHC.Stack.Types at CAF +388586: cost centre 45 CAF in GHC.Stack.CCS at CAF +389424: cost centre 44 CAF in GHC.Stable at CAF +390262: cost centre 43 CAF in GHC.Show at CAF +391100: cost centre 42 CAF in GHC.STRef at CAF +391868: cost centre 41 CAF in GHC.ST at CAF +392776: cost centre 40 CAF in GHC.Real at CAF +393614: cost centre 39 CAF in GHC.Read at CAF +394452: cost centre 38 CAF in GHC.Ptr at CAF +395290: cost centre 37 CAF in GHC.Pack at CAF +396128: cost centre 36 CAF in GHC.Num at CAF +396967: cost centre 35 CAF in GHC.MVar at CAF +397874: cost centre 34 CAF in GHC.List at CAF +398713: cost centre 33 CAF in GHC.Int at CAF +399551: cost centre 32 CAF in GHC.IORef at CAF +400389: cost centre 31 CAF in GHC.IO.Unsafe at CAF +401366: cost centre 30 CAF in GHC.IO.IOMode at CAF +402344: cost centre 29 CAF in GHC.IO.Handle.Types at CAF +403182: cost centre 28 CAF in GHC.IO.Handle.Text at CAF +404020: cost centre 27 CAF in GHC.IO.Handle.Internals at CAF +405208: cost centre 26 CAF in GHC.IO.Handle.FD at CAF +406116: cost centre 25 CAF in GHC.IO.Handle at CAF +407023: cost centre 24 CAF in GHC.IO.Exception at CAF +407931: cost centre 23 CAF in GHC.IO.Encoding.UTF8 at CAF +408839: cost centre 22 CAF in GHC.IO.Encoding.UTF32 at CAF +409817: cost centre 21 CAF in GHC.IO.Encoding.UTF16 at CAF +410725: cost centre 20 CAF in GHC.IO.Encoding.Types at CAF +411633: cost centre 19 CAF in GHC.IO.Encoding.Latin1 at CAF +412471: cost centre 18 CAF in GHC.IO.Encoding.Iconv at CAF +413518: cost centre 17 CAF in GHC.IO.Encoding.Failure at CAF +414357: cost centre 16 CAF in GHC.IO.Encoding at CAF +415264: cost centre 15 CAF in GHC.IO.Buffer at CAF +416103: cost centre 14 CAF in GHC.IO at CAF +417360: cost centre 13 CAF in GHC.ForeignPtr at CAF +418268: cost centre 12 CAF in GHC.Foreign at CAF +419175: cost centre 11 CAF in GHC.Fingerprint.Type at CAF +420014: cost centre 10 CAF in GHC.Fingerprint at CAF +420991: cost centre 9 CAF in GHC.Exception at CAF +421899: cost centre 8 CAF in GHC.Err at CAF +422807: cost centre 7 CAF in GHC.Conc.Sync at CAF +423715: cost centre 6 CAF in GHC.Conc.Signal at CAF +424693: cost centre 5 CAF in GHC.Conc.IO at CAF +425531: cost centre 4 CAF in GHC.Base at CAF +426299: cost centre 3 CAF in Data.Either at CAF +427137: cost centre 2 CAF in Control.Exception.Base at CAF +427975: cost centre 1 CAF in Main at CAF +483777: task 0x7ff63b736740 created on cap 0 with OS kernel thread 30307 +488177: cap 0: creating thread 1 +491599: cap 0: running thread 1 +534131: cap 0: stopping thread 1 (stack overflow) +538670: cap 0: running thread 1 +558365: cap 0: creating thread 2 +570377: cap 0: stopping thread 1 (thread yielding) +647480: task 0x7ff6393ef700 created on cap 0 with OS kernel thread 30309 +649785: cap 0: running thread 2 +665778: cap 0: stopping thread 2 (thread yielding) +676952: cap 0: running thread 1 +694063: cap 0: thread 2 has label "IOManager on cap 0" +716132: cap 0: creating thread 3 +719344: cap 0: stopping thread 1 (thread yielding) +729960: cap 0: running thread 2 +734220: cap 0: stopping thread 2 (making a foreign call) +808739: task 0x7ff638bee700 created on cap 0 with OS kernel thread 30310 +810834: cap 0: running thread 3 +829411: cap 0: stopping thread 3 (making a foreign call) +839258: cap 0: running thread 1 +845684: cap 0: thread 3 has label "TimerManager" +847220: cap 0: stopping thread 1 (thread finished) +1082159: task 0x7ff63b736740 deleted +1116800: task 0x7ff633fff700 created on cap 0 with OS kernel thread 30311 +1156398: task 0x7ff63b736740 created on cap 0 with OS kernel thread 30307 +1162963: cap 0: creating thread 4 +1164430: cap 0: running thread 4 +1201445: cap 0: stopping thread 4 (blocked on an MVar) +1233291: cap 0: running thread 3 +1245723: cap 0: stopping thread 3 (making a foreign call) +302580179: cap 0: running thread 3 +302602876: cap 0: stopping thread 3 (thread yielding) +302606159: cap 0: running thread 3 +302630603: cap 0: stopping thread 3 (making a foreign call) +302700791: cap 0: requesting parallel GC +302707635: cap 0: starting GC +302719578: cap 0: GC working +302930003: cap 0: GC idle +302931260: cap 0: GC done +302936568: cap 0: GC idle +302937476: cap 0: GC done +302938943: cap 0: GC idle +302939851: cap 0: GC done +302960314: cap 0: allocated on heap capset 0: 75736 total bytes till now +302963526: cap 0: finished GC +302964853: cap 0: all caps stopped for GC +302966040: cap 0: GC stats for heap capset 0: generation 1, 19984 bytes copied, 8728 bytes slop, 925696 bytes fragmentation, 1 par threads, 0 bytes max par copied, 19984 bytes total par copied +302967717: cap 0: live data in heap capset 0: 19944 bytes +302968694: cap 0: size of heap capset 0: 2097152 bytes +302971069: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5006421365: cap 0: running thread 3 +5006434984: cap 0: waking up thread 4 on cap 0 +5006442736: cap 0: stopping thread 3 (making a foreign call) +5006509083: cap 0: running thread 4 +5006512575: cap 0: stopping thread 4 (thread finished) +5006515508: task 0x7ff63b736740 deleted +5006525216: task 0x7ff63b736740 created on cap 0 with OS kernel thread 30307 +5006528149: cap 0: creating thread 5 +5006530594: cap 0: running thread 5 +5006560694: cap 0: stopping thread 5 (thread yielding) +5006566212: cap 0: requesting parallel GC +5006571659: cap 0: starting GC +5006579621: cap 0: GC working +5006733337: cap 0: GC idle +5006734245: cap 0: GC done +5006737178: cap 0: GC idle +5006737876: cap 0: GC done +5006738924: cap 0: GC idle +5006739622: cap 0: GC done +5006778383: start heap prof sample 0 +5006781945: heap prof sample 0, residency 16, label +5006784180: heap prof sample 0, residency 16, label +5006785158: heap prof sample 0, residency 96, label W +5006786345: heap prof sample 0, residency 32, label +5006787392: heap prof sample 0, residency 32, label +5006788440: heap prof sample 0, residency 72, label +5006789418: heap prof sample 0, residency 80, label +5006790465: heap prof sample 0, residency 24, label EPoll +5006791513: heap prof sample 0, residency 80, label TimerManager +5006792561: heap prof sample 0, residency 288, label MUT_ARR_PTRS_FROZEN +5006793608: heap prof sample 0, residency 80, label STArray +5006794656: heap prof sample 0, residency 72, label +5006795634: heap prof sample 0, residency 24, label +5006796611: heap prof sample 0, residency 112, label EventManager +5006797589: heap prof sample 0, residency 16, label +5006798706: heap prof sample 0, residency 32, label PlainPtr +5006799754: heap prof sample 0, residency 24, label Poll +5006800802: heap prof sample 0, residency 72, label (,) +5006802129: heap prof sample 0, residency 96, label +5006803106: heap prof sample 0, residency 48, label ARR_WORDS +5006804154: heap prof sample 0, residency 96, label Backend +5006805201: heap prof sample 0, residency 24, label +5006806179: heap prof sample 0, residency 24, label +5006807157: heap prof sample 0, residency 560, label MVar +5006808135: heap prof sample 0, residency 48, label DEAD_WEAK +5006809043: heap prof sample 0, residency 96, label WEAK +5006810020: heap prof sample 0, residency 1024, label IT +5006811208: heap prof sample 0, residency 16, label +5006812116: heap prof sample 0, residency 16, label +5006813163: heap prof sample 0, residency 24, label Dynamic +5006814211: heap prof sample 0, residency 1184, label MVAR +5006815258: heap prof sample 0, residency 32, label ThreadId +5006816166: heap prof sample 0, residency 768, label MallocPtr +5006817144: heap prof sample 0, residency 3664, label MUT_ARR_PTRS_CLEAN +5006818261: heap prof sample 0, residency 16, label PlainForeignPtr +5006819309: heap prof sample 0, residency 24, label +5006820357: heap prof sample 0, residency 72, label ForeignPtr +5006821334: heap prof sample 0, residency 80, label Just +5006822312: heap prof sample 0, residency 96, label AC +5006823430: heap prof sample 0, residency 96, label +5006824407: heap prof sample 0, residency 48, label BLACKHOLE +5006827760: heap prof sample 0, residency 816, label : +5006828807: heap prof sample 0, residency 64, label +5006829715: heap prof sample 0, residency 1232, label MUT_VAR_CLEAN +5006830763: heap prof sample 0, residency 32, label +5006831740: heap prof sample 0, residency 608, label STRef +5006876298: cap 0: allocated on heap capset 0: 81112 total bytes till now +5006877625: cap 0: finished GC +5006878672: cap 0: all caps stopped for GC +5006879650: cap 0: GC stats for heap capset 0: generation 1, 21824 bytes copied, 7432 bytes slop, 954368 bytes fragmentation, 1 par threads, 0 bytes max par copied, 21824 bytes total par copied +5006881117: cap 0: live data in heap capset 0: 21240 bytes +5006881955: cap 0: size of heap capset 0: 2097152 bytes +5006883352: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5006885167: cap 0: running thread 5 +5006912544: cap 0: stopping thread 5 (thread finished) +5006914011: task 0x7ff63b736740 deleted +5006936779: cap 0: requesting sequential GC +5006938664: cap 0: starting GC +5006940899: cap 0: GC working +5006995863: cap 0: GC idle +5006996631: cap 0: GC done +5006999075: cap 0: GC idle +5006999774: cap 0: GC done +5007000682: cap 0: GC idle +5007001380: cap 0: GC done +5007008992: cap 0: allocated on heap capset 0: 119504 total bytes till now +5007010319: cap 0: finished GC +5007011157: cap 0: all caps stopped for GC +5007011856: cap 0: GC stats for heap capset 0: generation 1, 23152 bytes copied, 26368 bytes slop, 856064 bytes fragmentation, 1 par threads, 0 bytes max par copied, 23152 bytes total par copied +5007012764: cap 0: live data in heap capset 0: 55552 bytes +5007013462: cap 0: size of heap capset 0: 2097152 bytes +5007014510: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5007060883: cap 0: running thread 3 +5007086235: cap 0: stopping thread 3 (thread finished) +5007091123: task 0x7ff638bee700 deleted +5007098037: cap 0: running thread 2 +5007122970: cap 0: stopping thread 2 (thread finished) +5007129675: task 0x7ff6393ef700 deleted +5007163197: task 0x7ff633fff700 deleted +5007170321: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5007576785: cap 0: allocated on heap capset 0: 121184 total bytes till now +5007583979: removed cap 0 from capset 0 +5007585166: removed cap 0 from capset 1 +5007586284: deleted cap 0 +5007587401: deleted capset 0 +5007588449: deleted capset 1 + diff --git a/test/sleep.hm.eventlog b/test/sleep.hm.eventlog new file mode 100644 Binary files /dev/null and b/test/sleep.hm.eventlog differ diff --git a/test/sleep.hm.eventlog.reference b/test/sleep.hm.eventlog.reference new file mode 100644 --- /dev/null +++ b/test/sleep.hm.eventlog.reference @@ -0,0 +1,301 @@ +Event Types: +0: Create thread (size 4) +1: Run thread (size 4) +2: Stop thread (size 10) +3: Thread runnable (size 4) +4: Migrate thread (size 6) +8: Wakeup thread (size 6) +9: Starting GC (size 0) +10: Finished GC (size 0) +11: Request sequential GC (size 0) +12: Request parallel GC (size 0) +15: Create spark thread (size 4) +16: Log message (size variable) +18: Block marker (size 14) +19: User message (size variable) +20: GC idle (size 0) +21: GC working (size 0) +22: GC done (size 0) +25: Create capability set (size 6) +26: Delete capability set (size 4) +27: Add capability to capability set (size 6) +28: Remove capability from capability set (size 6) +29: RTS name and version (size variable) +30: Program arguments (size variable) +31: Program environment variables (size variable) +32: Process ID (size 8) +33: Parent process ID (size 8) +34: Spark counters (size 56) +35: Spark create (size 0) +36: Spark dud (size 0) +37: Spark overflow (size 0) +38: Spark run (size 0) +39: Spark steal (size 2) +40: Spark fizzle (size 0) +41: Spark GC (size 0) +43: Wall clock time (size 16) +44: Thread label (size variable) +45: Create capability (size 2) +46: Delete capability (size 2) +47: Disable capability (size 2) +48: Enable capability (size 2) +49: Total heap mem ever allocated (size 12) +50: Current heap size (size 12) +51: Current heap live data (size 12) +52: Heap static parameters (size 38) +53: GC statistics (size 50) +54: Synchronise stop-the-world GC (size 0) +55: Task create (size 18) +56: Task migrate (size 12) +57: Task delete (size 8) +58: User marker (size variable) +59: Empty event for bug #9003 (size 0) +160: Start of heap profile (size variable) +161: Cost center definition (size variable) +162: Start of heap profile sample (size 8) +163: Heap profile cost-centre sample (size variable) +164: Heap profile string sample (size variable) + +Events: +63274: created capset 0 of type CapsetOsProcess +64951: created capset 1 of type CapsetClockDomain +67604: created cap 0 +68442: assigned cap 0 to capset 0 +69211: assigned cap 0 to capset 1 +70049: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +73401: capset 1: wall clock time 1496042138s 798224000ns (unix epoch) +74518: capset 0: pid 30441 +75915: capset 0: parent pid 27111 +77871: capset 0: RTS version "GHC-8.2.0.20170507 rts_thr_p" +79547: capset 0: args: ["./sleep","+RTS","-l","-hm"] +81782: capset 0: env: ["ADOTDIR=/home/maoe/.antigen","ANTIGEN_COMPDUMPFILE=/home/maoe/.zcompdump","ANTIGEN_DEFAULT_REPO_URL=https://github.com/robbyrussell/oh-my-zsh.git","AUTOJUMP_ERROR_PATH=/home/maoe/.local/share/autojump/errors.log","AUTOJUMP_SOURCED=1","CLUTTER_IM_MODULE=xim","DBUS_SESSION_BUS_ADDRESS=unix:abstract=/tmp/dbus-ioIEQwU7Ny","DEFAULTS_PATH=/usr/share/gconf/gnome.default.path","DERBY_HOME=/usr/lib/jvm/java-8-oracle/db","DESKTOP_SESSION=gnome","DISPLAY=:0","EDITOR=vim","GDMSESSION=gnome","GDM_LANG=en","GJS_DEBUG_OUTPUT=stderr","GJS_DEBUG_TOPICS=JS ERROR;JS LOG","GNOME_DESKTOP_SESSION_ID=this-is-deprecated","GNOME_KEYRING_CONTROL=","GNOME_KEYRING_PID=","GOPATH=/home/maoe/.go","GPG_AGENT_INFO=/home/maoe/.gnupg/S.gpg-agent:0:1","GTK_IM_MODULE=ibus","HOME=/home/maoe","IM_CONFIG_PHASE=1","INSTANCE=","J2REDIR=/usr/lib/jvm/java-8-oracle/jre","J2SDKDIR=/usr/lib/jvm/java-8-oracle","JAVA_HOME=/usr/lib/jvm/java-8-oracle","JOB=dbus","LANG=en_US.UTF-8","LANGUAGE=en","LC_ADDRESS=en_US.UTF-8","LC_CTYPE=en_US.UTF-8","LC_IDENTIFICATION=en_US.UTF-8","LC_MEASUREMENT=en_US.UTF-8","LC_MONETARY=en_US.UTF-8","LC_NAME=en_US.UTF-8","LC_NUMERIC=en_US.UTF-8","LC_PAPER=en_US.UTF-8","LC_TELEPHONE=en_US.UTF-8","LC_TIME=en_US.UTF-8","LESS=-R","LIBVIRT_DEFAULT_URI=qemu:///system","LOGNAME=maoe","LS_COLORS=di=34:ln=35:so=32:pi=33:ex=31:bd=46;34:cd=43;34:su=41;30:sg=46;30:tw=42;30:ow=43;30","MANDATORY_PATH=/usr/share/gconf/gnome.mandatory.path","NODE_PATH=/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript","OLDPWD=/home/maoe/src/github.com/haskell/ghc-events","PAGER=less","PAPERSIZE=letter","PATH=/usr/local/ghc/ghc-8.2.0-rc2/bin:/home/maoe/.npm-packages/bin:/home/maoe/Downloads/google-cloud-sdk/bin:/home/maoe/src/github.com/phacility/arcanist/bin:/home/maoe/.cargo/bin:/home/maoe/.local/bin:/home/maoe/.cabal/bin:/home/maoe/bin:/usr/local/bin:/usr/local/sbin:/home/maoe/.npm-packages/bin:/home/maoe/Downloads/google-cloud-sdk/bin:/home/maoe/src/github.com/phacility/arcanist/bin:/home/maoe/.cargo/bin:/home/maoe/.local/bin:/home/maoe/.cabal/bin:/home/maoe/bin:/usr/local/bin:/usr/local/sbin:/home/maoe/.cargo/bin:/home/maoe/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/usr/lib/jvm/java-8-oracle/bin:/usr/lib/jvm/java-8-oracle/db/bin:/usr/lib/jvm/java-8-oracle/jre/bin","PWD=/home/maoe/src/github.com/haskell/ghc-events","QT4_IM_MODULE=ibus","QT_ACCESSIBILITY=1","QT_IM_MODULE=ibus","QT_LINUX_ACCESSIBILITY_ALWAYS_ON=1","SESSION=gnome","SESSIONTYPE=gnome-session","SESSION_MANAGER=local/vangelis.tsuru.it:@/tmp/.ICE-unix/5489,unix/vangelis.tsuru.it:/tmp/.ICE-unix/5489","SHELL=/bin/zsh","SHLVL=2","SSH_AUTH_SOCK=/run/user/2016/keyring/ssh","TERM=screen-256color","TMUX=/tmp/tmux-2016/default,10542,3","TMUX_PANE=%93","UBUNTU_MENUPROXY=libappmenu.so","UPSTART_SESSION=unix:abstract=/com/ubuntu/upstart-session/2016/5282","USER=maoe","VTE_VERSION=4205","WINDOWID=71468690","XAUTHORITY=/home/maoe/.Xauthority","XDG_CONFIG_DIRS=/etc/xdg/xdg-gnome:/usr/share/upstart/xdg:/etc/xdg","XDG_CURRENT_DESKTOP=GNOME","XDG_DATA_DIRS=/usr/share/gnome:/usr/local/share/:/usr/share/","XDG_GREETER_DATA_DIR=/var/lib/lightdm-data/maoe","XDG_MENU_PREFIX=gnome-","XDG_RUNTIME_DIR=/run/user/2016","XDG_SEAT=seat0","XDG_SEAT_PATH=/org/freedesktop/DisplayManager/Seat0","XDG_SESSION_DESKTOP=gnome","XDG_SESSION_ID=c2","XDG_SESSION_PATH=/org/freedesktop/DisplayManager/Session0","XDG_SESSION_TYPE=x11","XDG_VTNR=7","XMODIFIERS=@im=ibus","ZSH=/home/maoe/.antigen/repos/https-COLON--SLASH--SLASH-github.com-SLASH-robbyrussell-SLASH-oh-my-zsh.git","ZSH_CACHE_DIR=/home/maoe/.antigen/repos/https-COLON--SLASH--SLASH-github.com-SLASH-robbyrussell-SLASH-oh-my-zsh.git/cache/","_=/home/maoe/src/github.com/haskell/ghc-events/./sleep","_ANTIGEN_BUNDLE_RECORD=\nhttps://github.com/robbyrussell/oh-my-zsh.git lib plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git plugins/git plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git plugins/pass plugin true \nhttps://github.com/zsh-users/zsh-syntax-highlighting.git / plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git themes/kphoen.zsh-theme theme true ","_ANTIGEN_LOG_PATH=/home/maoe/.antigen/antigen.log","_ZCACHE_BUNDLES_PATH=/home/maoe/.antigen/.cache/.zcache-bundles","_ZCACHE_CACHE_LOADED=true","_ZCACHE_CACHE_VERSION=v1.4.1","_ZCACHE_EXTENSION_BUNDLE=false","_ZCACHE_EXTENSION_CLEAN_FUNCTIONS=true","_ZCACHE_PATH=/home/maoe/.antigen/.cache","_ZCACHE_PAYLOAD_PATH=/home/maoe/.antigen/.cache/.zcache-payload","LSCOLORS=Gxfxcxdxbxegedabagacad","MANPATH=/home/maoe/.npm-packages/share/man:/home/maoe/.local/share/man:/home/maoe/.cabal/share/man:/usr/local/man:/usr/local/share/man:/usr/share/man:/usr/lib/jvm/java-8-oracle/man"] +109298: heap stats for heap capset 0: generations 2, 0 bytes max heap size, 1048576 bytes alloc area size, 1048576 bytes mblock size, 4096 bytes block size +217060: start heap profiling 0 at sampling period 100000000 broken down by module +218876: cost centre 110 IDLE in IDLE at +220063: cost centre 109 PINNED in SYSTEM at +220902: cost centre 108 DONT_CARE in MAIN at +221670: cost centre 107 OVERHEAD_of in PROFILING at +222438: cost centre 106 GC in GC at +223276: cost centre 105 SYSTEM in SYSTEM at +223974: cost centre 104 MAIN in MAIN at +224813: cost centre 103 CAF in GHC.Types at CAF +225930: cost centre 102 CAF in GHC.Tuple at CAF +226768: cost centre 101 CAF in GHC.Classes at CAF +227606: cost centre 100 CAF in GHC.CString at CAF +228514: cost centre 99 CAF in GHC.Integer.Type at CAF +229282: cost centre 98 CAF in GHC.Integer.Logarithms.Internals at CAF +230120: cost centre 97 CAF in GHC.Integer.Logarithms at CAF +230889: cost centre 96 CAF in GHC.Event.Array at CAF +231866: cost centre 95 CAF in GHC.Event.Arr at CAF +232635: cost centre 94 CAF in Data.Proxy at CAF +233263: cost centre 93 CAF in GHC.Event.Poll at CAF +234241: cost centre 92 CAF in GHC.Event.PSQ at CAF +235079: cost centre 91 CAF in GHC.Event.Manager at CAF +235987: cost centre 90 CAF in GHC.Event.IntTable at CAF +236825: cost centre 89 CAF in GHC.Event.EPoll at CAF +237733: cost centre 88 CAF in GHC.Event.Control at CAF +238501: cost centre 87 CAF in System.Posix.Types at CAF +239269: cost centre 86 CAF in GHC.Storable at CAF +240037: cost centre 85 CAF in GHC.Natural at CAF +240945: cost centre 84 CAF in GHC.IO.FD at CAF +241783: cost centre 83 CAF in GHC.IO.Device at CAF +242622: cost centre 82 CAF in GHC.IO.BufferedIO at CAF +243320: cost centre 81 CAF in GHC.Generics at CAF +244158: cost centre 80 CAF in GHC.Float.RealFracMethods at CAF +244926: cost centre 79 CAF in GHC.Float.ConversionUtils at CAF +245694: cost centre 78 CAF in GHC.Float at CAF +246463: cost centre 77 CAF in GHC.Enum at CAF +247231: cost centre 76 CAF in GHC.Char at CAF +248139: cost centre 75 CAF in GHC.Arr at CAF +248977: cost centre 74 CAF in Foreign.Storable at CAF +249815: cost centre 73 CAF in Foreign.Marshal.Array at CAF +250653: cost centre 72 CAF in Foreign.Marshal.Alloc at CAF +251421: cost centre 71 CAF in Foreign.C.Types at CAF +252190: cost centre 70 CAF in Foreign.C.String at CAF +253237: cost centre 69 CAF in Foreign.C.Error at CAF +254075: cost centre 68 CAF in Data.Type.Equality at CAF +254843: cost centre 67 CAF in Data.Tuple at CAF +255542: cost centre 66 CAF in Data.Maybe at CAF +256380: cost centre 65 CAF in Data.Dynamic at CAF +257078: cost centre 64 CAF in Data.Bits at CAF +257846: cost centre 63 CAF in Control.Monad.Fail at CAF +258685: cost centre 62 CAF in GHC.Event.Unique at CAF +259592: cost centre 61 CAF in GHC.Event.TimerManager at CAF +260431: cost centre 60 CAF in GHC.Event.Thread at CAF +261269: cost centre 59 CAF in GHC.Event.Internal at CAF +262177: cost centre 58 CAF in Data.Typeable.Internal at CAF +262945: cost centre 57 CAF in Data.OldList at CAF +263713: cost centre 56 CAF in Text.Read.Lex at CAF +264551: cost centre 55 CAF in Text.ParserCombinators.ReadPrec at CAF +265319: cost centre 54 CAF in Text.ParserCombinators.ReadP at CAF +266088: cost centre 53 CAF in System.Posix.Internals at CAF +266856: cost centre 52 CAF in System.IO at CAF +267624: cost centre 51 CAF in Numeric at CAF +268462: cost centre 50 CAF in GHC.Word at CAF +269300: cost centre 49 CAF in GHC.Weak at CAF +270068: cost centre 48 CAF in GHC.Unicode at CAF +270906: cost centre 47 CAF in GHC.TopHandler at CAF +271745: cost centre 46 CAF in GHC.Stack.Types at CAF +273910: cost centre 45 CAF in GHC.Stack.CCS at CAF +274678: cost centre 44 CAF in GHC.Stable at CAF +275516: cost centre 43 CAF in GHC.Show at CAF +276284: cost centre 42 CAF in GHC.STRef at CAF +276982: cost centre 41 CAF in GHC.ST at CAF +277821: cost centre 40 CAF in GHC.Real at CAF +278589: cost centre 39 CAF in GHC.Read at CAF +279357: cost centre 38 CAF in GHC.Ptr at CAF +280125: cost centre 37 CAF in GHC.Pack at CAF +281033: cost centre 36 CAF in GHC.Num at CAF +281801: cost centre 35 CAF in GHC.MVar at CAF +282570: cost centre 34 CAF in GHC.List at CAF +283477: cost centre 33 CAF in GHC.Int at CAF +284176: cost centre 32 CAF in GHC.IORef at CAF +284944: cost centre 31 CAF in GHC.IO.Unsafe at CAF +285852: cost centre 30 CAF in GHC.IO.IOMode at CAF +286760: cost centre 29 CAF in GHC.IO.Handle.Types at CAF +287528: cost centre 28 CAF in GHC.IO.Handle.Text at CAF +288296: cost centre 27 CAF in GHC.IO.Handle.Internals at CAF +289134: cost centre 26 CAF in GHC.IO.Handle.FD at CAF +289973: cost centre 25 CAF in GHC.IO.Handle at CAF +290811: cost centre 24 CAF in GHC.IO.Exception at CAF +291649: cost centre 23 CAF in GHC.IO.Encoding.UTF8 at CAF +292696: cost centre 22 CAF in GHC.IO.Encoding.UTF32 at CAF +293534: cost centre 21 CAF in GHC.IO.Encoding.UTF16 at CAF +294372: cost centre 20 CAF in GHC.IO.Encoding.Types at CAF +295141: cost centre 19 CAF in GHC.IO.Encoding.Latin1 at CAF +295979: cost centre 18 CAF in GHC.IO.Encoding.Iconv at CAF +296747: cost centre 17 CAF in GHC.IO.Encoding.Failure at CAF +297585: cost centre 16 CAF in GHC.IO.Encoding at CAF +298353: cost centre 15 CAF in GHC.IO.Buffer at CAF +299191: cost centre 14 CAF in GHC.IO at CAF +300099: cost centre 13 CAF in GHC.ForeignPtr at CAF +300937: cost centre 12 CAF in GHC.Foreign at CAF +301775: cost centre 11 CAF in GHC.Fingerprint.Type at CAF +302613: cost centre 10 CAF in GHC.Fingerprint at CAF +303452: cost centre 9 CAF in GHC.Exception at CAF +304429: cost centre 8 CAF in GHC.Err at CAF +305197: cost centre 7 CAF in GHC.Conc.Sync at CAF +306036: cost centre 6 CAF in GHC.Conc.Signal at CAF +306874: cost centre 5 CAF in GHC.Conc.IO at CAF +307712: cost centre 4 CAF in GHC.Base at CAF +308410: cost centre 3 CAF in Data.Either at CAF +309318: cost centre 2 CAF in Control.Exception.Base at CAF +310016: cost centre 1 CAF in Main at CAF +353596: task 0x7f96b7bda740 created on cap 0 with OS kernel thread 30441 +357647: cap 0: creating thread 1 +360859: cap 0: running thread 1 +395500: cap 0: stopping thread 1 (stack overflow) +402414: cap 0: running thread 1 +419524: cap 0: creating thread 2 +429162: cap 0: stopping thread 1 (thread yielding) +491529: task 0x7f96b5893700 created on cap 0 with OS kernel thread 30443 +492925: cap 0: running thread 2 +502982: cap 0: stopping thread 2 (thread yielding) +542162: cap 0: running thread 1 +559273: cap 0: thread 2 has label "IOManager on cap 0" +581691: cap 0: creating thread 3 +584415: cap 0: stopping thread 1 (thread yielding) +593145: cap 0: running thread 2 +597545: cap 0: stopping thread 2 (making a foreign call) +670317: task 0x7f96b5092700 created on cap 0 with OS kernel thread 30444 +672133: cap 0: running thread 3 +687288: cap 0: stopping thread 3 (making a foreign call) +695529: cap 0: running thread 1 +701535: cap 0: thread 3 has label "TimerManager" +702932: cap 0: stopping thread 1 (thread finished) +750353: task 0x7f96b7bda740 deleted +764670: task 0x7f96b4891700 created on cap 0 with OS kernel thread 30445 +771235: task 0x7f96b7bda740 created on cap 0 with OS kernel thread 30441 +774587: cap 0: creating thread 4 +775774: cap 0: running thread 4 +805526: cap 0: stopping thread 4 (blocked on an MVar) +810065: cap 0: running thread 3 +818167: cap 0: stopping thread 3 (making a foreign call) +302513831: cap 0: running thread 3 +302537507: cap 0: stopping thread 3 (thread yielding) +302554687: cap 0: running thread 3 +302581994: cap 0: stopping thread 3 (making a foreign call) +302712524: cap 0: requesting parallel GC +302718320: cap 0: starting GC +302729076: cap 0: GC working +302893268: cap 0: GC idle +302894385: cap 0: GC done +302898436: cap 0: GC idle +302899274: cap 0: GC done +302900531: cap 0: GC idle +302901369: cap 0: GC done +302917921: cap 0: allocated on heap capset 0: 75736 total bytes till now +302920505: cap 0: finished GC +302922111: cap 0: all caps stopped for GC +302923159: cap 0: GC stats for heap capset 0: generation 1, 19984 bytes copied, 8728 bytes slop, 925696 bytes fragmentation, 1 par threads, 0 bytes max par copied, 19984 bytes total par copied +302924625: cap 0: live data in heap capset 0: 19944 bytes +302925533: cap 0: size of heap capset 0: 2097152 bytes +302927349: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5006341678: cap 0: running thread 3 +5006356694: cap 0: waking up thread 4 on cap 0 +5006364516: cap 0: stopping thread 3 (making a foreign call) +5006433447: cap 0: running thread 4 +5006436729: cap 0: stopping thread 4 (thread finished) +5006439942: task 0x7f96b7bda740 deleted +5006449300: task 0x7f96b7bda740 created on cap 0 with OS kernel thread 30441 +5006452583: cap 0: creating thread 5 +5006454608: cap 0: running thread 5 +5006484499: cap 0: stopping thread 5 (thread yielding) +5006489807: cap 0: requesting parallel GC +5006508943: cap 0: starting GC +5006517044: cap 0: GC working +5006736898: cap 0: GC idle +5006738016: cap 0: GC done +5006743254: cap 0: GC idle +5006744162: cap 0: GC done +5006745908: cap 0: GC idle +5006746816: cap 0: GC done +5006839492: start heap prof sample 0 +5006846616: heap prof sample 0, residency 48, label GHC.Event.Poll +5006850527: heap prof sample 0, residency 120, label GHC.IO.Encoding.Iconv +5006852482: heap prof sample 0, residency 640, label GHC.Conc.Signal +5006854368: heap prof sample 0, residency 560, label GHC.Event.Thread +5006855974: heap prof sample 0, residency 128, label GHC.IO.Handle.FD +5006857511: heap prof sample 0, residency 696, label GHC.IO.Encoding +5006859117: heap prof sample 0, residency 9880, label MAIN +5006932378: cap 0: allocated on heap capset 0: 81112 total bytes till now +5006934334: cap 0: finished GC +5006935731: cap 0: all caps stopped for GC +5006936918: cap 0: GC stats for heap capset 0: generation 1, 21824 bytes copied, 7432 bytes slop, 954368 bytes fragmentation, 1 par threads, 0 bytes max par copied, 21824 bytes total par copied +5006938105: cap 0: live data in heap capset 0: 21240 bytes +5006939153: cap 0: size of heap capset 0: 2097152 bytes +5006941807: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5006945019: cap 0: running thread 5 +5007003894: cap 0: stopping thread 5 (thread finished) +5007005779: task 0x7f96b7bda740 deleted +5007024217: cap 0: requesting sequential GC +5007027220: cap 0: starting GC +5007031341: cap 0: GC working +5007190714: cap 0: GC idle +5007191761: cap 0: GC done +5007196091: cap 0: GC idle +5007196929: cap 0: GC done +5007198117: cap 0: GC idle +5007199094: cap 0: GC done +5007213272: cap 0: allocated on heap capset 0: 119504 total bytes till now +5007215437: cap 0: finished GC +5007216415: cap 0: all caps stopped for GC +5007217323: cap 0: GC stats for heap capset 0: generation 1, 23152 bytes copied, 26368 bytes slop, 856064 bytes fragmentation, 1 par threads, 0 bytes max par copied, 23152 bytes total par copied +5007218440: cap 0: live data in heap capset 0: 55552 bytes +5007219348: cap 0: size of heap capset 0: 2097152 bytes +5007221024: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5007240579: cap 0: running thread 3 +5007285067: cap 0: stopping thread 3 (thread finished) +5007294914: task 0x7f96b5092700 deleted +5007323478: cap 0: running thread 2 +5007359026: cap 0: stopping thread 2 (thread finished) +5007366639: task 0x7f96b5893700 deleted +5007392619: task 0x7f96b4891700 deleted +5007414828: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5007493746: cap 0: allocated on heap capset 0: 121184 total bytes till now +5007498356: removed cap 0 from capset 0 +5007499403: removed cap 0 from capset 1 +5007500381: deleted cap 0 +5007501429: deleted capset 0 +5007502336: deleted capset 1 + diff --git a/test/sleep.hy.eventlog b/test/sleep.hy.eventlog new file mode 100644 Binary files /dev/null and b/test/sleep.hy.eventlog differ diff --git a/test/sleep.hy.eventlog.reference b/test/sleep.hy.eventlog.reference new file mode 100644 --- /dev/null +++ b/test/sleep.hy.eventlog.reference @@ -0,0 +1,328 @@ +Event Types: +0: Create thread (size 4) +1: Run thread (size 4) +2: Stop thread (size 10) +3: Thread runnable (size 4) +4: Migrate thread (size 6) +8: Wakeup thread (size 6) +9: Starting GC (size 0) +10: Finished GC (size 0) +11: Request sequential GC (size 0) +12: Request parallel GC (size 0) +15: Create spark thread (size 4) +16: Log message (size variable) +18: Block marker (size 14) +19: User message (size variable) +20: GC idle (size 0) +21: GC working (size 0) +22: GC done (size 0) +25: Create capability set (size 6) +26: Delete capability set (size 4) +27: Add capability to capability set (size 6) +28: Remove capability from capability set (size 6) +29: RTS name and version (size variable) +30: Program arguments (size variable) +31: Program environment variables (size variable) +32: Process ID (size 8) +33: Parent process ID (size 8) +34: Spark counters (size 56) +35: Spark create (size 0) +36: Spark dud (size 0) +37: Spark overflow (size 0) +38: Spark run (size 0) +39: Spark steal (size 2) +40: Spark fizzle (size 0) +41: Spark GC (size 0) +43: Wall clock time (size 16) +44: Thread label (size variable) +45: Create capability (size 2) +46: Delete capability (size 2) +47: Disable capability (size 2) +48: Enable capability (size 2) +49: Total heap mem ever allocated (size 12) +50: Current heap size (size 12) +51: Current heap live data (size 12) +52: Heap static parameters (size 38) +53: GC statistics (size 50) +54: Synchronise stop-the-world GC (size 0) +55: Task create (size 18) +56: Task migrate (size 12) +57: Task delete (size 8) +58: User marker (size variable) +59: Empty event for bug #9003 (size 0) +160: Start of heap profile (size variable) +161: Cost center definition (size variable) +162: Start of heap profile sample (size 8) +163: Heap profile cost-centre sample (size variable) +164: Heap profile string sample (size variable) + +Events: +148828: created capset 0 of type CapsetOsProcess +151691: created capset 1 of type CapsetClockDomain +156999: created cap 0 +172433: assigned cap 0 to capset 0 +173900: assigned cap 0 to capset 1 +175087: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +181163: capset 1: wall clock time 1496042169s 339444000ns (unix epoch) +182769: capset 0: pid 30775 +185353: capset 0: parent pid 27111 +189753: capset 0: RTS version "GHC-8.2.0.20170507 rts_thr_p" +192826: capset 0: args: ["./sleep","+RTS","-l","-hy"] +197506: capset 0: env: ["ADOTDIR=/home/maoe/.antigen","ANTIGEN_COMPDUMPFILE=/home/maoe/.zcompdump","ANTIGEN_DEFAULT_REPO_URL=https://github.com/robbyrussell/oh-my-zsh.git","AUTOJUMP_ERROR_PATH=/home/maoe/.local/share/autojump/errors.log","AUTOJUMP_SOURCED=1","CLUTTER_IM_MODULE=xim","DBUS_SESSION_BUS_ADDRESS=unix:abstract=/tmp/dbus-ioIEQwU7Ny","DEFAULTS_PATH=/usr/share/gconf/gnome.default.path","DERBY_HOME=/usr/lib/jvm/java-8-oracle/db","DESKTOP_SESSION=gnome","DISPLAY=:0","EDITOR=vim","GDMSESSION=gnome","GDM_LANG=en","GJS_DEBUG_OUTPUT=stderr","GJS_DEBUG_TOPICS=JS ERROR;JS LOG","GNOME_DESKTOP_SESSION_ID=this-is-deprecated","GNOME_KEYRING_CONTROL=","GNOME_KEYRING_PID=","GOPATH=/home/maoe/.go","GPG_AGENT_INFO=/home/maoe/.gnupg/S.gpg-agent:0:1","GTK_IM_MODULE=ibus","HOME=/home/maoe","IM_CONFIG_PHASE=1","INSTANCE=","J2REDIR=/usr/lib/jvm/java-8-oracle/jre","J2SDKDIR=/usr/lib/jvm/java-8-oracle","JAVA_HOME=/usr/lib/jvm/java-8-oracle","JOB=dbus","LANG=en_US.UTF-8","LANGUAGE=en","LC_ADDRESS=en_US.UTF-8","LC_CTYPE=en_US.UTF-8","LC_IDENTIFICATION=en_US.UTF-8","LC_MEASUREMENT=en_US.UTF-8","LC_MONETARY=en_US.UTF-8","LC_NAME=en_US.UTF-8","LC_NUMERIC=en_US.UTF-8","LC_PAPER=en_US.UTF-8","LC_TELEPHONE=en_US.UTF-8","LC_TIME=en_US.UTF-8","LESS=-R","LIBVIRT_DEFAULT_URI=qemu:///system","LOGNAME=maoe","LS_COLORS=di=34:ln=35:so=32:pi=33:ex=31:bd=46;34:cd=43;34:su=41;30:sg=46;30:tw=42;30:ow=43;30","MANDATORY_PATH=/usr/share/gconf/gnome.mandatory.path","NODE_PATH=/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript","OLDPWD=/home/maoe/src/github.com/haskell/ghc-events","PAGER=less","PAPERSIZE=letter","PATH=/usr/local/ghc/ghc-8.2.0-rc2/bin:/home/maoe/.npm-packages/bin:/home/maoe/Downloads/google-cloud-sdk/bin:/home/maoe/src/github.com/phacility/arcanist/bin:/home/maoe/.cargo/bin:/home/maoe/.local/bin:/home/maoe/.cabal/bin:/home/maoe/bin:/usr/local/bin:/usr/local/sbin:/home/maoe/.npm-packages/bin:/home/maoe/Downloads/google-cloud-sdk/bin:/home/maoe/src/github.com/phacility/arcanist/bin:/home/maoe/.cargo/bin:/home/maoe/.local/bin:/home/maoe/.cabal/bin:/home/maoe/bin:/usr/local/bin:/usr/local/sbin:/home/maoe/.cargo/bin:/home/maoe/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/usr/lib/jvm/java-8-oracle/bin:/usr/lib/jvm/java-8-oracle/db/bin:/usr/lib/jvm/java-8-oracle/jre/bin","PWD=/home/maoe/src/github.com/haskell/ghc-events","QT4_IM_MODULE=ibus","QT_ACCESSIBILITY=1","QT_IM_MODULE=ibus","QT_LINUX_ACCESSIBILITY_ALWAYS_ON=1","SESSION=gnome","SESSIONTYPE=gnome-session","SESSION_MANAGER=local/vangelis.tsuru.it:@/tmp/.ICE-unix/5489,unix/vangelis.tsuru.it:/tmp/.ICE-unix/5489","SHELL=/bin/zsh","SHLVL=2","SSH_AUTH_SOCK=/run/user/2016/keyring/ssh","TERM=screen-256color","TMUX=/tmp/tmux-2016/default,10542,3","TMUX_PANE=%93","UBUNTU_MENUPROXY=libappmenu.so","UPSTART_SESSION=unix:abstract=/com/ubuntu/upstart-session/2016/5282","USER=maoe","VTE_VERSION=4205","WINDOWID=71468690","XAUTHORITY=/home/maoe/.Xauthority","XDG_CONFIG_DIRS=/etc/xdg/xdg-gnome:/usr/share/upstart/xdg:/etc/xdg","XDG_CURRENT_DESKTOP=GNOME","XDG_DATA_DIRS=/usr/share/gnome:/usr/local/share/:/usr/share/","XDG_GREETER_DATA_DIR=/var/lib/lightdm-data/maoe","XDG_MENU_PREFIX=gnome-","XDG_RUNTIME_DIR=/run/user/2016","XDG_SEAT=seat0","XDG_SEAT_PATH=/org/freedesktop/DisplayManager/Seat0","XDG_SESSION_DESKTOP=gnome","XDG_SESSION_ID=c2","XDG_SESSION_PATH=/org/freedesktop/DisplayManager/Session0","XDG_SESSION_TYPE=x11","XDG_VTNR=7","XMODIFIERS=@im=ibus","ZSH=/home/maoe/.antigen/repos/https-COLON--SLASH--SLASH-github.com-SLASH-robbyrussell-SLASH-oh-my-zsh.git","ZSH_CACHE_DIR=/home/maoe/.antigen/repos/https-COLON--SLASH--SLASH-github.com-SLASH-robbyrussell-SLASH-oh-my-zsh.git/cache/","_=/home/maoe/src/github.com/haskell/ghc-events/./sleep","_ANTIGEN_BUNDLE_RECORD=\nhttps://github.com/robbyrussell/oh-my-zsh.git lib plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git plugins/git plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git plugins/pass plugin true \nhttps://github.com/zsh-users/zsh-syntax-highlighting.git / plugin true \nhttps://github.com/robbyrussell/oh-my-zsh.git themes/kphoen.zsh-theme theme true ","_ANTIGEN_LOG_PATH=/home/maoe/.antigen/antigen.log","_ZCACHE_BUNDLES_PATH=/home/maoe/.antigen/.cache/.zcache-bundles","_ZCACHE_CACHE_LOADED=true","_ZCACHE_CACHE_VERSION=v1.4.1","_ZCACHE_EXTENSION_BUNDLE=false","_ZCACHE_EXTENSION_CLEAN_FUNCTIONS=true","_ZCACHE_PATH=/home/maoe/.antigen/.cache","_ZCACHE_PAYLOAD_PATH=/home/maoe/.antigen/.cache/.zcache-payload","LSCOLORS=Gxfxcxdxbxegedabagacad","MANPATH=/home/maoe/.npm-packages/share/man:/home/maoe/.local/share/man:/home/maoe/.cabal/share/man:/usr/local/man:/usr/local/share/man:/usr/share/man:/usr/lib/jvm/java-8-oracle/man"] +254355: heap stats for heap capset 0: generations 2, 0 bytes max heap size, 1048576 bytes alloc area size, 1048576 bytes mblock size, 4096 bytes block size +551660: start heap profiling 0 at sampling period 100000000 broken down by type description +554454: cost centre 110 IDLE in IDLE at +556340: cost centre 109 PINNED in SYSTEM at +557597: cost centre 108 DONT_CARE in MAIN at +558714: cost centre 107 OVERHEAD_of in PROFILING at +559762: cost centre 106 GC in GC at +560949: cost centre 105 SYSTEM in SYSTEM at +561997: cost centre 104 MAIN in MAIN at +563114: cost centre 103 CAF in GHC.Types at CAF +564301: cost centre 102 CAF in GHC.Tuple at CAF +565488: cost centre 101 CAF in GHC.Classes at CAF +566606: cost centre 100 CAF in GHC.CString at CAF +568003: cost centre 99 CAF in GHC.Integer.Type at CAF +569120: cost centre 98 CAF in GHC.Integer.Logarithms.Internals at CAF +570238: cost centre 97 CAF in GHC.Integer.Logarithms at CAF +571425: cost centre 96 CAF in GHC.Event.Array at CAF +572542: cost centre 95 CAF in GHC.Event.Arr at CAF +573590: cost centre 94 CAF in Data.Proxy at CAF +574777: cost centre 93 CAF in GHC.Event.Poll at CAF +575825: cost centre 92 CAF in GHC.Event.PSQ at CAF +577082: cost centre 91 CAF in GHC.Event.Manager at CAF +578269: cost centre 90 CAF in GHC.Event.IntTable at CAF +579666: cost centre 89 CAF in GHC.Event.EPoll at CAF +580853: cost centre 88 CAF in GHC.Event.Control at CAF +581831: cost centre 87 CAF in System.Posix.Types at CAF +582948: cost centre 86 CAF in GHC.Storable at CAF +583926: cost centre 85 CAF in GHC.Natural at CAF +585183: cost centre 84 CAF in GHC.IO.FD at CAF +586370: cost centre 83 CAF in GHC.IO.Device at CAF +587488: cost centre 82 CAF in GHC.IO.BufferedIO at CAF +588466: cost centre 81 CAF in GHC.Generics at CAF +589583: cost centre 80 CAF in GHC.Float.RealFracMethods at CAF +590631: cost centre 79 CAF in GHC.Float.ConversionUtils at CAF +591608: cost centre 78 CAF in GHC.Float at CAF +592726: cost centre 77 CAF in GHC.Enum at CAF +593773: cost centre 76 CAF in GHC.Char at CAF +594961: cost centre 75 CAF in GHC.Arr at CAF +596078: cost centre 74 CAF in Foreign.Storable at CAF +597195: cost centre 73 CAF in Foreign.Marshal.Array at CAF +598313: cost centre 72 CAF in Foreign.Marshal.Alloc at CAF +599361: cost centre 71 CAF in Foreign.C.Types at CAF +600548: cost centre 70 CAF in Foreign.C.String at CAF +601735: cost centre 69 CAF in Foreign.C.Error at CAF +603062: cost centre 68 CAF in Data.Type.Equality at CAF +604040: cost centre 67 CAF in Data.Tuple at CAF +605087: cost centre 66 CAF in Data.Maybe at CAF +606135: cost centre 65 CAF in Data.Dynamic at CAF +607113: cost centre 64 CAF in Data.Bits at CAF +608160: cost centre 63 CAF in Control.Monad.Fail at CAF +609278: cost centre 62 CAF in GHC.Event.Unique at CAF +610465: cost centre 61 CAF in GHC.Event.TimerManager at CAF +611722: cost centre 60 CAF in GHC.Event.Thread at CAF +612770: cost centre 59 CAF in GHC.Event.Internal at CAF +614027: cost centre 58 CAF in Data.Typeable.Internal at CAF +615074: cost centre 57 CAF in Data.OldList at CAF +616122: cost centre 56 CAF in Text.Read.Lex at CAF +617239: cost centre 55 CAF in Text.ParserCombinators.ReadPrec at CAF +618217: cost centre 54 CAF in Text.ParserCombinators.ReadP at CAF +619335: cost centre 53 CAF in System.Posix.Internals at CAF +620382: cost centre 52 CAF in System.IO at CAF +621360: cost centre 51 CAF in Numeric at CAF +622477: cost centre 50 CAF in GHC.Word at CAF +623595: cost centre 49 CAF in GHC.Weak at CAF +624572: cost centre 48 CAF in GHC.Unicode at CAF +625760: cost centre 47 CAF in GHC.TopHandler at CAF +626877: cost centre 46 CAF in GHC.Stack.Types at CAF +632534: cost centre 45 CAF in GHC.Stack.CCS at CAF +633512: cost centre 44 CAF in GHC.Stable at CAF +634699: cost centre 43 CAF in GHC.Show at CAF +635747: cost centre 42 CAF in GHC.STRef at CAF +636864: cost centre 41 CAF in GHC.ST at CAF +637982: cost centre 40 CAF in GHC.Real at CAF +638959: cost centre 39 CAF in GHC.Read at CAF +640007: cost centre 38 CAF in GHC.Ptr at CAF +641055: cost centre 37 CAF in GHC.Pack at CAF +642521: cost centre 36 CAF in GHC.Num at CAF +643499: cost centre 35 CAF in GHC.MVar at CAF +644616: cost centre 34 CAF in GHC.List at CAF +645664: cost centre 33 CAF in GHC.Int at CAF +646642: cost centre 32 CAF in GHC.IORef at CAF +647689: cost centre 31 CAF in GHC.IO.Unsafe at CAF +648877: cost centre 30 CAF in GHC.IO.IOMode at CAF +650134: cost centre 29 CAF in GHC.IO.Handle.Types at CAF +651251: cost centre 28 CAF in GHC.IO.Handle.Text at CAF +652299: cost centre 27 CAF in GHC.IO.Handle.Internals at CAF +653416: cost centre 26 CAF in GHC.IO.Handle.FD at CAF +654534: cost centre 25 CAF in GHC.IO.Handle at CAF +655721: cost centre 24 CAF in GHC.IO.Exception at CAF +656908: cost centre 23 CAF in GHC.IO.Encoding.UTF8 at CAF +658165: cost centre 22 CAF in GHC.IO.Encoding.UTF32 at CAF +659283: cost centre 21 CAF in GHC.IO.Encoding.UTF16 at CAF +660400: cost centre 20 CAF in GHC.IO.Encoding.Types at CAF +661448: cost centre 19 CAF in GHC.IO.Encoding.Latin1 at CAF +662565: cost centre 18 CAF in GHC.IO.Encoding.Iconv at CAF +663613: cost centre 17 CAF in GHC.IO.Encoding.Failure at CAF +664730: cost centre 16 CAF in GHC.IO.Encoding at CAF +665847: cost centre 15 CAF in GHC.IO.Buffer at CAF +666965: cost centre 14 CAF in GHC.IO at CAF +668152: cost centre 13 CAF in GHC.ForeignPtr at CAF +669339: cost centre 12 CAF in GHC.Foreign at CAF +670457: cost centre 11 CAF in GHC.Fingerprint.Type at CAF +671574: cost centre 10 CAF in GHC.Fingerprint at CAF +672762: cost centre 9 CAF in GHC.Exception at CAF +673809: cost centre 8 CAF in GHC.Err at CAF +674927: cost centre 7 CAF in GHC.Conc.Sync at CAF +676044: cost centre 6 CAF in GHC.Conc.Signal at CAF +677231: cost centre 5 CAF in GHC.Conc.IO at CAF +678279: cost centre 4 CAF in GHC.Base at CAF +679257: cost centre 3 CAF in Data.Either at CAF +680374: cost centre 2 CAF in Control.Exception.Base at CAF +681422: cost centre 1 CAF in Main at CAF +779825: task 0x7fb8915af740 created on cap 0 with OS kernel thread 30775 +786949: cap 0: creating thread 1 +791209: cap 0: running thread 1 +859093: cap 0: stopping thread 1 (stack overflow) +867264: cap 0: running thread 1 +899809: cap 0: creating thread 2 +916291: cap 0: stopping thread 1 (thread yielding) +1047309: task 0x7fb88f268700 created on cap 0 with OS kernel thread 30777 +1050941: cap 0: running thread 2 +1075455: cap 0: stopping thread 2 (thread yielding) +1094381: cap 0: running thread 1 +1121618: cap 0: thread 2 has label "IOManager on cap 0" +1157725: cap 0: creating thread 3 +1162684: cap 0: stopping thread 1 (thread yielding) +1177769: cap 0: running thread 2 +1184963: cap 0: stopping thread 2 (making a foreign call) +1311302: task 0x7fb88ea67700 created on cap 0 with OS kernel thread 30778 +1314933: cap 0: running thread 3 +1345244: cap 0: stopping thread 3 (making a foreign call) +1362494: cap 0: running thread 1 +1373738: cap 0: thread 3 has label "TimerManager" +1376182: cap 0: stopping thread 1 (thread finished) +1453983: task 0x7fb8915af740 deleted +1496236: task 0x7fb88e266700 created on cap 0 with OS kernel thread 30779 +1512718: task 0x7fb8915af740 created on cap 0 with OS kernel thread 30775 +1518934: cap 0: creating thread 4 +1520750: cap 0: running thread 4 +1574177: cap 0: stopping thread 4 (blocked on an MVar) +1581929: cap 0: running thread 3 +1597084: cap 0: stopping thread 3 (making a foreign call) +303221442: cap 0: running thread 3 +303244838: cap 0: stopping thread 3 (thread yielding) +303247981: cap 0: running thread 3 +303287720: cap 0: stopping thread 3 (making a foreign call) +303416992: cap 0: requesting parallel GC +303425163: cap 0: starting GC +303438642: cap 0: GC working +303656401: cap 0: GC idle +303657588: cap 0: GC done +303662896: cap 0: GC idle +303663874: cap 0: GC done +303665480: cap 0: GC idle +303666388: cap 0: GC done +303688038: cap 0: allocated on heap capset 0: 75736 total bytes till now +303691391: cap 0: finished GC +303693067: cap 0: all caps stopped for GC +303694324: cap 0: GC stats for heap capset 0: generation 1, 19984 bytes copied, 8728 bytes slop, 925696 bytes fragmentation, 1 par threads, 0 bytes max par copied, 19984 bytes total par copied +303696000: cap 0: live data in heap capset 0: 19944 bytes +303697117: cap 0: size of heap capset 0: 2097152 bytes +303699492: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5007132468: cap 0: running thread 3 +5007146156: cap 0: waking up thread 4 on cap 0 +5007153559: cap 0: stopping thread 3 (making a foreign call) +5007211526: cap 0: running thread 4 +5007228497: cap 0: stopping thread 4 (thread finished) +5007232338: task 0x7fb8915af740 deleted +5007242185: task 0x7fb8915af740 created on cap 0 with OS kernel thread 30775 +5007245328: cap 0: creating thread 5 +5007247633: cap 0: running thread 5 +5007278083: cap 0: stopping thread 5 (thread yielding) +5007283740: cap 0: requesting parallel GC +5007289187: cap 0: starting GC +5007297009: cap 0: GC working +5007509321: cap 0: GC idle +5007510508: cap 0: GC done +5007515885: cap 0: GC idle +5007516793: cap 0: GC done +5007518539: cap 0: GC idle +5007519447: cap 0: GC done +5007603045: start heap prof sample 0 +5007609191: heap prof sample 0, residency 96, label Control +5007613171: heap prof sample 0, residency 24, label EPoll +5007614708: heap prof sample 0, residency 80, label TimerManager +5007616454: heap prof sample 0, residency 288, label MUT_ARR_PTRS_FROZEN +5007618200: heap prof sample 0, residency 80, label STArray +5007619876: heap prof sample 0, residency 144, label ->>(#,#) +5007621412: heap prof sample 0, residency 168, label ->(#,#) +5007622949: heap prof sample 0, residency 112, label EventManager +5007624416: heap prof sample 0, residency 24, label Poll +5007626022: heap prof sample 0, residency 72, label (,) +5007627698: heap prof sample 0, residency 48, label ARR_WORDS +5007629234: heap prof sample 0, residency 96, label Backend +5007630771: heap prof sample 0, residency 24, label ->>>>(#,#) +5007632377: heap prof sample 0, residency 560, label MVar +5007633914: heap prof sample 0, residency 48, label DEAD_WEAK +5007635311: heap prof sample 0, residency 96, label WEAK +5007636777: heap prof sample 0, residency 1024, label IT +5007638453: heap prof sample 0, residency 32, label IO +5007639850: heap prof sample 0, residency 32, label ->IO +5007641456: heap prof sample 0, residency 24, label Dynamic +5007643132: heap prof sample 0, residency 1184, label MVAR +5007645088: heap prof sample 0, residency 32, label ThreadId +5007646834: heap prof sample 0, residency 3664, label MUT_ARR_PTRS_CLEAN +5007648440: heap prof sample 0, residency 816, label ForeignPtrContents +5007649977: heap prof sample 0, residency 72, label ForeignPtr +5007651443: heap prof sample 0, residency 80, label Maybe +5007652980: heap prof sample 0, residency 96, label AC +5007654656: heap prof sample 0, residency 120, label ->>>(#,#) +5007656332: heap prof sample 0, residency 48, label BLACKHOLE +5007657729: heap prof sample 0, residency 936, label [] +5007659405: heap prof sample 0, residency 64, label ->[] +5007660942: heap prof sample 0, residency 1232, label MUT_VAR_CLEAN +5007662478: heap prof sample 0, residency 48, label ->>IO +5007663945: heap prof sample 0, residency 608, label STRef +5007742723: cap 0: allocated on heap capset 0: 81112 total bytes till now +5007744539: cap 0: finished GC +5007745936: cap 0: all caps stopped for GC +5007747123: cap 0: GC stats for heap capset 0: generation 1, 21824 bytes copied, 7432 bytes slop, 954368 bytes fragmentation, 1 par threads, 0 bytes max par copied, 21824 bytes total par copied +5007749009: cap 0: live data in heap capset 0: 21240 bytes +5007749987: cap 0: size of heap capset 0: 2097152 bytes +5007752361: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5007755224: cap 0: running thread 5 +5007818010: cap 0: stopping thread 5 (thread finished) +5007820594: task 0x7fb8915af740 deleted +5007839451: cap 0: requesting sequential GC +5007842873: cap 0: starting GC +5007847273: cap 0: GC working +5007973332: cap 0: GC idle +5007974380: cap 0: GC done +5007979548: cap 0: GC idle +5007980456: cap 0: GC done +5007981923: cap 0: GC idle +5007982831: cap 0: GC done +5007999382: cap 0: allocated on heap capset 0: 119504 total bytes till now +5008001967: cap 0: finished GC +5008003084: cap 0: all caps stopped for GC +5008004132: cap 0: GC stats for heap capset 0: generation 1, 23152 bytes copied, 26368 bytes slop, 856064 bytes fragmentation, 1 par threads, 0 bytes max par copied, 23152 bytes total par copied +5008005319: cap 0: live data in heap capset 0: 55552 bytes +5008006297: cap 0: size of heap capset 0: 2097152 bytes +5008008112: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5008025642: cap 0: running thread 2 +5008090802: cap 0: stopping thread 2 (thread finished) +5008097926: task 0x7fb88f268700 deleted +5008122788: cap 0: running thread 3 +5008156521: cap 0: stopping thread 3 (thread finished) +5008167765: task 0x7fb88ea67700 deleted +5008221122: task 0x7fb88e266700 deleted +5008234531: cap 0: spark stats: 0 created, 0 converted, 0 remaining (0 overflowed, 0 dud, 0 GC'd, 0 fizzled) +5009129311: cap 0: allocated on heap capset 0: 121184 total bytes till now +5009135807: removed cap 0 from capset 0 +5009136994: removed cap 0 from capset 1 +5009138041: deleted cap 0 +5009139368: deleted capset 0 +5009140346: deleted capset 1 +