Changes between Version 35 and Version 36 of RTSsummaryEvents

Timestamp:

04/06/12 21:11:51 (15 months ago)

Author:

MikolajKonarski (IP: 95.160.111.162)

Comment:

Paste one of the emails about bad event ordering

RTSsummaryEvents

@@ -269 +269 @@
 I'd guess the elapsed time should always be higher than the CPU time, shouldn't it?
 
-== The list of considered new events or even parameters (not final) ==
+== The list of considered new events (the implementation closely follows this draft, even though not all details match) ==
 
 There is a wealth of statistics around heaps and GC. Some of the stats are reasonably common, shared by different implementations while many more are highly specific to a particular implementation. Even if we ignore RTSs other than GHC, we still have an issue of flexibility for future changes in GHC's RTS.
@@ -283 +283 @@
  * `EVENT_HEAP_LIVE (heap_capset, live_bytes)`: is the current amount of live/reachable data in the heap. This is almost certainly only known after a major GC.
 
-
 ==== New GHC-specific general memory stats events ====
 
@@ -300 +299 @@
 If in future we allow multiple independent heaps in the same OS process (e.g. separate RTS instances) then this scheme would let us cope by making a separate capset. Similarly it'd cope with implementations like GdH which use a global heap spanning multiple OS processes.
 
-==== Tinkering ====
-
-While we tinker with these events, we could try to ensure
-that RequestSeqGC and RequestParGC are emitted before their corresponding
+== Problems with the order of event in the eventlog ==
+
+In the implemented version, we sidestep the issues with event order
+by tightly controlling the timestamps in the GC_START 
+and GC_END events on the main GC cap (the one that requests GC)
+and by adding the GC_GLOBAL_SYNC event.
+We also treat the elapsed time delays needed to synchronise caps for parallel GC
+(both at GC start and GC end) as MUT time, instead of GC time,
+because while they are needed for GC, their cause is (slow) 
+OS scheduling, just as for any other delays when switching threads.
+Below is a detailed discussion of the original GC event order
+and initial design choices considered.
+
+We can try to ensure that RequestSeqGC and RequestParGC are emitted before their corresponding
 GC_START events, by using the following tip from JaffaCake: 
 "actually you could try moving the interruptAllCapabilities() call in Schedule.c:1500 down below the traceEvent calls". 
-Currently they can be emitted in arbitrary order and it complicates analysis, 
+However, even with this implemented in GHC HEAD, the events can still
+be emitted in arbitrary order and it complicates analysis, 
 especially for selected intervals (and complicates and makes less strict
-the future validation of the events).
+the future validation of events).
+
+The example of the event order issues below are on a system with 2 caps, on an eventlog
+with lots of small GCs. They show how GC times measured by "+RTS -s",
+that is from START_GC to the "GC stats" event, are different from TS times.
+The TS times are the average over all caps of the pause
+between START_GC, when the caps stop mutating,
+and END_GC, when they resume mutating. (Most of) the difference
+stems probably from the thread sleep/wake delays, some ending GC bookkeeping
+(including the time taken to emit GC and other events)
+and related overheads.
+
+It seems the TS times are more useful to the programmer that is mostly
+concerned in how much time is spend mutating and not how the wasted time
+is divided between the actual GC and the cap switching overhead.
+Moreover "+RTS -s" just adds the cap switching overhead to the MUT time
+hiding the fact that it's caused by GC.
+
+The differences accumulate and affect the "GC total elapsed time",
+"Avg pause" and "Max pause" columns of the GC table in "+RTS -s".
+They also influence the "Task" table (not reproduced in TS).
+They add up in total "GC time (elapsed)" and consequently in
+"MUT time (elapsed)" that is obtained by subtracting GC time from total time.
+In the result, they influence "Alloc rate" and "Productivity", too.
+The figures are seriously different between TS and "+RTS -s",
+except on small eventlogs.
+
+It seems for all these figures the TS version is the right one.
+In particular, if by "pause" we mean the time between
+GC_START and GC_END, by "Max pause" we neither mean
+the "maximum over all GCs of (minimal pause over all caps)",
+similarly as in +RTS -s (but not exactly the same, because
+even the minimal GC_END is usually a tick after "GC stats"),
+nor "maximum over all GCs of (maximal pause over all caps)", which
+we could easily show in TS and which could make sense for a real-time
+system with specialized, non-interchangeable caps,
+but "maximum over all GCs of (average pause over all caps)".
+
+Here's an example demonstrating END_GC
+for the previous GC following REQUEST_PAR_GC for the next GC on another cap.
+Note that the early END_GC on cap 1 still comes 1000 nanoseconds after
+the "GC stats" event. Even such small differences accumulate over all GCs:
+
+{{{
+9366536000: cap 1: GC stats for heap capset 0: generation 0, 77552
+bytes copied, 226056 bytes slop, 696320 bytes fragmentation, 2 par
+threads, 71736 bytes max par copied, 77520 bytes total par copied
+9366537000: cap 1: finished GC
+9366538000: cap 1: spark stats: 1910358 created, 1228256 converted,
+1000 remaining (0 overflowed, 0 dud, 58306 GC'd, 144981 fizzled)
+9366541000: cap 1: running thread 3
+9367310000: cap 1: stopping thread 3 (heap overflow)
+9367312000: cap 1: requesting parallel GC
+9367316000: cap 0: finished GC
+9367317000: cap 0: spark stats: 1071418 created, 1292489 converted, 0
+remaining (0 overflowed, 0 dud, 41840 GC'd, 214904 fizzled)
+9367318000: cap 0: starting GC
+9368131000: cap 1: starting GC
+}}}
+
+Another example with END_GC on one of the caps coming very late:
+
+{{{
+9378252000: cap 1: GC stats for heap capset 0: generation 0, 45160
+bytes copied, 58296 bytes slop, 1757184 bytes fragmentation, 2 par
+threads, 45080 bytes max par copied, 45112 bytes total par copied
+9378253000: cap 1: finished GC
+9378254000: cap 1: spark stats: 1913071 created, 1229807 converted,
+221 remaining (0 overflowed, 0 dud, 58923 GC'd, 144981 fizzled)
+9378255000: cap 1: waking up thread 3 on cap 1
+9378257000: cap 1: running thread 2885
+9378259000: cap 1: stopping thread 2885 (thread finished)
+9378268000: cap 1: running thread 3
+9378354000: cap 1: stopping thread 3 (blocked on black hole owned by
+thread 2884)
+9378355000: cap 1: creating thread 2886
+9378363000: cap 0: finished GC
+}}}
+
+Yet another example, this time there's a different event
+("allocated on heap capset") on the late cap, at the same time
+as "GC stats" an another cap and before END_GC finally arrives.
+Not sure how this can happen. The END_GC on the early cap comes here
+a bit later that usually (2000 nanoseconds after the "GC stats" event), too:
+
+{{{
+836505000: cap 0: GC stats for heap capset 0: generation 0, 11584
+bytes copied, 205232 bytes slop, 1007616 bytes fragmentation, 2 par
+threads, 11472 bytes max par copied, 11536 bytes total par copied
+836505000: cap 1: allocated on heap capset 0: 180717856 total bytes till now
+836507000: cap 0: finished GC
+836507000: cap 0: spark stats: 5893 created, 114894 converted, 228
+remaining (0 overflowed, 0 dud, 13 GC'd, 22190 fizzled)
+836509000: cap 0: waking up thread 3 on cap 0
+836511000: cap 0: running thread 233
+836514000: cap 0: stopping thread 233 (thread finished)
+836521000: cap 1: finished GC
+}}}
+
+Finally an example where END_GC is quite late on both caps
+(3000 nanoseconds and 6000 nanoseconds):
+
+{{{
+67582000: cap 1: GC stats for heap capset 0: generation 1, 58248 bytes
+copied, 40096 bytes slop, 1912832 bytes fragmentation, 2 par threads,
+51920 bytes max par copied, 58208 bytes total par copied
+67583000: cap 1: live data in heap capset 0: 82784 bytes
+67585000: cap 1: finished GC
+67585000: cap 1: spark stats: 15101 created, 2570 converted, 508
+remaining (0 overflowed, 0 dud, 879 GC'd, 12 fizzled)
+67588000: cap 0: finished GC
+}}}