[IMPALA-10049] Include RPC call_id in slow RPC logs

• Type: Sub-task
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Fix Version/s: Impala 4.1.0
• Component/s: Distributed Exec
• Labels: observability
• Epic Color: ghx-label-7
• Assignee: Riza Suminto
• Reporter: Sahil Takiar
• Created: 05/Aug/20 18:20
• Updated: 02/Mar/22 03:31
• Resolved: 02/Mar/22 03:31

Description

The current code for logging slow RPCs on the sender side looks something like this:

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();
} 

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.