Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

&try / backtrack() usage too expensive due to unconditional stack unwinding #1565

Closed
awelzel opened this issue Oct 4, 2023 · 3 comments · Fixed by #1578
Closed

&try / backtrack() usage too expensive due to unconditional stack unwinding #1565

awelzel opened this issue Oct 4, 2023 · 3 comments · Fixed by #1578
Assignees

Comments

@awelzel
Copy link
Contributor

awelzel commented Oct 4, 2023

The initial implementation of the QUIC parser uses two &try / backtrack() constructs for parsing the initial byte and a second one for capturing all the data. During tests, the output of perf report --no-children indicates 8.5% of the samples fall into _Unwind_GetTextRelBase which seems surprising: The pcap in question produces a single analyzer.log entry only.

Concretely, processing a a 274MB pure QUIC traffic pcap with latest Zeek master (v6.1.0-dev-487-ge22bf8ebb6, RelWithDebInfo, frame pointers enabled) and latest spicy-quic parser takes ~30seconds.

Replacing the two &try / backtrack() constructs with &parse-at=self.input() and resetting the input reduces the processing time to ~24seconds. That's 20% faster for that specific pcap (and not using try/backtrack() looks actually better).

Light grepping through Spicy makes me believe that for every &try and backtrack() execution a new Backtrace object is instantiated, which unconditionally calls backtrace() and then _Unwind_GetTextRelBase. For the try / backtrack() mechanism that is unproductive work. Flamegraphs before/after below. They look quite bit different, so wonder if the backtrack() also triggers something with the fiber execution.

Anyway, try/backtrack() should probably not come with such a huge overhead or otherwise cause a warning with discouragement and alternatives to use instead.


Flamegraphs

try-backtrack (before)

try-backtrack

parse-at (after)

parse-at

@rsmmr
Copy link
Member

rsmmr commented Oct 5, 2023

I think it's the exception being thrown by backtrack() that internally captures the stack at construction time. Looks like that unwinding is pretty expensive. Is this Linux? We could skip that, but we'd loose the ability to show where the backtrack happened in case the exception remains uncaught.

That said, I also wouldn't want encourage such use of try/backtrack(); it's meant as an last-resort mechanism if there's nothing better available, usually to step back across some layers of parsing (hence the exception mechanism).

@awelzel
Copy link
Contributor Author

awelzel commented Oct 5, 2023

Is this Linux? We could skip that, but we'd loose the ability to show where the backtrack happened in case the exception remains uncaught.

Yep, Linux. For the unhandled backtrack() exception the location in the .spicy file would be sufficient, doesn't seem the whole native code stack is required for sufficient error reporting.

That said, I also wouldn't want encourage such use of try/backtrack(); it's meant as an last-resort mechanism if there's nothing better available, usually to step back across some layers of parsing (hence the exception mechanism).

Yep, not arguing. Performance can likely be fixed, but also the issue in understanding control flow in anything more complex. But then, for a beginner it's an easy to understand tool in reach also for simple cases. In the docs, it's also just before the "Changing Input" section that has the better alternatives. A warning/info box in the documentation suggesting to use the set_input() / input() / parse-at constructs might prevent some misuse, too.

The spicy-postgres parser also has a &try / backtrack() to parse into a few bytes and backtrack(), but that was also me :-)

awelzel added a commit to zeek/spicy-quic that referenced this issue Oct 5, 2023
Improves performance processing pure QUIC traffic by ~20%

Relates to zeek/spicy#1565.
awelzel added a commit to zeek/spicy-quic that referenced this issue Oct 5, 2023
Improves performance processing pure QUIC traffic by ~20%

Relates to zeek/spicy#1565.
@rsmmr
Copy link
Member

rsmmr commented Oct 19, 2023

Turns out these backtraces aren't used anywhere by default anyways, only if requested explicitly through a runtime option. I'll limit capture to debug builds.

rsmmr added a commit that referenced this issue Oct 19, 2023
They can be expensive to capture, and aren't used anywhere by default
unless explicitly requested.

Closes #1565.
@rsmmr rsmmr self-assigned this Oct 19, 2023
rsmmr added a commit that referenced this issue Oct 21, 2023
They can be expensive to capture, and aren't used anywhere by default
unless explicitly requested.

Closes #1565.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants