You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@impala.apache.org by "Mostafa Mokhtar (JIRA)" <ji...@apache.org> on 2017/10/14 17:02:00 UTC
[jira] [Created] (IMPALA-6058) Address log spew originating from
InboundCall::Respond()
Mostafa Mokhtar created IMPALA-6058:
---------------------------------------
Summary: 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
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)