Add basic logging for async operation processing time

We're already storing this as a metric, but on a registry of our
scale these operations tend to only happen on a daily-ish basis,
for which seeing results in logs is easier to deal with than metrics
(and also still very light-weight).

-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=160552291
This commit is contained in:
mcilwain 2017-06-29 11:39:31 -07:00 committed by Ben McIlwain
parent aed4f56112
commit 80f8f5ac7f

View file

@ -18,6 +18,7 @@ import static com.google.appengine.api.taskqueue.QueueConstants.maxLeaseCount;
import static google.registry.flows.async.AsyncFlowMetrics.OperationType.CONTACT_AND_HOST_DELETE;
import static google.registry.flows.async.AsyncFlowMetrics.OperationType.DNS_REFRESH;
import static google.registry.monitoring.metrics.EventMetric.DEFAULT_FITTER;
import static google.registry.util.FormattingLogger.getLoggerForCallerClass;
import com.google.common.annotations.VisibleForTesting;
import com.google.common.collect.ImmutableSet;
@ -28,6 +29,7 @@ import google.registry.monitoring.metrics.IncrementableMetric;
import google.registry.monitoring.metrics.LabelDescriptor;
import google.registry.monitoring.metrics.MetricRegistryImpl;
import google.registry.util.Clock;
import google.registry.util.FormattingLogger;
import google.registry.util.NonFinalForTesting;
import javax.inject.Inject;
import org.joda.time.DateTime;
@ -40,6 +42,8 @@ import org.joda.time.Duration;
*/
public class AsyncFlowMetrics {
private static final FormattingLogger logger = getLoggerForCallerClass();
private final Clock clock;
@Inject
@ -144,10 +148,16 @@ public class AsyncFlowMetrics {
OperationType operationType, OperationResult operationResult, DateTime whenEnqueued) {
asyncFlowOperationCounts.increment(
operationType.getMetricLabelValue(), operationResult.getMetricLabelValue());
long processingMillis = new Duration(whenEnqueued, clock.nowUtc()).getMillis();
asyncFlowOperationProcessingTime.record(
new Duration(whenEnqueued, clock.nowUtc()).getMillis(),
processingMillis,
operationType.getMetricLabelValue(),
operationResult.getMetricLabelValue());
logger.infofmt(
"Asynchronous %s operation took %d ms to process, yielding result: %s.",
operationType.getMetricLabelValue(),
processingMillis,
operationResult.getMetricLabelValue());
}
public void recordContactHostDeletionBatchSize(long batchSize) {