Details

    • ghx-label-7

    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.

      Attachments

        Activity

          People

            rizaon Riza Suminto
            stakiar Sahil Takiar
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: