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

Reduced slowdown with Stracktrace middleware #697

Closed

Conversation

allanwhiteford
Copy link

During normal operation errors will be thrown and caught by various modules. e.g. Mason throws:

Can't locate Mason/Plugin/DollarDot/Result.pm

The Middleware doesn't display these but it still slows it down.

Specifically, if the strack trace itself is large (either from being reasonably deep or because a lot of data are being moved around in it) then the logic that checks to display it first checks if there is a stracktrace and then if it should display it.

However, checking for a stacktrace (when using Devel::Stracktrace) is expensive because, in effect, what looks like a boolean operation in the middleware is actually calling Devel::Stracktrace->as_string.

This commit swaps the order of checking so that if we aren't going to use the stacktrace then we don't see if it's truthy (hence don't recurse down the structure making a string).

The specific test case that caused this was pushing 32MB through a Mason/Plack request on the first request of the server. The Mason interpreter throws an error as it loads the template but since 32MB is being passed around the ->as_string call to the stacktrace is expensive (even though it is then ignored). This resulted in a 4.2s slowdown on an i7-1065G7 with laptop-spec RAM/disk etc.

During normal operation errors will be thrown and caught by
various modules. e.g. Mason throws:

Can't locate Mason/Plugin/DollarDot/Result.pm

The Middleware doesn't display these but it still slows it down.

Specifically, if the strack trace itself is large (either from being
reasonably deep or because a lot of data are being moved around in
it) then the logic that checks to display it first checks if there
is a stracktrace and then if it should display it.

However, checking for a stacktrace (when using Devel::Stracktrace)
is expensive because, in effect, what looks like a boolean operation
in the middleware is actually calling Devel::Stracktrace->as_string.

This commit swaps the order of checking so that if we aren't going
to use the stacktrace then we don't see if it's truthy (hence don't
recurse down the structure making a string).

The specific test case that caused this was pushing 32MB through
a Mason/Plack request on the first request of the server. The Mason
interpreter throws an error as it loads the template but since 32MB
is being passed around the ->as_string call to the stacktrace is
expensive (even though it is then ignored). This resulted in a 4.2s
slowdown on an i7-1065G7 with laptop-spec RAM/disk etc.
@miyagawa
Copy link
Member

However, checking for a stacktrace (when using Devel::Stracktrace) is expensive because, in effect, what looks like a boolean operation in the middleware is actually calling Devel::Stracktrace->as_string.

Huh, is that because Devel::StackTrace has overload for "" with as_string but doesn't define overloading for booleans? It's a little surprising and not ideal.

I guess this patch is simple enough but I wonder if it would be more readable to change it to ref $trace instead.

@miyagawa miyagawa closed this in 5a52015 Sep 14, 2023
@miyagawa
Copy link
Member

ref $trace has an advantage of not calling ->as_string twice in the caught case as well.

@allanwhiteford
Copy link
Author

Looks better to me as well, thank you!

netbsd-srcmastr pushed a commit to NetBSD/pkgsrc that referenced this pull request Jan 14, 2024
2.05   2024-01-08

- Added explicit boolean overloading for trace objects. Without this, Perl
  will use the object's string overloading and then check the truthiness of
  the returned string, which is a lot of extra work. This can produce
  significant slowdowns in some cases, as seen in
  plack/Plack#697. Requested by Tatsuhiko
  Miyagawa. GH #23.
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 this pull request may close these issues.

2 participants