ARCHIVE/clio
1
0
Fork 0
mirror of https://github.com/XRPLF/clio.git synced 2025-11-24 13:45:52 +00:00
Code Issues Packages Projects Releases Wiki Activity

Log cleanup (#150)

Browse Source 
* log duration of rpc requests and request itself
* clean up book_offers logging
This commit is contained in:
CJ Cobb
2022-05-11 13:46:40 -04:00
committed by GitHub
parent cdabdec620
commit 8bf44c978e
6 changed files with 36 additions and 8 deletions
Download Patch File Download Diff File Expand all files Collapse all files

9
src/backend/BackendInterface.cpp
View File

@@ -180,7 +180,7 @@ BackendInterface::fetchBookOffers(
succMillis += getMillis(mid2 - mid1);
if (!offerDir || offerDir->key >= bookEnd)
{
BOOST_LOG_TRIVIAL(debug) << __func__ << " - offerDir.has_value() "
BOOST_LOG_TRIVIAL(trace) << __func__ << " - offerDir.has_value() "
<< offerDir.has_value() << " breaking";
break;
}
@@ -197,7 +197,7 @@ BackendInterface::fetchBookOffers(
auto next = sle.getFieldU64(ripple::sfIndexNext);
if (!next)
{
BOOST_LOG_TRIVIAL(debug)
BOOST_LOG_TRIVIAL(trace)
<< __func__ << " next is empty. breaking";
break;
}
@@ -215,7 +215,7 @@ BackendInterface::fetchBookOffers(
auto objs = fetchLedgerObjects(keys, ledgerSequence, yield);
for (size_t i = 0; i < keys.size() && i < limit; ++i)
{
BOOST_LOG_TRIVIAL(debug)
BOOST_LOG_TRIVIAL(trace)
<< __func__ << " key = " << ripple::strHex(keys[i])
<< " blob = " << ripple::strHex(objs[i])
<< " ledgerSequence = " << ledgerSequence;
@@ -236,7 +236,8 @@ BackendInterface::fetchBookOffers(
<< ". Fetching all objects took "
<< std::to_string(getMillis(end - mid))
<< " milliseconds. total time = "
<< std::to_string(getMillis(end - begin)) << " milliseconds";
<< std::to_string(getMillis(end - begin)) << " milliseconds"
<< " book = " << ripple::strHex(book);
return page;
}

1
src/rpc/RPC.cpp
View File

@@ -238,4 +238,5 @@ buildResponse(Context const& ctx)
return Status{Error::rpcINTERNAL, err.what()};
}
}
} // namespace RPC

18
src/rpc/RPC.h
View File

@@ -190,6 +190,24 @@ buildResponse(Context const& ctx);
bool
validHandler(std::string const& method);
template <class T>
void
logDuration(Context const& ctx, T const& dur)
{
std::stringstream ss;
ss << "Request processing duration = "
<< std::chrono::duration_cast<std::chrono::milliseconds>(dur).count()
<< " milliseconds. request = " << ctx.params;
auto seconds =
std::chrono::duration_cast<std::chrono::seconds>(dur).count();
if (seconds > 10)
BOOST_LOG_TRIVIAL(error) << ss.str();
else if (seconds > 1)
BOOST_LOG_TRIVIAL(warning) << ss.str();
else
BOOST_LOG_TRIVIAL(debug) << ss.str();
}
} // namespace RPC
#endif // REPORTING_RPC_H_INCLUDED

14
src/rpc/handlers/BookOffers.cpp
View File

@@ -87,7 +87,10 @@ doBookOffers(Context const& context)
auto end = std::chrono::system_clock::now();
BOOST_LOG_TRIVIAL(warning)
<< "Time loading books: " << ((end - start).count() / 1000000000.0);
<< "Time loading books: "
<< std::chrono::duration_cast<std::chrono::milliseconds>(end - start)
.count()
<< " milliseconds - request = " << request;
response["ledger_hash"] = ripple::strHex(lgrInfo.hash);
response["ledger_index"] = lgrInfo.seq;
@@ -95,10 +98,13 @@ doBookOffers(Context const& context)
response["offers"] = postProcessOrderBook(
offers, book, takerID, *context.backend, lgrInfo.seq, context.yield);
end = std::chrono::system_clock::now();
auto end2 = std::chrono::system_clock::now();
BOOST_LOG_TRIVIAL(warning) << "Time transforming to json: "
<< ((end - start).count() / 1000000000.0);
BOOST_LOG_TRIVIAL(warning)
<< "Time transforming to json: "
<< std::chrono::duration_cast<std::chrono::milliseconds>(end2 - end)
.count()
<< " milliseconds - request = " << request;
if (retCursor)
response["marker"] = ripple::strHex(*retCursor);

1
src/webserver/HttpBase.h
View File

@@ -366,6 +366,7 @@ handle_request(
auto end = std::chrono::system_clock::now();
auto us =
std::chrono::duration_cast<std::chrono::microseconds>(end - start);
RPC::logDuration(*context, us);
if (auto status = std::get_if<RPC::Status>(&v))
{

1
src/webserver/WsBase.h
View File

@@ -275,6 +275,7 @@ public:
auto end = std::chrono::system_clock::now();
auto us = std::chrono::duration_cast<std::chrono::microseconds>(
end - start);
logDuration(*context, us);
if (auto status = std::get_if<RPC::Status>(&v))
{