Bugfix/lowering log volume (#6847)

In our zeal to debug some things we made the logs a bit noisy, lowering the volume for now.
minor renaming of a method call to more accurately reflect that it's called on domain update

Author: davidporter-id-au

common/cache/domainCache.go

@@ -533,6 +533,7 @@ UpdateLoop:
 	if now.Sub(c.lastCallbackEmitTime) > 30*time.Minute {
 		c.lastCallbackEmitTime = now
 		c.scope.AddCounter(metrics.DomainCacheCallbacksCount, int64(len(c.callbacks)))
+		c.scope.RecordHistogramDuration(metrics.DomainCacheUpdateLatency, c.timeSource.Now().Sub(now))
 	}
 
 	return nil

common/log/tag/tags.go

@@ -229,6 +229,10 @@ func WorkflowTerminationReason(reason string) Tag {
 	return newStringTag("wf-termination-reason", reason)
 }
 
+func Duration(duration time.Duration) Tag {
+	return newDurationTag("duration", duration)
+}
+
 // domain related
 
 // WorkflowDomainID returns tag for WorkflowDomainID

common/metrics/defs.go

@@ -2275,6 +2275,7 @@ const (
 
 	DomainReplicationQueueSizeGauge
 	DomainReplicationQueueSizeErrorCount
+	DomainCacheUpdateLatency
 
 	ParentClosePolicyProcessorSuccess
 	ParentClosePolicyProcessorFailures
@@ -3022,6 +3023,7 @@ var MetricDefs = map[ServiceIdx]map[int]metricDefinition{
 		CadenceShardFailureGauge:             {metricName: "cadence_shard_failure", metricType: Gauge},
 		DomainReplicationQueueSizeGauge:      {metricName: "domain_replication_queue_size", metricType: Gauge},
 		DomainReplicationQueueSizeErrorCount: {metricName: "domain_replication_queue_failed", metricType: Counter},
+		DomainCacheUpdateLatency:             {metricName: "domain_cache_update_latency", metricType: Histogram, buckets: DomainCacheUpdateBuckets},
 		ParentClosePolicyProcessorSuccess:    {metricName: "parent_close_policy_processor_requests", metricType: Counter},
 		ParentClosePolicyProcessorFailures:   {metricName: "parent_close_policy_processor_errors", metricType: Counter},
 
@@ -3620,6 +3622,12 @@ var ResponseRowSizeBuckets = append(
 	tally.MustMakeExponentialValueBuckets(1, 2, 17)..., // 1..65536
 )
 
+// DomainCacheUpdateBuckets contain metric results for domain update operations
+var DomainCacheUpdateBuckets = append(
+	tally.ValueBuckets{0},                              // need an explicit 0 or zero is reported as 1
+	tally.MustMakeExponentialValueBuckets(1, 2, 17)..., // 1..65536
+)
+
 // ResponsePayloadSizeBuckets contains buckets for tracking the size of the payload returned per persistence operation
 var ResponsePayloadSizeBuckets = append(
 	tally.ValueBuckets{0},                                 // need an explicit 0 or zero is reported as 1

service/history/engine/engineimpl/register_domain_failover_callback.go

@@ -57,14 +57,14 @@ func (e *historyEngineImpl) registerDomainFailoverCallback() {
 	e.shard.GetDomainCache().RegisterDomainChangeCallback(
 		e.shard.GetShardID(),
 		e.shard.GetDomainNotificationVersion(),
-		e.lockProcessingForFailover,
+		e.lockTaskProcessingForDomainUpdate,
 		e.domainChangeCB,
 	)
 }
 
 func (e *historyEngineImpl) domainChangeCB(nextDomains []*cache.DomainCacheEntry) {
 	defer func() {
-		e.unlockProcessingForFailover()
+		e.unlockProcessingForDomainUpdate()
 	}()
 
 	if len(nextDomains) == 0 {
@@ -149,14 +149,14 @@ func (e *historyEngineImpl) generateGracefulFailoverTasksForDomainUpdateCallback
 	return failoverMarkerTasks
 }
 
-func (e *historyEngineImpl) lockProcessingForFailover() {
-	e.logger.Info("Locking processing for failover")
+func (e *historyEngineImpl) lockTaskProcessingForDomainUpdate() {
+	e.logger.Debug("Locking processing for domain update")
 	e.txProcessor.LockTaskProcessing()
 	e.timerProcessor.LockTaskProcessing()
 }
 
-func (e *historyEngineImpl) unlockProcessingForFailover() {
-	e.logger.Info("Unlocking processing for failover")
+func (e *historyEngineImpl) unlockProcessingForDomainUpdate() {
+	e.logger.Debug("Unlocking processing for failover")
 	e.txProcessor.UnlockTaskProcessing()
 	e.timerProcessor.UnlockTaskProcessing()
 }

service/history/engine/engineimpl/register_domain_failover_callback_test.go

@@ -674,6 +674,6 @@ func TestDomainLocking(t *testing.T) {
 		shard:              shardCtx,
 	}
 
-	he.lockProcessingForFailover()
-	he.unlockProcessingForFailover()
+	he.lockTaskProcessingForDomainUpdate()
+	he.unlockProcessingForDomainUpdate()
 }

service/history/queue/timer_queue_processor.go

@@ -386,12 +386,12 @@ func (t *timerQueueProcessor) HandleAction(ctx context.Context, clusterName stri
 }
 
 func (t *timerQueueProcessor) LockTaskProcessing() {
-	t.logger.Info("Timer queue processor locking task processing")
+	t.logger.Debug("Timer queue processor locking task processing")
 	t.taskAllocator.Lock()
 }
 
 func (t *timerQueueProcessor) UnlockTaskProcessing() {
-	t.logger.Info("Timer queue processor unlocking task processing")
+	t.logger.Debug("Timer queue processor unlocking task processing")
 	t.taskAllocator.Unlock()
 }
 

service/history/queue/transfer_queue_processor.go

@@ -353,12 +353,12 @@ func (t *transferQueueProcessor) HandleAction(
 }
 
 func (t *transferQueueProcessor) LockTaskProcessing() {
-	t.logger.Info("Transfer queue processor locking task processing")
+	t.logger.Debug("Transfer queue processor locking task processing")
 	t.taskAllocator.Lock()
 }
 
 func (t *transferQueueProcessor) UnlockTaskProcessing() {
-	t.logger.Info("Transfer queue processor unlocking task processing")
+	t.logger.Debug("Transfer queue processor unlocking task processing")
 	t.taskAllocator.Unlock()
 }