Enable EventPipe streaming#915
Conversation
1) The IO underlaying Deserializer assumes that the stream has bounded length and is seekable (like a file) but neither of these is true for a network stream. I made a few modifications that avoid those assumptions, but the result feels fragile - it depends on the input stream not having references that require seeking to occur. This appears true for the netperf file format but not true for arbitrary graphs serialized with FastSerialization. 2) EventPipeEventSource needed a new constructor that accepted a Stream rather than a file 3) Dynamic parsing for EventPipe events appeared to be broken, but its possible in my relative new-ness to TraceEvent work I just don't understand how all the pieces are supposed to fit together. a) From what I can tell EventPipeEventSource had an atypical member _eventParser and it had a private contract to send it all the metadata packets for parsing. However a parser won't register new templates with the source if nobody has subscribed to those event types and it appears impossible to subscribe to the private parser. At the same time DynamicTraceEventParser had a 2nd EventPipeParser but that one would never be asked to resolve an unhandled template because ExternalTraceEventParser from which it derives prevents more than one parser of the same type from registering. From my read Parsers that want to get metadata from the stream have to extract it from the sequence of TraceEvent objects that are produced by the source, however EventPipe metadata packets aren't surfaced as TraceEvent objects. Although its plausible that they could be abstracted that way, it would be a breaking change to produce a different set of events than we did in the past and direct analysis of the metadata packets probably isn't that interesting. This meant EventPipeParser needed an alternate way of accessing metadata so I added a side-band communication where EventPipeParser knows how to access templates that have been pre-populated on EventPipeSource. Most of the new code EventPipeSource is a direct move from EventPipeParser. Specifically code in ReadEventParametersAndBuildTemplate, ParseFields, and GetOpcodeFromEventName is unchanged. b) The dynamic parser wasn't transitively applying its subscriptions to the child EventPipeParser, but that was easily solved by following the same pattern as the registeredParser that was already there.
| inputStream.Seek(positionInStream + endPosition, SeekOrigin.Begin); | ||
| if(inputStream.CanSeek) | ||
| { | ||
| // for non-seekable streams we always keep the stream positioned at this point |
There was a problem hiding this comment.
Is this comment correct? It talks about non-seekable streams but is in an if block that only applies to seekable streams.
There was a problem hiding this comment.
the comment was intended to justify why we only do the Seek() in the seekable case but let me update it for better clarity : )
| for(int i = 0; i < bytesToRead; i++) | ||
| { | ||
| // a non-seekable stream should always be positioned at positionInStream + endPosition | ||
| inputStream.ReadByte(); |
There was a problem hiding this comment.
This is the one thing in this file that feels odd to me. From a quick read of this stream code, it looks like it should go through Fill when reading the input stream. By doing the read here, I wonder if anything with respect to the input stream gets out of sync with the fields here. I can't point to anything directly, and your code seems to pass the tests, so it hasn't broken seekable streams. I would say that if this does break something, we can always fix it, but this is the thing that feels odd.
There was a problem hiding this comment.
My understanding is that seekable stream was allowed to be lazy, but I am preventing the non-seekable stream from being lazy. "Lazy" specifically referring to entering a state where positionInStream+endPosition != inputStream.Position and then later in Fill we do a Seek() to bring inputStream.Position back into agreement.
Thinking on it I could probably make the non-seekable case match a little more closely by deferring the Read() until Fill(). I am planning to do a unit test and I'll try a change for this at the same time.
|
@noahfalk, overall this change feels reasonable. Especially the move of code from EventPipeTraceEventParser to EventPipeEventSource. I agree that we should not expose the metadata events outside of TraceEvent. These aren't real events and they're just there to represent the description of the real events. In terms of handling dynamic events, my guess is that the call from EventPipeEventSource::ReadEvent to OnNewEventPipeEventDefinition was just using the private _eventParser to build up the set of dynamic parsers. I'm not sure where they're getting used and would need to be debug it to be sure. Either way, what you've done here looks reasonable to me and I believe we have sufficient coverage of EventPipe files in the test bed that nothing went terribly wrong. I would love to see a stream test case if possible, but I understand that might be something more difficult to harness. |
1) Updated the code in StreamReaderWriter so that the seek and non-seek case are a little more symmetrical.
2) Added the new streaming EventPipe unit tests which promptly started hitting new issues that needed fixing below...
3) Updated the naming format of the ProcessName field on EventPipeEventSource so that it matches the convention used in TraceLog
4) Avoided an assert that was firing on TraceEvent objects that initialized taskName to "" instead of null. This case occurs when
the parser encounters native runtime events which do not provide an event name in the EventPipe metadata.
5) Fixed an assert that was triggering when trying to listed to the "All" event on ClrTraceEventParser. This parser has multiple
templates that match every field except the name which violates asserts in the Dispatcher subscribe code that expect each new
template to be unique relative all previously added ones.
|
I've added a streaming unit test by reusing the existing file backed trace files + throwing a wrapper over it to enforce a read-only/read-once access pattern + verified that buffering didn't occur at larger than eventblock granularity. In our real streaming cases the eventblocks are flushed and truncated to whatever size necessary to ensure that slow event pipelines don't buffer for long (currently 100ms). The unit test also flushed out some issues and let me know if the fixes for them are acceptable. All the tests pass, but some of those changes did modify the behavior of existing APIs. Thanks Brian! |
When streaming the EventPipe data any attempt to buffer beyond the minimum required data to read the next EventBlock can cause event processing to stall. There is no guarantee about when or if more bytes will ever be written to the stream. FastSerialization was doing this with an automatic 16KB look-ahead that caused several iterations of EventCounter data to accumulate in the buffer before any of it was made available in the event callbacks. I modified StreamReaderWriter so that it does not buffer beyond the caller's minimum requested data (modulo 8byte alignment) when dealing with non-seekable streams.
|
Added one (hopefully final) change to eliminate some buffering that was causing events to batch up with unnecessary latency. If this looks good I'd love to merge it or handle any remaining feedback you've got. Thanks Brian! |
|
@noahfalk We should probably update the file format documentation in the near future. |
| } | ||
| else | ||
| { | ||
| uint seekForwardDistance = (uint)((positionInStream + endPosition) - inputStreamBytesRead); |
There was a problem hiding this comment.
| uint seekForwardDistance = (uint)((positionInStream + endPosition) - inputStreamBytesRead); | |
| // For non-seekable streams we can only move forward. A check in the Goto routine | |
| // insures that we don't try to move backwards. Here is where we use it. | |
| Debug.Assert( (uint)(positionInStream + endPosition)) >= inputStreamBytesRead); | |
| uint seekForwardDistance = (uint)((positionInStream + endPosition) - inputStreamBytesRead); |
There was a problem hiding this comment.
Another worry with streaming is that you can definitely imagine it exceeding the 4GB stream size. We should change things so that variables like inputStreamBytesRead and positionInStream are longs and to avoid issues with overflow.
There was a problem hiding this comment.
Hmm, it is worse than that. The upper level event-pipe logic uses StreamLabels (which are 32 bit), and thus would have issues if the stream gets larger than 4GB. Fixing it at the StreamReader level is not sufficient.
I was tempted when I first saw the logic to simply disallow Goto at all (thus very little change is needed), but saw that we DO use Goto (but we don't need to). We do have a extension method called Skip() that can avoid these problems. Thus my recommendation is
- Change EventPipeEventSource so that it uses Skip instead of GoTo.
- Promote Skip to be a instance method on a StreamReader.
- Make Goto uniformly fail (throw exception) on non-seekable streams.
- Make Skip work properly regardless of stream size (basically make some of these variables long instead of uint).
There was a problem hiding this comment.
Hmm, it is worse than that...
Yeah, I believe there are a variety of problems that need to be resolved before this can scale up. I wasn't planning to tackle those issues just yet as I only needed something good enough to preview dotnet-counters which has small data sizes. In addition to the issues you spotted I noticed we've also got caching.
saw that we DO use Goto (but we don't need to)
Goto() isn't always forward, it appears to depend on the data we are reading and the mode the deserializer is operating in. For example:
- Peeking
- Recovering after invalid data
- Returning after reading a forward reference
- Reading a back-reference
The PR avoids the first two issues by allowing backwards movement within the range of the Fill buffer. It relies on the netperf format not to use forward or backward references to handle the other cases.
- Make Goto uniformly fail (throw exception) on non-seekable streams.
I'm not sure what value this would get us? It will require lots of places that are calling Goto to be refactored and the places that are legitimately back-tracking inside the fill buffer for peeking and error recovery will now need algorithmic changes or a 2nd level of buffering.
The other ones seem like fine improvements, though I propose doing them in a future PR for expedience in the current work.
|
I just saw this pull request yesterday. The making StreamReader work for non-seekable streams is reasonable (but see comments on working when stream exceeds 4GB). Yes, things that want to work on non-seekable streams need to be careful not to use capabilities that need seeking (that is Goto). By promoting 'Skip' to be a real part of the interface, things are at least reasonably clear (you can always use skip, you can never use Goto for non-seekable things). I need to wrap my head around the issue you brought up with meta-data. I am looking at that now... |
|
One concern I have is that one of the responsibilities of a TraceEventParser is to PERSIST any meta-data it needs into the ETLX format (that is what is ultimately used by PerfView). For dynamic parsers (like this one), it amounts to persisting the templates. I think that gets lost in the current change (in theory this would mean that PerfView would not be able to parse most events which I would have expected to cause most event to not parse in PerfView (which should be 'obvious'). This however would not be the first time the code surprised me, so I need to investigate... |
|
OK I have thought about it a bit and here are some observations/information
I don't want to act as a blocking factor here, but I am trying to insure that we don't do things differently in different places. Parsers are supposed to hold all the information they need in themselves (can persist it if asked). Also Parsers are what have the apis that actually do subscribing, and in general remember event-specific meta-data, and sources really don't do these things (Source do keep a dispatch table, logically that is different). To the degree we can keep the design consistent, that would keep things simpler and more understandable. If I am being to vague, I can morph this checkin into something aligned with the principles above. It may not fix everything however (I don't know what tests/issues you ran into that pushed you to this fix). Let me know if you wish for me to do this. Finally I could also be mistaken with some of my statements above (I think they are right, but I have not actually experimentally verified them). Let me know if you think I am just wrong about something (I would like to have the repro to debug through to understand why it differs from my understanding). |
@jorive - The changes here are only to facilitate parsing the format as it already exists, no format changes were made. I'm not sure what update you had in mind?
@vancem Welcome back ; ) One piece of context here is that the demo for dotnet-counters we currently plan to sim-ship with Preview5 is dependent on this work so there is time pressure to either get something working checked in (which this PR appears to do as-is), or ship using a private fork of TraceEvent. My preference is to check this in so that we save ourselves the engineering hassle of developing using a private fork. However if there is a significant downside to checking this in and making further improvements later we should get that clarified right away.
I believe the current PR has preserved that behavior but let me know if this analysis appears incorrect: Serialization requires the TraceEventParser.StateObject to persist a set of templates using the FastSerialization ToStream() API. In the case of EventPipeTraceEventParser it derives from ExternalTraceEventParser, which has a ExternalTraceEventParserState typed StateObject. Serializing that StateObject requires that ExternalTraceEventParserState.m_templates has been populated. The templates are populated in the unhandled event callback whenever a derived Parser's TryLookup method resolves a template. The EventPipeTraceEventParser in the PR conforms to that convention by returning all the metadata templates it is discovering through TryLookup.
The implementation you are suggesting also resolves the issue. The problem in the original code is that there are two EventPipeParsers, one created by the DynamicParser and a second created by the EventPipeEventSource. However for all parsers derived from ExternalTraceEventParser the first parser of a given type attached to the source has special status, it is the only one that gets to register its unhandled event callback. Thus if a user subscribes to events A, B, C on the first parser and C, D, E on the 2nd parser, only templates for A, B, C will ever be registered on the dispatcher. Both of us solved the issue by ensuring the scenario created one parser, you put it on the source, the current PR put it on the Dynamic parser. I'd be fine switching to a model where the Parser is cached on the source rather than in the DynamicParser, though I propose not doing it in this PR for expediency. Are there any concerns submitting this as-is for Preview5, then using a follow-up PR to shift the implementation?
This PR added new unit tests. Although they weren't my exact initial test case I'd expect them to fail similarly if you reverted TraceEvent portion of the changes. Thanks @vancem ! |
|
If there is a time crunch, I am OK with checking in what you have. It actually makes it easier for me to make a counter-proposal, since we are all working from the same thing. I have not actually tried to experiment with the updated code. If basic PerfView scenarios on *.netperf files work, I can't argue that it is broken (although I need to look into why it worked!). So you can go ahead and merge this if you need to. |
|
@noahfalk, thanks for the updates and added tests. I do agree with a bunch of @vancem's feedback, especially around promoting Skip vs. using Goto, etc. Skip should be sufficient for EventPipe. I also like the idea of moving the parsing logic back to EventPipeTraceEventParser. I understand the time crunch as well, so I'm completely fine with continuing this post-demo. Can you double check that things work with *.netperf files? We do have some as part of the test bed, but validating that things look right in PerfView would be awesome. As long as things in PerfView look OK, consider me signed off. |
|
I did some basic sniff testing of the PerfView UI using the same example netperf files that the unit tests use. The events view and the thread time view both seemed reasonable to me and I looked at both EventSource and runtime generated events. It was by no means exhaustive, but nothing jumped out. If you could merge this (I don't have write privilege in this repo) that would be fantastic. Thanks! |
4 participants
The IO underlaying Deserializer assumes that the stream has bounded length and is seekable (like a file) but neither of these is true for a network stream. I made a few modifications that avoid those assumptions, but the result feels fragile - it depends on the input stream not having references that require seeking to occur. This appears true for the netperf file format but not true for arbitrary graphs serialized with FastSerialization.
EventPipeEventSource needed a new constructor that accepted a Stream rather than a file
Dynamic parsing for EventPipe events appeared to be broken, but its possible in my relative new-ness to TraceEvent work I just don't understand how all the pieces are supposed to fit together.
a) From what I can tell EventPipeEventSource had an atypical member _eventParser and it had a private contract to send it all the metadata packets for parsing. However a parser won't register new templates with the source if nobody has subscribed to those event types and it appears impossible to subscribe to the private parser. At the same time DynamicTraceEventParser had a 2nd EventPipeParser but that one would never be asked to resolve an unhandled template because ExternalTraceEventParser from which it derives prevents more than one parser of the same type from registering.
From my read Parsers that want to get metadata from the stream have to extract it from the sequence of TraceEvent objects that are produced by the source, however EventPipe metadata packets aren't surfaced as TraceEvent objects. Although its plausible that they could be abstracted that way, it would be a breaking change to produce a different set of events than we did in the past and direct analysis of the metadata packets probably isn't that interesting. This meant EventPipeParser needed an alternate way of accessing metadata so I added a side-band communication where EventPipeParser knows how to access templates that have been pre-populated on EventPipeSource.
Most of the new code EventPipeSource is a direct move from EventPipeParser. Specifically code in ReadEventParametersAndBuildTemplate, ParseFields, and GetOpcodeFromEventName is unchanged.
b) The dynamic parser wasn't transitively applying its subscriptions to the child EventPipeParser, but that was easily solved by following the same pattern as the registeredParser that was already there.
Thanks for taking a look!