resolver_wrapper: add early return in addChannelzTraceEvent

[jsm]

Note: this is a degradation introduced in this PR: #5192

Which used to wrap calls to addChannelzTraceEvent in a if channelz.IsOn() {

Problem

Large and frequent calls to this method in UpdateState can cause an extremely high usage of CPU time and Memory due to underlying json.Marshal calls that are not used or needed if were not Info level logging as it is.

Alternative approach to: #7436

Pprofs

RELEASE NOTES: none

[codecov]

Codecov Report

Attention: Patch coverage is 0% with 2 lines in your changes missing coverage. Please review.

Project coverage is 81.31%. Comparing base (ac5a7fe) to head (9ec7522).
Report is 12 commits behind head on master.

Files	Patch %	Lines
resolver_wrapper.go	0.00%	1 Missing and 1 partial ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##           master    #7437      +/-   ##
==========================================
- Coverage   81.33%   81.31%   -0.03%     
==========================================
  Files         352      354       +2     
  Lines       26919    27080     +161     
==========================================
+ Hits        21895    22020     +125     
- Misses       3824     3844      +20     
- Partials     1200     1216      +16     

Files	Coverage Δ
resolver_wrapper.go	83.33% <0.00%> (-1.78%)	⬇️

... and 28 files with indirect coverage changes

[jsm]

Note: this is a degradation introduced in this PR: #5192

Which used to wrap calls to addChannelzTraceEvent in a if channelz.IsOn() {

[arjan-bal]

Hi @jsm, thanks for reporting the issue and contributing the fix!
The method that is called through addChannelzTraceEvent is AddTraceEvent:

grpc-go/internal/channelz/trace.go

Lines 182 to 204 in 0b33bfe

	// AddTraceEvent adds trace related to the entity with specified id, using the
	// provided TraceEventDesc.
	//
	// If channelz is not turned ON, this will simply log the event descriptions.
	func AddTraceEvent(l grpclog.DepthLoggerV2, e Entity, depth int, desc *TraceEvent) {
	// Log only the trace description associated with the bottom most entity.
	d := fmt.Sprintf("[%s]%s", e, desc.Desc)
	switch desc.Severity {
	case CtUnknown, CtInfo:
	l.InfoDepth(depth+1, d)
	case CtWarning:
	l.WarningDepth(depth+1, d)
	case CtError:
	l.ErrorDepth(depth+1, d)
	}
	if getMaxTraceEntry() == 0 {
	return
	}
	if IsOn() {
	db.traceEvent(e.id(), desc)
	}
	}

AddTraceEvent logs the event even if channelz is disabled. To retain the same behaviour, you should combine the conditions from both the PRs: if !logger.V(0) && !channelz.IsOn() before returning early.

[arjan-bal]

LGTM, adding another reviewer for a second approval.

[dfawley]

Logging is typically enabled. Maybe we should also be looking to remove the use of pretty.ToJSON for the purpose of printing this struct? Would %+v or %#v not work just as well?

[jsm]

Would %+v or %#v not work just as well?

I looked into this. The format call is still made before any checks to the log level or if channelz is on. We would have to refactor how channelz works for it to return before doing any format calls.

It could prevent the json Marshalling expense, but I'm not sure if %+v or %#v are particularly cheaper?

[dfawley]

I suspect %v is faster than JSON marshalling, but I haven't benchmarked it. It also should be able to avoid any formatting unless the logging is actually happening.