You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues-all@impala.apache.org by "Sahil Takiar (Jira)" <ji...@apache.org> on 2020/08/05 18:21:00 UTC
[jira] [Updated] (IMPALA-10049) Include RPC call_id in slow RPC
logs
[ https://issues.apache.org/jira/browse/IMPALA-10049?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Sahil Takiar updated IMPALA-10049:
----------------------------------
Description:
The current code for logging slow RPCs on the sender side looks something like this:
{code:java}
template <typename ResponsePBType>
void KrpcDataStreamSender::Channel::LogSlowRpc(
¦ const char* rpc_name, int64_t total_time_ns, const ResponsePBType& resp) {
int64_t network_time_ns = total_time_ns - resp_.receiver_latency_ns();
LOG(INFO) << "Slow " << rpc_name << " RPC to " << address_
¦ ¦ ¦ ¦ ¦ << " (fragment_instance_id=" << PrintId(fragment_instance_id_) << "): "
¦ ¦ ¦ ¦ ¦ << "took " << PrettyPrinter::Print(total_time_ns, TUnit::TIME_NS) << ". "
¦ ¦ ¦ ¦ ¦ << "Receiver time: "
¦ ¦ ¦ ¦ ¦ << PrettyPrinter::Print(resp_.receiver_latency_ns(), TUnit::TIME_NS)
¦ ¦ ¦ ¦ ¦ << " Network time: " << PrettyPrinter::Print(network_time_ns, TUnit::TIME_NS);
}
void KrpcDataStreamSender::Channel::LogSlowFailedRpc(
¦ const char* rpc_name, int64_t total_time_ns, const kudu::Status& err) {
LOG(INFO) << "Slow " << rpc_name << " RPC to " << address_
¦ ¦ ¦ ¦ ¦ << " (fragment_instance_id=" << PrintId(fragment_instance_id_) << "): "
¦ ¦ ¦ ¦ ¦ << "took " << PrettyPrinter::Print(total_time_ns, TUnit::TIME_NS) << ". "
¦ ¦ ¦ ¦ ¦ << "Error: " << err.ToString();
} {code}
It would be nice to include the call_id in the logs as well so that RPCs can more easily be traced. The RPC call_id is dumped in RPC traces on the receiver side, as well as in the /rpcz output on the debug ui.
was:
The current code for logging slow RPCs on the sender side looks something like this:
{code:java}
template <typename ResponsePBType>
void KrpcDataStreamSender::Channel::LogSlowRpc(
¦ const char* rpc_name, int64_t total_time_ns, const ResponsePBType& resp) {
int64_t network_time_ns = total_time_ns - resp_.receiver_latency_ns();
LOG(INFO) << "Slow " << rpc_name << " RPC to " << address_
¦ ¦ ¦ ¦ ¦ << " (fragment_instance_id=" << PrintId(fragment_instance_id_) << "): "
¦ ¦ ¦ ¦ ¦ << "took " << PrettyPrinter::Print(total_time_ns, TUnit::TIME_NS) << ". "
¦ ¦ ¦ ¦ ¦ << "Receiver time: "
¦ ¦ ¦ ¦ ¦ << PrettyPrinter::Print(resp_.receiver_latency_ns(), TUnit::TIME_NS)
¦ ¦ ¦ ¦ ¦ << " Network time: " << PrettyPrinter::Print(network_time_ns, TUnit::TIME_NS);
}void KrpcDataStreamSender::Channel::LogSlowFailedRpc(
¦ const char* rpc_name, int64_t total_time_ns, const kudu::Status& err) {
LOG(INFO) << "Slow " << rpc_name << " RPC to " << address_
¦ ¦ ¦ ¦ ¦ << " (fragment_instance_id=" << PrintId(fragment_instance_id_) << "): "
¦ ¦ ¦ ¦ ¦ << "took " << PrettyPrinter::Print(total_time_ns, TUnit::TIME_NS) << ". "
¦ ¦ ¦ ¦ ¦ << "Error: " << err.ToString();
} {code}
It would be nice to include the call_id in the logs as well so that RPCs can more easily be traced. The RPC call_id is dumped in RPC traces on the receiver side, as well as in the /rpcz output on the debug ui.
> Include RPC call_id in slow RPC logs
> ------------------------------------
>
> Key: IMPALA-10049
> URL: https://issues.apache.org/jira/browse/IMPALA-10049
> Project: IMPALA
> Issue Type: Improvement
> Reporter: Sahil Takiar
> Priority: Major
>
> The current code for logging slow RPCs on the sender side looks something like this:
> {code:java}
> template <typename ResponsePBType>
> void KrpcDataStreamSender::Channel::LogSlowRpc(
> ¦ const char* rpc_name, int64_t total_time_ns, const ResponsePBType& resp) {
> int64_t network_time_ns = total_time_ns - resp_.receiver_latency_ns();
> LOG(INFO) << "Slow " << rpc_name << " RPC to " << address_
> ¦ ¦ ¦ ¦ ¦ << " (fragment_instance_id=" << PrintId(fragment_instance_id_) << "): "
> ¦ ¦ ¦ ¦ ¦ << "took " << PrettyPrinter::Print(total_time_ns, TUnit::TIME_NS) << ". "
> ¦ ¦ ¦ ¦ ¦ << "Receiver time: "
> ¦ ¦ ¦ ¦ ¦ << PrettyPrinter::Print(resp_.receiver_latency_ns(), TUnit::TIME_NS)
> ¦ ¦ ¦ ¦ ¦ << " Network time: " << PrettyPrinter::Print(network_time_ns, TUnit::TIME_NS);
> }
> void KrpcDataStreamSender::Channel::LogSlowFailedRpc(
> ¦ const char* rpc_name, int64_t total_time_ns, const kudu::Status& err) {
> LOG(INFO) << "Slow " << rpc_name << " RPC to " << address_
> ¦ ¦ ¦ ¦ ¦ << " (fragment_instance_id=" << PrintId(fragment_instance_id_) << "): "
> ¦ ¦ ¦ ¦ ¦ << "took " << PrettyPrinter::Print(total_time_ns, TUnit::TIME_NS) << ". "
> ¦ ¦ ¦ ¦ ¦ << "Error: " << err.ToString();
> } {code}
> It would be nice to include the call_id in the logs as well so that RPCs can more easily be traced. The RPC call_id is dumped in RPC traces on the receiver side, as well as in the /rpcz output on the debug ui.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: issues-all-unsubscribe@impala.apache.org
For additional commands, e-mail: issues-all-help@impala.apache.org