GHC issueshttps://gitlab.haskell.org/ghc/ghc/-/issues2019-07-07T18:46:23Zhttps://gitlab.haskell.org/ghc/ghc/-/issues/8123GHCi warns about -eventlog even though it's sometimes necessary2019-07-07T18:46:23Ztakano-akioGHCi warns about -eventlog even though it's sometimes necessaryIf I invoke GHCi as `ghci -eventlog`, it says: `Warning: -debug, -threaded and -ticky are ignored by GHCi`. However, the flag does make a difference, in that GHCi will be able to load object files that were compiled using `-eventlog`. Fo...If I invoke GHCi as `ghci -eventlog`, it says: `Warning: -debug, -threaded and -ticky are ignored by GHCi`. However, the flag does make a difference, in that GHCi will be able to load object files that were compiled using `-eventlog`. For this reason, I don't think `-eventlog` should trigger the warning.
Also runghc has the same issue.
<details><summary>Trac metadata</summary>
| Trac field | Value |
| ---------------------- | ------------ |
| Version | 7.6.3 |
| Type | Bug |
| TypeOfFailure | OtherFailure |
| Priority | normal |
| Resolution | Unresolved |
| Component | GHCi |
| Test case | |
| Differential revisions | |
| BlockedBy | |
| Related | |
| Blocking | |
| CC | |
| Operating system | |
| Architecture | |
</details>
<!-- {"blocked_by":[],"summary":"GHCi warns about -eventlog even though it's sometimes necessary","status":"New","operating_system":"","component":"GHCi","related":[],"milestone":"","resolution":"Unresolved","owner":{"tag":"Unowned"},"version":"7.6.3","keywords":[],"differentials":[],"test_case":"","architecture":"","cc":[""],"type":"Bug","description":"If I invoke GHCi as {{{ghci -eventlog}}}, it says: {{{Warning: -debug, -threaded and -ticky are ignored by GHCi}}}. However, the flag does make a difference, in that GHCi will be able to load object files that were compiled using {{{-eventlog}}}. For this reason, I don't think {{{-eventlog}}} should trigger the warning.\r\n\r\nAlso runghc has the same issue.","type_of_failure":"OtherFailure","blocking":[]} -->https://gitlab.haskell.org/ghc/ghc/-/issues/11950Eventlog should include delimiters showing when the process writes to the .ev...2022-04-27T18:00:16ZJamesFisherEventlog should include delimiters showing when the process writes to the .eventlog fileQuoting a comment I just added at https://ghc.haskell.org/trac/ghc/wiki/EventLog\#Limitations :
> Event logging can produce "observer effects". In particular, programs can pause while writing to the `.eventlog` file. These display in Th...Quoting a comment I just added at https://ghc.haskell.org/trac/ghc/wiki/EventLog\#Limitations :
> Event logging can produce "observer effects". In particular, programs can pause while writing to the `.eventlog` file. These display in Threadscope as periods of 100% CPU use with no obvious cause. This effect is exacerbated by heavy use of debug tools which expand the eventlog file, such as `Trace.traceMarkerIO`. (This effect was at least seen on OS X. In an extreme case, a program doing nothing but writing 200,000 trace markers, which took 120 ms to run, showed a single 10ms pause in the middle to write them to the `.eventlog` file. These periods were shown to be due to writing the `.eventlog` file by using `dtruss -a`, which shows long periods of `write_nocancel` syscalls, writing to the `.eventlog` file opened earlier with `open_nocancel`.)
This behavior caused a few hours of investigation for us. It would make it much more obvious what is happening if this behavior were logged in the eventlog. Specifically, I would like for the eventlog to include a "starting writing eventlog file" event at the start of each of these periods, and a "stopped" event at the end of each period.
<details><summary>Trac metadata</summary>
| Trac field | Value |
| ---------------------- | -------------- |
| Version | 7.10.3 |
| Type | FeatureRequest |
| TypeOfFailure | OtherFailure |
| Priority | normal |
| Resolution | Unresolved |
| Component | Runtime System |
| Test case | |
| Differential revisions | |
| BlockedBy | |
| Related | |
| Blocking | |
| CC | simonmar |
| Operating system | |
| Architecture | |
</details>
<!-- {"blocked_by":[],"summary":"Eventlog should include delimiters showing when the process writes to the .eventlog file","status":"New","operating_system":"","component":"Runtime System","related":[],"milestone":"","resolution":"Unresolved","owner":{"tag":"Unowned"},"version":"7.10.3","keywords":[],"differentials":[],"test_case":"","architecture":"","cc":["simonmar"],"type":"FeatureRequest","description":"Quoting a comment I just added at https://ghc.haskell.org/trac/ghc/wiki/EventLog#Limitations :\r\n\r\n> Event logging can produce \"observer effects\". In particular, programs can pause while writing to the `.eventlog` file. These display in Threadscope as periods of 100% CPU use with no obvious cause. This effect is exacerbated by heavy use of debug tools which expand the eventlog file, such as `Trace.traceMarkerIO`. (This effect was at least seen on OS X. In an extreme case, a program doing nothing but writing 200,000 trace markers, which took 120 ms to run, showed a single 10ms pause in the middle to write them to the `.eventlog` file. These periods were shown to be due to writing the `.eventlog` file by using `dtruss -a`, which shows long periods of `write_nocancel` syscalls, writing to the `.eventlog` file opened earlier with `open_nocancel`.)\r\n\r\nThis behavior caused a few hours of investigation for us. It would make it much more obvious what is happening if this behavior were logged in the eventlog. Specifically, I would like for the eventlog to include a \"starting writing eventlog file\" event at the start of each of these periods, and a \"stopped\" event at the end of each period.","type_of_failure":"OtherFailure","blocking":[]} -->https://gitlab.haskell.org/ghc/ghc/-/issues/13529eventlog to report more information about stopping threads because of FFI calls2019-07-07T18:21:28Zvarosieventlog to report more information about stopping threads because of FFI callsCurrently eventlog file doesn't contain more information about FFI than:
"stopping thread \#\#\# (making a foreign call)"
It would be very-very useful if we know what actual foreign calls are made. For example:
"stopping thread \#\#\#...Currently eventlog file doesn't contain more information about FFI than:
"stopping thread \#\#\# (making a foreign call)"
It would be very-very useful if we know what actual foreign calls are made. For example:
"stopping thread \#\#\# (making a foreign call to function YYYY)
So we could see which function and how much time is spent on that call.
If creation of threads because of in-bound foreign calls (callbacks) have which callbacks are created for it will be very useful, too.
<details><summary>Trac metadata</summary>
| Trac field | Value |
| ---------------------- | ---------------- |
| Version | 8.0.2 |
| Type | FeatureRequest |
| TypeOfFailure | OtherFailure |
| Priority | normal |
| Resolution | Unresolved |
| Component | Profiling |
| Test case | |
| Differential revisions | |
| BlockedBy | |
| Related | |
| Blocking | |
| CC | |
| Operating system | Unknown/Multiple |
| Architecture | |
</details>
<!-- {"blocked_by":[],"summary":"eventlog to report more information about stopping threads because of FFI calls","status":"New","operating_system":"Unknown/Multiple","component":"Profiling","related":[],"milestone":"","resolution":"Unresolved","owner":{"tag":"Unowned"},"version":"8.0.2","keywords":[],"differentials":[],"test_case":"","architecture":"","cc":[""],"type":"FeatureRequest","description":"Currently eventlog file doesn't contain more information about FFI than:\r\n\r\n\"stopping thread ### (making a foreign call)\"\r\n\r\nIt would be very-very useful if we know what actual foreign calls are made. For example:\r\n\r\n\"stopping thread ### (making a foreign call to function YYYY)\r\n\r\nSo we could see which function and how much time is spent on that call.\r\nIf creation of threads because of in-bound foreign calls (callbacks) have which callbacks are created for it will be very useful, too.","type_of_failure":"OtherFailure","blocking":[]} -->https://gitlab.haskell.org/ghc/ghc/-/issues/15587traceEvent tests failing in slow validate2019-07-07T18:04:01ZÖmer Sinan AğacantraceEvent tests failing in slow validatetraceEvent tests are failing in slow validate when testing in GHCi way:
```
=====> traceEvent(ghci) 1 of 2 [0, 0, 0]
cd "rts/traceEvent.run" && "/home/omer/haskell/ghc/inplace/test spaces/ghc-stage2" traceEvent.hs -dcore-lint -dcmm-li...traceEvent tests are failing in slow validate when testing in GHCi way:
```
=====> traceEvent(ghci) 1 of 2 [0, 0, 0]
cd "rts/traceEvent.run" && "/home/omer/haskell/ghc/inplace/test spaces/ghc-stage2" traceEvent.hs -dcore-lint -dcmm-lint -no-user-package-db -rtsopts -fno-warn-missed-specialisations -fshow-warning-groups -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output --interactive -v0 -ignore-dot-ghci -fno-ghci-history +RTS -I0.1 -RTS -eventlog< traceEvent.genscript
Actual stderr output differs from expected:
diff -uw "rts/traceEvent.run/traceEvent.stderr.normalised" "rts/traceEvent.run/traceEvent.run.stderr.normalised"
--- rts/traceEvent.run/traceEvent.stderr.normalised 2018-08-31 12:48:13.548375420 +0300
+++ rts/traceEvent.run/traceEvent.run.stderr.normalised 2018-08-31 12:48:13.548375420 +0300
@@ -1 +0,0 @@
-traceEvent: Event size exceeds EVENT_PAYLOAD_SIZE_MAX, bail out
*** unexpected failure for traceEvent(ghci)
=====> traceBinaryEvent(ghci) 2 of 2 [0, 1, 0]
cd "rts/traceBinaryEvent.run" && "/home/omer/haskell/ghc/inplace/test spaces/ghc-stage2" traceBinaryEvent.hs -dcore-lint -dcmm-lint -no-user-package-db -rtsopts -fno-warn-missed-specialisations -fshow-warning-groups -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output --interactive -v0 -ignore-dot-ghci -fno-ghci-history +RTS -I0.1 -RTS -eventlog< traceBinaryEvent.genscript
Actual stderr output differs from expected:
diff -uw "rts/traceBinaryEvent.run/traceBinaryEvent.stderr.normalised" "rts/traceBinaryEvent.run/traceBinaryEvent.run.stderr.normalised"
--- rts/traceBinaryEvent.run/traceBinaryEvent.stderr.normalised 2018-08-31 12:48:13.712373185 +0300
+++ rts/traceBinaryEvent.run/traceBinaryEvent.run.stderr.normalised 2018-08-31 12:48:13.712373185 +0300
@@ -1 +0,0 @@
-traceBinaryEvent: Event size exceeds EVENT_PAYLOAD_SIZE_MAX, bail out
*** unexpected failure for traceBinaryEvent(ghci)
Unexpected results from:
TEST="traceBinaryEvent traceEvent"
```
I think GHCi doesn't generate eventlogs so there's no way to make these pass. I submitted [D5119](https://phabricator.haskell.org/D5119) to skip these tests in GHCi way.
<details><summary>Trac metadata</summary>
| Trac field | Value |
| ---------------------- | ------------ |
| Version | 8.5 |
| Type | Bug |
| TypeOfFailure | OtherFailure |
| Priority | normal |
| Resolution | Unresolved |
| Component | Test Suite |
| Test case | |
| Differential revisions | |
| BlockedBy | |
| Related | |
| Blocking | |
| CC | |
| Operating system | |
| Architecture | |
</details>
<!-- {"blocked_by":[],"summary":"traceEvent tests failing in slow validate","status":"New","operating_system":"","component":"Test Suite","related":[],"milestone":"8.6.1","resolution":"Unresolved","owner":{"tag":"Unowned"},"version":"8.5","keywords":[],"differentials":[],"test_case":"","architecture":"","cc":[""],"type":"Bug","description":"traceEvent tests are failing in slow validate when testing in GHCi way:\r\n\r\n{{{\r\n=====> traceEvent(ghci) 1 of 2 [0, 0, 0]\r\ncd \"rts/traceEvent.run\" && \"/home/omer/haskell/ghc/inplace/test spaces/ghc-stage2\" traceEvent.hs -dcore-lint -dcmm-lint -no-user-package-db -rtsopts -fno-warn-missed-specialisations -fshow-warning-groups -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output --interactive -v0 -ignore-dot-ghci -fno-ghci-history +RTS -I0.1 -RTS -eventlog< traceEvent.genscript\r\nActual stderr output differs from expected:\r\ndiff -uw \"rts/traceEvent.run/traceEvent.stderr.normalised\" \"rts/traceEvent.run/traceEvent.run.stderr.normalised\"\r\n--- rts/traceEvent.run/traceEvent.stderr.normalised 2018-08-31 12:48:13.548375420 +0300\r\n+++ rts/traceEvent.run/traceEvent.run.stderr.normalised 2018-08-31 12:48:13.548375420 +0300\r\n@@ -1 +0,0 @@\r\n-traceEvent: Event size exceeds EVENT_PAYLOAD_SIZE_MAX, bail out\r\n*** unexpected failure for traceEvent(ghci)\r\n=====> traceBinaryEvent(ghci) 2 of 2 [0, 1, 0]\r\ncd \"rts/traceBinaryEvent.run\" && \"/home/omer/haskell/ghc/inplace/test spaces/ghc-stage2\" traceBinaryEvent.hs -dcore-lint -dcmm-lint -no-user-package-db -rtsopts -fno-warn-missed-specialisations -fshow-warning-groups -fdiagnostics-color=never -fno-diagnostics-show-caret -dno-debug-output --interactive -v0 -ignore-dot-ghci -fno-ghci-history +RTS -I0.1 -RTS -eventlog< traceBinaryEvent.genscript\r\nActual stderr output differs from expected:\r\ndiff -uw \"rts/traceBinaryEvent.run/traceBinaryEvent.stderr.normalised\" \"rts/traceBinaryEvent.run/traceBinaryEvent.run.stderr.normalised\"\r\n--- rts/traceBinaryEvent.run/traceBinaryEvent.stderr.normalised 2018-08-31 12:48:13.712373185 +0300\r\n+++ rts/traceBinaryEvent.run/traceBinaryEvent.run.stderr.normalised 2018-08-31 12:48:13.712373185 +0300\r\n@@ -1 +0,0 @@\r\n-traceBinaryEvent: Event size exceeds EVENT_PAYLOAD_SIZE_MAX, bail out\r\n*** unexpected failure for traceBinaryEvent(ghci)\r\n\r\nUnexpected results from:\r\nTEST=\"traceBinaryEvent traceEvent\"\r\n}}}\r\n\r\nI think GHCi doesn't generate eventlogs so there's no way to make these pass. I submitted Phab:D5119 to skip these tests in GHCi way.","type_of_failure":"OtherFailure","blocking":[]} -->8.6.1Ömer Sinan AğacanÖmer Sinan Ağacanhttps://gitlab.haskell.org/ghc/ghc/-/issues/17948`-p` and eventlog produces an invalid eventlog2021-03-19T17:33:32ZMatthew Pickering`-p` and eventlog produces an invalid eventlogI am trying to use the cost centre profiling support in the eventlog with 8.10 but it seems that when there are multiple threads that specifying `-p -l` can produce a corrupted eventlog.
When you try to decode it using `ghc-events` you...I am trying to use the cost centre profiling support in the eventlog with 8.10 but it seems that when there are multiple threads that specifying `-p -l` can produce a corrupted eventlog.
When you try to decode it using `ghc-events` you get failures such as `ghc-events: Ix{Int}.index: Index (768) out of range ((0,207))`.
At the moment I don't have any further information about why this happens or how to reproduce it with a small case.https://gitlab.haskell.org/ghc/ghc/-/issues/17949Debug.Trace.traceEvent et al. is too expensive if disabled2021-08-03T12:27:12ZBen GamariDebug.Trace.traceEvent et al. is too expensive if disabled@mpickering recently pointed out the existence of the [ghc-trace-events](https://hackage.haskell.org/package/ghc-trace-events) library, which offers an cheaper alternative to the eventlog utilities in `Debug.Trace`. The problem with the ...@mpickering recently pointed out the existence of the [ghc-trace-events](https://hackage.haskell.org/package/ghc-trace-events) library, which offers an cheaper alternative to the eventlog utilities in `Debug.Trace`. The problem with the latter is that they do appreciable work even if eventlogging is disabled. These should really be no-ops in this case.https://gitlab.haskell.org/ghc/ghc/-/issues/17972labelThread should work with just eventlog enabled RTS2020-12-21T01:45:58ZMatthew PickeringlabelThread should work with just eventlog enabled RTSIt is unclear to myself and the one and only @bgamari why `labelThead` needs to also use the `-debug` RTS. It would useful to use with the normal eventlog to label threads. In my mind it is similar to something like `traceEvent` and `tra...It is unclear to myself and the one and only @bgamari why `labelThead` needs to also use the `-debug` RTS. It would useful to use with the normal eventlog to label threads. In my mind it is similar to something like `traceEvent` and `traceMarker` which do not require the debug RTS to work.
Someone should investigate why this is, sounds like a good task for a newcomer.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/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/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/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/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/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/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/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/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.