log request and duration for every RPC call #4036
Closed
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Comment on lines
387
to
398
| std::stringstream logMsg; | ||
| logMsg << "RPC request processing duration = " | ||
| << std::chrono::duration_cast<std::chrono::microseconds>(duration) | ||
| .count() | ||
| << " microseconds. request = " << request; | ||
| if (std::chrono::duration_cast<std::chrono::seconds>(duration).count() >= | ||
| 10) | ||
| { | ||
| JLOG(journal.error()) << logMsg.str(); | ||
| } | ||
| else if ( | ||
| std::chrono::duration_cast<std::chrono::seconds>(duration).count() >= 1) | ||
| { | ||
| JLOG(journal.warn()) << logMsg.str(); | ||
| } | ||
| else | ||
| { | ||
| JLOG(journal.debug()) << logMsg.str(); | ||
| } | ||
| } | ||
|
|
There was a problem hiding this comment.
Consider trying this. This is off the top of the dome, so it might require some finessing.
auto const seconds = std::chrono::duration_cast<std::chrono::seconds>(duration).count();
using J = decltype(journal);
auto const level = (seconds >= 10) ? &J::error : (seconds >= 1) ? &J:warn : &J:debug;
JLOG(journal.*level()) << "RPC request processing duration = "
<< std::chrono::duration_cast<std::chrono::microseconds>(duration)
.count()
<< " microseconds. request = " << request;There was a problem hiding this comment.
auto const seconds =
std::chrono::duration_cast<std::chrono::seconds>(duration).count();
auto const level = (seconds >= 10)
? journal.error()
: (seconds >= 1) ? journal.warn() : journal.debug();
JLOG(level) << "RPC request processing duration = "
<< std::chrono::duration_cast<std::chrono::microseconds>(
duration)
.count()
<< " microseconds. request = " << request;worked for me. Tested by logging a request that ran for > 1s, and got the appropriate warn() message.
There was a problem hiding this comment.
level can be inlined by wrapping it in an extra set of (), not that that's necessarily a good idea.
Comment on lines
+489
to
+483
| auto start = std::chrono::system_clock::now(); | ||
| RPC::doCommand(context, jr[jss::result]); | ||
| auto end = std::chrono::system_clock::now(); | ||
| logDuration(jv, end - start, m_journal); |
There was a problem hiding this comment.
If this pattern is used in more places, it might be worth investing in a helper class that uses RAII in the style of scope_guard.
thejohnfreeman
approved these changes
Dec 15, 2021
mtrippled
approved these changes
Dec 15, 2021
natenichols
added
the
Ready to merge
ximinez
requested changes
Dec 15, 2021
Comment on lines
387
to
392
| auto const seconds = | ||
| std::chrono::duration_cast<std::chrono::seconds>(duration).count(); | ||
|
|
||
| auto const level = (seconds >= 10) | ||
| ? journal.error() | ||
| : (seconds >= 1) ? journal.warn() : journal.debug(); |
There was a problem hiding this comment.
This can be significantly simplified:
using namespace std::chrono_literals;
auto const level = (duration >= 10s)
? journal.error()
: (duration >= 1s) ? journal.warn() : journal.debug();
26a8203 to
1b676f1
Compare
natenichols
force-pushed
the
duration-logging
branch
from
1b676f1 to
0160194
Compare
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
@cjcobb23 authored this commit
High Level Overview of Change
For every RPC, the request itself and the duration it took to process is logged. This helps immensely with debugging performance issues. The log level is determined by how long the request took:
Less than 1 second: debug
1 - 10 seconds: warning
Greater than 10 seconds: error
Context of Change
We were noticing some very long running calls on the reporting servers, and we wanted to determine exactly what was taking so long, and how often this was happening. The stats in grafana are just averages, and so the logging gives a much finer granularity, as well as a way to reproduce the long running requests, since the entire request is also logged.