Uploaded image for project: 'IMPALA'
  1. IMPALA
  2. IMPALA-2567 KRPC milestone 1
  3. IMPALA-6058

Address log spew originating from InboundCall::Respond()

    Details

    • Type: Sub-task
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: Impala 2.11.0
    • Component/s: Distributed Exec
    • Labels:
      None
    • Epic Color:
      ghx-label-9

      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)
      

        Attachments

          Activity

            People

            • Assignee:
              sailesh Sailesh Mukil
              Reporter:
              mmokhtar Mostafa Mokhtar
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: