GHC issueshttps://gitlab.haskell.org/ghc/ghc/-/issues2024-01-16T16:30:56Zhttps://gitlab.haskell.org/ghc/ghc/-/issues/24319EVENT_IPE payload length can easily overflow2024-01-16T16:30:56ZMatthew PickeringEVENT_IPE payload length can easily overflowProblem: EVENT_IPE has a payload length which is Word16, hence limit 65536. This can overflow if there are very long string fields in IPE info.
However, I don't know why this field exists because it's not needed to decode the payload.
...Problem: EVENT_IPE has a payload length which is Word16, hence limit 65536. This can overflow if there are very long string fields in IPE info.
However, I don't know why this field exists because it's not needed to decode the payload.
Also see !11767 which is related to this but would truncate each string to size Word16 (still not sufficient to fix this overflow).
This caused an issue in `ghc-events` where the assertion failed which checked the payload size matched up with what was actually parsed.https://gitlab.haskell.org/ghc/ghc/-/issues/24287ACQUIRE_LOCK deadlock with ipe2024-02-08T20:09:11ZZubinACQUIRE_LOCK deadlock with ipeWhen GHC is compiled with both profiling and ipe information, we try to acquire the eventlog mutex twice in the same thread.
```
ghc: internal error: ACQUIRE_LOCK(0x1dc2e7e0) failed (rts/eventlog/EventLog.c:1572): 35
(GHC version 9....When GHC is compiled with both profiling and ipe information, we try to acquire the eventlog mutex twice in the same thread.
```
ghc: internal error: ACQUIRE_LOCK(0x1dc2e7e0) failed (rts/eventlog/EventLog.c:1572): 35
(GHC version 9.9.20231213 for x86_64_unknown_linux)
Please report this as a GHC bug: https://www.haskell.org/ghc/reportabug
```
GHC is compiled using `--flavour=perf+profiled_ghc+no_dynamic_ghc+ipe+debug_ghc+debug_info`
Then we run ghc with both heap profiling and eventlogs enabled: `ghc +RTS -hb -l`
The lock is initially acquired in `postIPE`:
```c
void postIPE(const InfoProvEnt *ipe)
{
ACQUIRE_LOCK(&eventBufMutex);
```
Then we attempt to acquire it again in `flushAllCapsEventsBufs`
```c
void flushAllCapsEventsBufs(void)
{
if (!event_log_writer) {
return;
}
ACQUIRE_LOCK(&eventBufMutex);
printAndClearEventBuf(&eventBuf);
RELEASE_LOCK(&eventBufMutex);
```https://gitlab.haskell.org/ghc/ghc/-/issues/24197`dumpIPEToEventLog` disregards maximum event length2024-01-30T11:44:36ZBen Gamari`dumpIPEToEventLog` disregards maximum event lengthBuilding a compiler in the `default+ipe+debug_info+ghc_debug` flavour will quickly reveal that `dumpIPEToEventLog` makes no attempt to honor the maximum event length:
```
ghc: internal error: ASSERTION FAILED: file rts/eventlog/EventLog....Building a compiler in the `default+ipe+debug_info+ghc_debug` flavour will quickly reveal that `dumpIPEToEventLog` makes no attempt to honor the maximum event length:
```
ghc: internal error: ASSERTION FAILED: file rts/eventlog/EventLog.c, line 183
Stack trace:
0x110e52c8 set_initial_registers (rts/Libdw.c:294.5)
0x7ffff7b826b8 dwfl_thread_getframes (/nix/store/dbvlgp6fsp0ar1pn9chyc41j8y2lh2jx-elfutils-0.189/lib/libdw-0.189.so)
0x7ffff7b8220b get_one_thread_cb (/nix/store/dbvlgp6fsp0ar1pn9chyc41j8y2lh2jx-elfutils-0.189/lib/libdw-0.189.so)
0x7ffff7b8251a dwfl_getthreads (/nix/store/dbvlgp6fsp0ar1pn9chyc41j8y2lh2jx-elfutils-0.189/lib/libdw-0.189.so)
0x7ffff7b82a47 dwfl_getthread_frames (/nix/store/dbvlgp6fsp0ar1pn9chyc41j8y2lh2jx-elfutils-0.189/lib/libdw-0.189.so)
0x110e519b libdwGetBacktrace (rts/Libdw.c:263.15)
0x1107def8 rtsFatalInternalErrorFn (rts/RtsMessages.c:175.22)
0x1107dab7 barf (rts/RtsMessages.c:49.3)
0x1107db1a errorBelch (rts/RtsMessages.c:68.1)
0x1109959c postString (rts/eventlog/EventLog.c:184.9)
0x1109c6ca postIPE (rts/eventlog/EventLog.c:1449.36)
0x11095807 traceIPE (rts/Trace.c:702.1)
0x11074957 dumpIPEToEventLog (rts/IPE.c:122.50)
0x11099a1d postInitEvent (rts/eventlog/EventLog.c:321.5)
0x1107e721 hs_init_ghc (rts/RtsStartup.c:403.5)
0x1107d93e hs_main (rts/RtsMain.c:57.5)
0x751bc1 (null) (/mnt/data/exp/ghc/ghc-landing/_build/stage1/bin/ghc)
0x7ffff7c09ace __libc_start_call_main (/nix/store/dg8mpqqykmw9c7l0bgzzb5znkymlbfjw-glibc-2.37-8/lib/libc.so.6)
0x7ffff7c09b89 __libc_start_main@@GLIBC_2.34 (/nix/store/dg8mpqqykmw9c7l0bgzzb5znkymlbfjw-glibc-2.37-8/lib/libc.so.6)
0x409055 _start (/mnt/data/exp/ghc/ghc-landing/_build/stage1/bin/ghc)
(GHC version 9.9.20231025 for x86_64_unknown_linux)
Please report this as a GHC bug: https://www.haskell.org/ghc/reportabug
```
The offending IPE field appears to be `ty_desc`, which in this case is 76314 characters long (being the `Generic` representation of the `GHC.Tc.Errors.Types.TcRnMessage` type).
Without RTS assertions enabled this results in the program crashing due to non-obvious heap corruption.https://gitlab.haskell.org/ghc/ghc/-/issues/24148Cost centres registered after the program begins are missing from the eventlog2023-11-07T14:55:51ZAlexis KingCost centres registered after the program begins are missing from the eventlogOn initialization, the RTS dumps all registered cost centres to the eventlog (`dumpCostCentresToEventLog`), and if code is loaded after that point, any cost centres it registers won’t be included. This can be observed by compiling code t...On initialization, the RTS dumps all registered cost centres to the eventlog (`dumpCostCentresToEventLog`), and if code is loaded after that point, any cost centres it registers won’t be included. This can be observed by compiling code that uses Template Haskell using a profiled GHC:
```haskell
module A where
mkBigList :: Int -> [Int]
mkBigList x = {-# SCC "A.mkBigList" #-} go x
where
go 0 = []
go x = x : go (x - 1)
```
```haskell
{-# LANGUAGE TemplateHaskell #-}
module B where
import Control.Exception (evaluate)
import GHC.Profiling (requestHeapCensus)
import Language.Haskell.TH.Syntax (lift, runIO)
import System.Mem (performMajorGC)
import A
bigList :: [Int]
bigList = $(do let x = mkBigList 10000
runIO $ do
evaluate (length x)
requestHeapCensus
performMajorGC
lift x)
```
```
$ ghc -prof A B +RTS -l-a -hc -RTS
```
The `.hp` heap profile includes a sample that mentions `mkBigList`, but that cost centre’s definition is absent from the generated eventlog. Consequently, there is a `HEAP_PROF_SAMPLE_COST_CENTRE` event that includes a cost centre number without any corresponding definition. The RTS should probably keep track of how many cost centres have already been emitted to the eventlog and dump any that have been newly registered before writing a new heap sample.9.10.1https://gitlab.haskell.org/ghc/ghc/-/issues/24140Eventlog + Debugging flag order shows unexpected behaviour2023-11-22T14:27:43ZJavier SagredoEventlog + Debugging flag order shows unexpected behaviour## Summary
Order of debug options and eventlog result in unexpected behavior.
- `-Dm`: emits messages `-Dm` to stderr :white_check_mark:
- `-Dm -l`: emits messages `-Dm` to the eventlog :white_check_mark:
- `-l -Dm`: emits `-Dm` to s...## Summary
Order of debug options and eventlog result in unexpected behavior.
- `-Dm`: emits messages `-Dm` to stderr :white_check_mark:
- `-Dm -l`: emits messages `-Dm` to the eventlog :white_check_mark:
- `-l -Dm`: emits `-Dm` to stderr and **enables what I believe is `-Ds`** :warning:
## Steps to reproduce
Any program would suffice. I can provide this one:
```bash
$ cat A.hs
module Main where
{-# NOINLINE fib #-}
fib 0 = 0
fib 1 = 1
fib n = fib (n-1) + fib (n-2)
main = do
print (fib 30)
$ ghc A.hs -debug
[1 of 2] Compiling Main ( A.hs, A.o )
[2 of 2] Linking A [Objects changed]
$ ./A +RTS -Dm 2>&1 | head
STM: 0x5b0780 : lock_stm()
STM: stmPreGCHook
STM: 0x5b0780 : unlock_stm()
STM: 0x5b0780 : lock_stm()
STM: stmPreGCHook
STM: 0x5b0780 : unlock_stm()
STM: 0x5b0780 : lock_stm()
STM: stmPreGCHook
STM: 0x5b0780 : unlock_stm()
STM: 0x5b0780 : lock_stm()
$ ./A +RTS -l -Dm 2>&1 | head
created capset 0 of type 2
created capset 1 of type 3
cap 0: initialised
assigned cap 0 to capset 0
assigned cap 0 to capset 1
cap 0: created thread 1[""]
cap 0: running thread 1[""] (ThreadRunGHC)
cap 0: thread 1[""] stopped (stack overflow, size 104)
cap 0: running thread 1[""] (ThreadRunGHC)
cap 0: thread 1[""] stopped (yielding)
$ ./A +RTS -Dm -l 2>&1 | head
832040
```
## Expected behavior
I would expect `-Ds` not to be enabled by this combination of flags, and furthermore I though the order of the options should not modify the behaviour.
## Environment
* GHC version used: 9.6.3
Optional:
* Operating System: Ubuntu 23.10
* System Architecture: x86_64-linuxMatthew PickeringMatthew Pickeringhttps://gitlab.haskell.org/ghc/ghc/-/issues/23200TICKY_COUNTER_DEF documentation is out of date2023-04-04T14:49:30ZMatthew PickeringTICKY_COUNTER_DEF documentation is out of dateSee https://downloads.haskell.org/ghc/latest/docs/users_guide/eventlog-formats.html#ticky-counters
* Problem 1: It should be section 16.7 rather than nested in the 16.6.3 (non-moving GC events)
* Problem 2: The description doesn't docum...See https://downloads.haskell.org/ghc/latest/docs/users_guide/eventlog-formats.html#ticky-counters
* Problem 1: It should be section 16.7 rather than nested in the 16.6.3 (non-moving GC events)
* Problem 2: The description doesn't document the 6th field which contains a JSON string
See aba482ea941bb0b06f041be950712ed71e047e819.6.2Andreas KlebingerAndreas Klebingerhttps://gitlab.haskell.org/ghc/ghc/-/issues/22603Wasm backend testsuite failure: T200062023-02-01T13:31:42ZCheng ShaoWasm backend testsuite failure: T20006`T20006` fails with:
```
Wrong exit code for T20006(normal)(expected 0 , actual 1 )
Stderr ( T20006 ):
error: Uncaught RuntimeError: divide by zero
at setupRtsFlags (wasm://wasm/005c2cca:1:781073)
at hs_init_ghc (wasm://wasm/005...`T20006` fails with:
```
Wrong exit code for T20006(normal)(expected 0 , actual 1 )
Stderr ( T20006 ):
error: Uncaught RuntimeError: divide by zero
at setupRtsFlags (wasm://wasm/005c2cca:1:781073)
at hs_init_ghc (wasm://wasm/005c2cca:1:809573)
at hs_main (wasm://wasm/005c2cca:1:790284)
at main (wasm://wasm/005c2cca:1:27177)
at __main_void (wasm://wasm/005c2cca:1:1116161)
at _start (wasm://wasm/005c2cca:1:26644)
at Context.start (https://deno.land/std@0.167.0/wasi/snapshot_preview1.ts:1765:7)
at file:///workspace/.ghc-wasm/wasm-run/bin/wasm-run.js:24:9
*** unexpected failure for T20006(normal)
```
`T20006.hs`:
```haskell
module Main where
main :: IO ()
main = return ()
```
Run opts:
```python
test('T20006', [extra_run_opts('+RTS --eventlog-flush-interval=1')],
compile_and_run,
[''])
```Cheng ShaoCheng Shaohttps://gitlab.haskell.org/ghc/ghc/-/issues/22136Feature parity between GHC.Stats and eventlog2023-01-22T01:40:25ZTeo CamarasuFeature parity between GHC.Stats and eventlogBoth the GHC.Stats and eventlog interfaces expose statistics about a running program.
Some statistics are only available in one interface, eg, #21537 GHC.Stats lacked a fragmentation statistic that was available in the eventlog.
It wou...Both the GHC.Stats and eventlog interfaces expose statistics about a running program.
Some statistics are only available in one interface, eg, #21537 GHC.Stats lacked a fragmentation statistic that was available in the eventlog.
It would be good that if a statistic is available in one then it is also available in the other.
Though it need not be available in the same way. For instance GHC.Stats exposes a number of GCs stat whereas the eventlog exposes this information through having GC events that a user can add up to get the number of GCs.
The aim of this ticket is to track progress towards this goal. If no one objects with the goal, I'll soon look through the two interfaces and see where they diverge, and add a todo list here.https://gitlab.haskell.org/ghc/ghc/-/issues/21813`-la` doesn't enable all event types2022-11-23T18:18:12ZTeo Camarasu`-la` doesn't enable all event types
If you look at the implementation of `read_trace_flags` (https://gitlab.haskell.org/ghc/ghc/-/blob/master/rts/RtsFlags.c#L2335) you will see that `-la` doesn't in fact turn on all classes of events.
It seems to be missing `nonmoving_g...
If you look at the implementation of `read_trace_flags` (https://gitlab.haskell.org/ghc/ghc/-/blob/master/rts/RtsFlags.c#L2335) you will see that `-la` doesn't in fact turn on all classes of events.
It seems to be missing `nonmoving_gc` and `ticky`.
I'd be happy to submit a fix.Teo CamarasuTeo Camarasuhttps://gitlab.haskell.org/ghc/ghc/-/issues/21647Crash on shutdown when eventlog is used2023-09-07T09:35:25ZAdam GundryCrash on shutdown when eventlog is used## Summary
When using the eventlog in a large server application, I observe
```
munmap_chunk(): invalid pointer
Aborted (core dumped)
```
when the program exits. The problem does not arise without the `-l` flag. The resulting eventlog c...## Summary
When using the eventlog in a large server application, I observe
```
munmap_chunk(): invalid pointer
Aborted (core dumped)
```
when the program exits. The problem does not arise without the `-l` flag. The resulting eventlog cannot be read by `eventlog2html`, presumably because it is incomplete or corrupted.
A backtrace indicates the problem is that `finishCapEventLogging` tries to call `stgFree` on a buffer that has already been freed.
```
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1 0x00007fcc82cde859 in __GI_abort () at abort.c:79
#2 0x00007fcc82d4926e in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x7fcc82e73298 "%s\n") at ../sysdeps/posix/libc_fatal.c:155
#3 0x00007fcc82d512fc in malloc_printerr (str=str@entry=0x7fcc82e751e0 "munmap_chunk(): invalid pointer") at malloc.c:5347
#4 0x00007fcc82d5154c in munmap_chunk (p=<optimised out>) at malloc.c:2830
#5 0x00007fcc834004e6 in finishCapEventLogging () at rts/eventlog/EventLog.c:778
#6 0x00007fcc833d1a94 in hs_exit_ (wait_foreign=false) at rts/RtsStartup.c:526
#7 0x00007fcc833d2055 in shutdownHaskellAndExit (n=1, fastExit=<optimised out>) at rts/RtsStartup.c:652
#8 0x00007fcc84206680 in ?? () from /opt/ghc/9.2.2/lib/ghc-9.2.2/base-4.16.1.0/libHSbase-4.16.1.0-ghc9.2.2.so
#9 0x0000000000000000 in ?? ()
```
I don't see why `finishCapEventLogging` would be called twice though.
## Steps to reproduce
Unfortunately this is a large commercial codebase so I can't post a public reproducer, and I'm not sure where to start with extracting a minimal example.
## Expected behavior
`finishCapEventLogging` should not double free the buffer.
## Environment
* GHC version used: 9.2.2
* Operating System: Linux
* System Architecture: x86_649.8.1https://gitlab.haskell.org/ghc/ghc/-/issues/21597Running a debug RTS with `-DS` seems to emit the whole IPE table stderr.2022-09-26T17:22:43ZAndreas KlebingerRunning a debug RTS with `-DS` seems to emit the whole IPE table stderr.I'm trying to run a profiled ghc with IPE information linked against the debug RTS like this:
_prof_late/stage1/bin/ghc ... +RTS -s -RTS -O2 -fforce-recomp +RTS -s -p -I0 -A500m -DS
And I get about two million lines of IPE output like ...I'm trying to run a profiled ghc with IPE information linked against the debug RTS like this:
_prof_late/stage1/bin/ghc ... +RTS -s -RTS -O2 -fforce-recomp +RTS -s -p -I0 -A500m -DS
And I get about two million lines of IPE output like the entry below:
```
7f01900b5080: IPE: table_name PushCallStack_GHC.HsToCore.Match.Constructor_0_con_info, closure_desc 1, ty_desc CallStack, label emptyCallStack, module GHC.HsToCore.Match.Constructor, srcloc libraries/base/GHC/Stack/Types.hs:196:1-31
```
I don't think dumping 250MB of data to stderr on startup when we enable sanity checks is reasonable.
I think it's triggered from ` traceInitEvent(dumpIPEToEventLog);` in the RTS startup code.
@mpickeringBen GamariBen Gamarihttps://gitlab.haskell.org/ghc/ghc/-/issues/21537Add fragmentation statistics to GHC.Stats2022-09-22T10:35:26ZTeo CamarasuAdd fragmentation statistics to GHC.Stats## Motivation
Fragmentation is a key statistic when using the non-moving garbage collector. The event log has information about heap fragmentation, but it would be helpful to have the same information available from `GHC.Stats`.
As far...## Motivation
Fragmentation is a key statistic when using the non-moving garbage collector. The event log has information about heap fragmentation, but it would be helpful to have the same information available from `GHC.Stats`.
As far as I understand we can already get at this statistic by taking `gcdetails_mem_in_use_bytes - gcdetails_live_bytes `. But I'm not sure that's right. And even if that's true, I think it would be more user friendly to make this stat available in an explicit way.
## Proposal
Add a field to `GHC.Stats.GCDetails` called `gcdetails_fragmentation_bytes` that gives the same stats as the event log fragmentation counter.
I'm happy to implement this.9.6.1Teo CamarasuTeo Camarasuhttps://gitlab.haskell.org/ghc/ghc/-/issues/21070gen_event_types requires an audit2022-04-01T17:27:27ZMatthew Pickeringgen_event_types requires an auditDue to the recent refactor of the eventlog event generation I discovered two bugs due to incorrect information in `gen_event_types.py`, in particular the size for `EVENT_IPE` and `EVENT_MEM_RETURN` were incorrect. The whole file should b...Due to the recent refactor of the eventlog event generation I discovered two bugs due to incorrect information in `gen_event_types.py`, in particular the size for `EVENT_IPE` and `EVENT_MEM_RETURN` were incorrect. The whole file should be audited to ensure there are no more of these bugs.9.4.1Ben GamariBen Gamarihttps://gitlab.haskell.org/ghc/ghc/-/issues/20384ProfSampleCostCentre eventlog output lacks information about allocation2021-09-21T15:04:35ZMatthew PickeringProfSampleCostCentre eventlog output lacks information about allocationThe ProfSampleCostCentre contains the cost centre stack for the current tick but nothing about the allocation performed under that stack.
If you look at the definition for `CostCentreStack` there are quite a few other fields which coul...The ProfSampleCostCentre contains the cost centre stack for the current tick but nothing about the allocation performed under that stack.
If you look at the definition for `CostCentreStack` there are quite a few other fields which could be emitted but are elided.
```
typedef struct CostCentreStack_ {
StgInt ccsID; // unique ID, allocated by the RTS
CostCentre *cc; // Cost centre at the top of the stack
struct CostCentreStack_ *prevStack; // parent
struct IndexTable_ *indexTable; // children
struct CostCentreStack_ *root; // root of stack
StgWord depth; // number of items in the stack
StgWord64 scc_count; // Count of times this CCS is entered
// align 8 (Note [struct alignment])
StgWord selected; // is this CCS shown in the heap
// profile? (zero if excluded via -hc
// -hm etc.)
StgWord time_ticks; // number of time ticks accumulated by
// this CCS
StgWord64 mem_alloc; // mem allocated by this CCS
// align 8 (Note [struct alignment])
StgWord64 inherited_alloc; // sum of mem_alloc over all children
// (calculated at the end)
// align 8 (Note [struct alignment])
StgWord inherited_ticks; // sum of time_ticks over all children
// (calculated at the end)
} CostCentreStack;
```
We should probably have at least the scc_count and mem_alloc fields?
cc @bgamarihttps://gitlab.haskell.org/ghc/ghc/-/issues/20221Very long command line leads to an invalid eventlog2023-05-03T11:31:31ZMatthew PickeringVery long command line leads to an invalid eventlogReproduce with:
```
echo "module A100 where" > A100.hs
echo -optP-D__F{1..10000}__ > T14697-flags
ghc --make A100 $(cat T14697-flags) +RTS -l
```
Produces an eventlog which `ghc-events` fails to parse.
```
[nix-shell:~/eventlog2htm...Reproduce with:
```
echo "module A100 where" > A100.hs
echo -optP-D__F{1..10000}__ > T14697-flags
ghc --make A100 $(cat T14697-flags) +RTS -l
```
Produces an eventlog which `ghc-events` fails to parse.
```
[nix-shell:~/eventlog2html]$ cabal run eventlog2html -- ghc.eventlog
eventlog2html: Ix{Int}.index: Index (24415) out of range ((0,212))
```https://gitlab.haskell.org/ghc/ghc/-/issues/19949`+RTS -va` does not show all events2021-08-01T11:37:28ZSven Tennie`+RTS -va` does not show all events*Unfortunately the template support in this GitLab instance seems to be broken - I hope to provide all needed information.*
## Description
`+RTS -va` does not show all events that `+RTS -la` would show. I recognized this while working ...*Unfortunately the template support in this GitLab instance seems to be broken - I hope to provide all needed information.*
## Description
`+RTS -va` does not show all events that `+RTS -la` would show. I recognized this while working on Info Table Provenance (IPE) events. These are part of `+RTS -la`, but not of `+RTS -va`.
## Example
Consider this simple Haskell program (any Haskell program would work):
```haskell
main = pure (1 + 1)
```
Build it:
```sh
ghc -debug -finfo-table-map -rtsopts -fdistinct-constructor-tables -v0 EventlogOutput_IPE.hs
```
Run it and show the events from the event file:
```
./EventlogOutput_IPE +RTS -la
ghc-events show EventlogOutput_IPE.eventlog
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 of allocated mblocks) (size 12)
51: Current heap live data (size 12)
52: Heap static parameters (size 38)
53: GC statistics (size 58)
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)
90: Memory return statistics (size 16)
91: Current heap size (size of allocated blocks) (size 12)
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)
165: End of heap profile sample (size 8)
166: Start of heap profile (biographical) sample (size 16)
167: Time profile cost-centre stack (size variable)
168: Start of a time profile (size 8)
169: Info Table Source Position (size variable)
181: User binary message (size variable)
200: Begin concurrent mark phase (size 0)
201: End concurrent mark phase (size 4)
202: Begin concurrent GC synchronisation (size 0)
203: End concurrent GC synchronisation (size 0)
204: Begin concurrent sweep (size 0)
205: End concurrent sweep (size 0)
206: Update remembered set flushed (size 2)
207: Nonmoving heap census (size 13)
210: Ticky-ticky entry counter definition (size variable)
211: Ticky-ticky entry counter sample (size 32)
212: Ticky-ticky entry counter begin sample (size 0)
Events:
39708: created capset 0 of type CapsetOsProcess
39838: created capset 1 of type CapsetClockDomain
40248: created cap 0
40348: assigned cap 0 to capset 0
40448: assigned cap 0 to capset 1
40838: capset 1: wall clock time 1622972801s 32367000ns (unix epoch)
41138: capset 0: pid 10684
41338: capset 0: parent pid 10488
41877: capset 0: RTS version "GHC-9.3.20210530 rts_debug"
42067: capset 0: args: ["./EventlogOutput_IPE","+RTS","-la"]
87355: heap stats for heap capset 0: generations 2, 0 bytes max heap size, 4194304 bytes alloc area size, 1048576 bytes mblock size, 4096 bytes block size
99954: Info Table Source Position
100224: Info Table Source Position
100434: Info Table Source Position
100634: Info Table Source Position
100834: Info Table Source Position
101034: Info Table Source Position
101254: Info Table Source Position
101414: Info Table Source Position
105214: task 0xceca70 created on cap 0 with OS kernel thread 10684
107843: cap 0: creating thread 1
109523: cap 0: running thread 1
122943: cap 0: stopping thread 1 (thread finished)
123872: task 0xceca70 deleted
124442: task 0xceca70 created on cap 0 with OS kernel thread 10684
124632: cap 0: creating thread 2
124872: cap 0: running thread 2
157310: cap 0: stopping thread 2 (thread finished)
157560: task 0xceca70 deleted
159210: cap 0: starting GC
164220: cap 0: GC working
312461: cap 0: GC idle
312541: cap 0: GC done
315311: cap 0: GC idle
315371: cap 0: GC done
315891: cap 0: GC idle
315951: cap 0: GC done
326670: cap 0: Memory return statistics
329120: cap 0: allocated on heap capset 0: 40840 total bytes till now
329520: cap 0: finished GC
329660: cap 0: all caps stopped for GC
329760: cap 0: GC stats for heap capset 0: generation 1, 3144 bytes copied, 21360 bytes slop, 905216 bytes fragmentation, 1 par threads, 0 bytes max par copied, 3144 bytes total par copied, 0 bytes balanced par copied
330080: cap 0: live data in heap capset 0: 35984 bytes
330200: cap 0: size of heap capset 0: 5242880 bytes
330310: cap 0: Current heap size (size of allocated blocks)
333760: cap 0: allocated on heap capset 0: 40840 total bytes till now
338579: removed cap 0 from capset 0
338699: removed cap 0 from capset 1
338809: deleted cap 0
338929: deleted capset 0
339029: deleted capset 1
```
Run it with `+RTS -va`:
```
./EventlogOutput_IPE +RTS -va
created capset 0 of type 2
created capset 1 of type 3
cap 0: initialised
assigned cap 0 to capset 0
assigned cap 0 to capset 1
cap 0: created thread 1[""]
cap 0: running thread 1[""] (ThreadRunGHC)
cap 0: thread 1[""] stopped (finished)
cap 0: created thread 2[""]
cap 0: running thread 2[""] (ThreadRunGHC)
cap 0: thread 2[""] stopped (finished)
cap 0: starting GC
cap 0: GC working
cap 0: GC idle
cap 0: GC done
cap 0: GC idle
cap 0: GC done
cap 0: GC idle
cap 0: GC done
cap 0: Memory Return (Current: 5) (Needed: 8) (Returned: 0)
cap 0: all caps stopped for GC
cap 0: finished GC
removed cap 0 from capset 0
removed cap 0 from capset 1
cap 0: shutting down
deleted capset 0
deleted capset 1
```
## First Analyses
- `+RTS -va` itself does not enable event logging. The condition if event logging should be started is missing a case for `TRACE_STDERR`.
```C
if (RtsFlags.TraceFlags.tracing == TRACE_EVENTLOG
&& rtsConfig.eventlog_writer != NULL) {
startEventLogging(rtsConfig.eventlog_writer);
}
```
https://gitlab.haskell.org/ghc/ghc/-/blob/5e1a224435fc6ebd34d02566f17fe1eaf5475bab/rts/Trace.c#L99
- There is (to my best knowledge) no `EventLogWriter` instance that would write to the console (`stderr`). There's only an implementation for writing to files.
## Possible solutions
- Remove the `+RTS -va` option or adjust it's documentation/description.
- Fix this issue by implementing for event logging to `stderr`. This might be non-trivial, as event log files are written in binary while the console needs (meaningful) text output.https://gitlab.haskell.org/ghc/ghc/-/issues/19724Non-reproducible failure in RestartEventLogging test in `threaded1` way.2021-04-22T01:01:31ZvdukhovniNon-reproducible failure in RestartEventLogging test in `threaded1` way.## Summary
Running `validate` by hand the test typically succeeds, but on one run I got:
```
...
--- tests/rts/RestartEventLogging.run/RestartEventLogging.stdout.normalised 2021-04-20 21:29:06.924934000 -0400
+++ tests/rts/RestartEventL...## Summary
Running `validate` by hand the test typically succeeds, but on one run I got:
```
...
--- tests/rts/RestartEventLogging.run/RestartEventLogging.stdout.normalised 2021-04-20 21:29:06.924934000 -0400
+++ tests/rts/RestartEventLogging.run/RestartEventLogging.run.stdout.normalised 2021-04-20 21:29:06.925062000 -0400
@@ -8,6 +8,11 @@
stop
init
Event log started with EVENT_HEADER_BEGIN
+ERROR: event does not start with EVENT_HEADER_BEGIN
+0x0 != 0x68
+0x12 != 0x64
+0x0 != 0x72
+0x0 != 0x62
stop
init
Event log started with EVENT_HEADER_BEGIN
...
tests/rts/RestartEventLogging.run RestartEventLogging [bad stdout] (threaded1)
```
The expected value is:
```
includes/rts/EventLogFormat.h:#define EVENT_HEADER_BEGIN 0x68647262 /* 'h' 'd' 'r' 'b' */
```
but we got '\0\x12\0\0'.
## Steps to reproduce
Not easily reproducible, could even be a hardware glitch, though that seems unlikely...
## Expected behavior
The test should ideally pass consistently
## Environment
* GHC version used: commit 4cfb6b89479d873f1091dce59f7fbed635d37d6a (HEAD -> freebsd-tlsgd, v/freebsd-tlsgd) of MR !5561. The merge-base with head is: commit 0619fb0fb14a98f04aac5f031f6566419fd27495 (origin/master, origin/HEAD, master)
Optional:
* Operating System: FreeBSD 12.2
* System Architecture: X86_64https://gitlab.haskell.org/ghc/ghc/-/issues/19436Eventlog flushing in non-threaded is broken2021-03-01T16:19:18ZMatthew PickeringEventlog flushing in non-threaded is broken`flushEventLog` in non-threaded way doesn't flush the `capEventBuf[0]` event buffer.`flushEventLog` in non-threaded way doesn't flush the `capEventBuf[0]` event buffer.Matthew PickeringMatthew Pickeringhttps://gitlab.haskell.org/ghc/ghc/-/issues/19435Eventlog flushing with threaded is broken2021-03-01T15:19:39ZMatthew PickeringEventlog flushing with threaded is brokenCalling `flushEventLog` doesn't flush the buffers for each capability.
This is because the flush is in the wrong place. `yieldCapability` is not called on the normal code path for `stopAllCapabilities`, `yieldCapability` is only called ...Calling `flushEventLog` doesn't flush the buffers for each capability.
This is because the flush is in the wrong place. `yieldCapability` is not called on the normal code path for `stopAllCapabilities`, `yieldCapability` is only called when a sync has already been requested for another reason.
The probably correct place to flush is in between the `stop/releaseAllCapabilities` call.https://gitlab.haskell.org/ghc/ghc/-/issues/19382Interupting doesn't seem to flush eventlog buffers2021-06-19T15:18:51ZMatthew PickeringInterupting doesn't seem to flush eventlog buffersWhen heap profiling long-running applications it seems that killing a process with `Ctrl-C` doesn't cause the eventlog buffers to be flushed. The signal handle seems to be designed to flush "profiling output" but the control flow around ...When heap profiling long-running applications it seems that killing a process with `Ctrl-C` doesn't cause the eventlog buffers to be flushed. The signal handle seems to be designed to flush "profiling output" but the control flow around this area made my head spin, so I couldn't see where the flush was supposed to happen.