You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@impala.apache.org by "Sailesh Mukil (JIRA)" <ji...@apache.org> on 2017/10/17 17:31:00 UTC
[jira] [Resolved] (IMPALA-6058) Address log spew originating from
InboundCall::Respond()
[ https://issues.apache.org/jira/browse/IMPALA-6058?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Sailesh Mukil resolved IMPALA-6058.
-----------------------------------
Resolution: Fixed
Fix Version/s: Impala 2.11.0
Commit in:
https://github.com/apache/incubator-impala/commit/80f0c5ae820efeb9e3714cf844e856b264ed291d
> Address log spew originating from InboundCall::Respond()
> --------------------------------------------------------
>
> Key: IMPALA-6058
> URL: https://issues.apache.org/jira/browse/IMPALA-6058
> Project: IMPALA
> Issue Type: Sub-task
> Components: Distributed Exec
> Reporter: Mostafa Mokhtar
> Assignee: Sailesh Mukil
> Fix For: Impala 2.11.0
>
>
> 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.
> {code}
> 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));
> }
> {code}
> Then the line below is printed from
> {code}
> 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();
> }
> }
> {code}
> {code}
> 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)
> {code}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)