Changes between Version 40 and Version 41 of RTSsummaryEvents

Timestamp:

04/06/12 23:12:08 (14 months ago)

Author:

MikolajKonarski (IP: 95.160.111.162)

Comment:

Move the IRC logs about the final solution to the end

RTSsummaryEvents

@@ -333 +333 @@
 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.
+In the subsection there are detailed discussions of the original GC event order
+problems and about the initially considered design choices.
+
+==== Summary of the problems ====
+
+The main issue is how we measure the time spent doing GC. The +RTS -s
+measurement is taken from the stat_startGC() to stat_endGC() on the
+"primary" GC thread. In ThreadScope the main GC events we have access to
+are GC_START and GC_END on each capability.
+
+It turns out that these different measurements are often quite
+different.  In particular there can often be a significant delay between
+when +RTS -s reports and when the other capabilities start the mutator
+again (and hence emit GC_END). Our guess is that this is because the
+other caps are suspended at the end of the GC while the primary GC
+thread does its stats etc, then when it releases them it can take a
+while for the other caps to be rescheduled by the OS.
+
+In this example, END_GC on one of the caps comes 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
+}}}
+
+From the user's point of view it is perhaps more accurate to look at the
+GC_START/END because that's when the caps really get back to the
+mutator.
+
+This different GC vs mutator measurement affects several other
+statistics and the difference vs +RTS -s can build up to be quite large
+on larger eventlogs.
+
+Additionally, if we only look at the GC_START/GC_END then it's not
+entirely clear what the average or maximum pause time should mean, since
+we have multiple capabilities. Is the max the max for any individual
+cap, or from when the first cap does GC_START 'til when the last cap
+does GC_END.
+
+Which brings up another issue: some of the GC statistics rely on a GC
+being global across all capabilities, but strictly speaking the current
+GC events do not let us associate a GC_START/END on one cap with that on
+another. One core can issue a new REQUEST_SEQ_GC
+before another has issued it's GC_END from the previous GC. Add in the
+fact that not all cores have to take part in a GC and it's tricky to
+associate GCs on each core to a global GC.
+
+We have added a GC_GLOBAL_SYNC event which is emitted strictly between
+GC_START/GC_END on all cores, used for associating GC across all cores. 
+If we could calculate stats in such a way that we do not 
+need to associate GC across
+all cores then that would be better (and more flexible e.g. to work with
+your local GC branch).
+
+==== An implemented partial solution for RequestParGC ====
+
+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". 
+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 events).
+
+Here are the results of implementing it:
+
+{{{
+18:13 < mikolaj> dcoutts, JaffaCake: I've tested the "moving the interruptAllCapabilities() 
+call below the traceEvent calls" tweak and it helps in 99-ish % of cases
+18:13 < mikolaj> that is, the order of GC events is much, much better now
+18:14 < mikolaj> but there are still very rare cases, especially when the par GC request was 
+from one HEC, and another, busy HEC is too slow to report finishing a previous GC
+18:15 < mikolaj> so it does not help that much in validating eventlogs, but makes them 
+so much more readable, if a user wants to inspect the event messages one by one
+}}}
+
+==== More example eventlog fragments ====
+
+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, 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
+}}}
+
+
+==== Discussions that led to the implemented GC_START/GC_END/GC_GLOBAL_SYNC solution ====
 
 Here are two IRC logs with the discussion that led
@@ -463 +645 @@
 }}}
 
+Below is the second log.
+
 {{{
 12:38 < dcoutts> JaffaCake: we didn't plan on adding a per-HEC GC stat event, do you think that would be useful? what info would we get?
@@ -486 +670 @@
 13:04 < mikolaj_> that's why I asked about moving GC_END, but perhaps wait until dcoutts write the paper and you finish overhauling stat gathering
 }}}
-
-==== Summary of the problems ====
-
-The main issue is how we measure the time spent doing GC. The +RTS -s
-measurement is taken from the stat_startGC() to stat_endGC() on the
-"primary" GC thread. In ThreadScope the main GC events we have access to
-are GC_START and GC_END on each capability.
-
-It turns out that these different measurements are often quite
-different.  In particular there can often be a significant delay between
-when +RTS -s reports and when the other capabilities start the mutator
-again (and hence emit GC_END). Our guess is that this is because the
-other caps are suspended at the end of the GC while the primary GC
-thread does its stats etc, then when it releases them it can take a
-while for the other caps to be rescheduled by the OS.
-
-In this example, END_GC on one of the caps comes 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
-}}}
-
-From the user's point of view it is perhaps more accurate to look at the
-GC_START/END because that's when the caps really get back to the
-mutator.
-
-This different GC vs mutator measurement affects several other
-statistics and the difference vs +RTS -s can build up to be quite large
-on larger eventlogs.
-
-Additionally, if we only look at the GC_START/GC_END then it's not
-entirely clear what the average or maximum pause time should mean, since
-we have multiple capabilities. Is the max the max for any individual
-cap, or from when the first cap does GC_START 'til when the last cap
-does GC_END.
-
-Which brings up another issue: some of the GC statistics rely on a GC
-being global across all capabilities, but strictly speaking the current
-GC events do not let us associate a GC_START/END on one cap with that on
-another. One core can issue a new REQUEST_SEQ_GC
-before another has issued it's GC_END from the previous GC. Add in the
-fact that not all cores have to take part in a GC and it's tricky to
-associate GCs on each core to a global GC.
-
-We have added a GC_GLOBAL_SYNC event which is emitted strictly between
-GC_START/GC_END on all cores, used for associating GC across all cores. 
-If we could calculate stats in such a way that we do not 
-need to associate GC across
-all cores then that would be better (and more flexible e.g. to work with
-your local GC branch).
-
-==== An implemented partial solution for RequestParGC ====
-
-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". 
-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 events).
-
-Here are the results of implementing it:
-
-{{{
-18:13 < mikolaj> dcoutts, JaffaCake: I've tested the "moving the interruptAllCapabilities() 
-call below the traceEvent calls" tweak and it helps in 99-ish % of cases
-18:13 < mikolaj> that is, the order of GC events is much, much better now
-18:14 < mikolaj> but there are still very rare cases, especially when the par GC request was 
-from one HEC, and another, busy HEC is too slow to report finishing a previous GC
-18:15 < mikolaj> so it does not help that much in validating eventlogs, but makes them 
-so much more readable, if a user wants to inspect the event messages one by one
-}}}
-
-==== More example eventlog fragments ====
-
-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, 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
-}}}