[IMPALA-6058] Address log spew originating from InboundCall::Respond()

• Type: Sub-task
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Fix Version/s: Impala 2.11.0
• Component/s: Distributed Exec
• Epic Color: ghx-label-9
• Assignee: Sailesh Mukil
• Reporter: Mostafa Mokhtar
• Created: 14/Oct/17 17:01
• Updated: 17/Oct/17 17:30
• Resolved: 17/Oct/17 17:30

Description

Noticed there lots of log lines like the one below which don't really help much.
Also I don't see the metrics collected in rpcz_store.cc showing up anywhere.

void InboundCall::Respond(const MessageLite& response,
                          bool is_success) {
  TRACE_EVENT_FLOW_END0("rpc", "InboundCall", this);
  SerializeResponseBuffer(response, is_success);

  TRACE_EVENT_ASYNC_END1("rpc", "InboundCall", this,
                         "method", remote_method_.method_name());
  TRACE_TO(trace_, "Queueing $0 response", is_success ? "success" : "failure");
  RecordHandlingCompleted();
  conn_->rpcz_store()->AddCall(this);
  conn_->QueueResponseForCall(gscoped_ptr<InboundCall>(this));
}

Then the line below is printed from

void MethodSampler::SampleCall(InboundCall* call) {
  // First determine which sample bucket to put this in.
  int duration_ms = call->timing().TotalDuration().ToMilliseconds();

  SampleBucket* bucket = &buckets_[kNumBuckets - 1];
  for (int i = 0 ; i < kNumBuckets - 1; i++) {
    if (duration_ms < kBucketThresholdsMs[i]) {
      bucket = &buckets_[i];
      break;
    }
  }

  MicrosecondsInt64 now = GetMonoTimeMicros();
  int64_t us_since_trace = now - bucket->last_sample_time.Load();
  if (us_since_trace > kSampleIntervalMs * 1000) {
    Sample new_sample = {call->header(), call->trace(), duration_ms};
    {
      std::unique_lock<simple_spinlock> lock(bucket->sample_lock, std::try_to_lock);
      // If another thread is already taking a sample, it's not worth waiting.
      if (!lock.owns_lock()) {
        return;
      }
      std::swap(bucket->sample, new_sample);
      bucket->last_sample_time.Store(now);
    }
    VLOG(1) << "Sampled call " << call->ToString();
  }
}

I1014 09:48:05.205354 169569 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.246.44:36159 (request call id 3621864)
I1014 09:48:06.205579 169566 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.232.21:56462 (request call id 3499519)
I1014 09:48:07.205763 169579 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.232.29:48213 (request call id 3623828)
I1014 09:48:08.205828 169606 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.221.37:40415 (request call id 3559438)
I1014 09:48:09.206635 169602 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.187.49:36739 (request call id 3561697)
I1014 09:48:10.209550 169566 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.187.52:48621 (request call id 3493490)
I1014 09:48:11.209615 169606 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.234.39:49777 (request call id 3620267)
I1014 09:48:12.209870 169606 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.221.14:42788 (request call id 3554497)
I1014 09:48:13.210436 169566 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.232.20:51551 (request call id 3544573)
I1014 09:48:14.211215 169602 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.221.29:40833 (request call id 3608438)
I1014 09:48:15.214787 169663 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.232.13:57607 (request call id 6234287)
^C
[mmokhtar@va1027 ~]$ tail -f /var/log/impalad/impalad.INFO
I1014 09:53:35.248751 169581 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.232.14:49148 (request call id 3616174)
I1014 09:53:36.249181 169626 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.187.46:42657 (request call id 3616104)
I1014 09:53:37.249719 169626 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.221.26:50146 (request call id 3564709)
I1014 09:53:38.249974 169581 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.234.47:39438 (request call id 3498629)
I1014 09:53:39.250092 169550 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.234.40:35972 (request call id 3492846)
I1014 09:53:40.250099 169646 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.232.28:40588 (request call id 3560510)
I1014 09:53:41.250762 169588 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.232.26:39506 (request call id 3560639)
I1014 09:53:42.251148 169590 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.232.17:36661 (request call id 3621613)
I1014 09:53:43.253104 169646 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.232.49:44377 (request call id 3561095)
I1014 09:53:44.253157 169581 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.234.51:56491 (request call id 3573151)
I1014 09:53:44.720561 169646 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.EndDataStream from 10.17.232.13:57607 (request call id 6239322)
I1014 09:53:44.725270 169646 krpc-data-stream-mgr.cc:256] Reduced stream ID cache from 54 items, to 53, eviction took: 0
I1014 09:53:45.253310 169646 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.246.51:41309 (request call id 3557282)
I1014 09:53:46.253759 169626 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.221.50:37038 (request call id 3616217)
I1014 09:53:46.427503 169612 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.221.32:41503 (request call id 3687311)
I1014 09:53:46.428117 169590 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.246.36:37462 (request call id 3562969)
I1014 09:53:47.254981 169538 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.221.37:40415 (request call id 3564643)
I1014 09:53:48.255583 169661 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.232.15:36205 (request call id 3556412)
I1014 09:53:48.305325 169538 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.EndDataStream from 10.17.246.44:36159 (request call id 3627174)
I1014 09:53:49.255690 169605 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.232.25:37804 (request call id 3605652)
I1014 09:53:50.256216 169661 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.221.39:57887 (request call id 3677966)
I1014 09:53:51.256448 169624 rpcz_store.cc:152] Sampled call Call impala.DataStreamService.TransmitData from 10.17.234.49:38099 (request call id 3620193)