Encountered two out-of-order inputs despite eventlog-flush-interval

[jasagredo]

I find this extremely useful, but I am having trouble setting it up. I start my application as:

./my-app +RTS -l -hi --eventlog-flush-interval=1

and the app is compiled with

❯ cat cabal.project.local
package *
  ghc-options: -finfo-table-map -fdistinct-constructor-tables

When starting eventlog-live-otelcol I get a period of silence and then the following errors:

❯ eventlog-live-otelcol \
  --eventlog-socket "$GHC_EVENTLOG_SOCKET" \
  -hi \
  --otelcol-host=localhost --service-name my-app --eventlog-flush-interval=1
[ERROR]Encountered two out-of-order inputs.
Did you pass --eventlog-flush-interval=SECONDS to the GHC RTS?
Did you pass the same flag to this program?
CallStack (from HasCallStack):
  writeLog, called at src/GHC/Eventlog/Live/Machine/Core.hs:776:22 in eventlog-live-0.5.0.0-39d483d17f5f7c69c5242af2bb3904f5f8b11594eb2dcc29581d51825d585ed1:GHC.Eventlog.Live.Machine.Core
[ERROR]Rejected 22232 metrics.
CallStack (from HasCallStack):
  writeLog, called at src/GHC/Eventlog/Live/Otelcol/Stats.hs:314:7 in eventlog-live-otelcol-0.6.0.0-82668d26395a507f970d76220f8ef1848e78d33b6569c636abce3fe6da011ac6:GHC.Eventlog.Live.Otelcol.Stats
[ERROR]ConnectionErrorIsSent EnhanceYourCalm 0 "too many ping"
CallStack (from HasCallStack):
  writeLog, called at src/GHC/Eventlog/Live/Otelcol/Stats.hs:318:7 in eventlog-live-otelcol-0.6.0.0-82668d26395a507f970d76220f8ef1848e78d33b6569c636abce3fe6da011ac6:GHC.Eventlog.Live.Otelcol.Stats
[ERROR]Rejected 7 logs.
CallStack (from HasCallStack):
  writeLog, called at src/GHC/Eventlog/Live/Otelcol/Stats.hs:300:7 in eventlog-live-otelcol-0.6.0.0-82668d26395a507f970d76220f8ef1848e78d33b6569c636abce3fe6da011ac6:GHC.Eventlog.Live.Otelcol.Stats

I installed eventlog-live-otelcol from the main branch of this repository instead of from Hackage, but the hackage version fails in a similar way:

❯ eventlog-live-otelcol \
  --eventlog-socket "$GHC_EVENTLOG_SOCKET" \
  -hi \
  --otelcol-host=localhost
Error (src/GHC/Eventlog/Live/Machine/Core.hs:497:15): Encountered two out-of-order inputs.
Did you pass --eventlog-flush-interval to the GHC RTS?
Did you set --batch-interval to be at least as big as the value of --eventlog-flush-interval?
❯ eventlog-live-otelcol \
  --eventlog-socket "$GHC_EVENTLOG_SOCKET" \
  -hi \
  --otelcol-host=localhost --batch-interval=2
eventlog-live-otelcol: ConnectionErrorIsSent EnhanceYourCalm 0 "too many ping"
❯ eventlog-live-otelcol \
  --eventlog-socket "$GHC_EVENTLOG_SOCKET" \
  -hi \
  --otelcol-host=localhost --batch-interval=1
eventlog-live-otelcol: ConnectionErrorIsSent EnhanceYourCalm 0 "too many ping"
❯ eventlog-live-otelcol \
  --eventlog-socket "$GHC_EVENTLOG_SOCKET" \
  -hi \
  --otelcol-host=localhost
Error (src/GHC/Eventlog/Live/Machine/Core.hs:497:15): Encountered two out-of-order inputs.
Did you pass --eventlog-flush-interval to the GHC RTS?
Did you set --batch-interval to be at least as big as the value of --eventlog-flush-interval?
eventlog-live-otelcol: GrpcException {grpcError = GrpcResourceExhausted, grpcErrorMessage = Just "grpc: received message larger than max (24771694 vs. 20971520)", grpcErrorDetails = Nothing, grpcErrorMetadata = []}

This is GHC 9.6.7, both for eventlog-live-otelcol and for my-app. I was able to have it run for some time (this one in particular was GHC 9.12.2 for my-app and 9.6.7 for eventlog-live-otelcol), but it crashed with these errors

The time it worked, there were these many warnings in the logs, then it crashed:

[wenkokke]

What version are you using? It's likely that you must pass the same --eventlog-flush-interval flag to eventlog-live-otelcol and that the warning about the --batch-interval is outdated.

[jasagredo]

I have used both the hackage version (which asks for the --batch-interval flag) and the one from the master branch here (which asks for the --eventlog-flush-interval flag).

I guess we should only consider the version from master from this repo. It fails with:

[ERROR]Encountered two out-of-order inputs.

The thing is that I did pass the --eventlog-flush-interval flag to the RTS of my app, and also to eventlog-live-otelcol as a normal flag:

❯ export GHC_EVENTLOG_SOCKET="/tmp/my_eventlog.sock"
❯ ./my-app +RTS -l -hi --eventlog-flush-interval=1 

-- in a separate terminal
❯ export GHC_EVENTLOG_SOCKET="/tmp/my_eventlog.sock"
❯ eventlog-live-otelcol \
  --eventlog-socket "$GHC_EVENTLOG_SOCKET" \
  -hi \
  --otelcol-host=localhost --service-name my-app --eventlog-flush-interval=1

[wenkokke]

Ah, I see, I didn't spot it at the end of the long line there. I've seen this a couple of times before, but I haven't been able to reproduce this locally.

Effectively, any time this error occurs, there'll have been be a slight degradation in the reliability of your threading analysis, i.e., the productivity, capability usage, and thread state diagrams. Realistically, unless you're seeing this error hundreds of times per second, that data's reliability isn't seriously compromised. The remainder of the data, e.g., heap analysis, isn't impacted at all.

If you manage to reproduce this with a small executable that you can share, then please do, so that I can work to debug this.

[jasagredo]

Ah so it should not make everything fall apart, but still, the other errors indicate something wrong is going on, no?

[ERROR]Rejected 22232 metrics.
CallStack (from HasCallStack):
  writeLog, called at src/GHC/Eventlog/Live/Otelcol/Stats.hs:314:7 in eventlog-live-otelcol-0.6.0.0-82668d26395a507f970d76220f8ef1848e78d33b6569c636abce3fe6da011ac6:GHC.Eventlog.Live.Otelcol.Stats
[ERROR]ConnectionErrorIsSent EnhanceYourCalm 0 "too many ping"
CallStack (from HasCallStack):
  writeLog, called at src/GHC/Eventlog/Live/Otelcol/Stats.hs:318:7 in eventlog-live-otelcol-0.6.0.0-82668d26395a507f970d76220f8ef1848e78d33b6569c636abce3fe6da011ac6:GHC.Eventlog.Live.Otelcol.Stats
[ERROR]Rejected 7 logs.
CallStack (from HasCallStack):
  writeLog, called at src/GHC/Eventlog/Live/Otelcol/Stats.hs:300:7 in eventlog-live-otelcol-0.6.0.0-82668d26395a507f970d76220f8ef1848e78d33b6569c636abce3fe6da011ac6:GHC.Eventlog.Live.Otelcol.Stats

[wenkokke]

Ah so it should not make everything fall apart, but still, the other errors indicate something wrong is going on, no?

[ERROR]Rejected 22232 metrics.
CallStack (from HasCallStack):
  writeLog, called at src/GHC/Eventlog/Live/Otelcol/Stats.hs:314:7 in eventlog-live-otelcol-0.6.0.0-82668d26395a507f970d76220f8ef1848e78d33b6569c636abce3fe6da011ac6:GHC.Eventlog.Live.Otelcol.Stats
[ERROR]ConnectionErrorIsSent EnhanceYourCalm 0 "too many ping"
CallStack (from HasCallStack):
  writeLog, called at src/GHC/Eventlog/Live/Otelcol/Stats.hs:318:7 in eventlog-live-otelcol-0.6.0.0-82668d26395a507f970d76220f8ef1848e78d33b6569c636abce3fe6da011ac6:GHC.Eventlog.Live.Otelcol.Stats
[ERROR]Rejected 7 logs.
CallStack (from HasCallStack):
  writeLog, called at src/GHC/Eventlog/Live/Otelcol/Stats.hs:300:7 in eventlog-live-otelcol-0.6.0.0-82668d26395a507f970d76220f8ef1848e78d33b6569c636abce3fe6da011ac6:GHC.Eventlog.Live.Otelcol.Stats

That's an unrelated error. You're sending too much data to the server. You can mitigate this by changing the aggregation and export parameters in the configuration file (e.g., aggregate over longer periods of time, don't export too frequently or infrequently, disable traces) or by increasing those limits in the server configuration (my example configuration increases the message size limit, but there should be a similar option for message frequency, though I'm afraid you'd have to go looking for it).