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

Don't collect exception stack for log messages that won't be written out #1150

Merged
merged 2 commits into from
Feb 15, 2024

Conversation

nickrobinson251
Copy link
Collaborator

On an internal product benchmark we noticed the following in a continuous profile: during a mysterious period of activity, it seems like we spend a lot of time in the HTTP.jl connection error handling, but don’t see anything in the corresponding logs

Screenshot 2024-02-10 at 20 30 24

Changing all logs in HTTP.jl to be @warn or @error showed us thousands of logs from catching a EOFError from startread in handle_connection, all looking like:

handle_connection startread error. 

===========================
HTTP Error message:

ERROR: EOFError: read end of file
Stacktrace:
 [1] read_to_buffer(c::HTTP.Connections.Connection{Sockets.TCPSocket}, sizehint::Int64)
   @ HTTP.Connections /nix/store/y67cpp71jxfmndqz8k5h1bnyc88wnpky-rai-server-binary-linux/rai-server/.julia/packages/HTTP/eJmrJ/src/Connections.jl:221
 [2] readuntil(c::HTTP.Connections.Connection{Sockets.TCPSocket}, f::typeof(HTTP.Parsers.find_end_of_header), sizehint::Int64)
   @ HTTP.Connections /nix/store/y67cpp71jxfmndqz8k5h1bnyc88wnpky-rai-server-binary-linux/rai-server/.julia/packages/HTTP/eJmrJ/src/Connections.jl:240
 [3] readuntil
   @ /nix/store/y67cpp71jxfmndqz8k5h1bnyc88wnpky-rai-server-binary-linux/rai-server/.julia/packages/HTTP/eJmrJ/src/Connections.jl:238 [inlined]
 [4] readheaders(io::HTTP.Connections.Connection{Sockets.TCPSocket}, message::HTTP.Messages.Request)
   @ HTTP.Messages /nix/store/y67cpp71jxfmndqz8k5h1bnyc88wnpky-rai-server-binary-linux/rai-server/.julia/packages/HTTP/eJmrJ/src/Messages.jl:533
 [5] startread(http::HTTP.Streams.Stream{HTTP.Messages.Request, HTTP.Connections.Connection{Sockets.TCPSocket}})
   @ HTTP.Streams /nix/store/y67cpp71jxfmndqz8k5h1bnyc88wnpky-rai-server-binary-linux/rai-server/.julia/packages/HTTP/eJmrJ/src/Streams.jl:153
 [6] handle_connection(f::Function, c::HTTP.Connections.Connection{Sockets.TCPSocket}, listener::HTTP.Servers.Listener{Nothing, Sockets.TCPServer}, readtimeout::Int64, access_log::Nothing)
   @ HTTP.Servers /nix/store/y67cpp71jxfmndqz8k5h1bnyc88wnpky-rai-server-binary-linux/rai-server/.julia/packages/HTTP/eJmrJ/src/Servers.jl:428
 [7] macro expansion
   @ /nix/store/y67cpp71jxfmndqz8k5h1bnyc88wnpky-rai-server-binary-linux/rai-server/.julia/packages/HTTP/eJmrJ/src/Servers.jl:386 [inlined]
 [8] (::HTTP.Servers.var"#16#17"{HTTP.Handlers.var"#1#2"{RAICode.Server.var"#76#77"{HTTP.Handlers.Router{RAICode.Server.var"#error_handler_404#123"{RAICode.Server.var"#error_handler_function#122"}, RAICode.Server.var"#error_handler_405#124"{RAICode.Server.var"#error_handler_function#122"}, typeof(RAICode.Server.handle_generic_request)}, RAICode.Server.RAIServer}}, HTTP.Servers.Listener{Nothing, Sockets.TCPServer}, Set{HTTP.Connections.Connection}, Int64, Nothing, Base.Semaphore, HTTP.Connections.Connection{Sockets.TCPSocket}})()
   @ HTTP.Servers ./task.jl:514

@ HTTP.Servers /nix/store/y67cpp71jxfmndqz8k5h1bnyc88wnpky-rai-server-binary-linux/rai-server/.julia/packages/HTTP/eJmrJ/src/Servers.jl:437

This branch is spending time calling current_exceptions_to_string only to log an @debug level, even if @debug-level logging is not enabled.

This PR moves all calls to current_exceptions_to_string to be inside the scope of the logging macro, so that the message is only generated when the corresponding log level is enabled

@nickrobinson251 nickrobinson251 requested a review from Drvi February 15, 2024 12:31
@nickrobinson251 nickrobinson251 changed the title Npr conditional catch stack Don't collect exception stack if it won't be logged Feb 15, 2024
@nickrobinson251 nickrobinson251 changed the title Don't collect exception stack if it won't be logged Don't collect exception stack for log messages that won't be written out Feb 15, 2024
Copy link

@Sacha0 Sacha0 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks Nick!

@nickrobinson251 nickrobinson251 merged commit 581c6fc into master Feb 15, 2024
8 of 11 checks passed
@nickrobinson251 nickrobinson251 deleted the npr-conditional-catch-stack branch February 15, 2024 23:55
Copy link
Member

@quinnj quinnj left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

SGTM; so moving the current_exception inside the logging macros ensures that they won't be called because there's the initial log filter happening? Do I understand that right?

Thanks for the fix!

@nickrobinson251
Copy link
Collaborator Author

nickrobinson251 commented Feb 17, 2024

yeah exactly, the logging macros check shouldlog before constructing the message

behaviour:

julia> foo() = (println("boo"); 1)
foo (generic function with 1 method)

julia> @debug foo()

julia> @info foo()
boo
[ Info: 1

julia> with_logger(ConsoleLogger(stderr, Logging.Warn)) do
           @info foo()
       end

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.

4 participants