Chiebot-Mirror
/
grpc
mirror of https://github.com/grpc/grpc.git
8
0
Fork 0
Code Issues Projects Releases Wiki Activity

Merge pull request #15189 from markdroth/tracer_log_level

Browse Source 
Change trace logging to use GPR_INFO instead of GPR_DEBUG.
pull/15226/head
Mark D. Roth 7 years ago committed by GitHub
parent 8acece911a 48854d2061
commit 342a371b7c
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
40 changed files with 383 additions and 392 deletions
Whitespace
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Split View
Diff Options
Show Stats Download Patch File Download Diff File
  1. 151
      src/core/ext/filters/client_channel/client_channel.cc
  2. 4
      src/core/ext/filters/client_channel/lb_policy.cc
  3. 17
      src/core/ext/filters/client_channel/lb_policy/grpclb/grpclb.cc
  4. 10
      src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc
  5. 31
      src/core/ext/filters/client_channel/lb_policy/round_robin/round_robin.cc
  6. 22
      src/core/ext/filters/client_channel/lb_policy/subchannel_list.cc
  7. 4
      src/core/ext/filters/http/message_compress/message_compress_filter.cc
  8. 25
      src/core/ext/transport/chttp2/transport/chttp2_transport.cc
  9. 6
      src/core/ext/transport/chttp2/transport/frame_settings.cc
  10. 4
      src/core/ext/transport/chttp2/transport/hpack_encoder.cc
  11. 2
      src/core/ext/transport/chttp2/transport/hpack_parser.cc
  12. 4
      src/core/ext/transport/chttp2/transport/hpack_table.cc
  13. 6
      src/core/ext/transport/chttp2/transport/stream_lists.cc
  14. 10
      src/core/ext/transport/chttp2/transport/writing.cc
  15. 84
      src/core/ext/transport/inproc/inproc_transport.cc
  16. 8
      src/core/lib/channel/handshaker.cc
  17. 4
      src/core/lib/gprpp/orphanable.h
  18. 4
      src/core/lib/gprpp/ref_counted.h
  19. 26
      src/core/lib/iomgr/call_combiner.cc
  20. 22
      src/core/lib/iomgr/combiner.cc
  21. 48
      src/core/lib/iomgr/ev_epoll1_linux.cc
  22. 54
      src/core/lib/iomgr/ev_epollex_linux.cc
  23. 4
      src/core/lib/iomgr/ev_epollsig_linux.cc
  24. 6
      src/core/lib/iomgr/ev_poll_posix.cc
  25. 2
      src/core/lib/iomgr/ev_posix.cc
  26. 12
      src/core/lib/iomgr/executor.cc
  27. 21
      src/core/lib/iomgr/resource_quota.cc
  28. 4
      src/core/lib/iomgr/tcp_client_custom.cc
  29. 8
      src/core/lib/iomgr/tcp_client_posix.cc
  30. 20
      src/core/lib/iomgr/tcp_custom.cc
  31. 48
      src/core/lib/iomgr/tcp_posix.cc
  32. 10
      src/core/lib/iomgr/tcp_server_custom.cc
  33. 2
      src/core/lib/iomgr/tcp_server_posix.cc
  34. 34
      src/core/lib/iomgr/timer_generic.cc
  35. 23
      src/core/lib/iomgr/timer_manager.cc
  36. 4
      src/core/lib/security/transport/secure_endpoint.cc
  37. 4
      src/core/lib/surface/call.cc
  38. 6
      src/core/lib/transport/bdp_estimator.cc
  39. 4
      src/core/lib/transport/bdp_estimator.h
  40. 13
      src/core/lib/transport/connectivity_state.cc

151
src/core/ext/filters/client_channel/client_channel.cc
Unescape View File

@ -174,7 +174,7 @@ static void set_channel_connectivity_state_locked(channel_data* chand,
}
}
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p: setting connectivity state to %s", chand,
gpr_log(GPR_INFO, "chand=%p: setting connectivity state to %s", chand,
grpc_connectivity_state_name(state));
}
grpc_connectivity_state_set(&chand->state_tracker, state, error, reason);
@ -186,7 +186,7 @@ static void on_lb_policy_state_changed_locked(void* arg, grpc_error* error) {
/* check if the notification is for the latest policy */
if (w->lb_policy == w->chand->lb_policy.get()) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p: lb_policy=%p state changed to %s", w->chand,
gpr_log(GPR_INFO, "chand=%p: lb_policy=%p state changed to %s", w->chand,
w->lb_policy, grpc_connectivity_state_name(w->state));
}
set_channel_connectivity_state_locked(w->chand, w->state,
@ -215,7 +215,7 @@ static void watch_lb_policy_locked(channel_data* chand,
static void start_resolving_locked(channel_data* chand) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p: starting name resolution", chand);
gpr_log(GPR_INFO, "chand=%p: starting name resolution", chand);
}
GPR_ASSERT(!chand->started_resolving);
chand->started_resolving = true;
@ -297,7 +297,7 @@ static void request_reresolution_locked(void* arg, grpc_error* error) {
return;
}
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p: started name re-resolving", chand);
gpr_log(GPR_INFO, "chand=%p: started name re-resolving", chand);
}
chand->resolver->RequestReresolutionLocked();
// Give back the closure to the LB policy.
@ -311,7 +311,7 @@ static void request_reresolution_locked(void* arg, grpc_error* error) {
static void on_resolver_result_changed_locked(void* arg, grpc_error* error) {
channel_data* chand = static_cast<channel_data*>(arg);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p: got resolver result: resolver_result=%p error=%s", chand,
chand->resolver_result, grpc_error_string(error));
}
@ -431,7 +431,7 @@ static void on_resolver_result_changed_locked(void* arg, grpc_error* error) {
}
}
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p: resolver result: lb_policy_name=\"%s\"%s, "
"service_config=\"%s\"",
chand, lb_policy_name_dup,
@ -466,7 +466,7 @@ static void on_resolver_result_changed_locked(void* arg, grpc_error* error) {
chand->resolver == nullptr) {
if (chand->lb_policy != nullptr) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p: unreffing lb_policy=%p", chand,
gpr_log(GPR_INFO, "chand=%p: unreffing lb_policy=%p", chand,
chand->lb_policy.get());
}
grpc_pollset_set_del_pollset_set(chand->lb_policy->interested_parties(),
@ -480,11 +480,11 @@ static void on_resolver_result_changed_locked(void* arg, grpc_error* error) {
// error or shutdown.
if (error != GRPC_ERROR_NONE || chand->resolver == nullptr) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p: shutting down", chand);
gpr_log(GPR_INFO, "chand=%p: shutting down", chand);
}
if (chand->resolver != nullptr) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p: shutting down resolver", chand);
gpr_log(GPR_INFO, "chand=%p: shutting down resolver", chand);
}
chand->resolver.reset();
}
@ -506,7 +506,7 @@ static void on_resolver_result_changed_locked(void* arg, grpc_error* error) {
GRPC_ERROR_CREATE_FROM_STATIC_STRING("No load balancing policy");
if (lb_policy_created) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p: initializing new LB policy", chand);
gpr_log(GPR_INFO, "chand=%p: initializing new LB policy", chand);
}
GRPC_ERROR_UNREF(state_error);
state = chand->lb_policy->CheckConnectivityLocked(&state_error);
@ -999,7 +999,7 @@ static void maybe_cache_send_ops_for_batch(call_data* calld,
static void free_cached_send_initial_metadata(channel_data* chand,
call_data* calld) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: destroying calld->send_initial_metadata", chand,
calld);
}
@ -1010,7 +1010,7 @@ static void free_cached_send_initial_metadata(channel_data* chand,
static void free_cached_send_message(channel_data* chand, call_data* calld,
size_t idx) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: destroying calld->send_messages[%" PRIuPTR "]",
chand, calld, idx);
}
@ -1021,7 +1021,7 @@ static void free_cached_send_message(channel_data* chand, call_data* calld,
static void free_cached_send_trailing_metadata(channel_data* chand,
call_data* calld) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: destroying calld->send_trailing_metadata",
chand, calld);
}
@ -1088,7 +1088,7 @@ static void pending_batches_add(grpc_call_element* elem,
call_data* calld = static_cast<call_data*>(elem->call_data);
const size_t idx = get_batch_index(batch);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: adding pending batch at index %" PRIuPTR, chand,
calld, idx);
}
@ -1116,7 +1116,7 @@ static void pending_batches_add(grpc_call_element* elem,
}
if (calld->bytes_buffered_for_retry > chand->per_rpc_retry_buffer_size) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: exceeded retry buffer size, committing",
chand, calld);
}
@ -1131,7 +1131,7 @@ static void pending_batches_add(grpc_call_element* elem,
// retries are disabled so that we don't bother with retry overhead.
if (calld->num_attempts_completed == 0) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: disabling retries before first attempt",
chand, calld);
}
@ -1178,7 +1178,7 @@ static void pending_batches_fail(grpc_call_element* elem, grpc_error* error,
for (size_t i = 0; i < GPR_ARRAY_SIZE(calld->pending_batches); ++i) {
if (calld->pending_batches[i].batch != nullptr) ++num_batches;
}
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: failing %" PRIuPTR " pending batches: %s",
elem->channel_data, calld, num_batches, grpc_error_string(error));
}
@ -1240,7 +1240,7 @@ static void pending_batches_resume(grpc_call_element* elem) {
for (size_t i = 0; i < GPR_ARRAY_SIZE(calld->pending_batches); ++i) {
if (calld->pending_batches[i].batch != nullptr) ++num_batches;
}
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: starting %" PRIuPTR
" pending batches on subchannel_call=%p",
chand, calld, num_batches, calld->subchannel_call);
@ -1285,7 +1285,7 @@ static void maybe_clear_pending_batch(grpc_call_element* elem,
(!batch->recv_message ||
batch->payload->recv_message.recv_message_ready == nullptr)) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: clearing pending batch", chand,
gpr_log(GPR_INFO, "chand=%p calld=%p: clearing pending batch", chand,
calld);
}
pending_batch_clear(calld, pending);
@ -1375,7 +1375,7 @@ static void retry_commit(grpc_call_element* elem,
if (calld->retry_committed) return;
calld->retry_committed = true;
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: committing retries", chand, calld);
gpr_log(GPR_INFO, "chand=%p calld=%p: committing retries", chand, calld);
}
if (retry_state != nullptr) {
free_cached_send_op_data_after_commit(elem, retry_state);
@ -1420,7 +1420,7 @@ static void do_retry(grpc_call_element* elem,
next_attempt_time = calld->retry_backoff->NextAttemptTime();
}
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: retrying failed call in %" PRIuPTR " ms", chand,
calld, next_attempt_time - grpc_core::ExecCtx::Get()->Now());
}
@ -1454,7 +1454,7 @@ static bool maybe_retry(grpc_call_element* elem,
batch_data->subchannel_call));
if (retry_state->retry_dispatched) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: retry already dispatched", chand,
gpr_log(GPR_INFO, "chand=%p calld=%p: retry already dispatched", chand,
calld);
}
return true;
@ -1466,14 +1466,14 @@ static bool maybe_retry(grpc_call_element* elem,
calld->retry_throttle_data->RecordSuccess();
}
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: call succeeded", chand, calld);
gpr_log(GPR_INFO, "chand=%p calld=%p: call succeeded", chand, calld);
}
return false;
}
// Status is not OK. Check whether the status is retryable.
if (!retry_policy->retryable_status_codes.Contains(status)) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: status %s not configured as retryable", chand,
calld, grpc_status_code_to_string(status));
}
@ -1489,14 +1489,14 @@ static bool maybe_retry(grpc_call_element* elem,
if (calld->retry_throttle_data != nullptr &&
!calld->retry_throttle_data->RecordFailure()) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: retries throttled", chand, calld);
gpr_log(GPR_INFO, "chand=%p calld=%p: retries throttled", chand, calld);
}
return false;
}
// Check whether the call is committed.
if (calld->retry_committed) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: retries already committed", chand,
gpr_log(GPR_INFO, "chand=%p calld=%p: retries already committed", chand,
calld);
}
return false;
@ -1505,7 +1505,7 @@ static bool maybe_retry(grpc_call_element* elem,
++calld->num_attempts_completed;
if (calld->num_attempts_completed >= retry_policy->max_attempts) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: exceeded %d retry attempts", chand,
gpr_log(GPR_INFO, "chand=%p calld=%p: exceeded %d retry attempts", chand,
calld, retry_policy->max_attempts);
}
return false;
@ -1513,7 +1513,7 @@ static bool maybe_retry(grpc_call_element* elem,
// If the call was cancelled from the surface, don't retry.
if (calld->cancel_error != GRPC_ERROR_NONE) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: call cancelled from surface, not retrying",
chand, calld);
}
@ -1526,16 +1526,15 @@ static bool maybe_retry(grpc_call_element* elem,
uint32_t ms;
if (!grpc_parse_slice_to_uint32(GRPC_MDVALUE(*server_pushback_md), &ms)) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: not retrying due to server push-back",
chand, calld);
}
return false;
} else {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
"chand=%p calld=%p: server push-back: retry in %u ms", chand,
calld, ms);
gpr_log(GPR_INFO, "chand=%p calld=%p: server push-back: retry in %u ms",
chand, calld, ms);
}
server_pushback_ms = (grpc_millis)ms;
}
@ -1608,7 +1607,7 @@ static void invoke_recv_initial_metadata_callback(void* arg,
batch->payload->recv_initial_metadata.recv_initial_metadata_ready !=
nullptr) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: invoking recv_initial_metadata_ready for "
"pending batch at index %" PRIuPTR,
chand, calld, i);
@ -1644,7 +1643,7 @@ static void recv_initial_metadata_ready(void* arg, grpc_error* error) {
channel_data* chand = static_cast<channel_data*>(elem->channel_data);
call_data* calld = static_cast<call_data*>(elem->call_data);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: got recv_initial_metadata_ready, error=%s",
chand, calld, grpc_error_string(error));
}
@ -1659,7 +1658,7 @@ static void recv_initial_metadata_ready(void* arg, grpc_error* error) {
if ((batch_data->trailing_metadata_available || error != GRPC_ERROR_NONE) &&
!retry_state->completed_recv_trailing_metadata) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: deferring recv_initial_metadata_ready "
"(Trailers-Only)",
chand, calld);
@ -1701,7 +1700,7 @@ static void invoke_recv_message_callback(void* arg, grpc_error* error) {
if (batch != nullptr && batch->recv_message &&
batch->payload->recv_message.recv_message_ready != nullptr) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: invoking recv_message_ready for "
"pending batch at index %" PRIuPTR,
chand, calld, i);
@ -1734,7 +1733,7 @@ static void recv_message_ready(void* arg, grpc_error* error) {
channel_data* chand = static_cast<channel_data*>(elem->channel_data);
call_data* calld = static_cast<call_data*>(elem->call_data);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: got recv_message_ready, error=%s",
gpr_log(GPR_INFO, "chand=%p calld=%p: got recv_message_ready, error=%s",
chand, calld, grpc_error_string(error));
}
subchannel_call_retry_state* retry_state =
@ -1748,7 +1747,7 @@ static void recv_message_ready(void* arg, grpc_error* error) {
if ((batch_data->recv_message == nullptr || error != GRPC_ERROR_NONE) &&
!retry_state->completed_recv_trailing_metadata) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: deferring recv_message_ready (nullptr "
"message and recv_trailing_metadata pending)",
chand, calld);
@ -1796,7 +1795,7 @@ static void execute_closures_in_call_combiner(grpc_call_element* elem,
// have to re-enter the call combiner.
if (num_closures > 0) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: %s starting closure: %s", chand,
gpr_log(GPR_INFO, "chand=%p calld=%p: %s starting closure: %s", chand,
calld, caller, closures[0].reason);
}
GRPC_CLOSURE_SCHED(closures[0].closure, closures[0].error);
@ -1805,7 +1804,7 @@ static void execute_closures_in_call_combiner(grpc_call_element* elem,
}
for (size_t i = 1; i < num_closures; ++i) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: %s starting closure in call combiner: %s",
chand, calld, caller, closures[i].reason);
}
@ -1817,7 +1816,7 @@ static void execute_closures_in_call_combiner(grpc_call_element* elem,
}
} else {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: no closures to run for %s", chand,
gpr_log(GPR_INFO, "chand=%p calld=%p: no closures to run for %s", chand,
calld, caller);
}
GRPC_CALL_COMBINER_STOP(calld->call_combiner, "no closures to run");
@ -1912,7 +1911,7 @@ static void add_closures_for_replay_or_pending_send_ops(
}
if (have_pending_send_message_ops || have_pending_send_trailing_metadata_op) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: starting next batch for pending send op(s)",
chand, calld);
}
@ -1937,7 +1936,7 @@ static void add_closures_for_completed_pending_batches(
pending_batch* pending = &calld->pending_batches[i];
if (pending_batch_is_completed(pending, calld, retry_state)) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: pending batch completed at index %" PRIuPTR,
chand, calld, i);
}
@ -1970,7 +1969,7 @@ static void add_closures_to_fail_unstarted_pending_batches(
pending_batch* pending = &calld->pending_batches[i];
if (pending_batch_is_unstarted(pending, calld, retry_state)) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: failing unstarted pending batch at index "
"%" PRIuPTR,
chand, calld, i);
@ -2014,7 +2013,7 @@ static void on_complete(void* arg, grpc_error* error) {
call_data* calld = static_cast<call_data*>(elem->call_data);
if (grpc_client_channel_trace.enabled()) {
char* batch_str = grpc_transport_stream_op_batch_string(&batch_data->batch);
gpr_log(GPR_DEBUG, "chand=%p calld=%p: got on_complete, error=%s, batch=%s",
gpr_log(GPR_INFO, "chand=%p calld=%p: got on_complete, error=%s, batch=%s",
chand, calld, grpc_error_string(error), batch_str);
gpr_free(batch_str);
}
@ -2031,7 +2030,7 @@ static void on_complete(void* arg, grpc_error* error) {
update_retry_state_for_completed_batch(batch_data, retry_state);
if (call_finished) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: call already finished", chand,
gpr_log(GPR_INFO, "chand=%p calld=%p: call already finished", chand,
calld);
}
} else {
@ -2059,7 +2058,7 @@ static void on_complete(void* arg, grpc_error* error) {
// If the call just finished, check if we should retry.
if (call_finished) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: call finished, status=%s", chand,
gpr_log(GPR_INFO, "chand=%p calld=%p: call finished, status=%s", chand,
calld, grpc_status_code_to_string(status));
}
if (maybe_retry(elem, batch_data, status, server_pushback_md)) {
@ -2224,7 +2223,7 @@ static void add_retriable_send_message_op(
channel_data* chand = static_cast<channel_data*>(elem->channel_data);
call_data* calld = static_cast<call_data*>(elem->call_data);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: starting calld->send_messages[%" PRIuPTR "]",
chand, calld, retry_state->started_send_message_count);
}
@ -2311,7 +2310,7 @@ static void start_internal_recv_trailing_metadata(grpc_call_element* elem) {
channel_data* chand = static_cast<channel_data*>(elem->channel_data);
call_data* calld = static_cast<call_data*>(elem->call_data);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: call failed but recv_trailing_metadata not "
"started; starting it internally",
chand, calld);
@ -2343,7 +2342,7 @@ static subchannel_batch_data* maybe_create_subchannel_batch_for_replay(
!retry_state->started_send_initial_metadata &&
!calld->pending_send_initial_metadata) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: replaying previously completed "
"send_initial_metadata op",
chand, calld);
@ -2359,7 +2358,7 @@ static subchannel_batch_data* maybe_create_subchannel_batch_for_replay(
retry_state->completed_send_message_count &&
!calld->pending_send_message) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: replaying previously completed "
"send_message op",
chand, calld);
@ -2378,7 +2377,7 @@ static subchannel_batch_data* maybe_create_subchannel_batch_for_replay(
!retry_state->started_send_trailing_metadata &&
!calld->pending_send_trailing_metadata) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: replaying previously completed "
"send_trailing_metadata op",
chand, calld);
@ -2518,7 +2517,7 @@ static void start_retriable_subchannel_batches(void* arg, grpc_error* ignored) {
channel_data* chand = static_cast<channel_data*>(elem->channel_data);
call_data* calld = static_cast<call_data*>(elem->call_data);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: constructing retriable batches",
gpr_log(GPR_INFO, "chand=%p calld=%p: constructing retriable batches",
chand, calld);
}
subchannel_call_retry_state* retry_state =
@ -2541,7 +2540,7 @@ static void start_retriable_subchannel_batches(void* arg, grpc_error* ignored) {
&num_closures);
// Start batches on subchannel call.
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: starting %" PRIuPTR
" retriable batches on subchannel_call=%p",
chand, calld, num_closures, calld->subchannel_call);
@ -2572,7 +2571,7 @@ static void create_subchannel_call(grpc_call_element* elem, grpc_error* error) {
grpc_error* new_error = calld->pick.connected_subchannel->CreateCall(
call_args, &calld->subchannel_call);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: create subchannel_call=%p: error=%s",
gpr_log(GPR_INFO, "chand=%p calld=%p: create subchannel_call=%p: error=%s",
chand, calld, calld->subchannel_call, grpc_error_string(new_error));
}
if (new_error != GRPC_ERROR_NONE) {
@ -2613,7 +2612,7 @@ static void pick_done(void* arg, grpc_error* error) {
: GRPC_ERROR_CREATE_REFERENCING_FROM_STATIC_STRING(
"Failed to create subchannel", &error, 1);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: failed to create subchannel: error=%s",
chand, calld, grpc_error_string(new_error));
}
@ -2657,7 +2656,7 @@ static void pick_callback_cancel_locked(void* arg, grpc_error* error) {
// the one we started it on. However, this will just be a no-op.
if (error != GRPC_ERROR_NONE && chand->lb_policy != nullptr) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: cancelling pick from LB policy %p",
gpr_log(GPR_INFO, "chand=%p calld=%p: cancelling pick from LB policy %p",
chand, calld, chand->lb_policy.get());
}
chand->lb_policy->CancelPickLocked(&calld->pick, GRPC_ERROR_REF(error));
@ -2672,8 +2671,8 @@ static void pick_callback_done_locked(void* arg, grpc_error* error) {
channel_data* chand = static_cast<channel_data*>(elem->channel_data);
call_data* calld = static_cast<call_data*>(elem->call_data);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: pick completed asynchronously",
chand, calld);
gpr_log(GPR_INFO, "chand=%p calld=%p: pick completed asynchronously", chand,
calld);
}
async_pick_done_locked(elem, GRPC_ERROR_REF(error));
GRPC_CALL_STACK_UNREF(calld->owning_call, "pick_callback");
@ -2685,7 +2684,7 @@ static void apply_service_config_to_call_locked(grpc_call_element* elem) {
channel_data* chand = static_cast<channel_data*>(elem->channel_data);
call_data* calld = static_cast<call_data*>(elem->call_data);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: applying service config to call",
gpr_log(GPR_INFO, "chand=%p calld=%p: applying service config to call",
chand, calld);
}
if (chand->retry_throttle_data != nullptr) {
@ -2723,8 +2722,8 @@ static bool pick_callback_start_locked(grpc_call_element* elem) {
channel_data* chand = static_cast<channel_data*>(elem->channel_data);
call_data* calld = static_cast<call_data*>(elem->call_data);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: starting pick on lb_policy=%p",
chand, calld, chand->lb_policy.get());
gpr_log(GPR_INFO, "chand=%p calld=%p: starting pick on lb_policy=%p", chand,
calld, chand->lb_policy.get());
}
// Only get service config data on the first attempt.
if (calld->num_attempts_completed == 0) {
@ -2771,7 +2770,7 @@ static bool pick_callback_start_locked(grpc_call_element* elem) {
if (pick_done) {
// Pick completed synchronously.
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: pick completed synchronously",
gpr_log(GPR_INFO, "chand=%p calld=%p: pick completed synchronously",
chand, calld);
}
GRPC_CALL_STACK_UNREF(calld->owning_call, "pick_callback");
@ -2815,7 +2814,7 @@ static void pick_after_resolver_result_cancel_locked(void* arg,
channel_data* chand = static_cast<channel_data*>(elem->channel_data);
call_data* calld = static_cast<call_data*>(elem->call_data);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: cancelling pick waiting for resolver result",
chand, calld);
}
@ -2835,7 +2834,7 @@ static void pick_after_resolver_result_done_locked(void* arg,
if (args->finished) {
/* cancelled, do nothing */
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "call cancelled before resolver result");
gpr_log(GPR_INFO, "call cancelled before resolver result");
}
gpr_free(args);
return;
@ -2846,14 +2845,14 @@ static void pick_after_resolver_result_done_locked(void* arg,
call_data* calld = static_cast<call_data*>(elem->call_data);
if (error != GRPC_ERROR_NONE) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: resolver failed to return data",
gpr_log(GPR_INFO, "chand=%p calld=%p: resolver failed to return data",
chand, calld);
}
async_pick_done_locked(elem, GRPC_ERROR_REF(error));
} else if (chand->resolver == nullptr) {
// Shutting down.
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: resolver disconnected", chand,
gpr_log(GPR_INFO, "chand=%p calld=%p: resolver disconnected", chand,
calld);
}
async_pick_done_locked(
@ -2869,7 +2868,7 @@ static void pick_after_resolver_result_done_locked(void* arg,
.send_initial_metadata_flags;
if (send_initial_metadata_flags & GRPC_INITIAL_METADATA_WAIT_FOR_READY) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: resolver returned but no LB policy; "
"wait_for_ready=true; trying again",
chand, calld);
@ -2877,7 +2876,7 @@ static void pick_after_resolver_result_done_locked(void* arg,
pick_after_resolver_result_start_locked(elem);
} else {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: resolver returned but no LB policy; "
"wait_for_ready=false; failing",
chand, calld);
@ -2890,7 +2889,7 @@ static void pick_after_resolver_result_done_locked(void* arg,
}
} else {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: resolver returned, doing pick",
gpr_log(GPR_INFO, "chand=%p calld=%p: resolver returned, doing pick",
chand, calld);
}
if (pick_callback_start_locked(elem)) {
@ -2908,7 +2907,7 @@ static void pick_after_resolver_result_start_locked(grpc_call_element* elem) {
channel_data* chand = static_cast<channel_data*>(elem->channel_data);
call_data* calld = static_cast<call_data*>(elem->call_data);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: deferring pick pending resolver result", chand,
calld);
}
@ -2975,7 +2974,7 @@ static void cc_start_transport_stream_op_batch(
// If we've previously been cancelled, immediately fail any new batches.
if (calld->cancel_error != GRPC_ERROR_NONE) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: failing batch with error: %s",
gpr_log(GPR_INFO, "chand=%p calld=%p: failing batch with error: %s",
chand, calld, grpc_error_string(calld->cancel_error));
}
// Note: This will release the call combiner.
@ -2994,7 +2993,7 @@ static void cc_start_transport_stream_op_batch(
calld->cancel_error =
GRPC_ERROR_REF(batch->payload->cancel_stream.cancel_error);
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: recording cancel_error=%s", chand,
gpr_log(GPR_INFO, "chand=%p calld=%p: recording cancel_error=%s", chand,
calld, grpc_error_string(calld->cancel_error));
}
// If we do not have a subchannel call (i.e., a pick has not yet
@ -3020,7 +3019,7 @@ static void cc_start_transport_stream_op_batch(
// streaming calls).
if (calld->subchannel_call != nullptr) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: starting batch on subchannel_call=%p", chand,
calld, calld->subchannel_call);
}
@ -3032,7 +3031,7 @@ static void cc_start_transport_stream_op_batch(
// combiner to start a pick.
if (batch->send_initial_metadata) {
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG, "chand=%p calld=%p: entering client_channel combiner",
gpr_log(GPR_INFO, "chand=%p calld=%p: entering client_channel combiner",
chand, calld);
}
GRPC_CLOSURE_SCHED(
@ -3042,7 +3041,7 @@ static void cc_start_transport_stream_op_batch(
} else {
// For all other batches, release the call combiner.
if (grpc_client_channel_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"chand=%p calld=%p: saved batch, yeilding call combiner", chand,
calld);
}

4
src/core/ext/filters/client_channel/lb_policy.cc
Unescape View File

@ -44,13 +44,13 @@ void LoadBalancingPolicy::TryReresolutionLocked(
GRPC_CLOSURE_SCHED(request_reresolution_, error);
request_reresolution_ = nullptr;
if (grpc_lb_trace->enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"%s %p: scheduling re-resolution closure with error=%s.",
grpc_lb_trace->name(), this, grpc_error_string(error));
}
} else {
if (grpc_lb_trace->enabled()) {
gpr_log(GPR_DEBUG, "%s %p: no available re-resolution closure.",
gpr_log(GPR_INFO, "%s %p: no available re-resolution closure.",
grpc_lb_trace->name(), this);
}
}

17
src/core/ext/filters/client_channel/lb_policy/grpclb/grpclb.cc
Unescape View File

@ -1247,7 +1247,7 @@ bool GrpcLb::PickLocked(PickState* pick) {
}
} else { // rr_policy_ == NULL
if (grpc_lb_glb_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"[grpclb %p] No RR policy. Adding to grpclb's pending picks",
this);
}
@ -1413,14 +1413,13 @@ void GrpcLb::OnFallbackTimerLocked(void* arg, grpc_error* error) {
void GrpcLb::StartBalancerCallRetryTimerLocked() {
grpc_millis next_try = lb_call_backoff_.NextAttemptTime();
if (grpc_lb_glb_trace.enabled()) {
gpr_log(GPR_DEBUG, "[grpclb %p] Connection to LB server lost...", this);
gpr_log(GPR_INFO, "[grpclb %p] Connection to LB server lost...", this);
grpc_millis timeout = next_try - ExecCtx::Get()->Now();
if (timeout > 0) {
gpr_log(GPR_DEBUG,
"[grpclb %p] ... retry_timer_active in %" PRIuPTR "ms.", this,
timeout);
gpr_log(GPR_INFO, "[grpclb %p] ... retry_timer_active in %" PRIuPTR "ms.",
this, timeout);
} else {
gpr_log(GPR_DEBUG, "[grpclb %p] ... retry_timer_active immediately.",
gpr_log(GPR_INFO, "[grpclb %p] ... retry_timer_active immediately.",
this);
}
}
@ -1728,7 +1727,7 @@ void GrpcLb::CreateOrUpdateRoundRobinPolicyLocked() {
GPR_ASSERT(args != nullptr);
if (rr_policy_ != nullptr) {
if (grpc_lb_glb_trace.enabled()) {
gpr_log(GPR_DEBUG, "[grpclb %p] Updating RR policy %p", this,
gpr_log(GPR_INFO, "[grpclb %p] Updating RR policy %p", this,
rr_policy_.get());
}
rr_policy_->UpdateLocked(*args);
@ -1739,7 +1738,7 @@ void GrpcLb::CreateOrUpdateRoundRobinPolicyLocked() {
lb_policy_args.args = args;
CreateRoundRobinPolicyLocked(lb_policy_args);
if (grpc_lb_glb_trace.enabled()) {
gpr_log(GPR_DEBUG, "[grpclb %p] Created new RR policy %p", this,
gpr_log(GPR_INFO, "[grpclb %p] Created new RR policy %p", this,
rr_policy_.get());
}
}
@ -1755,7 +1754,7 @@ void GrpcLb::OnRoundRobinRequestReresolutionLocked(void* arg,
}
if (grpc_lb_glb_trace.enabled()) {
gpr_log(
GPR_DEBUG,
GPR_INFO,
"[grpclb %p] Re-resolution requested from the internal RR policy (%p).",
grpclb_policy, grpclb_policy->rr_policy_.get());
}

10
src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc
Unescape View File

@ -95,7 +95,7 @@ PickFirst::PickFirst(const Args& args) : LoadBalancingPolicy(args) {
grpc_connectivity_state_init(&state_tracker_, GRPC_CHANNEL_IDLE,
"pick_first");
if (grpc_lb_pick_first_trace.enabled()) {
gpr_log(GPR_DEBUG, "Pick First %p created.", this);
gpr_log(GPR_INFO, "Pick First %p created.", this);
}
UpdateLocked(*args.args);
grpc_subchannel_index_ref();
@ -103,7 +103,7 @@ PickFirst::PickFirst(const Args& args) : LoadBalancingPolicy(args) {
PickFirst::~PickFirst() {
if (grpc_lb_pick_first_trace.enabled()) {
gpr_log(GPR_DEBUG, "Destroying Pick First %p", this);
gpr_log(GPR_INFO, "Destroying Pick First %p", this);
}
GPR_ASSERT(subchannel_list_ == nullptr);
GPR_ASSERT(latest_pending_subchannel_list_ == nullptr);
@ -126,7 +126,7 @@ void PickFirst::HandOffPendingPicksLocked(LoadBalancingPolicy* new_policy) {
void PickFirst::ShutdownLocked() {
grpc_error* error = GRPC_ERROR_CREATE_FROM_STATIC_STRING("Channel shutdown");
if (grpc_lb_pick_first_trace.enabled()) {
gpr_log(GPR_DEBUG, "Pick First %p Shutting down", this);
gpr_log(GPR_INFO, "Pick First %p Shutting down", this);
}
shutdown_ = true;
PickState* pick;
@ -372,7 +372,7 @@ void PickFirst::UpdateLocked(const grpc_channel_args& args) {
// subchannel list.
if (latest_pending_subchannel_list_ != nullptr) {
if (grpc_lb_pick_first_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"Pick First %p Shutting down latest pending subchannel list "
"%p, about to be replaced by newer latest %p",
this, latest_pending_subchannel_list_, subchannel_list);
@ -396,7 +396,7 @@ void PickFirst::OnConnectivityChangedLocked(void* arg, grpc_error* error) {
grpc_lb_subchannel_data* sd = static_cast<grpc_lb_subchannel_data*>(arg);
PickFirst* p = static_cast<PickFirst*>(sd->subchannel_list->policy);
if (grpc_lb_pick_first_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"Pick First %p connectivity changed for subchannel %p (%" PRIuPTR
" of %" PRIuPTR
"), subchannel_list %p: state=%s p->shutdown_=%d "

31
src/core/ext/filters/client_channel/lb_policy/round_robin/round_robin.cc
Unescape View File

@ -114,7 +114,7 @@ RoundRobin::RoundRobin(const Args& args) : LoadBalancingPolicy(args) {
"round_robin");
UpdateLocked(*args.args);
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(GPR_DEBUG, "[RR %p] Created with %" PRIuPTR " subchannels", this,
gpr_log(GPR_INFO, "[RR %p] Created with %" PRIuPTR " subchannels", this,
subchannel_list_->num_subchannels);
}
grpc_subchannel_index_ref();
@ -122,7 +122,7 @@ RoundRobin::RoundRobin(const Args& args) : LoadBalancingPolicy(args) {
RoundRobin::~RoundRobin() {
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(GPR_DEBUG, "[RR %p] Destroying Round Robin policy", this);
gpr_log(GPR_INFO, "[RR %p] Destroying Round Robin policy", this);
}
GPR_ASSERT(subchannel_list_ == nullptr);
GPR_ASSERT(latest_pending_subchannel_list_ == nullptr);
@ -152,7 +152,7 @@ size_t RoundRobin::GetNextReadySubchannelIndexLocked() {
subchannel_list_->num_subchannels;
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(
GPR_DEBUG,
GPR_INFO,
"[RR %p] checking subchannel %p, subchannel_list %p, index %" PRIuPTR
": state=%s",
this, subchannel_list_->subchannels[index].subchannel,
@ -163,7 +163,7 @@ size_t RoundRobin::GetNextReadySubchannelIndexLocked() {
if (subchannel_list_->subchannels[index].curr_connectivity_state ==
GRPC_CHANNEL_READY) {
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"[RR %p] found next ready subchannel (%p) at index %" PRIuPTR
" of subchannel_list %p",
this, subchannel_list_->subchannels[index].subchannel, index,
@ -173,7 +173,7 @@ size_t RoundRobin::GetNextReadySubchannelIndexLocked() {
}
}
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(GPR_DEBUG, "[RR %p] no subchannels in ready state", this);
gpr_log(GPR_INFO, "[RR %p] no subchannels in ready state", this);
}
return subchannel_list_->num_subchannels;
}
@ -183,7 +183,7 @@ void RoundRobin::UpdateLastReadySubchannelIndexLocked(size_t last_ready_index) {
GPR_ASSERT(last_ready_index < subchannel_list_->num_subchannels);
last_ready_subchannel_index_ = last_ready_index;
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"[RR %p] setting last_ready_subchannel_index=%" PRIuPTR
" (SC %p, CSC %p)",
this, last_ready_index,
@ -207,7 +207,7 @@ void RoundRobin::HandOffPendingPicksLocked(LoadBalancingPolicy* new_policy) {
void RoundRobin::ShutdownLocked() {
grpc_error* error = GRPC_ERROR_CREATE_FROM_STATIC_STRING("Channel shutdown");
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(GPR_DEBUG, "[RR %p] Shutting down", this);
gpr_log(GPR_INFO, "[RR %p] Shutting down", this);
}
shutdown_ = true;
PickState* pick;
@ -311,8 +311,7 @@ void RoundRobin::ExitIdleLocked() {
bool RoundRobin::PickLocked(PickState* pick) {
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(GPR_DEBUG, "[RR %p] Trying to pick (shutdown: %d)", this,
shutdown_);
gpr_log(GPR_INFO, "[RR %p] Trying to pick (shutdown: %d)", this, shutdown_);
}
GPR_ASSERT(!shutdown_);
if (subchannel_list_ != nullptr) {
@ -327,7 +326,7 @@ bool RoundRobin::PickLocked(PickState* pick) {
}
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(
GPR_DEBUG,
GPR_INFO,
"[RR %p] Picked target <-- Subchannel %p (connected %p) (sl %p, "
"index %" PRIuPTR ")",
this, sd->subchannel, pick->connected_subchannel.get(),
@ -416,7 +415,7 @@ void RoundRobin::OnConnectivityChangedLocked(void* arg, grpc_error* error) {
RoundRobin* p = static_cast<RoundRobin*>(sd->subchannel_list->policy);
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(
GPR_DEBUG,
GPR_INFO,
"[RR %p] connectivity changed for subchannel %p, subchannel_list %p: "
"prev_state=%s new_state=%s p->shutdown=%d "
"sd->subchannel_list->shutting_down=%d error=%s",
@ -458,7 +457,7 @@ void RoundRobin::OnConnectivityChangedLocked(void* arg, grpc_error* error) {
case GRPC_CHANNEL_TRANSIENT_FAILURE: {
sd->connected_subchannel.reset();
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"[RR %p] Subchannel %p has gone into TRANSIENT_FAILURE. "
"Requesting re-resolution",
p, sd->subchannel);
@ -483,7 +482,7 @@ void RoundRobin::OnConnectivityChangedLocked(void* arg, grpc_error* error) {
p->subchannel_list_ != nullptr
? p->subchannel_list_->num_subchannels
: 0;
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"[RR %p] phasing out subchannel list %p (size %" PRIuPTR
") in favor of %p (size %" PRIuPTR ")",
p, p->subchannel_list_, num_subchannels, sd->subchannel_list,
@ -517,7 +516,7 @@ void RoundRobin::OnConnectivityChangedLocked(void* arg, grpc_error* error) {
*pick->user_data = selected->user_data;
}
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"[RR %p] Fulfilling pending pick. Target <-- subchannel %p "
"(subchannel_list %p, index %" PRIuPTR ")",
p, selected->subchannel, p->subchannel_list_,
@ -584,7 +583,7 @@ void RoundRobin::UpdateLocked(const grpc_channel_args& args) {
}
grpc_lb_addresses* addresses = (grpc_lb_addresses*)arg->value.pointer.p;
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(GPR_DEBUG, "[RR %p] received update with %" PRIuPTR " addresses",
gpr_log(GPR_INFO, "[RR %p] received update with %" PRIuPTR " addresses",
this, addresses->num_addresses);
}
grpc_lb_subchannel_list* subchannel_list = grpc_lb_subchannel_list_create(
@ -629,7 +628,7 @@ void RoundRobin::UpdateLocked(const grpc_channel_args& args) {
}
if (latest_pending_subchannel_list_ != nullptr) {
if (grpc_lb_round_robin_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"[RR %p] Shutting down latest pending subchannel list %p, "
"about to be replaced by newer latest %p",
this, latest_pending_subchannel_list_, subchannel_list);

22
src/core/ext/filters/client_channel/lb_policy/subchannel_list.cc
Unescape View File

@ -34,7 +34,7 @@ void grpc_lb_subchannel_data_unref_subchannel(grpc_lb_subchannel_data* sd,
const char* reason) {
if (sd->subchannel != nullptr) {
if (sd->subchannel_list->tracer->enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"[%s %p] subchannel list %p index %" PRIuPTR " of %" PRIuPTR
" (subchannel %p): unreffing subchannel",
sd->subchannel_list->tracer->name(), sd->subchannel_list->policy,
@ -57,7 +57,7 @@ void grpc_lb_subchannel_data_start_connectivity_watch(
grpc_lb_subchannel_data* sd) {
if (sd->subchannel_list->tracer->enabled()) {
gpr_log(
GPR_DEBUG,
GPR_INFO,
"[%s %p] subchannel list %p index %" PRIuPTR " of %" PRIuPTR
" (subchannel %p): requesting connectivity change "
"notification (from %s)",
@ -77,7 +77,7 @@ void grpc_lb_subchannel_data_start_connectivity_watch(
void grpc_lb_subchannel_data_stop_connectivity_watch(
grpc_lb_subchannel_data* sd) {
if (sd->subchannel_list->tracer->enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"[%s %p] subchannel list %p index %" PRIuPTR " of %" PRIuPTR
" (subchannel %p): stopping connectivity watch",
sd->subchannel_list->tracer->name(), sd->subchannel_list->policy,
@ -98,7 +98,7 @@ grpc_lb_subchannel_list* grpc_lb_subchannel_list_create(
static_cast<grpc_lb_subchannel_list*>(
gpr_zalloc(sizeof(*subchannel_list)));
if (tracer->enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"[%s %p] Creating subchannel list %p for %" PRIuPTR " subchannels",
tracer->name(), p, subchannel_list, addresses->num_addresses);
}
@ -132,7 +132,7 @@ grpc_lb_subchannel_list* grpc_lb_subchannel_list_create(
if (tracer->enabled()) {
char* address_uri =
grpc_sockaddr_to_uri(&addresses->addresses[i].address);
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"[%s %p] could not create subchannel for address uri %s, "
"ignoring",
tracer->name(), subchannel_list->policy, address_uri);
@ -143,7 +143,7 @@ grpc_lb_subchannel_list* grpc_lb_subchannel_list_create(
if (tracer->enabled()) {
char* address_uri =
grpc_sockaddr_to_uri(&addresses->addresses[i].address);
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"[%s %p] subchannel list %p index %" PRIuPTR
": Created subchannel %p for address uri %s",
tracer->name(), p, subchannel_list, subchannel_index, subchannel,
@ -175,7 +175,7 @@ grpc_lb_subchannel_list* grpc_lb_subchannel_list_create(
static void subchannel_list_destroy(grpc_lb_subchannel_list* subchannel_list) {
if (subchannel_list->tracer->enabled()) {
gpr_log(GPR_DEBUG, "[%s %p] Destroying subchannel_list %p",
gpr_log(GPR_INFO, "[%s %p] Destroying subchannel_list %p",
subchannel_list->tracer->name(), subchannel_list->policy,
subchannel_list);
}
@ -192,7 +192,7 @@ void grpc_lb_subchannel_list_ref(grpc_lb_subchannel_list* subchannel_list,
gpr_ref_non_zero(&subchannel_list->refcount);
if (subchannel_list->tracer->enabled()) {
const gpr_atm count = gpr_atm_acq_load(&subchannel_list->refcount.count);
gpr_log(GPR_DEBUG, "[%s %p] subchannel_list %p REF %lu->%lu (%s)",
gpr_log(GPR_INFO, "[%s %p] subchannel_list %p REF %lu->%lu (%s)",
subchannel_list->tracer->name(), subchannel_list->policy,
subchannel_list, static_cast<unsigned long>(count - 1),
static_cast<unsigned long>(count), reason);
@ -204,7 +204,7 @@ void grpc_lb_subchannel_list_unref(grpc_lb_subchannel_list* subchannel_list,
const bool done = gpr_unref(&subchannel_list->refcount);
if (subchannel_list->tracer->enabled()) {
const gpr_atm count = gpr_atm_acq_load(&subchannel_list->refcount.count);
gpr_log(GPR_DEBUG, "[%s %p] subchannel_list %p UNREF %lu->%lu (%s)",
gpr_log(GPR_INFO, "[%s %p] subchannel_list %p UNREF %lu->%lu (%s)",
subchannel_list->tracer->name(), subchannel_list->policy,
subchannel_list, static_cast<unsigned long>(count + 1),
static_cast<unsigned long>(count), reason);
@ -217,7 +217,7 @@ void grpc_lb_subchannel_list_unref(grpc_lb_subchannel_list* subchannel_list,
static void subchannel_data_cancel_connectivity_watch(
grpc_lb_subchannel_data* sd, const char* reason) {
if (sd->subchannel_list->tracer->enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"[%s %p] subchannel list %p index %" PRIuPTR " of %" PRIuPTR
" (subchannel %p): canceling connectivity watch (%s)",
sd->subchannel_list->tracer->name(), sd->subchannel_list->policy,
@ -232,7 +232,7 @@ static void subchannel_data_cancel_connectivity_watch(
void grpc_lb_subchannel_list_shutdown_and_unref(
grpc_lb_subchannel_list* subchannel_list, const char* reason) {
if (subchannel_list->tracer->enabled()) {
gpr_log(GPR_DEBUG, "[%s %p] Shutting down subchannel_list %p (%s)",
gpr_log(GPR_INFO, "[%s %p] Shutting down subchannel_list %p (%s)",
subchannel_list->tracer->name(), subchannel_list->policy,
subchannel_list, reason);
}

4
src/core/ext/filters/http/message_compress/message_compress_filter.cc
Unescape View File

@ -234,7 +234,7 @@ static void finish_send_message(grpc_call_element* elem) {
static_cast<float>(before_size);
GPR_ASSERT(grpc_message_compression_algorithm_name(
calld->message_compression_algorithm, &algo_name));
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"Compressed[%s] %" PRIuPTR " bytes vs. %" PRIuPTR
" bytes (%.2f%% savings)",
algo_name, before_size, after_size, 100 * savings_ratio);
@ -246,7 +246,7 @@ static void finish_send_message(grpc_call_element* elem) {
const char* algo_name;
GPR_ASSERT(grpc_message_compression_algorithm_name(
calld->message_compression_algorithm, &algo_name));
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"Algorithm '%s' enabled but decided not to compress. Input size: "
"%" PRIuPTR,
algo_name, calld->slices.length);

25
src/core/ext/transport/chttp2/transport/chttp2_transport.cc
Unescape View File

@ -807,7 +807,7 @@ static const char* write_state_name(grpc_chttp2_write_state st) {
static void set_write_state(grpc_chttp2_transport* t,
grpc_chttp2_write_state st, const char* reason) {
GRPC_CHTTP2_IF_TRACING(gpr_log(GPR_DEBUG, "W:%p %s state %s -> %s [%s]", t,
GRPC_CHTTP2_IF_TRACING(gpr_log(GPR_INFO, "W:%p %s state %s -> %s [%s]", t,
t->is_client ? "CLIENT" : "SERVER",
write_state_name(t->write_state),
write_state_name(st), reason));
@ -1072,7 +1072,7 @@ void grpc_chttp2_add_incoming_goaway(grpc_chttp2_transport* t,
uint32_t goaway_error,
grpc_slice goaway_text) {
// GRPC_CHTTP2_IF_TRACING(
// gpr_log(GPR_DEBUG, "got goaway [%d]: %s", goaway_error, msg));
// gpr_log(GPR_INFO, "got goaway [%d]: %s", goaway_error, msg));
// Discard the error from a previous goaway frame (if any)
if (t->goaway_error != GRPC_ERROR_NONE) {
@ -1118,7 +1118,7 @@ static void maybe_start_some_streams(grpc_chttp2_transport* t) {
grpc_chttp2_list_pop_waiting_for_concurrency(t, &s)) {
/* safe since we can't (legally) be parsing this stream yet */
GRPC_CHTTP2_IF_TRACING(gpr_log(
GPR_DEBUG, "HTTP:%s: Allocating new grpc_chttp2_stream %p to id %d",
GPR_INFO, "HTTP:%s: Allocating new grpc_chttp2_stream %p to id %d",
t->is_client ? "CLI" : "SVR", s, t->next_stream_id));
GPR_ASSERT(s->id == 0);
@ -1183,7 +1183,7 @@ void grpc_chttp2_complete_closure_step(grpc_chttp2_transport* t,
if (grpc_http_trace.enabled()) {
const char* errstr = grpc_error_string(error);
gpr_log(
GPR_DEBUG,
GPR_INFO,
"complete_closure_step: t=%p %p refs=%d flags=0x%04x desc=%s err=%s "
"write_state=%s",
t, closure,
@ -1336,7 +1336,7 @@ static void perform_stream_op_locked(void* stream_op,
if (grpc_http_trace.enabled()) {
char* str = grpc_transport_stream_op_batch_string(op);
gpr_log(GPR_DEBUG, "perform_stream_op_locked: %s; on_complete = %p", str,
gpr_log(GPR_INFO, "perform_stream_op_locked: %s; on_complete = %p", str,
op->on_complete);
gpr_free(str);
if (op->send_initial_metadata) {
@ -1638,7 +1638,7 @@ static void perform_stream_op(grpc_transport* gt, grpc_stream* gs,
if (grpc_http_trace.enabled()) {
char* str = grpc_transport_stream_op_batch_string(op);
gpr_log(GPR_DEBUG, "perform_stream_op[s=%p]: %s", s, str);
gpr_log(GPR_INFO, "perform_stream_op[s=%p]: %s", s, str);
gpr_free(str);
}
@ -2529,7 +2529,7 @@ static void schedule_bdp_ping_locked(grpc_chttp2_transport* t) {
static void start_bdp_ping_locked(void* tp, grpc_error* error) {
grpc_chttp2_transport* t = static_cast<grpc_chttp2_transport*>(tp);
if (grpc_http_trace.enabled()) {
gpr_log(GPR_DEBUG, "%s: Start BDP ping err=%s", t->peer_string,
gpr_log(GPR_INFO, "%s: Start BDP ping err=%s", t->peer_string,
grpc_error_string(error));
}
/* Reset the keepalive ping timer */
@ -2542,7 +2542,7 @@ static void start_bdp_ping_locked(void* tp, grpc_error* error) {
static void finish_bdp_ping_locked(void* tp, grpc_error* error) {
grpc_chttp2_transport* t = static_cast<grpc_chttp2_transport*>(tp);
if (grpc_http_trace.enabled()) {
gpr_log(GPR_DEBUG, "%s: Complete BDP ping err=%s", t->peer_string,
gpr_log(GPR_INFO, "%s: Complete BDP ping err=%s", t->peer_string,
grpc_error_string(error));
}
if (error != GRPC_ERROR_NONE) {
@ -2716,8 +2716,7 @@ static void keepalive_watchdog_fired_locked(void* arg, grpc_error* error) {
static void connectivity_state_set(grpc_chttp2_transport* t,
grpc_connectivity_state state,
grpc_error* error, const char* reason) {
GRPC_CHTTP2_IF_TRACING(
gpr_log(GPR_DEBUG, "set connectivity_state=%d", state));
GRPC_CHTTP2_IF_TRACING(gpr_log(GPR_INFO, "set connectivity_state=%d", state));
grpc_connectivity_state_set(&t->channel_callback.state_tracker, state, error,
reason);
}
@ -2984,7 +2983,7 @@ static void benign_reclaimer_locked(void* arg, grpc_error* error) {
/* Channel with no active streams: send a goaway to try and make it
* disconnect cleanly */
if (grpc_resource_quota_trace.enabled()) {
gpr_log(GPR_DEBUG, "HTTP2: %s - send goaway to free memory",
gpr_log(GPR_INFO, "HTTP2: %s - send goaway to free memory",
t->peer_string);
}
send_goaway(t,
@ -2992,7 +2991,7 @@ static void benign_reclaimer_locked(void* arg, grpc_error* error) {
GRPC_ERROR_CREATE_FROM_STATIC_STRING("Buffers full"),
GRPC_ERROR_INT_HTTP2_ERROR, GRPC_HTTP2_ENHANCE_YOUR_CALM));
} else if (error == GRPC_ERROR_NONE && grpc_resource_quota_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"HTTP2: %s - skip benign reclamation, there are still %" PRIdPTR
" streams",
t->peer_string, grpc_chttp2_stream_map_size(&t->stream_map));
@ -3013,7 +3012,7 @@ static void destructive_reclaimer_locked(void* arg, grpc_error* error) {
grpc_chttp2_stream* s = static_cast<grpc_chttp2_stream*>(
grpc_chttp2_stream_map_rand(&t->stream_map));
if (grpc_resource_quota_trace.enabled()) {
gpr_log(GPR_DEBUG, "HTTP2: %s - abandon stream id %d", t->peer_string,
gpr_log(GPR_INFO, "HTTP2: %s - abandon stream id %d", t->peer_string,
s->id);
}
grpc_chttp2_cancel_stream(

6
src/core/ext/transport/chttp2/transport/frame_settings.cc
Unescape View File

@ -217,14 +217,14 @@ grpc_error* grpc_chttp2_settings_parser_parse(void* p, grpc_chttp2_transport* t,
t->initial_window_update += static_cast<int64_t>(parser->value) -
parser->incoming_settings[id];
if (grpc_http_trace.enabled() || grpc_flowctl_trace.enabled()) {
gpr_log(GPR_DEBUG, "%p[%s] adding %d for initial_window change",
t, t->is_client ? "cli" : "svr",
gpr_log(GPR_INFO, "%p[%s] adding %d for initial_window change", t,
t->is_client ? "cli" : "svr",
static_cast<int>(t->initial_window_update));
}
}
parser->incoming_settings[id] = parser->value;
if (grpc_http_trace.enabled()) {
gpr_log(GPR_DEBUG, "CHTTP2:%s:%s: got setting %s = %d",
gpr_log(GPR_INFO, "CHTTP2:%s:%s: got setting %s = %d",
t->is_client ? "CLI" : "SVR", t->peer_string, sp->name,
parser->value);
}

4
src/core/ext/transport/chttp2/transport/hpack_encoder.cc
Unescape View File

@ -470,7 +470,7 @@ static void hpack_enc(grpc_chttp2_hpack_compressor* c, grpc_mdelem elem,
v = grpc_slice_to_c_string(GRPC_MDVALUE(elem));
}
gpr_log(
GPR_DEBUG,
GPR_INFO,
"Encode: '%s: %s', elem_interned=%d [%d], k_interned=%d, v_interned=%d",
k, v, GRPC_MDELEM_IS_INTERNED(elem), GRPC_MDELEM_STORAGE(elem),
grpc_slice_is_interned(GRPC_MDKEY(elem)),
@ -654,7 +654,7 @@ void grpc_chttp2_hpack_compressor_set_max_table_size(
}
c->advertise_table_size_change = 1;
if (grpc_http_trace.enabled()) {
gpr_log(GPR_DEBUG, "set max table size from encoder to %d", max_table_size);
gpr_log(GPR_INFO, "set max table size from encoder to %d", max_table_size);
}
}

2
src/core/ext/transport/chttp2/transport/hpack_parser.cc
Unescape View File

@ -633,7 +633,7 @@ static grpc_error* on_hdr(grpc_chttp2_hpack_parser* p, grpc_mdelem md,
v = grpc_slice_to_c_string(GRPC_MDVALUE(md));
}
gpr_log(
GPR_DEBUG,
GPR_INFO,
"Decode: '%s: %s', elem_interned=%d [%d], k_interned=%d, v_interned=%d",
k, v, GRPC_MDELEM_IS_INTERNED(md), GRPC_MDELEM_STORAGE(md),
grpc_slice_is_interned(GRPC_MDKEY(md)),

4
src/core/ext/transport/chttp2/transport/hpack_table.cc
Unescape View File

@ -247,7 +247,7 @@ void grpc_chttp2_hptbl_set_max_bytes(grpc_chttp2_hptbl* tbl,
return;
}
if (grpc_http_trace.enabled()) {
gpr_log(GPR_DEBUG, "Update hpack parser max size to %d", max_bytes);
gpr_log(GPR_INFO, "Update hpack parser max size to %d", max_bytes);
}
while (tbl->mem_used > max_bytes) {
evict1(tbl);
@ -270,7 +270,7 @@ grpc_error* grpc_chttp2_hptbl_set_current_table_size(grpc_chttp2_hptbl* tbl,
return err;
}
if (grpc_http_trace.enabled()) {
gpr_log(GPR_DEBUG, "Update hpack parser table size to %d", bytes);
gpr_log(GPR_INFO, "Update hpack parser table size to %d", bytes);
}
while (tbl->mem_used > bytes) {
evict1(tbl);

6
src/core/ext/transport/chttp2/transport/stream_lists.cc
Unescape View File

@ -68,7 +68,7 @@ static bool stream_list_pop(grpc_chttp2_transport* t,
}
*stream = s;
if (s && grpc_trace_http2_stream_state.enabled()) {
gpr_log(GPR_DEBUG, "%p[%d][%s]: pop from %s", t, s->id,
gpr_log(GPR_INFO, "%p[%d][%s]: pop from %s", t, s->id,
t->is_client ? "cli" : "svr", stream_list_id_string(id));
}
return s != nullptr;
@ -90,7 +90,7 @@ static void stream_list_remove(grpc_chttp2_transport* t, grpc_chttp2_stream* s,
t->lists[id].tail = s->links[id].prev;
}
if (grpc_trace_http2_stream_state.enabled()) {
gpr_log(GPR_DEBUG, "%p[%d][%s]: remove from %s", t, s->id,
gpr_log(GPR_INFO, "%p[%d][%s]: remove from %s", t, s->id,
t->is_client ? "cli" : "svr", stream_list_id_string(id));
}
}
@ -122,7 +122,7 @@ static void stream_list_add_tail(grpc_chttp2_transport* t,
t->lists[id].tail = s;
s->included[id] = 1;
if (grpc_trace_http2_stream_state.enabled()) {
gpr_log(GPR_DEBUG, "%p[%d][%s]: add to %s", t, s->id,
gpr_log(GPR_INFO, "%p[%d][%s]: add to %s", t, s->id,
t->is_client ? "cli" : "svr", stream_list_id_string(id));
}
}

10
src/core/ext/transport/chttp2/transport/writing.cc
Unescape View File

@ -52,7 +52,7 @@ static void maybe_initiate_ping(grpc_chttp2_transport* t) {
if (!grpc_closure_list_empty(pq->lists[GRPC_CHTTP2_PCL_INFLIGHT])) {
/* ping already in-flight: wait */
if (grpc_http_trace.enabled() || grpc_bdp_estimator_trace.enabled()) {
gpr_log(GPR_DEBUG, "%s: Ping delayed [%p]: already pinging",
gpr_log(GPR_INFO, "%s: Ping delayed [%p]: already pinging",
t->is_client ? "CLIENT" : "SERVER", t->peer_string);
}
return;
@ -61,7 +61,7 @@ static void maybe_initiate_ping(grpc_chttp2_transport* t) {
t->ping_policy.max_pings_without_data != 0) {
/* need to receive something of substance before sending a ping again */
if (grpc_http_trace.enabled() || grpc_bdp_estimator_trace.enabled()) {
gpr_log(GPR_DEBUG, "%s: Ping delayed [%p]: too many recent pings: %d/%d",
gpr_log(GPR_INFO, "%s: Ping delayed [%p]: too many recent pings: %d/%d",
t->is_client ? "CLIENT" : "SERVER", t->peer_string,
t->ping_state.pings_before_data_required,
t->ping_policy.max_pings_without_data);
@ -81,7 +81,7 @@ static void maybe_initiate_ping(grpc_chttp2_transport* t) {
if (next_allowed_ping > now) {
/* not enough elapsed time between successive pings */
if (grpc_http_trace.enabled() || grpc_bdp_estimator_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"%s: Ping delayed [%p]: not enough time elapsed since last ping. "
" Last ping %f: Next ping %f: Now %f",
t->is_client ? "CLIENT" : "SERVER", t->peer_string,
@ -107,7 +107,7 @@ static void maybe_initiate_ping(grpc_chttp2_transport* t) {
GRPC_STATS_INC_HTTP2_PINGS_SENT();
t->ping_state.last_ping_sent_time = now;
if (grpc_http_trace.enabled() || grpc_bdp_estimator_trace.enabled()) {
gpr_log(GPR_DEBUG, "%s: Ping sent [%p]: %d/%d",
gpr_log(GPR_INFO, "%s: Ping sent [%p]: %d/%d",
t->is_client ? "CLIENT" : "SERVER", t->peer_string,
t->ping_state.pings_before_data_required,
t->ping_policy.max_pings_without_data);
@ -401,7 +401,7 @@ class StreamWriteContext {
StreamWriteContext(WriteContext* write_context, grpc_chttp2_stream* s)
: write_context_(write_context), t_(write_context->transport()), s_(s) {
GRPC_CHTTP2_IF_TRACING(
gpr_log(GPR_DEBUG, "W:%p %s[%d] im-(sent,send)=(%d,%d) announce=%d", t_,
gpr_log(GPR_INFO, "W:%p %s[%d] im-(sent,send)=(%d,%d) announce=%d", t_,
t_->is_client ? "CLIENT" : "SERVER", s->id,
s->sent_initial_metadata, s->send_initial_metadata != nullptr,
(int)(s->flow_control->local_window_delta() -

84
src/core/ext/transport/inproc/inproc_transport.cc
Unescape View File

@ -125,12 +125,12 @@ static bool cancel_stream_locked(inproc_stream* s, grpc_error* error);
static void op_state_machine(void* arg, grpc_error* error);
static void ref_transport(inproc_transport* t) {
INPROC_LOG(GPR_DEBUG, "ref_transport %p", t);
INPROC_LOG(GPR_INFO, "ref_transport %p", t);
gpr_ref(&t->refs);
}
static void really_destroy_transport(inproc_transport* t) {
INPROC_LOG(GPR_DEBUG, "really_destroy_transport %p", t);
INPROC_LOG(GPR_INFO, "really_destroy_transport %p", t);
grpc_connectivity_state_destroy(&t->connectivity);
if (gpr_unref(&t->mu->refs)) {
gpr_free(t->mu);
@ -139,7 +139,7 @@ static void really_destroy_transport(inproc_transport* t) {
}
static void unref_transport(inproc_transport* t) {
INPROC_LOG(GPR_DEBUG, "unref_transport %p", t);
INPROC_LOG(GPR_INFO, "unref_transport %p", t);
if (gpr_unref(&t->refs)) {
really_destroy_transport(t);
}
@ -154,17 +154,17 @@ static void unref_transport(inproc_transport* t) {
#endif
static void ref_stream(inproc_stream* s, const char* reason) {
INPROC_LOG(GPR_DEBUG, "ref_stream %p %s", s, reason);
INPROC_LOG(GPR_INFO, "ref_stream %p %s", s, reason);
STREAM_REF(s->refs, reason);
}
static void unref_stream(inproc_stream* s, const char* reason) {
INPROC_LOG(GPR_DEBUG, "unref_stream %p %s", s, reason);
INPROC_LOG(GPR_INFO, "unref_stream %p %s", s, reason);
STREAM_UNREF(s->refs, reason);
}
static void really_destroy_stream(inproc_stream* s) {
INPROC_LOG(GPR_DEBUG, "really_destroy_stream %p", s);
INPROC_LOG(GPR_INFO, "really_destroy_stream %p", s);
GRPC_ERROR_UNREF(s->write_buffer_cancel_error);
GRPC_ERROR_UNREF(s->cancel_self_error);
@ -225,7 +225,7 @@ static grpc_error* fill_in_metadata(inproc_stream* s,
static int init_stream(grpc_transport* gt, grpc_stream* gs,
grpc_stream_refcount* refcount, const void* server_data,
gpr_arena* arena) {
INPROC_LOG(GPR_DEBUG, "init_stream %p %p %p", gt, gs, server_data);
INPROC_LOG(GPR_INFO, "init_stream %p %p %p", gt, gs, server_data);
inproc_transport* t = reinterpret_cast<inproc_transport*>(gt);
inproc_stream* s = reinterpret_cast<inproc_stream*>(gs);
s->arena = arena;
@ -282,8 +282,8 @@ static int init_stream(grpc_transport* gt, grpc_stream* gs,
// Pass the client-side stream address to the server-side for a ref
ref_stream(s, "inproc_init_stream:clt"); // ref it now on behalf of server
// side to avoid destruction
INPROC_LOG(GPR_DEBUG, "calling accept stream cb %p %p",
st->accept_stream_cb, st->accept_stream_data);
INPROC_LOG(GPR_INFO, "calling accept stream cb %p %p", st->accept_stream_cb,
st->accept_stream_data);
(*st->accept_stream_cb)(st->accept_stream_data, &st->base, (void*)s);
} else {
// This is the server-side and is being called through accept_stream_cb
@ -378,7 +378,7 @@ static void complete_if_batch_end_locked(inproc_stream* s, grpc_error* error,
int is_rtm = static_cast<int>(op == s->recv_trailing_md_op);
if ((is_sm + is_stm + is_rim + is_rm + is_rtm) == 1) {
INPROC_LOG(GPR_DEBUG, "%s %p %p %p", msg, s, op, error);
INPROC_LOG(GPR_INFO, "%s %p %p %p", msg, s, op, error);
GRPC_CLOSURE_SCHED(op->on_complete, GRPC_ERROR_REF(error));
}
}
@ -393,7 +393,7 @@ static void maybe_schedule_op_closure_locked(inproc_stream* s,
}
static void fail_helper_locked(inproc_stream* s, grpc_error* error) {
INPROC_LOG(GPR_DEBUG, "op_state_machine %p fail_helper", s);
INPROC_LOG(GPR_INFO, "op_state_machine %p fail_helper", s);
// If we're failing this side, we need to make sure that
// we also send or have already sent trailing metadata
if (!s->trailing_md_sent) {
@ -458,7 +458,7 @@ static void fail_helper_locked(inproc_stream* s, grpc_error* error) {
*s->recv_initial_md_op->payload->recv_initial_metadata
.trailing_metadata_available = true;
}
INPROC_LOG(GPR_DEBUG,
INPROC_LOG(GPR_INFO,
"fail_helper %p scheduling initial-metadata-ready %p %p", s,
error, err);
GRPC_CLOSURE_SCHED(s->recv_initial_md_op->payload->recv_initial_metadata
@ -472,7 +472,7 @@ static void fail_helper_locked(inproc_stream* s, grpc_error* error) {
s->recv_initial_md_op = nullptr;
}
if (s->recv_message_op) {
INPROC_LOG(GPR_DEBUG, "fail_helper %p scheduling message-ready %p", s,
INPROC_LOG(GPR_INFO, "fail_helper %p scheduling message-ready %p", s,
error);
GRPC_CLOSURE_SCHED(
s->recv_message_op->payload->recv_message.recv_message_ready,
@ -496,9 +496,8 @@ static void fail_helper_locked(inproc_stream* s, grpc_error* error) {
s->send_trailing_md_op = nullptr;
}
if (s->recv_trailing_md_op) {
INPROC_LOG(GPR_DEBUG,
"fail_helper %p scheduling trailing-md-on-complete %p", s,
error);
INPROC_LOG(GPR_INFO, "fail_helper %p scheduling trailing-md-on-complete %p",
s, error);
complete_if_batch_end_locked(
s, error, s->recv_trailing_md_op,
"fail_helper scheduling recv-trailing-metadata-on-complete");
@ -549,7 +548,7 @@ static void message_transfer_locked(inproc_stream* sender,
receiver->recv_stream.Init(&receiver->recv_message, 0);
receiver->recv_message_op->payload->recv_message.recv_message->reset(
receiver->recv_stream.get());
INPROC_LOG(GPR_DEBUG, "message_transfer_locked %p scheduling message-ready",
INPROC_LOG(GPR_INFO, "message_transfer_locked %p scheduling message-ready",
receiver);
GRPC_CLOSURE_SCHED(
receiver->recv_message_op->payload->recv_message.recv_message_ready,
@ -577,7 +576,7 @@ static void op_state_machine(void* arg, grpc_error* error) {
bool needs_close = false;
INPROC_LOG(GPR_DEBUG, "op_state_machine %p", arg);
INPROC_LOG(GPR_INFO, "op_state_machine %p", arg);
inproc_stream* s = static_cast<inproc_stream*>(arg);
gpr_mu* mu = &s->t->mu->mu; // keep aside in case s gets closed
gpr_mu_lock(mu);
@ -626,7 +625,7 @@ static void op_state_machine(void* arg, grpc_error* error) {
: &other->to_read_trailing_md_filled;
if (*destfilled || s->trailing_md_sent) {
// The buffer is already in use; that's an error!
INPROC_LOG(GPR_DEBUG, "Extra trailing metadata %p", s);
INPROC_LOG(GPR_INFO, "Extra trailing metadata %p", s);
new_err = GRPC_ERROR_CREATE_FROM_STATIC_STRING("Extra trailing metadata");
fail_helper_locked(s, GRPC_ERROR_REF(new_err));
goto done;
@ -639,7 +638,7 @@ static void op_state_machine(void* arg, grpc_error* error) {
}
s->trailing_md_sent = true;
if (!s->t->is_client && s->trailing_md_recvd && s->recv_trailing_md_op) {
INPROC_LOG(GPR_DEBUG,
INPROC_LOG(GPR_INFO,
"op_state_machine %p scheduling trailing-md-on-complete", s);
GRPC_CLOSURE_SCHED(s->recv_trailing_md_op->on_complete,
GRPC_ERROR_NONE);
@ -658,7 +657,7 @@ static void op_state_machine(void* arg, grpc_error* error) {
new_err =
GRPC_ERROR_CREATE_FROM_STATIC_STRING("Already recvd initial md");
INPROC_LOG(
GPR_DEBUG,
GPR_INFO,
"op_state_machine %p scheduling on_complete errors for already "
"recvd initial md %p",
s, new_err);
@ -684,7 +683,7 @@ static void op_state_machine(void* arg, grpc_error* error) {
}
grpc_metadata_batch_clear(&s->to_read_initial_md);
s->to_read_initial_md_filled = false;
INPROC_LOG(GPR_DEBUG,
INPROC_LOG(GPR_INFO,
"op_state_machine %p scheduling initial-metadata-ready %p", s,
new_err);
GRPC_CLOSURE_SCHED(s->recv_initial_md_op->payload->recv_initial_metadata
@ -696,7 +695,7 @@ static void op_state_machine(void* arg, grpc_error* error) {
s->recv_initial_md_op = nullptr;
if (new_err != GRPC_ERROR_NONE) {
INPROC_LOG(GPR_DEBUG,
INPROC_LOG(GPR_INFO,
"op_state_machine %p scheduling on_complete errors2 %p", s,
new_err);
fail_helper_locked(s, GRPC_ERROR_REF(new_err));
@ -719,7 +718,7 @@ static void op_state_machine(void* arg, grpc_error* error) {
new_err =
GRPC_ERROR_CREATE_FROM_STATIC_STRING("Already recvd trailing md");
INPROC_LOG(
GPR_DEBUG,
GPR_INFO,
"op_state_machine %p scheduling on_complete errors for already "
"recvd trailing md %p",
s, new_err);
@ -729,7 +728,7 @@ static void op_state_machine(void* arg, grpc_error* error) {
if (s->recv_message_op != nullptr) {
// This message needs to be wrapped up because it will never be
// satisfied
INPROC_LOG(GPR_DEBUG, "op_state_machine %p scheduling message-ready", s);
INPROC_LOG(GPR_INFO, "op_state_machine %p scheduling message-ready", s);
GRPC_CLOSURE_SCHED(
s->recv_message_op->payload->recv_message.recv_message_ready,
GRPC_ERROR_NONE);
@ -764,7 +763,7 @@ static void op_state_machine(void* arg, grpc_error* error) {
// (If the server hasn't already sent its trailing md, it doesn't have
// a final status, so don't mark this op complete)
if (s->t->is_client || s->trailing_md_sent) {
INPROC_LOG(GPR_DEBUG,
INPROC_LOG(GPR_INFO,
"op_state_machine %p scheduling trailing-md-on-complete %p",
s, new_err);
GRPC_CLOSURE_SCHED(s->recv_trailing_md_op->on_complete,
@ -772,21 +771,21 @@ static void op_state_machine(void* arg, grpc_error* error) {
s->recv_trailing_md_op = nullptr;
needs_close = true;
} else {
INPROC_LOG(GPR_DEBUG,
INPROC_LOG(GPR_INFO,
"op_state_machine %p server needs to delay handling "
"trailing-md-on-complete %p",
s, new_err);
}
} else {
INPROC_LOG(
GPR_DEBUG,
GPR_INFO,
"op_state_machine %p has trailing md but not yet waiting for it", s);
}
}
if (s->trailing_md_recvd && s->recv_message_op) {
// No further message will come on this stream, so finish off the
// recv_message_op
INPROC_LOG(GPR_DEBUG, "op_state_machine %p scheduling message-ready", s);
INPROC_LOG(GPR_INFO, "op_state_machine %p scheduling message-ready", s);
GRPC_CLOSURE_SCHED(
s->recv_message_op->payload->recv_message.recv_message_ready,
GRPC_ERROR_NONE);
@ -810,7 +809,7 @@ static void op_state_machine(void* arg, grpc_error* error) {
// Didn't get the item we wanted so we still need to get
// rescheduled
INPROC_LOG(
GPR_DEBUG, "op_state_machine %p still needs closure %p %p %p %p %p", s,
GPR_INFO, "op_state_machine %p still needs closure %p %p %p %p %p", s,
s->send_message_op, s->send_trailing_md_op, s->recv_initial_md_op,
s->recv_message_op, s->recv_trailing_md_op);
s->ops_needed = true;
@ -826,8 +825,7 @@ done:
static bool cancel_stream_locked(inproc_stream* s, grpc_error* error) {
bool ret = false; // was the cancel accepted
INPROC_LOG(GPR_DEBUG, "cancel_stream %p with %s", s,
grpc_error_string(error));
INPROC_LOG(GPR_INFO, "cancel_stream %p with %s", s, grpc_error_string(error));
if (s->cancel_self_error == GRPC_ERROR_NONE) {
ret = true;
s->cancel_self_error = GRPC_ERROR_REF(error);
@ -877,7 +875,7 @@ static bool cancel_stream_locked(inproc_stream* s, grpc_error* error) {
static void perform_stream_op(grpc_transport* gt, grpc_stream* gs,
grpc_transport_stream_op_batch* op) {
INPROC_LOG(GPR_DEBUG, "perform_stream_op %p %p %p", gt, gs, op);
INPROC_LOG(GPR_INFO, "perform_stream_op %p %p %p", gt, gs, op);
inproc_stream* s = reinterpret_cast<inproc_stream*>(gs);
gpr_mu* mu = &s->t->mu->mu; // save aside in case s gets closed
gpr_mu_lock(mu);
@ -907,7 +905,7 @@ static void perform_stream_op(grpc_transport* gt, grpc_stream* gs,
// already self-canceled so still give it an error
error = GRPC_ERROR_REF(s->cancel_self_error);
} else {
INPROC_LOG(GPR_DEBUG, "perform_stream_op %p %s%s%s%s%s%s%s", s,
INPROC_LOG(GPR_INFO, "perform_stream_op %p %s%s%s%s%s%s%s", s,
s->t->is_client ? "client" : "server",
op->send_initial_metadata ? " send_initial_metadata" : "",
op->send_message ? " send_message" : "",
@ -936,7 +934,7 @@ static void perform_stream_op(grpc_transport* gt, grpc_stream* gs,
: &other->to_read_initial_md_filled;
if (*destfilled || s->initial_md_sent) {
// The buffer is already in use; that's an error!
INPROC_LOG(GPR_DEBUG, "Extra initial metadata %p", s);
INPROC_LOG(GPR_INFO, "Extra initial metadata %p", s);
error = GRPC_ERROR_CREATE_FROM_STATIC_STRING("Extra initial metadata");
} else {
if (!other || !other->closed) {
@ -1013,7 +1011,7 @@ static void perform_stream_op(grpc_transport* gt, grpc_stream* gs,
true;
}
INPROC_LOG(
GPR_DEBUG,
GPR_INFO,
"perform_stream_op error %p scheduling initial-metadata-ready %p",
s, error);
GRPC_CLOSURE_SCHED(
@ -1022,14 +1020,14 @@ static void perform_stream_op(grpc_transport* gt, grpc_stream* gs,
}
if (op->recv_message) {
INPROC_LOG(
GPR_DEBUG,
GPR_INFO,
"perform_stream_op error %p scheduling recv message-ready %p", s,
error);
GRPC_CLOSURE_SCHED(op->payload->recv_message.recv_message_ready,
GRPC_ERROR_REF(error));
}
}
INPROC_LOG(GPR_DEBUG, "perform_stream_op %p scheduling on_complete %p", s,
INPROC_LOG(GPR_INFO, "perform_stream_op %p scheduling on_complete %p", s,
error);
GRPC_CLOSURE_SCHED(on_complete, GRPC_ERROR_REF(error));
}
@ -1042,7 +1040,7 @@ static void perform_stream_op(grpc_transport* gt, grpc_stream* gs,
}
static void close_transport_locked(inproc_transport* t) {
INPROC_LOG(GPR_DEBUG, "close_transport %p %d", t, t->is_closed);
INPROC_LOG(GPR_INFO, "close_transport %p %d", t, t->is_closed);
grpc_connectivity_state_set(
&t->connectivity, GRPC_CHANNEL_SHUTDOWN,
GRPC_ERROR_CREATE_FROM_STATIC_STRING("Closing transport."),
@ -1063,7 +1061,7 @@ static void close_transport_locked(inproc_transport* t) {
static void perform_transport_op(grpc_transport* gt, grpc_transport_op* op) {
inproc_transport* t = reinterpret_cast<inproc_transport*>(gt);
INPROC_LOG(GPR_DEBUG, "perform_transport_op %p %p", t, op);
INPROC_LOG(GPR_INFO, "perform_transport_op %p %p", t, op);
gpr_mu_lock(&t->mu->mu);
if (op->on_connectivity_state_change) {
grpc_connectivity_state_notify_on_state_change(
@ -1096,7 +1094,7 @@ static void perform_transport_op(grpc_transport* gt, grpc_transport_op* op) {
static void destroy_stream(grpc_transport* gt, grpc_stream* gs,
grpc_closure* then_schedule_closure) {
INPROC_LOG(GPR_DEBUG, "destroy_stream %p %p", gs, then_schedule_closure);
INPROC_LOG(GPR_INFO, "destroy_stream %p %p", gs, then_schedule_closure);
inproc_stream* s = reinterpret_cast<inproc_stream*>(gs);
s->closure_at_destroy = then_schedule_closure;
really_destroy_stream(s);
@ -1104,7 +1102,7 @@ static void destroy_stream(grpc_transport* gt, grpc_stream* gs,
static void destroy_transport(grpc_transport* gt) {
inproc_transport* t = reinterpret_cast<inproc_transport*>(gt);
INPROC_LOG(GPR_DEBUG, "destroy_transport %p", t);
INPROC_LOG(GPR_INFO, "destroy_transport %p", t);
gpr_mu_lock(&t->mu->mu);
close_transport_locked(t);
gpr_mu_unlock(&t->mu->mu);
@ -1165,7 +1163,7 @@ static void inproc_transports_create(grpc_transport** server_transport,
const grpc_channel_args* server_args,
grpc_transport** client_transport,
const grpc_channel_args* client_args) {
INPROC_LOG(GPR_DEBUG, "inproc_transports_create");
INPROC_LOG(GPR_INFO, "inproc_transports_create");
inproc_transport* st =
static_cast<inproc_transport*>(gpr_zalloc(sizeof(*st)));
inproc_transport* ct =

8
src/core/lib/channel/handshaker.cc
Unescape View File

@ -137,7 +137,7 @@ void grpc_handshake_manager_add(grpc_handshake_manager* mgr,
grpc_handshaker* handshaker) {
if (grpc_handshaker_trace.enabled()) {
gpr_log(
GPR_DEBUG,
GPR_INFO,
"handshake_manager %p: adding handshaker %s [%p] at index %" PRIuPTR,
mgr, grpc_handshaker_name(handshaker), handshaker, mgr->count);
}
@ -208,7 +208,7 @@ static bool call_next_handshaker_locked(grpc_handshake_manager* mgr,
grpc_error* error) {
if (grpc_handshaker_trace.enabled()) {
char* args_str = handshaker_args_string(&mgr->args);
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"handshake_manager %p: error=%s shutdown=%d index=%" PRIuPTR
", args=%s",
mgr, grpc_error_string(error), mgr->shutdown, mgr->index, args_str);
@ -221,7 +221,7 @@ static bool call_next_handshaker_locked(grpc_handshake_manager* mgr,
if (error != GRPC_ERROR_NONE || mgr->shutdown || mgr->args.exit_early ||
mgr->index == mgr->count) {
if (grpc_handshaker_trace.enabled()) {
gpr_log(GPR_DEBUG, "handshake_manager %p: handshaking complete", mgr);
gpr_log(GPR_INFO, "handshake_manager %p: handshaking complete", mgr);
}
// Cancel deadline timer, since we're invoking the on_handshake_done
// callback now.
@ -231,7 +231,7 @@ static bool call_next_handshaker_locked(grpc_handshake_manager* mgr,
} else {
if (grpc_handshaker_trace.enabled()) {
gpr_log(
GPR_DEBUG,
GPR_INFO,
"handshake_manager %p: calling handshaker %s [%p] at index %" PRIuPTR,
mgr, grpc_handshaker_name(mgr->handshakers[mgr->index]),
mgr->handshakers[mgr->index], mgr->index);

4
src/core/lib/gprpp/orphanable.h
Unescape View File

@ -159,7 +159,7 @@ class InternallyRefCountedWithTracing : public Orphanable {
const char* reason) GRPC_MUST_USE_RESULT {
if (location.Log() && trace_flag_ != nullptr && trace_flag_->enabled()) {
gpr_atm old_refs = gpr_atm_no_barrier_load(&refs_.count);
gpr_log(GPR_DEBUG, "%s:%p %s:%d ref %" PRIdPTR " -> %" PRIdPTR " %s",
gpr_log(GPR_INFO, "%s:%p %s:%d ref %" PRIdPTR " -> %" PRIdPTR " %s",
trace_flag_->name(), this, location.file(), location.line(),
old_refs, old_refs + 1, reason);
}
@ -180,7 +180,7 @@ class InternallyRefCountedWithTracing : public Orphanable {
void Unref(const DebugLocation& location, const char* reason) {
if (location.Log() && trace_flag_ != nullptr && trace_flag_->enabled()) {
gpr_atm old_refs = gpr_atm_no_barrier_load(&refs_.count);
gpr_log(GPR_DEBUG, "%s:%p %s:%d unref %" PRIdPTR " -> %" PRIdPTR " %s",
gpr_log(GPR_INFO, "%s:%p %s:%d unref %" PRIdPTR " -> %" PRIdPTR " %s",
trace_flag_->name(), this, location.file(), location.line(),
old_refs, old_refs - 1, reason);
}

4
src/core/lib/gprpp/ref_counted.h
Unescape View File

@ -100,7 +100,7 @@ class RefCountedWithTracing {
const char* reason) GRPC_MUST_USE_RESULT {
if (location.Log() && trace_flag_ != nullptr && trace_flag_->enabled()) {
gpr_atm old_refs = gpr_atm_no_barrier_load(&refs_.count);
gpr_log(GPR_DEBUG, "%s:%p %s:%d ref %" PRIdPTR " -> %" PRIdPTR " %s",
gpr_log(GPR_INFO, "%s:%p %s:%d ref %" PRIdPTR " -> %" PRIdPTR " %s",
trace_flag_->name(), this, location.file(), location.line(),
old_refs, old_refs + 1, reason);
}
@ -121,7 +121,7 @@ class RefCountedWithTracing {
void Unref(const DebugLocation& location, const char* reason) {
if (location.Log() && trace_flag_ != nullptr && trace_flag_->enabled()) {
gpr_atm old_refs = gpr_atm_no_barrier_load(&refs_.count);
gpr_log(GPR_DEBUG, "%s:%p %s:%d unref %" PRIdPTR " -> %" PRIdPTR " %s",
gpr_log(GPR_INFO, "%s:%p %s:%d unref %" PRIdPTR " -> %" PRIdPTR " %s",
trace_flag_->name(), this, location.file(), location.line(),
old_refs, old_refs - 1, reason);
}

26
src/core/lib/iomgr/call_combiner.cc
Unescape View File

@ -64,7 +64,7 @@ void grpc_call_combiner_start(grpc_call_combiner* call_combiner,
const char* reason) {
GPR_TIMER_SCOPE("call_combiner_start", 0);
if (grpc_call_combiner_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"==> grpc_call_combiner_start() [%p] closure=%p [" DEBUG_FMT_STR
"%s] error=%s",
call_combiner, closure DEBUG_FMT_ARGS, reason,
@ -73,7 +73,7 @@ void grpc_call_combiner_start(grpc_call_combiner* call_combiner,
size_t prev_size = static_cast<size_t>(
gpr_atm_full_fetch_add(&call_combiner->size, (gpr_atm)1));
if (grpc_call_combiner_trace.enabled()) {
gpr_log(GPR_DEBUG, " size: %" PRIdPTR " -> %" PRIdPTR, prev_size,
gpr_log(GPR_INFO, " size: %" PRIdPTR " -> %" PRIdPTR, prev_size,
prev_size + 1);
}
GRPC_STATS_INC_CALL_COMBINER_LOCKS_SCHEDULED_ITEMS();
@ -82,7 +82,7 @@ void grpc_call_combiner_start(grpc_call_combiner* call_combiner,
GPR_TIMER_MARK("call_combiner_initiate", 0);
if (grpc_call_combiner_trace.enabled()) {
gpr_log(GPR_DEBUG, " EXECUTING IMMEDIATELY");
gpr_log(GPR_INFO, " EXECUTING IMMEDIATELY");
}
// Queue was empty, so execute this closure immediately.
GRPC_CLOSURE_SCHED(closure, error);
@ -101,21 +101,21 @@ void grpc_call_combiner_stop(grpc_call_combiner* call_combiner DEBUG_ARGS,
const char* reason) {
GPR_TIMER_SCOPE("call_combiner_stop", 0);
if (grpc_call_combiner_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"==> grpc_call_combiner_stop() [%p] [" DEBUG_FMT_STR "%s]",
call_combiner DEBUG_FMT_ARGS, reason);
}
size_t prev_size = static_cast<size_t>(
gpr_atm_full_fetch_add(&call_combiner->size, (gpr_atm)-1));
if (grpc_call_combiner_trace.enabled()) {
gpr_log(GPR_DEBUG, " size: %" PRIdPTR " -> %" PRIdPTR, prev_size,
gpr_log(GPR_INFO, " size: %" PRIdPTR " -> %" PRIdPTR, prev_size,
prev_size - 1);
}
GPR_ASSERT(prev_size >= 1);
if (prev_size > 1) {
while (true) {
if (grpc_call_combiner_trace.enabled()) {
gpr_log(GPR_DEBUG, " checking queue");
gpr_log(GPR_INFO, " checking queue");
}
bool empty;
grpc_closure* closure = reinterpret_cast<grpc_closure*>(
@ -124,19 +124,19 @@ void grpc_call_combiner_stop(grpc_call_combiner* call_combiner DEBUG_ARGS,
// This can happen either due to a race condition within the mpscq
// code or because of a race with grpc_call_combiner_start().
if (grpc_call_combiner_trace.enabled()) {
gpr_log(GPR_DEBUG, " queue returned no result; checking again");
gpr_log(GPR_INFO, " queue returned no result; checking again");
}
continue;
}
if (grpc_call_combiner_trace.enabled()) {
gpr_log(GPR_DEBUG, " EXECUTING FROM QUEUE: closure=%p error=%s",
gpr_log(GPR_INFO, " EXECUTING FROM QUEUE: closure=%p error=%s",
closure, grpc_error_string(closure->error_data.error));
}
GRPC_CLOSURE_SCHED(closure, closure->error_data.error);
break;
}
} else if (grpc_call_combiner_trace.enabled()) {
gpr_log(GPR_DEBUG, " queue empty");
gpr_log(GPR_INFO, " queue empty");
}
}
@ -151,7 +151,7 @@ void grpc_call_combiner_set_notify_on_cancel(grpc_call_combiner* call_combiner,
// Otherwise, store the new closure.
if (original_error != GRPC_ERROR_NONE) {
if (grpc_call_combiner_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"call_combiner=%p: scheduling notify_on_cancel callback=%p "
"for pre-existing cancellation",
call_combiner, closure);
@ -162,7 +162,7 @@ void grpc_call_combiner_set_notify_on_cancel(grpc_call_combiner* call_combiner,
if (gpr_atm_full_cas(&call_combiner->cancel_state, original_state,
(gpr_atm)closure)) {
if (grpc_call_combiner_trace.enabled()) {
gpr_log(GPR_DEBUG, "call_combiner=%p: setting notify_on_cancel=%p",
gpr_log(GPR_INFO, "call_combiner=%p: setting notify_on_cancel=%p",
call_combiner, closure);
}
// If we replaced an earlier closure, invoke the original
@ -171,7 +171,7 @@ void grpc_call_combiner_set_notify_on_cancel(grpc_call_combiner* call_combiner,
if (original_state != 0) {
closure = (grpc_closure*)original_state;
if (grpc_call_combiner_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"call_combiner=%p: scheduling old cancel callback=%p",
call_combiner, closure);
}
@ -199,7 +199,7 @@ void grpc_call_combiner_cancel(grpc_call_combiner* call_combiner,
if (original_state != 0) {
grpc_closure* notify_on_cancel = (grpc_closure*)original_state;
if (grpc_call_combiner_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"call_combiner=%p: scheduling notify_on_cancel callback=%p",
call_combiner, notify_on_cancel);
}

22
src/core/lib/iomgr/combiner.cc
Unescape View File

@ -83,12 +83,12 @@ grpc_combiner* grpc_combiner_create(void) {
grpc_closure_list_init(&lock->final_list);
GRPC_CLOSURE_INIT(&lock->offload, offload, lock,
grpc_executor_scheduler(GRPC_EXECUTOR_SHORT));
GRPC_COMBINER_TRACE(gpr_log(GPR_DEBUG, "C:%p create", lock));
GRPC_COMBINER_TRACE(gpr_log(GPR_INFO, "C:%p create", lock));
return lock;
}
static void really_destroy(grpc_combiner* lock) {
GRPC_COMBINER_TRACE(gpr_log(GPR_DEBUG, "C:%p really_destroy", lock));
GRPC_COMBINER_TRACE(gpr_log(GPR_INFO, "C:%p really_destroy", lock));
GPR_ASSERT(gpr_atm_no_barrier_load(&lock->state) == 0);
gpr_mpscq_destroy(&lock->queue);
gpr_free(lock);
@ -97,7 +97,7 @@ static void really_destroy(grpc_combiner* lock) {
static void start_destroy(grpc_combiner* lock) {
gpr_atm old_state = gpr_atm_full_fetch_add(&lock->state, -STATE_UNORPHANED);
GRPC_COMBINER_TRACE(gpr_log(
GPR_DEBUG, "C:%p really_destroy old_state=%" PRIdPTR, lock, old_state));
GPR_INFO, "C:%p really_destroy old_state=%" PRIdPTR, lock, old_state));
if (old_state == 1) {
really_destroy(lock);
}
@ -159,7 +159,7 @@ static void combiner_exec(grpc_closure* cl, grpc_error* error) {
GRPC_STATS_INC_COMBINER_LOCKS_SCHEDULED_ITEMS();
grpc_combiner* lock = COMBINER_FROM_CLOSURE_SCHEDULER(cl, scheduler);
gpr_atm last = gpr_atm_full_fetch_add(&lock->state, STATE_ELEM_COUNT_LOW_BIT);
GRPC_COMBINER_TRACE(gpr_log(GPR_DEBUG,
GRPC_COMBINER_TRACE(gpr_log(GPR_INFO,
"C:%p grpc_combiner_execute c=%p last=%" PRIdPTR,
lock, cl, last));
if (last == 1) {
@ -203,7 +203,7 @@ static void offload(void* arg, grpc_error* error) {
static void queue_offload(grpc_combiner* lock) {
GRPC_STATS_INC_COMBINER_LOCKS_OFFLOADED();
move_next();
GRPC_COMBINER_TRACE(gpr_log(GPR_DEBUG, "C:%p queue_offload", lock));
GRPC_COMBINER_TRACE(gpr_log(GPR_INFO, "C:%p queue_offload", lock));
GRPC_CLOSURE_SCHED(&lock->offload, GRPC_ERROR_NONE);
}
@ -218,7 +218,7 @@ bool grpc_combiner_continue_exec_ctx() {
bool contended =
gpr_atm_no_barrier_load(&lock->initiating_exec_ctx_or_null) == 0;
GRPC_COMBINER_TRACE(gpr_log(GPR_DEBUG,
GRPC_COMBINER_TRACE(gpr_log(GPR_INFO,
"C:%p grpc_combiner_continue_exec_ctx "
"contended=%d "
"exec_ctx_ready_to_finish=%d "
@ -242,7 +242,7 @@ bool grpc_combiner_continue_exec_ctx() {
(gpr_atm_acq_load(&lock->state) >> 1) > 1) {
gpr_mpscq_node* n = gpr_mpscq_pop(&lock->queue);
GRPC_COMBINER_TRACE(
gpr_log(GPR_DEBUG, "C:%p maybe_finish_one n=%p", lock, n));
gpr_log(GPR_INFO, "C:%p maybe_finish_one n=%p", lock, n));
if (n == nullptr) {
// queue is in an inconsistent state: use this as a cue that we should
// go off and do something else for a while (and come back later)
@ -266,7 +266,7 @@ bool grpc_combiner_continue_exec_ctx() {
while (c != nullptr) {
GPR_TIMER_SCOPE("combiner.exec_1final", 0);
GRPC_COMBINER_TRACE(
gpr_log(GPR_DEBUG, "C:%p execute_final[%d] c=%p", lock, loops, c));
gpr_log(GPR_INFO, "C:%p execute_final[%d] c=%p", lock, loops, c));
grpc_closure* next = c->next_data.next;
grpc_error* error = c->error_data.error;
#ifndef NDEBUG
@ -284,7 +284,7 @@ bool grpc_combiner_continue_exec_ctx() {
gpr_atm old_state =
gpr_atm_full_fetch_add(&lock->state, -STATE_ELEM_COUNT_LOW_BIT);
GRPC_COMBINER_TRACE(
gpr_log(GPR_DEBUG, "C:%p finish old_state=%" PRIdPTR, lock, old_state));
gpr_log(GPR_INFO, "C:%p finish old_state=%" PRIdPTR, lock, old_state));
// Define a macro to ease readability of the following switch statement.
#define OLD_STATE_WAS(orphaned, elem_count) \
(((orphaned) ? 0 : STATE_UNORPHANED) | \
@ -327,8 +327,8 @@ static void combiner_finally_exec(grpc_closure* closure, grpc_error* error) {
grpc_combiner* lock =
COMBINER_FROM_CLOSURE_SCHEDULER(closure, finally_scheduler);
GRPC_COMBINER_TRACE(gpr_log(
GPR_DEBUG, "C:%p grpc_combiner_execute_finally c=%p; ac=%p", lock,
closure, grpc_core::ExecCtx::Get()->combiner_data()->active_combiner));
GPR_INFO, "C:%p grpc_combiner_execute_finally c=%p; ac=%p", lock, closure,
grpc_core::ExecCtx::Get()->combiner_data()->active_combiner));
if (grpc_core::ExecCtx::Get()->combiner_data()->active_combiner != lock) {
GPR_TIMER_MARK("slowpath", 0);
GRPC_CLOSURE_SCHED(GRPC_CLOSURE_CREATE(enqueue_finally, closure,

48
src/core/lib/iomgr/ev_epoll1_linux.cc
Unescape View File

@ -658,7 +658,7 @@ static grpc_error* do_epoll_wait(grpc_pollset* ps, grpc_millis deadline) {
GRPC_STATS_INC_POLL_EVENTS_RETURNED(r);
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "ps: %p poll got %d events", ps, r);
gpr_log(GPR_INFO, "ps: %p poll got %d events", ps, r);
}
gpr_atm_rel_store(&g_epoll_set.num_events, r);
@ -678,7 +678,7 @@ static bool begin_worker(grpc_pollset* pollset, grpc_pollset_worker* worker,
pollset->begin_refs++;
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PS:%p BEGIN_STARTS:%p", pollset, worker);
gpr_log(GPR_INFO, "PS:%p BEGIN_STARTS:%p", pollset, worker);
}
if (pollset->seen_inactive) {
@ -697,7 +697,7 @@ static bool begin_worker(grpc_pollset* pollset, grpc_pollset_worker* worker,
gpr_mu_lock(&neighborhood->mu);
gpr_mu_lock(&pollset->mu);
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PS:%p BEGIN_REORG:%p kick_state=%s is_reassigning=%d",
gpr_log(GPR_INFO, "PS:%p BEGIN_REORG:%p kick_state=%s is_reassigning=%d",
pollset, worker, kick_state_string(worker->state),
is_reassigning);
}
@ -749,7 +749,7 @@ static bool begin_worker(grpc_pollset* pollset, grpc_pollset_worker* worker,
gpr_cv_init(&worker->cv);
while (worker->state == UNKICKED && !pollset->shutting_down) {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PS:%p BEGIN_WAIT:%p kick_state=%s shutdown=%d",
gpr_log(GPR_INFO, "PS:%p BEGIN_WAIT:%p kick_state=%s shutdown=%d",
pollset, worker, kick_state_string(worker->state),
pollset->shutting_down);
}
@ -766,7 +766,7 @@ static bool begin_worker(grpc_pollset* pollset, grpc_pollset_worker* worker,
}
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"PS:%p BEGIN_DONE:%p kick_state=%s shutdown=%d "
"kicked_without_poller: %d",
pollset, worker, kick_state_string(worker->state),
@ -809,7 +809,7 @@ static bool check_neighborhood_for_available_poller(
if (gpr_atm_no_barrier_cas(&g_active_poller, 0,
(gpr_atm)inspect_worker)) {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. choose next poller to be %p",
gpr_log(GPR_INFO, " .. choose next poller to be %p",
inspect_worker);
}
SET_KICK_STATE(inspect_worker, DESIGNATED_POLLER);
@ -820,7 +820,7 @@ static bool check_neighborhood_for_available_poller(
}
} else {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. beaten to choose next poller");
gpr_log(GPR_INFO, " .. beaten to choose next poller");
}
}
// even if we didn't win the cas, there's a worker, we can stop
@ -838,7 +838,7 @@ static bool check_neighborhood_for_available_poller(
}
if (!found_worker) {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. mark pollset %p inactive", inspect);
gpr_log(GPR_INFO, " .. mark pollset %p inactive", inspect);
}
inspect->seen_inactive = true;
if (inspect == neighborhood->active_root) {
@ -858,7 +858,7 @@ static void end_worker(grpc_pollset* pollset, grpc_pollset_worker* worker,
grpc_pollset_worker** worker_hdl) {
GPR_TIMER_SCOPE("end_worker", 0);
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PS:%p END_WORKER:%p", pollset, worker);
gpr_log(GPR_INFO, "PS:%p END_WORKER:%p", pollset, worker);
}
if (worker_hdl != nullptr) *worker_hdl = nullptr;
/* Make sure we appear kicked */
@ -868,7 +868,7 @@ static void end_worker(grpc_pollset* pollset, grpc_pollset_worker* worker,
if (gpr_atm_no_barrier_load(&g_active_poller) == (gpr_atm)worker) {
if (worker->next != worker && worker->next->state == UNKICKED) {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. choose next poller to be peer %p", worker);
gpr_log(GPR_INFO, " .. choose next poller to be peer %p", worker);
}
GPR_ASSERT(worker->next->initialized_cv);
gpr_atm_no_barrier_store(&g_active_poller, (gpr_atm)worker->next);
@ -920,7 +920,7 @@ static void end_worker(grpc_pollset* pollset, grpc_pollset_worker* worker,
gpr_cv_destroy(&worker->cv);
}
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. remove worker");
gpr_log(GPR_INFO, " .. remove worker");
}
if (EMPTIED == worker_remove(pollset, worker)) {
pollset_maybe_finish_shutdown(pollset);
@ -1022,7 +1022,7 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
GRPC_STATS_INC_POLLSET_KICKED_WITHOUT_POLLER();
pollset->kicked_without_poller = true;
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. kicked_without_poller");
gpr_log(GPR_INFO, " .. kicked_without_poller");
}
goto done;
}
@ -1030,14 +1030,14 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
if (root_worker->state == KICKED) {
GRPC_STATS_INC_POLLSET_KICKED_AGAIN();
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. already kicked %p", root_worker);
gpr_log(GPR_INFO, " .. already kicked %p", root_worker);
}
SET_KICK_STATE(root_worker, KICKED);
goto done;
} else if (next_worker->state == KICKED) {
GRPC_STATS_INC_POLLSET_KICKED_AGAIN();
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. already kicked %p", next_worker);
gpr_log(GPR_INFO, " .. already kicked %p", next_worker);
}
SET_KICK_STATE(next_worker, KICKED);
goto done;
@ -1048,7 +1048,7 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
&g_active_poller)) {
GRPC_STATS_INC_POLLSET_KICK_WAKEUP_FD();
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. kicked %p", root_worker);
gpr_log(GPR_INFO, " .. kicked %p", root_worker);
}
SET_KICK_STATE(root_worker, KICKED);
ret_err = grpc_wakeup_fd_wakeup(&global_wakeup_fd);
@ -1056,7 +1056,7 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
} else if (next_worker->state == UNKICKED) {
GRPC_STATS_INC_POLLSET_KICK_WAKEUP_CV();
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. kicked %p", next_worker);
gpr_log(GPR_INFO, " .. kicked %p", next_worker);
}
GPR_ASSERT(next_worker->initialized_cv);
SET_KICK_STATE(next_worker, KICKED);
@ -1066,7 +1066,7 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
if (root_worker->state != DESIGNATED_POLLER) {
if (grpc_polling_trace.enabled()) {
gpr_log(
GPR_DEBUG,
GPR_INFO,
" .. kicked root non-poller %p (initialized_cv=%d) (poller=%p)",
root_worker, root_worker->initialized_cv, next_worker);
}
@ -1079,7 +1079,7 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
} else {
GRPC_STATS_INC_POLLSET_KICK_WAKEUP_FD();
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. non-root poller %p (root=%p)", next_worker,
gpr_log(GPR_INFO, " .. non-root poller %p (root=%p)", next_worker,
root_worker);
}
SET_KICK_STATE(next_worker, KICKED);
@ -1095,7 +1095,7 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
} else {
GRPC_STATS_INC_POLLSET_KICK_OWN_THREAD();
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. kicked while waking up");
gpr_log(GPR_INFO, " .. kicked while waking up");
}
goto done;
}
@ -1105,14 +1105,14 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
if (specific_worker->state == KICKED) {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. specific worker already kicked");
gpr_log(GPR_INFO, " .. specific worker already kicked");
}
goto done;
} else if (gpr_tls_get(&g_current_thread_worker) ==
(intptr_t)specific_worker) {
GRPC_STATS_INC_POLLSET_KICK_OWN_THREAD();
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. mark %p kicked", specific_worker);
gpr_log(GPR_INFO, " .. mark %p kicked", specific_worker);
}
SET_KICK_STATE(specific_worker, KICKED);
goto done;
@ -1120,7 +1120,7 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
(grpc_pollset_worker*)gpr_atm_no_barrier_load(&g_active_poller)) {
GRPC_STATS_INC_POLLSET_KICK_WAKEUP_FD();
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. kick active poller");
gpr_log(GPR_INFO, " .. kick active poller");
}
SET_KICK_STATE(specific_worker, KICKED);
ret_err = grpc_wakeup_fd_wakeup(&global_wakeup_fd);
@ -1128,7 +1128,7 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
} else if (specific_worker->initialized_cv) {
GRPC_STATS_INC_POLLSET_KICK_WAKEUP_CV();
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. kick waiting worker");
gpr_log(GPR_INFO, " .. kick waiting worker");
}
SET_KICK_STATE(specific_worker, KICKED);
gpr_cv_signal(&specific_worker->cv);
@ -1136,7 +1136,7 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
} else {
GRPC_STATS_INC_POLLSET_KICKED_AGAIN();
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. kick non-waiting worker");
gpr_log(GPR_INFO, " .. kick non-waiting worker");
}
SET_KICK_STATE(specific_worker, KICKED);
goto done;

54
src/core/lib/iomgr/ev_epollex_linux.cc
Unescape View File

@ -518,7 +518,7 @@ static grpc_error* pollable_add_fd(pollable* p, grpc_fd* fd) {
const int epfd = p->epfd;
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "add fd %p (%d) to pollable %p", fd, fd->fd, p);
gpr_log(GPR_INFO, "add fd %p (%d) to pollable %p", fd, fd->fd, p);
}
struct epoll_event ev_fd;
@ -560,7 +560,7 @@ static void pollset_global_shutdown(void) {
/* pollset->mu must be held while calling this function */
static void pollset_maybe_finish_shutdown(grpc_pollset* pollset) {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"PS:%p (pollable:%p) maybe_finish_shutdown sc=%p (target:!NULL) "
"rw=%p (target:NULL) cpsc=%d (target:0)",
pollset, pollset->active_pollable, pollset->shutdown_closure,
@ -585,14 +585,14 @@ static grpc_error* kick_one_worker(grpc_pollset_worker* specific_worker) {
GPR_ASSERT(specific_worker != nullptr);
if (specific_worker->kicked) {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PS:%p kicked_specific_but_already_kicked", p);
gpr_log(GPR_INFO, "PS:%p kicked_specific_but_already_kicked", p);
}
GRPC_STATS_INC_POLLSET_KICKED_AGAIN();
return GRPC_ERROR_NONE;
}
if (gpr_tls_get(&g_current_thread_worker) == (intptr_t)specific_worker) {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PS:%p kicked_specific_but_awake", p);
gpr_log(GPR_INFO, "PS:%p kicked_specific_but_awake", p);
}
GRPC_STATS_INC_POLLSET_KICK_OWN_THREAD();
specific_worker->kicked = true;
@ -601,7 +601,7 @@ static grpc_error* kick_one_worker(grpc_pollset_worker* specific_worker) {
if (specific_worker == p->root_worker) {
GRPC_STATS_INC_POLLSET_KICK_WAKEUP_FD();
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PS:%p kicked_specific_via_wakeup_fd", p);
gpr_log(GPR_INFO, "PS:%p kicked_specific_via_wakeup_fd", p);
}
specific_worker->kicked = true;
grpc_error* error = grpc_wakeup_fd_wakeup(&p->wakeup);
@ -610,7 +610,7 @@ static grpc_error* kick_one_worker(grpc_pollset_worker* specific_worker) {
if (specific_worker->initialized_cv) {
GRPC_STATS_INC_POLLSET_KICK_WAKEUP_CV();
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PS:%p kicked_specific_via_cv", p);
gpr_log(GPR_INFO, "PS:%p kicked_specific_via_cv", p);
}
specific_worker->kicked = true;
gpr_cv_signal(&specific_worker->cv);
@ -626,7 +626,7 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
GPR_TIMER_SCOPE("pollset_kick", 0);
GRPC_STATS_INC_POLLSET_KICK();
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"PS:%p kick %p tls_pollset=%p tls_worker=%p pollset.root_worker=%p",
pollset, specific_worker,
(void*)gpr_tls_get(&g_current_thread_pollset),
@ -636,7 +636,7 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
if (gpr_tls_get(&g_current_thread_pollset) != (intptr_t)pollset) {
if (pollset->root_worker == nullptr) {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PS:%p kicked_any_without_poller", pollset);
gpr_log(GPR_INFO, "PS:%p kicked_any_without_poller", pollset);
}
GRPC_STATS_INC_POLLSET_KICKED_WITHOUT_POLLER();
pollset->kicked_without_poller = true;
@ -662,7 +662,7 @@ static grpc_error* pollset_kick(grpc_pollset* pollset,
}
} else {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PS:%p kicked_any_but_awake", pollset);
gpr_log(GPR_INFO, "PS:%p kicked_any_but_awake", pollset);
}
GRPC_STATS_INC_POLLSET_KICK_OWN_THREAD();
return GRPC_ERROR_NONE;
@ -784,7 +784,7 @@ static grpc_error* pollable_process_events(grpc_pollset* pollset,
void* data_ptr = ev->data.ptr;
if (1 & (intptr_t)data_ptr) {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PS:%p got pollset_wakeup %p", pollset, data_ptr);
gpr_log(GPR_INFO, "PS:%p got pollset_wakeup %p", pollset, data_ptr);
}
append_error(&error,
grpc_wakeup_fd_consume_wakeup(
@ -797,7 +797,7 @@ static grpc_error* pollable_process_events(grpc_pollset* pollset,
bool read_ev = (ev->events & (EPOLLIN | EPOLLPRI)) != 0;
bool write_ev = (ev->events & EPOLLOUT) != 0;
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"PS:%p got fd %p: cancel=%d read=%d "
"write=%d",
pollset, fd, cancel, read_ev, write_ev);
@ -827,7 +827,7 @@ static grpc_error* pollable_epoll(pollable* p, grpc_millis deadline) {
if (grpc_polling_trace.enabled()) {
char* desc = pollable_desc(p);
gpr_log(GPR_DEBUG, "POLLABLE:%p[%s] poll for %dms", p, desc, timeout);
gpr_log(GPR_INFO, "POLLABLE:%p[%s] poll for %dms", p, desc, timeout);
gpr_free(desc);
}
@ -846,7 +846,7 @@ static grpc_error* pollable_epoll(pollable* p, grpc_millis deadline) {
if (r < 0) return GRPC_OS_ERROR(errno, "epoll_wait");
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "POLLABLE:%p got %d events", p, r);
gpr_log(GPR_INFO, "POLLABLE:%p got %d events", p, r);
}
p->event_cursor = 0;
@ -917,7 +917,7 @@ static bool begin_worker(grpc_pollset* pollset, grpc_pollset_worker* worker,
gpr_mu_unlock(&pollset->mu);
if (grpc_polling_trace.enabled() &&
worker->pollable_obj->root_worker != worker) {
gpr_log(GPR_DEBUG, "PS:%p wait %p w=%p for %dms", pollset,
gpr_log(GPR_INFO, "PS:%p wait %p w=%p for %dms", pollset,
worker->pollable_obj, worker,
poll_deadline_to_millis_timeout(deadline));
}
@ -925,19 +925,19 @@ static bool begin_worker(grpc_pollset* pollset, grpc_pollset_worker* worker,
if (gpr_cv_wait(&worker->cv, &worker->pollable_obj->mu,
grpc_millis_to_timespec(deadline, GPR_CLOCK_REALTIME))) {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PS:%p timeout_wait %p w=%p", pollset,
gpr_log(GPR_INFO, "PS:%p timeout_wait %p w=%p", pollset,
worker->pollable_obj, worker);
}
do_poll = false;
} else if (worker->kicked) {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PS:%p wakeup %p w=%p", pollset,
gpr_log(GPR_INFO, "PS:%p wakeup %p w=%p", pollset,
worker->pollable_obj, worker);
}
do_poll = false;
} else if (grpc_polling_trace.enabled() &&
worker->pollable_obj->root_worker != worker) {
gpr_log(GPR_DEBUG, "PS:%p spurious_wakeup %p w=%p", pollset,
gpr_log(GPR_INFO, "PS:%p spurious_wakeup %p w=%p", pollset,
worker->pollable_obj, worker);
}
}
@ -1009,7 +1009,7 @@ static grpc_error* pollset_work(grpc_pollset* pollset,
WORKER_PTR->originator = gettid();
#endif
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"PS:%p work hdl=%p worker=%p now=%" PRIdPTR " deadline=%" PRIdPTR
" kwp=%d pollable=%p",
pollset, worker_hdl, WORKER_PTR, grpc_core::ExecCtx::Get()->Now(),
@ -1050,7 +1050,7 @@ static grpc_error* pollset_transition_pollable_from_empty_to_fd_locked(
static const char* err_desc = "pollset_transition_pollable_from_empty_to_fd";
grpc_error* error = GRPC_ERROR_NONE;
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"PS:%p add fd %p (%d); transition pollable from empty to fd",
pollset, fd, fd->fd);
}
@ -1067,7 +1067,7 @@ static grpc_error* pollset_transition_pollable_from_fd_to_multi_locked(
grpc_error* error = GRPC_ERROR_NONE;
if (grpc_polling_trace.enabled()) {
gpr_log(
GPR_DEBUG,
GPR_INFO,
"PS:%p add fd %p (%d); transition pollable from fd %p to multipoller",
pollset, and_add_fd, and_add_fd ? and_add_fd->fd : -1,
pollset->active_pollable->owner_fd);
@ -1137,7 +1137,7 @@ static grpc_error* pollset_as_multipollable_locked(grpc_pollset* pollset,
/* Any workers currently polling on this pollset must now be woked up so
* that they can pick up the new active_pollable */
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"PS:%p active pollable transition from empty to multi",
pollset);
}
@ -1224,7 +1224,7 @@ static void pollset_set_unref(grpc_pollset_set* pss) {
static void pollset_set_add_fd(grpc_pollset_set* pss, grpc_fd* fd) {
GPR_TIMER_SCOPE("pollset_set_add_fd", 0);
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PSS:%p: add fd %p (%d)", pss, fd, fd->fd);
gpr_log(GPR_INFO, "PSS:%p: add fd %p (%d)", pss, fd, fd->fd);
}
grpc_error* error = GRPC_ERROR_NONE;
static const char* err_desc = "pollset_set_add_fd";
@ -1248,7 +1248,7 @@ static void pollset_set_add_fd(grpc_pollset_set* pss, grpc_fd* fd) {
static void pollset_set_del_fd(grpc_pollset_set* pss, grpc_fd* fd) {
GPR_TIMER_SCOPE("pollset_set_del_fd", 0);
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PSS:%p: del fd %p", pss, fd);
gpr_log(GPR_INFO, "PSS:%p: del fd %p", pss, fd);
}
pss = pss_lock_adam(pss);
size_t i;
@ -1269,7 +1269,7 @@ static void pollset_set_del_fd(grpc_pollset_set* pss, grpc_fd* fd) {
static void pollset_set_del_pollset(grpc_pollset_set* pss, grpc_pollset* ps) {
GPR_TIMER_SCOPE("pollset_set_del_pollset", 0);
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PSS:%p: del pollset %p", pss, ps);
gpr_log(GPR_INFO, "PSS:%p: del pollset %p", pss, ps);
}
pss = pss_lock_adam(pss);
size_t i;
@ -1321,7 +1321,7 @@ static grpc_error* add_fds_to_pollsets(grpc_fd** fds, size_t fd_count,
static void pollset_set_add_pollset(grpc_pollset_set* pss, grpc_pollset* ps) {
GPR_TIMER_SCOPE("pollset_set_add_pollset", 0);
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PSS:%p: add pollset %p", pss, ps);
gpr_log(GPR_INFO, "PSS:%p: add pollset %p", pss, ps);
}
grpc_error* error = GRPC_ERROR_NONE;
static const char* err_desc = "pollset_set_add_pollset";
@ -1358,7 +1358,7 @@ static void pollset_set_add_pollset_set(grpc_pollset_set* a,
grpc_pollset_set* b) {
GPR_TIMER_SCOPE("pollset_set_add_pollset_set", 0);
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PSS: merge (%p, %p)", a, b);
gpr_log(GPR_INFO, "PSS: merge (%p, %p)", a, b);
}
grpc_error* error = GRPC_ERROR_NONE;
static const char* err_desc = "pollset_set_add_fd";
@ -1392,7 +1392,7 @@ static void pollset_set_add_pollset_set(grpc_pollset_set* a,
GPR_SWAP(grpc_pollset_set*, a, b);
}
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "PSS: parent %p to %p", b, a);
gpr_log(GPR_INFO, "PSS: parent %p to %p", b, a);
}
gpr_ref(&a->refs);
b->parent = a;

4
src/core/lib/iomgr/ev_epollsig_linux.cc
Unescape View File

@ -292,7 +292,7 @@ static void pi_add_ref_dbg(polling_island* pi, const char* reason,
const char* file, int line) {
if (grpc_polling_trace.enabled()) {
gpr_atm old_cnt = gpr_atm_acq_load(&pi->ref_count);
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"Add ref pi: %p, old:%" PRIdPTR " -> new:%" PRIdPTR
" (%s) - (%s, %d)",
pi, old_cnt, old_cnt + 1, reason, file, line);
@ -304,7 +304,7 @@ static void pi_unref_dbg(polling_island* pi, const char* reason,
const char* file, int line) {
if (grpc_polling_trace.enabled()) {
gpr_atm old_cnt = gpr_atm_acq_load(&pi->ref_count);
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"Unref pi: %p, old:%" PRIdPTR " -> new:%" PRIdPTR
" (%s) - (%s, %d)",
pi, old_cnt, (old_cnt - 1), reason, file, line);

6
src/core/lib/iomgr/ev_poll_posix.cc
Unescape View File

@ -983,7 +983,7 @@ static grpc_error* pollset_work(grpc_pollset* pollset,
GRPC_SCHEDULING_END_BLOCKING_REGION;
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "%p poll=%d", pollset, r);
gpr_log(GPR_INFO, "%p poll=%d", pollset, r);
}
if (r < 0) {
@ -1007,7 +1007,7 @@ static grpc_error* pollset_work(grpc_pollset* pollset,
} else {
if (pfds[0].revents & POLLIN_CHECK) {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "%p: got_wakeup", pollset);
gpr_log(GPR_INFO, "%p: got_wakeup", pollset);
}
work_combine_error(
&error, grpc_wakeup_fd_consume_wakeup(&worker.wakeup_fd->fd));
@ -1017,7 +1017,7 @@ static grpc_error* pollset_work(grpc_pollset* pollset,
fd_end_poll(&watchers[i], 0, 0, nullptr);
} else {
if (grpc_polling_trace.enabled()) {
gpr_log(GPR_DEBUG, "%p got_event: %d r:%d w:%d [%d]", pollset,
gpr_log(GPR_INFO, "%p got_event: %d r:%d w:%d [%d]", pollset,
pfds[i].fd, (pfds[i].revents & POLLIN_CHECK) != 0,
(pfds[i].revents & POLLOUT_CHECK) != 0, pfds[i].revents);
}

2
src/core/lib/iomgr/ev_posix.cc
Unescape View File

@ -48,7 +48,7 @@ grpc_core::DebugOnlyTraceFlag grpc_polling_api_trace(false, "polling_api");
// Polling API trace only enabled in debug builds
#define GRPC_POLLING_API_TRACE(format, ...) \
if (grpc_polling_api_trace.enabled()) { \
gpr_log(GPR_DEBUG, "(polling-api) " format, __VA_ARGS__); \
gpr_log(GPR_INFO, "(polling-api) " format, __VA_ARGS__); \
}
#else
#define GRPC_POLLING_API_TRACE(...)

12
src/core/lib/iomgr/executor.cc
Unescape View File

@ -69,7 +69,7 @@ static size_t run_closures(grpc_closure_list list) {
gpr_log(GPR_DEBUG, "EXECUTOR: run %p [created by %s:%d]", c,
c->file_created, c->line_created);
#else
gpr_log(GPR_DEBUG, "EXECUTOR: run %p", c);
gpr_log(GPR_INFO, "EXECUTOR: run %p", c);
#endif
}
#ifndef NDEBUG
@ -150,7 +150,7 @@ static void executor_thread(void* arg) {
size_t subtract_depth = 0;
for (;;) {
if (executor_trace.enabled()) {
gpr_log(GPR_DEBUG, "EXECUTOR[%d]: step (sub_depth=%" PRIdPTR ")",
gpr_log(GPR_INFO, "EXECUTOR[%d]: step (sub_depth=%" PRIdPTR ")",
static_cast<int>(ts - g_thread_state), subtract_depth);
}
gpr_mu_lock(&ts->mu);
@ -161,7 +161,7 @@ static void executor_thread(void* arg) {
}
if (ts->shutdown) {
if (executor_trace.enabled()) {
gpr_log(GPR_DEBUG, "EXECUTOR[%d]: shutdown",
gpr_log(GPR_INFO, "EXECUTOR[%d]: shutdown",
static_cast<int>(ts - g_thread_state));
}
gpr_mu_unlock(&ts->mu);
@ -172,7 +172,7 @@ static void executor_thread(void* arg) {
ts->elems = GRPC_CLOSURE_LIST_INIT;
gpr_mu_unlock(&ts->mu);
if (executor_trace.enabled()) {
gpr_log(GPR_DEBUG, "EXECUTOR[%d]: execute",
gpr_log(GPR_INFO, "EXECUTOR[%d]: execute",
static_cast<int>(ts - g_thread_state));
}
@ -199,7 +199,7 @@ static void executor_push(grpc_closure* closure, grpc_error* error,
gpr_log(GPR_DEBUG, "EXECUTOR: schedule %p (created %s:%d) inline",
closure, closure->file_created, closure->line_created);
#else
gpr_log(GPR_DEBUG, "EXECUTOR: schedule %p inline", closure);
gpr_log(GPR_INFO, "EXECUTOR: schedule %p inline", closure);
#endif
}
grpc_closure_list_append(grpc_core::ExecCtx::Get()->closure_list(),
@ -225,7 +225,7 @@ static void executor_push(grpc_closure* closure, grpc_error* error,
closure, is_short ? "short" : "long", closure->file_created,
closure->line_created, static_cast<int>(ts - g_thread_state));
#else
gpr_log(GPR_DEBUG, "EXECUTOR: try to schedule %p (%s) to thread %d",
gpr_log(GPR_INFO, "EXECUTOR: try to schedule %p (%s) to thread %d",
closure, is_short ? "short" : "long",
(int)(ts - g_thread_state));
#endif

21
src/core/lib/iomgr/resource_quota.cc
Unescape View File

@ -289,7 +289,7 @@ static bool rq_alloc(grpc_resource_quota* resource_quota) {
GRPC_RULIST_AWAITING_ALLOCATION))) {
gpr_mu_lock(&resource_user->mu);
if (grpc_resource_quota_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"RQ: check allocation for user %p shutdown=%" PRIdPTR
" free_pool=%" PRId64,
resource_user, gpr_atm_no_barrier_load(&resource_user->shutdown),
@ -315,7 +315,7 @@ static bool rq_alloc(grpc_resource_quota* resource_quota) {
resource_quota->free_pool -= amt;
rq_update_estimate(resource_quota);
if (grpc_resource_quota_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"RQ %s %s: grant alloc %" PRId64
" bytes; rq_free_pool -> %" PRId64,
resource_quota->name, resource_user->name, amt,
@ -323,7 +323,7 @@ static bool rq_alloc(grpc_resource_quota* resource_quota) {
}
} else if (grpc_resource_quota_trace.enabled() &&
resource_user->free_pool >= 0) {
gpr_log(GPR_DEBUG, "RQ %s %s: discard already satisfied alloc request",
gpr_log(GPR_INFO, "RQ %s %s: discard already satisfied alloc request",
resource_quota->name, resource_user->name);
}
if (resource_user->free_pool >= 0) {
@ -353,7 +353,7 @@ static bool rq_reclaim_from_per_user_free_pool(
resource_quota->free_pool += amt;
rq_update_estimate(resource_quota);
if (grpc_resource_quota_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"RQ %s %s: reclaim_from_per_user_free_pool %" PRId64
" bytes; rq_free_pool -> %" PRId64,
resource_quota->name, resource_user->name, amt,
@ -376,9 +376,8 @@ static bool rq_reclaim(grpc_resource_quota* resource_quota, bool destructive) {
grpc_resource_user* resource_user = rulist_pop_head(resource_quota, list);
if (resource_user == nullptr) return false;
if (grpc_resource_quota_trace.enabled()) {
gpr_log(GPR_DEBUG, "RQ %s %s: initiate %s reclamation",
resource_quota->name, resource_user->name,
destructive ? "destructive" : "benign");
gpr_log(GPR_INFO, "RQ %s %s: initiate %s reclamation", resource_quota->name,
resource_user->name, destructive ? "destructive" : "benign");
}
resource_quota->reclaiming = true;
grpc_resource_quota_ref_internal(resource_quota);
@ -506,7 +505,7 @@ static void ru_post_destructive_reclaimer(void* ru, grpc_error* error) {
static void ru_shutdown(void* ru, grpc_error* error) {
if (grpc_resource_quota_trace.enabled()) {
gpr_log(GPR_DEBUG, "RU shutdown %p", ru);
gpr_log(GPR_INFO, "RU shutdown %p", ru);
}
grpc_resource_user* resource_user = static_cast<grpc_resource_user*>(ru);
gpr_mu_lock(&resource_user->mu);
@ -793,7 +792,7 @@ void grpc_resource_user_alloc(grpc_resource_user* resource_user, size_t size,
resource_user->free_pool -= static_cast<int64_t>(size);
resource_user->outstanding_allocations += static_cast<int64_t>(size);
if (grpc_resource_quota_trace.enabled()) {
gpr_log(GPR_DEBUG, "RQ %s %s: alloc %" PRIdPTR "; free_pool -> %" PRId64,
gpr_log(GPR_INFO, "RQ %s %s: alloc %" PRIdPTR "; free_pool -> %" PRId64,
resource_user->resource_quota->name, resource_user->name, size,
resource_user->free_pool);
}
@ -816,7 +815,7 @@ void grpc_resource_user_free(grpc_resource_user* resource_user, size_t size) {
bool was_zero_or_negative = resource_user->free_pool <= 0;
resource_user->free_pool += static_cast<int64_t>(size);
if (grpc_resource_quota_trace.enabled()) {
gpr_log(GPR_DEBUG, "RQ %s %s: free %" PRIdPTR "; free_pool -> %" PRId64,
gpr_log(GPR_INFO, "RQ %s %s: free %" PRIdPTR "; free_pool -> %" PRId64,
resource_user->resource_quota->name, resource_user->name, size,
resource_user->free_pool);
}
@ -842,7 +841,7 @@ void grpc_resource_user_post_reclaimer(grpc_resource_user* resource_user,
void grpc_resource_user_finish_reclamation(grpc_resource_user* resource_user) {
if (grpc_resource_quota_trace.enabled()) {
gpr_log(GPR_DEBUG, "RQ %s %s: reclamation complete",
gpr_log(GPR_INFO, "RQ %s %s: reclamation complete",
resource_user->resource_quota->name, resource_user->name);
}
GRPC_CLOSURE_SCHED(

4
src/core/lib/iomgr/tcp_client_custom.cc
Unescape View File

@ -66,7 +66,7 @@ static void on_alarm(void* acp, grpc_error* error) {
grpc_custom_tcp_connect* connect = socket->connector;
if (grpc_tcp_trace.enabled()) {
const char* str = grpc_error_string(error);
gpr_log(GPR_DEBUG, "CLIENT_CONNECT: %s: on_alarm: error=%s",
gpr_log(GPR_INFO, "CLIENT_CONNECT: %s: on_alarm: error=%s",
connect->addr_name, str);
}
if (error == GRPC_ERROR_NONE) {
@ -136,7 +136,7 @@ static void tcp_connect(grpc_closure* closure, grpc_endpoint** ep,
connect->refs = 2;
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "CLIENT_CONNECT: %p %s: asynchronously connecting",
gpr_log(GPR_INFO, "CLIENT_CONNECT: %p %s: asynchronously connecting",
socket, connect->addr_name);
}

8
src/core/lib/iomgr/tcp_client_posix.cc
Unescape View File

@ -104,7 +104,7 @@ static void tc_on_alarm(void* acp, grpc_error* error) {
async_connect* ac = static_cast<async_connect*>(acp);
if (grpc_tcp_trace.enabled()) {
const char* str = grpc_error_string(error);
gpr_log(GPR_DEBUG, "CLIENT_CONNECT: %s: on_alarm: error=%s", ac->addr_str,
gpr_log(GPR_INFO, "CLIENT_CONNECT: %s: on_alarm: error=%s", ac->addr_str,
str);
}
gpr_mu_lock(&ac->mu);
@ -141,8 +141,8 @@ static void on_writable(void* acp, grpc_error* error) {
if (grpc_tcp_trace.enabled()) {
const char* str = grpc_error_string(error);
gpr_log(GPR_DEBUG, "CLIENT_CONNECT: %s: on_writable: error=%s",
ac->addr_str, str);
gpr_log(GPR_INFO, "CLIENT_CONNECT: %s: on_writable: error=%s", ac->addr_str,
str);
}
gpr_mu_lock(&ac->mu);
@ -325,7 +325,7 @@ void grpc_tcp_client_create_from_prepared_fd(
ac->channel_args = grpc_channel_args_copy(channel_args);
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "CLIENT_CONNECT: %s: asynchronously connecting fd %p",
gpr_log(GPR_INFO, "CLIENT_CONNECT: %s: asynchronously connecting fd %p",
ac->addr_str, fdobj);
}

20
src/core/lib/iomgr/tcp_custom.cc
Unescape View File

@ -125,16 +125,16 @@ static void tcp_ref(custom_tcp_endpoint* tcp) { gpr_ref(&tcp->refcount); }
static void call_read_cb(custom_tcp_endpoint* tcp, grpc_error* error) {
grpc_closure* cb = tcp->read_cb;
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "TCP:%p call_cb %p %p:%p", tcp->socket, cb, cb->cb,
gpr_log(GPR_INFO, "TCP:%p call_cb %p %p:%p", tcp->socket, cb, cb->cb,
cb->cb_arg);
size_t i;
const char* str = grpc_error_string(error);
gpr_log(GPR_DEBUG, "read: error=%s", str);
gpr_log(GPR_INFO, "read: error=%s", str);
for (i = 0; i < tcp->read_slices->count; i++) {
char* dump = grpc_dump_slice(tcp->read_slices->slices[i],
GPR_DUMP_HEX | GPR_DUMP_ASCII);
gpr_log(GPR_DEBUG, "READ %p (peer=%s): %s", tcp, tcp->peer_string, dump);
gpr_log(GPR_INFO, "READ %p (peer=%s): %s", tcp, tcp->peer_string, dump);
gpr_free(dump);
}
}
@ -171,7 +171,7 @@ static void custom_read_callback(grpc_custom_socket* socket, size_t nread,
static void tcp_read_allocation_done(void* tcpp, grpc_error* error) {
custom_tcp_endpoint* tcp = (custom_tcp_endpoint*)tcpp;
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "TCP:%p read_allocation_done: %s", tcp->socket,
gpr_log(GPR_INFO, "TCP:%p read_allocation_done: %s", tcp->socket,
grpc_error_string(error));
}
if (error == GRPC_ERROR_NONE) {
@ -188,7 +188,7 @@ static void tcp_read_allocation_done(void* tcpp, grpc_error* error) {
}
if (grpc_tcp_trace.enabled()) {
const char* str = grpc_error_string(error);
gpr_log(GPR_DEBUG, "Initiating read on %p: error=%s", tcp->socket, str);
gpr_log(GPR_INFO, "Initiating read on %p: error=%s", tcp->socket, str);
}
}
@ -214,7 +214,7 @@ static void custom_write_callback(grpc_custom_socket* socket,
tcp->write_cb = nullptr;
if (grpc_tcp_trace.enabled()) {
const char* str = grpc_error_string(error);
gpr_log(GPR_DEBUG, "write complete on %p: error=%s", tcp->socket, str);
gpr_log(GPR_INFO, "write complete on %p: error=%s", tcp->socket, str);
}
TCP_UNREF(tcp, "write");
GRPC_CLOSURE_SCHED(cb, error);
@ -231,8 +231,8 @@ static void endpoint_write(grpc_endpoint* ep, grpc_slice_buffer* write_slices,
for (j = 0; j < write_slices->count; j++) {
char* data = grpc_dump_slice(write_slices->slices[j],
GPR_DUMP_HEX | GPR_DUMP_ASCII);
gpr_log(GPR_DEBUG, "WRITE %p (peer=%s): %s", tcp->socket,
tcp->peer_string, data);
gpr_log(GPR_INFO, "WRITE %p (peer=%s): %s", tcp->socket, tcp->peer_string,
data);
gpr_free(data);
}
}
@ -283,7 +283,7 @@ static void endpoint_shutdown(grpc_endpoint* ep, grpc_error* why) {
if (!tcp->shutting_down) {
if (grpc_tcp_trace.enabled()) {
const char* str = grpc_error_string(why);
gpr_log(GPR_DEBUG, "TCP %p shutdown why=%s", tcp->socket, str);
gpr_log(GPR_INFO, "TCP %p shutdown why=%s", tcp->socket, str);
}
tcp->shutting_down = true;
// GRPC_CLOSURE_SCHED(tcp->read_cb, GRPC_ERROR_REF(why));
@ -345,7 +345,7 @@ grpc_endpoint* custom_tcp_endpoint_create(grpc_custom_socket* socket,
grpc_core::ExecCtx exec_ctx;
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "Creating TCP endpoint %p", socket);
gpr_log(GPR_INFO, "Creating TCP endpoint %p", socket);
}
memset(tcp, 0, sizeof(custom_tcp_endpoint));
socket->refs++;

48
src/core/lib/iomgr/tcp_posix.cc
Unescape View File

@ -120,7 +120,7 @@ static void tcp_drop_uncovered_then_handle_write(void* arg /* grpc_tcp */,
static void done_poller(void* bp, grpc_error* error_ignored) {
backup_poller* p = static_cast<backup_poller*>(bp);
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "BACKUP_POLLER:%p destroy", p);
gpr_log(GPR_INFO, "BACKUP_POLLER:%p destroy", p);
}
grpc_pollset_destroy(BACKUP_POLLER_POLLSET(p));
gpr_free(p);
@ -129,7 +129,7 @@ static void done_poller(void* bp, grpc_error* error_ignored) {
static void run_poller(void* bp, grpc_error* error_ignored) {
backup_poller* p = static_cast<backup_poller*>(bp);
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "BACKUP_POLLER:%p run", p);
gpr_log(GPR_INFO, "BACKUP_POLLER:%p run", p);
}
gpr_mu_lock(p->pollset_mu);
grpc_millis deadline = grpc_core::ExecCtx::Get()->Now() + 10 * GPR_MS_PER_SEC;
@ -145,18 +145,18 @@ static void run_poller(void* bp, grpc_error* error_ignored) {
gpr_mu_lock(p->pollset_mu);
bool cas_ok = gpr_atm_full_cas(&g_backup_poller, (gpr_atm)p, 0);
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "BACKUP_POLLER:%p done cas_ok=%d", p, cas_ok);
gpr_log(GPR_INFO, "BACKUP_POLLER:%p done cas_ok=%d", p, cas_ok);
}
gpr_mu_unlock(p->pollset_mu);
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "BACKUP_POLLER:%p shutdown", p);
gpr_log(GPR_INFO, "BACKUP_POLLER:%p shutdown", p);
}
grpc_pollset_shutdown(BACKUP_POLLER_POLLSET(p),
GRPC_CLOSURE_INIT(&p->run_poller, done_poller, p,
grpc_schedule_on_exec_ctx));
} else {
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "BACKUP_POLLER:%p reschedule", p);
gpr_log(GPR_INFO, "BACKUP_POLLER:%p reschedule", p);
}
GRPC_CLOSURE_SCHED(&p->run_poller, GRPC_ERROR_NONE);
}
@ -167,7 +167,7 @@ static void drop_uncovered(grpc_tcp* tcp) {
gpr_atm old_count =
gpr_atm_no_barrier_fetch_add(&g_uncovered_notifications_pending, -1);
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "BACKUP_POLLER:%p uncover cnt %d->%d", p,
gpr_log(GPR_INFO, "BACKUP_POLLER:%p uncover cnt %d->%d", p,
static_cast<int>(old_count), static_cast<int>(old_count) - 1);
}
GPR_ASSERT(old_count != 1);
@ -178,7 +178,7 @@ static void cover_self(grpc_tcp* tcp) {
gpr_atm old_count =
gpr_atm_no_barrier_fetch_add(&g_uncovered_notifications_pending, 2);
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "BACKUP_POLLER: cover cnt %d->%d",
gpr_log(GPR_INFO, "BACKUP_POLLER: cover cnt %d->%d",
static_cast<int>(old_count), 2 + static_cast<int>(old_count));
}
if (old_count == 0) {
@ -186,7 +186,7 @@ static void cover_self(grpc_tcp* tcp) {
p = static_cast<backup_poller*>(
gpr_zalloc(sizeof(*p) + grpc_pollset_size()));
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "BACKUP_POLLER:%p create", p);
gpr_log(GPR_INFO, "BACKUP_POLLER:%p create", p);
}
grpc_pollset_init(BACKUP_POLLER_POLLSET(p), &p->pollset_mu);
gpr_atm_rel_store(&g_backup_poller, (gpr_atm)p);
@ -201,7 +201,7 @@ static void cover_self(grpc_tcp* tcp) {
}
}
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "BACKUP_POLLER:%p add %p", p, tcp);
gpr_log(GPR_INFO, "BACKUP_POLLER:%p add %p", p, tcp);
}
grpc_pollset_add_fd(BACKUP_POLLER_POLLSET(p), tcp->em_fd);
if (old_count != 0) {
@ -211,7 +211,7 @@ static void cover_self(grpc_tcp* tcp) {
static void notify_on_read(grpc_tcp* tcp) {
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "TCP:%p notify_on_read", tcp);
gpr_log(GPR_INFO, "TCP:%p notify_on_read", tcp);
}
GRPC_CLOSURE_INIT(&tcp->read_done_closure, tcp_handle_read, tcp,
grpc_schedule_on_exec_ctx);
@ -220,7 +220,7 @@ static void notify_on_read(grpc_tcp* tcp) {
static void notify_on_write(grpc_tcp* tcp) {
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "TCP:%p notify_on_write", tcp);
gpr_log(GPR_INFO, "TCP:%p notify_on_write", tcp);
}
cover_self(tcp);
GRPC_CLOSURE_INIT(&tcp->write_done_closure,
@ -231,7 +231,7 @@ static void notify_on_write(grpc_tcp* tcp) {
static void tcp_drop_uncovered_then_handle_write(void* arg, grpc_error* error) {
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "TCP:%p got_write: %s", arg, grpc_error_string(error));
gpr_log(GPR_INFO, "TCP:%p got_write: %s", arg, grpc_error_string(error));
}
drop_uncovered(static_cast<grpc_tcp*>(arg));
tcp_handle_write(arg, error);
@ -351,15 +351,15 @@ static void call_read_cb(grpc_tcp* tcp, grpc_error* error) {
grpc_closure* cb = tcp->read_cb;
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "TCP:%p call_cb %p %p:%p", tcp, cb, cb->cb, cb->cb_arg);
gpr_log(GPR_INFO, "TCP:%p call_cb %p %p:%p", tcp, cb, cb->cb, cb->cb_arg);
size_t i;
const char* str = grpc_error_string(error);
gpr_log(GPR_DEBUG, "read: error=%s", str);
gpr_log(GPR_INFO, "read: error=%s", str);
for (i = 0; i < tcp->incoming_buffer->count; i++) {
char* dump = grpc_dump_slice(tcp->incoming_buffer->slices[i],
GPR_DUMP_HEX | GPR_DUMP_ASCII);
gpr_log(GPR_DEBUG, "READ %p (peer=%s): %s", tcp, tcp->peer_string, dump);
gpr_log(GPR_INFO, "READ %p (peer=%s): %s", tcp, tcp->peer_string, dump);
gpr_free(dump);
}
}
@ -441,7 +441,7 @@ static void tcp_do_read(grpc_tcp* tcp) {
static void tcp_read_allocation_done(void* tcpp, grpc_error* error) {
grpc_tcp* tcp = static_cast<grpc_tcp*>(tcpp);
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "TCP:%p read_allocation_done: %s", tcp,
gpr_log(GPR_INFO, "TCP:%p read_allocation_done: %s", tcp,
grpc_error_string(error));
}
if (error != GRPC_ERROR_NONE) {
@ -459,13 +459,13 @@ static void tcp_continue_read(grpc_tcp* tcp) {
if (tcp->incoming_buffer->length < target_read_size &&
tcp->incoming_buffer->count < MAX_READ_IOVEC) {
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "TCP:%p alloc_slices", tcp);
gpr_log(GPR_INFO, "TCP:%p alloc_slices", tcp);
}
grpc_resource_user_alloc_slices(&tcp->slice_allocator, target_read_size, 1,
tcp->incoming_buffer);
} else {
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "TCP:%p do_read", tcp);
gpr_log(GPR_INFO, "TCP:%p do_read", tcp);
}
tcp_do_read(tcp);
}
@ -475,7 +475,7 @@ static void tcp_handle_read(void* arg /* grpc_tcp */, grpc_error* error) {
grpc_tcp* tcp = static_cast<grpc_tcp*>(arg);
GPR_ASSERT(!tcp->finished_edge);
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "TCP:%p got_read: %s", tcp, grpc_error_string(error));
gpr_log(GPR_INFO, "TCP:%p got_read: %s", tcp, grpc_error_string(error));
}
if (error != GRPC_ERROR_NONE) {
@ -618,7 +618,7 @@ static void tcp_handle_write(void* arg /* grpc_tcp */, grpc_error* error) {
if (!tcp_flush(tcp, &error)) {
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "write: delayed");
gpr_log(GPR_INFO, "write: delayed");
}
notify_on_write(tcp);
} else {
@ -626,7 +626,7 @@ static void tcp_handle_write(void* arg /* grpc_tcp */, grpc_error* error) {
tcp->write_cb = nullptr;
if (grpc_tcp_trace.enabled()) {
const char* str = grpc_error_string(error);
gpr_log(GPR_DEBUG, "write: %s", str);
gpr_log(GPR_INFO, "write: %s", str);
}
GRPC_CLOSURE_RUN(cb, error);
@ -646,7 +646,7 @@ static void tcp_write(grpc_endpoint* ep, grpc_slice_buffer* buf,
for (i = 0; i < buf->count; i++) {
char* data =
grpc_dump_slice(buf->slices[i], GPR_DUMP_HEX | GPR_DUMP_ASCII);
gpr_log(GPR_DEBUG, "WRITE %p (peer=%s): %s", tcp, tcp->peer_string, data);
gpr_log(GPR_INFO, "WRITE %p (peer=%s): %s", tcp, tcp->peer_string, data);
gpr_free(data);
}
}
@ -668,13 +668,13 @@ static void tcp_write(grpc_endpoint* ep, grpc_slice_buffer* buf,
TCP_REF(tcp, "write");
tcp->write_cb = cb;
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "write: delayed");
gpr_log(GPR_INFO, "write: delayed");
}
notify_on_write(tcp);
} else {
if (grpc_tcp_trace.enabled()) {
const char* str = grpc_error_string(error);
gpr_log(GPR_DEBUG, "write: %s", str);
gpr_log(GPR_INFO, "write: %s", str);
}
GRPC_CLOSURE_SCHED(cb, error);
}

10
src/core/lib/iomgr/tcp_server_custom.cc
Unescape View File

@ -222,10 +222,10 @@ static void finish_accept(grpc_tcp_listener* sp, grpc_custom_socket* socket) {
}
if (grpc_tcp_trace.enabled()) {
if (peer_name_string) {
gpr_log(GPR_DEBUG, "SERVER_CONNECT: %p accepted connection: %s",
gpr_log(GPR_INFO, "SERVER_CONNECT: %p accepted connection: %s",
sp->server, peer_name_string);
} else {
gpr_log(GPR_DEBUG, "SERVER_CONNECT: %p accepted connection", sp->server);
gpr_log(GPR_INFO, "SERVER_CONNECT: %p accepted connection", sp->server);
}
}
ep = custom_tcp_endpoint_create(socket, sp->server->resource_quota,
@ -377,10 +377,10 @@ static grpc_error* tcp_server_add_port(grpc_tcp_server* s,
grpc_sockaddr_to_string(&port_string, addr, 0);
const char* str = grpc_error_string(error);
if (port_string) {
gpr_log(GPR_DEBUG, "SERVER %p add_port %s error=%s", s, port_string, str);
gpr_log(GPR_INFO, "SERVER %p add_port %s error=%s", s, port_string, str);
gpr_free(port_string);
} else {
gpr_log(GPR_DEBUG, "SERVER %p add_port error=%s", s, str);
gpr_log(GPR_INFO, "SERVER %p add_port error=%s", s, str);
}
}
@ -419,7 +419,7 @@ static void tcp_server_start(grpc_tcp_server* server, grpc_pollset** pollsets,
(void)pollset_count;
GRPC_CUSTOM_IOMGR_ASSERT_SAME_THREAD();
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "SERVER_START %p", server);
gpr_log(GPR_INFO, "SERVER_START %p", server);
}
GPR_ASSERT(on_accept_cb);
GPR_ASSERT(!server->on_accept_cb);

2
src/core/lib/iomgr/tcp_server_posix.cc
Unescape View File

@ -228,7 +228,7 @@ static void on_read(void* arg, grpc_error* err) {
gpr_asprintf(&name, "tcp-server-connection:%s", addr_str);
if (grpc_tcp_trace.enabled()) {
gpr_log(GPR_DEBUG, "SERVER_CONNECT: incoming connection: %s", addr_str);
gpr_log(GPR_INFO, "SERVER_CONNECT: incoming connection: %s", addr_str);
}
grpc_fd* fdobj = grpc_fd_create(fd, name);

34
src/core/lib/iomgr/timer_generic.cc
Unescape View File

@ -346,9 +346,9 @@ static void timer_init(grpc_timer* timer, grpc_millis deadline,
#endif
if (grpc_timer_trace.enabled()) {
gpr_log(GPR_DEBUG,
"TIMER %p: SET %" PRIdPTR " now %" PRIdPTR " call %p[%p]", timer,
deadline, grpc_core::ExecCtx::Get()->Now(), closure, closure->cb);
gpr_log(GPR_INFO, "TIMER %p: SET %" PRIdPTR " now %" PRIdPTR " call %p[%p]",
timer, deadline, grpc_core::ExecCtx::Get()->Now(), closure,
closure->cb);
}
if (!g_shared_mutables.initialized) {
@ -382,7 +382,7 @@ static void timer_init(grpc_timer* timer, grpc_millis deadline,
list_join(&shard->list, timer);
}
if (grpc_timer_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
" .. add to shard %d with queue_deadline_cap=%" PRIdPTR
" => is_first_timer=%s",
static_cast<int>(shard - g_shards), shard->queue_deadline_cap,
@ -404,7 +404,7 @@ static void timer_init(grpc_timer* timer, grpc_millis deadline,
if (is_first_timer) {
gpr_mu_lock(&g_shared_mutables.mu);
if (grpc_timer_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. old shard min_deadline=%" PRIdPTR,
gpr_log(GPR_INFO, " .. old shard min_deadline=%" PRIdPTR,
shard->min_deadline);
}
if (deadline < shard->min_deadline) {
@ -434,7 +434,7 @@ static void timer_cancel(grpc_timer* timer) {
timer_shard* shard = &g_shards[GPR_HASH_POINTER(timer, g_num_shards)];
gpr_mu_lock(&shard->mu);
if (grpc_timer_trace.enabled()) {
gpr_log(GPR_DEBUG, "TIMER %p: CANCEL pending=%s", timer,
gpr_log(GPR_INFO, "TIMER %p: CANCEL pending=%s", timer,
timer->pending ? "true" : "false");
}
@ -475,7 +475,7 @@ static int refill_heap(timer_shard* shard, gpr_atm now) {
static_cast<gpr_atm>(deadline_delta * 1000.0));
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. shard[%d]->queue_deadline_cap --> %" PRIdPTR,
gpr_log(GPR_INFO, " .. shard[%d]->queue_deadline_cap --> %" PRIdPTR,
static_cast<int>(shard - g_shards), shard->queue_deadline_cap);
}
for (timer = shard->list.next; timer != &shard->list; timer = next) {
@ -483,7 +483,7 @@ static int refill_heap(timer_shard* shard, gpr_atm now) {
if (timer->deadline < shard->queue_deadline_cap) {
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. add timer with deadline %" PRIdPTR " to heap",
gpr_log(GPR_INFO, " .. add timer with deadline %" PRIdPTR " to heap",
timer->deadline);
}
list_remove(timer);
@ -500,7 +500,7 @@ static grpc_timer* pop_one(timer_shard* shard, gpr_atm now) {
grpc_timer* timer;
for (;;) {
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. shard[%d]: heap_empty=%s",
gpr_log(GPR_INFO, " .. shard[%d]: heap_empty=%s",
static_cast<int>(shard - g_shards),
grpc_timer_heap_is_empty(&shard->heap) ? "true" : "false");
}
@ -510,13 +510,13 @@ static grpc_timer* pop_one(timer_shard* shard, gpr_atm now) {
}
timer = grpc_timer_heap_top(&shard->heap);
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
" .. check top timer deadline=%" PRIdPTR " now=%" PRIdPTR,
timer->deadline, now);
}
if (timer->deadline > now) return nullptr;
if (grpc_timer_trace.enabled()) {
gpr_log(GPR_DEBUG, "TIMER %p: FIRE %" PRIdPTR "ms late via %s scheduler",
gpr_log(GPR_INFO, "TIMER %p: FIRE %" PRIdPTR "ms late via %s scheduler",
timer, now - timer->deadline,
timer->closure->scheduler->vtable->name);
}
@ -540,7 +540,7 @@ static size_t pop_timers(timer_shard* shard, gpr_atm now,
*new_min_deadline = compute_min_deadline(shard);
gpr_mu_unlock(&shard->mu);
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. shard[%d] popped %" PRIdPTR,
gpr_log(GPR_INFO, " .. shard[%d] popped %" PRIdPTR,
static_cast<int>(shard - g_shards), n);
}
return n;
@ -563,7 +563,7 @@ static grpc_timer_check_result run_some_expired_timers(gpr_atm now,
result = GRPC_TIMERS_CHECKED_AND_EMPTY;
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, " .. shard[%d]->min_deadline = %" PRIdPTR,
gpr_log(GPR_INFO, " .. shard[%d]->min_deadline = %" PRIdPTR,
static_cast<int>(g_shard_queue[0] - g_shards),
g_shard_queue[0]->min_deadline);
}
@ -580,7 +580,7 @@ static grpc_timer_check_result run_some_expired_timers(gpr_atm now,
}
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
" .. result --> %d"
", shard[%d]->min_deadline %" PRIdPTR " --> %" PRIdPTR
", now=%" PRIdPTR,
@ -624,7 +624,7 @@ static grpc_timer_check_result timer_check(grpc_millis* next) {
*next = GPR_MIN(*next, min_timer);
}
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"TIMER CHECK SKIP: now=%" PRIdPTR " min_timer=%" PRIdPTR, now,
min_timer);
}
@ -644,7 +644,7 @@ static grpc_timer_check_result timer_check(grpc_millis* next) {
} else {
gpr_asprintf(&next_str, "%" PRIdPTR, *next);
}
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"TIMER CHECK BEGIN: now=%" PRIdPTR " next=%s tls_min=%" PRIdPTR
" glob_min=%" PRIdPTR,
now, next_str, gpr_tls_get(&g_last_seen_min_timer),
@ -662,7 +662,7 @@ static grpc_timer_check_result timer_check(grpc_millis* next) {
} else {
gpr_asprintf(&next_str, "%" PRIdPTR, *next);
}
gpr_log(GPR_DEBUG, "TIMER CHECK END: r=%d; next=%s", r, next_str);
gpr_log(GPR_INFO, "TIMER CHECK END: r=%d; next=%s", r, next_str);
gpr_free(next_str);
}
return r;

23
src/core/lib/iomgr/timer_manager.cc
Unescape View File

@ -82,7 +82,7 @@ static void start_timer_thread_and_unlock(void) {
++g_thread_count;
gpr_mu_unlock(&g_mu);
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, "Spawn timer thread");
gpr_log(GPR_INFO, "Spawn timer thread");
}
completed_thread* ct =
static_cast<completed_thread*>(gpr_malloc(sizeof(*ct)));
@ -108,7 +108,7 @@ static void run_some_timers() {
// waiter so that the next deadline is not missed
if (!g_has_timed_waiter) {
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, "kick untimed waiter");
gpr_log(GPR_INFO, "kick untimed waiter");
}
gpr_cv_signal(&g_cv_wait);
}
@ -116,7 +116,7 @@ static void run_some_timers() {
}
// without our lock, flush the exec_ctx
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, "flush exec_ctx");
gpr_log(GPR_INFO, "flush exec_ctx");
}
grpc_core::ExecCtx::Get()->Flush();
gpr_mu_lock(&g_mu);
@ -172,8 +172,7 @@ static bool wait_until(grpc_millis next) {
if (grpc_timer_check_trace.enabled()) {
grpc_millis wait_time = next - grpc_core::ExecCtx::Get()->Now();
gpr_log(GPR_DEBUG, "sleep for a %" PRIdPTR " milliseconds",
wait_time);
gpr_log(GPR_INFO, "sleep for a %" PRIdPTR " milliseconds", wait_time);
}
} else { // g_timed_waiter == true && next >= g_timed_waiter_deadline
next = GRPC_MILLIS_INF_FUTURE;
@ -181,14 +180,14 @@ static bool wait_until(grpc_millis next) {
}
if (grpc_timer_check_trace.enabled() && next == GRPC_MILLIS_INF_FUTURE) {
gpr_log(GPR_DEBUG, "sleep until kicked");
gpr_log(GPR_INFO, "sleep until kicked");
}
gpr_cv_wait(&g_cv_wait, &g_mu,
grpc_millis_to_timespec(next, GPR_CLOCK_MONOTONIC));
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, "wait ended: was_timed:%d kicked:%d",
gpr_log(GPR_INFO, "wait ended: was_timed:%d kicked:%d",
my_timed_waiter_generation == g_timed_waiter_generation,
g_kicked);
}
@ -233,7 +232,7 @@ static void timer_main_loop() {
Consequently, we can just sleep forever here and be happy at some
saved wakeup cycles. */
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, "timers not checked: expect another thread to");
gpr_log(GPR_INFO, "timers not checked: expect another thread to");
}
next = GRPC_MILLIS_INF_FUTURE;
/* fall through */
@ -259,7 +258,7 @@ static void timer_thread_cleanup(completed_thread* ct) {
g_completed_threads = ct;
gpr_mu_unlock(&g_mu);
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, "End timer thread");
gpr_log(GPR_INFO, "End timer thread");
}
}
@ -301,18 +300,18 @@ void grpc_timer_manager_init(void) {
static void stop_threads(void) {
gpr_mu_lock(&g_mu);
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, "stop timer threads: threaded=%d", g_threaded);
gpr_log(GPR_INFO, "stop timer threads: threaded=%d", g_threaded);
}
if (g_threaded) {
g_threaded = false;
gpr_cv_broadcast(&g_cv_wait);
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, "num timer threads: %d", g_thread_count);
gpr_log(GPR_INFO, "num timer threads: %d", g_thread_count);
}
while (g_thread_count > 0) {
gpr_cv_wait(&g_cv_shutdown, &g_mu, gpr_inf_future(GPR_CLOCK_MONOTONIC));
if (grpc_timer_check_trace.enabled()) {
gpr_log(GPR_DEBUG, "num timer threads: %d", g_thread_count);
gpr_log(GPR_INFO, "num timer threads: %d", g_thread_count);
}
gc_completed_threads();
}

4
src/core/lib/security/transport/secure_endpoint.cc
Unescape View File

@ -133,7 +133,7 @@ static void call_read_cb(secure_endpoint* ep, grpc_error* error) {
for (i = 0; i < ep->read_buffer->count; i++) {
char* data = grpc_dump_slice(ep->read_buffer->slices[i],
GPR_DUMP_HEX | GPR_DUMP_ASCII);
gpr_log(GPR_DEBUG, "READ %p: %s", ep, data);
gpr_log(GPR_INFO, "READ %p: %s", ep, data);
gpr_free(data);
}
}
@ -269,7 +269,7 @@ static void endpoint_write(grpc_endpoint* secure_ep, grpc_slice_buffer* slices,
for (i = 0; i < slices->count; i++) {
char* data =
grpc_dump_slice(slices->slices[i], GPR_DUMP_HEX | GPR_DUMP_ASCII);
gpr_log(GPR_DEBUG, "WRITE %p: %s", ep, data);
gpr_log(GPR_INFO, "WRITE %p: %s", ep, data);
gpr_free(data);
}
}

4
src/core/lib/surface/call.cc
Unescape View File

@ -747,10 +747,10 @@ static void get_final_status(
status[i] = unpack_received_status(gpr_atm_acq_load(&call->status[i]));
}
if (grpc_call_error_trace.enabled()) {
gpr_log(GPR_DEBUG, "get_final_status %s", call->is_client ? "CLI" : "SVR");
gpr_log(GPR_INFO, "get_final_status %s", call->is_client ? "CLI" : "SVR");
for (i = 0; i < STATUS_SOURCE_COUNT; i++) {
if (status[i].is_set) {
gpr_log(GPR_DEBUG, " %d: %s", i, grpc_error_string(status[i].error));
gpr_log(GPR_INFO, " %d: %s", i, grpc_error_string(status[i].error));
}
}
}

6
src/core/lib/transport/bdp_estimator.cc
Unescape View File

@ -47,7 +47,7 @@ grpc_millis BdpEstimator::CompletePing() {
double bw = dt > 0 ? (static_cast<double>(accumulator_) / dt) : 0;
int start_inter_ping_delay = inter_ping_delay_;
if (grpc_bdp_estimator_trace.enabled()) {
gpr_log(GPR_DEBUG,
gpr_log(GPR_INFO,
"bdp[%s]:complete acc=%" PRId64 " est=%" PRId64
" dt=%lf bw=%lfMbs bw_est=%lfMbs",
name_, accumulator_, estimate_, dt, bw / 125000.0,
@ -58,7 +58,7 @@ grpc_millis BdpEstimator::CompletePing() {
estimate_ = GPR_MAX(accumulator_, estimate_ * 2);
bw_est_ = bw;
if (grpc_bdp_estimator_trace.enabled()) {
gpr_log(GPR_DEBUG, "bdp[%s]: estimate increased to %" PRId64, name_,
gpr_log(GPR_INFO, "bdp[%s]: estimate increased to %" PRId64, name_,
estimate_);
}
inter_ping_delay_ /= 2; // if the ping estimate changes,
@ -75,7 +75,7 @@ grpc_millis BdpEstimator::CompletePing() {
if (start_inter_ping_delay != inter_ping_delay_) {
stable_estimate_count_ = 0;
if (grpc_bdp_estimator_trace.enabled()) {
gpr_log(GPR_DEBUG, "bdp[%s]:update_inter_time to %dms", name_,
gpr_log(GPR_INFO, "bdp[%s]:update_inter_time to %dms", name_,
inter_ping_delay_);
}
}

4
src/core/lib/transport/bdp_estimator.h
Unescape View File

@ -50,7 +50,7 @@ class BdpEstimator {
// transport (but not necessarily started)
void SchedulePing() {
if (grpc_bdp_estimator_trace.enabled()) {
gpr_log(GPR_DEBUG, "bdp[%s]:sched acc=%" PRId64 " est=%" PRId64, name_,
gpr_log(GPR_INFO, "bdp[%s]:sched acc=%" PRId64 " est=%" PRId64, name_,
accumulator_, estimate_);
}
GPR_ASSERT(ping_state_ == PingState::UNSCHEDULED);
@ -63,7 +63,7 @@ class BdpEstimator {
// the ping is on the wire
void StartPing() {
if (grpc_bdp_estimator_trace.enabled()) {
gpr_log(GPR_DEBUG, "bdp[%s]:start acc=%" PRId64 " est=%" PRId64, name_,
gpr_log(GPR_INFO, "bdp[%s]:start acc=%" PRId64 " est=%" PRId64, name_,
accumulator_, estimate_);
}
GPR_ASSERT(ping_state_ == PingState::SCHEDULED);

13
src/core/lib/transport/connectivity_state.cc
Unescape View File

@ -78,7 +78,7 @@ grpc_connectivity_state grpc_connectivity_state_check(
grpc_connectivity_state cur = static_cast<grpc_connectivity_state>(
gpr_atm_no_barrier_load(&tracker->current_state_atm));
if (grpc_connectivity_state_trace.enabled()) {
gpr_log(GPR_DEBUG, "CONWATCH: %p %s: get %s", tracker, tracker->name,
gpr_log(GPR_INFO, "CONWATCH: %p %s: get %s", tracker, tracker->name,
grpc_connectivity_state_name(cur));
}
return cur;
@ -89,7 +89,7 @@ grpc_connectivity_state grpc_connectivity_state_get(
grpc_connectivity_state cur = static_cast<grpc_connectivity_state>(
gpr_atm_no_barrier_load(&tracker->current_state_atm));
if (grpc_connectivity_state_trace.enabled()) {
gpr_log(GPR_DEBUG, "CONWATCH: %p %s: get %s", tracker, tracker->name,
gpr_log(GPR_INFO, "CONWATCH: %p %s: get %s", tracker, tracker->name,
grpc_connectivity_state_name(cur));
}
if (error != nullptr) {
@ -110,10 +110,10 @@ bool grpc_connectivity_state_notify_on_state_change(
gpr_atm_no_barrier_load(&tracker->current_state_atm));
if (grpc_connectivity_state_trace.enabled()) {
if (current == nullptr) {
gpr_log(GPR_DEBUG, "CONWATCH: %p %s: unsubscribe notify=%p", tracker,
gpr_log(GPR_INFO, "CONWATCH: %p %s: unsubscribe notify=%p", tracker,
tracker->name, notify);
} else {
gpr_log(GPR_DEBUG, "CONWATCH: %p %s: from %s [cur=%s] notify=%p", tracker,
gpr_log(GPR_INFO, "CONWATCH: %p %s: from %s [cur=%s] notify=%p", tracker,
tracker->name, grpc_connectivity_state_name(*current),
grpc_connectivity_state_name(cur), notify);
}
@ -161,7 +161,7 @@ void grpc_connectivity_state_set(grpc_connectivity_state_tracker* tracker,
grpc_connectivity_state_watcher* w;
if (grpc_connectivity_state_trace.enabled()) {
const char* error_string = grpc_error_string(error);
gpr_log(GPR_DEBUG, "SET: %p %s: %s --> %s [%s] error=%p %s", tracker,
gpr_log(GPR_INFO, "SET: %p %s: %s --> %s [%s] error=%p %s", tracker,
tracker->name, grpc_connectivity_state_name(cur),
grpc_connectivity_state_name(state), reason, error, error_string);
}
@ -187,8 +187,7 @@ void grpc_connectivity_state_set(grpc_connectivity_state_tracker* tracker,
*w->current = state;
tracker->watchers = w->next;
if (grpc_connectivity_state_trace.enabled()) {
gpr_log(GPR_DEBUG, "NOTIFY: %p %s: %p", tracker, tracker->name,
w->notify);
gpr_log(GPR_INFO, "NOTIFY: %p %s: %p", tracker, tracker->name, w->notify);
}
GRPC_CLOSURE_SCHED(w->notify, GRPC_ERROR_REF(tracker->current_error));
gpr_free(w);

Write Preview
Loading…
Cancel
Save