You are viewing a plain text version of this content. The canonical link for it is here.
Posted to server-dev@james.apache.org by rc...@apache.org on 2020/03/09 10:47:54 UTC

[james-project] 03/03: JAMES-3107 Log request when P99 is exceeded

This is an automated email from the ASF dual-hosted git repository.

rcordier pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/james-project.git

commit 26bac42462515862642b9aac0fec8a9858cfaee8
Author: Benoit Tellier <bt...@linagora.com>
AuthorDate: Sun Mar 8 14:17:15 2020 +0700

    JAMES-3107 Log request when P99 is exceeded
    
    Given our current tooling I struggle to correctly review slow requests
    from James.
    
    My current procedure is:
      - In grafana identify timestamp of a spike
      - Groke logs in kibana until I find something that could correspond
      - Pray and hope my analisys stands.
    
    This is both time consumming, hard to do and unreliable.
    
    Identifying slow queries is important as it can point us to critical
    path to optimize.
    
    Hence I propose to log an info message when p99 is exceeded for high
    level function (JMAP methods, IMAP processors, matcher mailet and
    overall processing, mailbox listeners, and remote delivery).
    
    In order to avoid log spamming I propose to only log when a
    function-specified threshold is exceeded (defaulting to 100ms)
    
    I belive it will help us coming up with more meaningful performance
    analysis and better fixes for the greater goods of our prduction
    platforms.
---
 .../mailbox/events/MailboxListenerExecutor.java    | 10 +++--
 .../apache/james/metrics/api/MetricFactory.java    | 11 +++++
 .../org/apache/james/metrics/api/TimeMetric.java   | 12 +++++-
 .../dropwizard/DropWizardMetricFactory.java        |  2 +-
 .../metrics/dropwizard/DropWizardTimeMetric.java   | 50 +++++++++++++++++++---
 .../james/metrics/logger/DefaultTimeMetric.java    | 22 +++++++++-
 .../james/metrics/tests/RecordingTimeMetric.java   | 26 +++++++++--
 .../imap/processor/AbstractMailboxProcessor.java   |  4 +-
 .../mailetcontainer/impl/JamesMailSpooler.java     |  4 +-
 .../mailetcontainer/impl/camel/CamelProcessor.java |  4 +-
 .../impl/camel/MatcherSplitter.java                |  4 +-
 .../mailets/remote/delivery/DeliveryRunnable.java  |  4 +-
 .../james/jmap/draft/AuthenticationServlet.java    |  4 +-
 .../james/jmap/draft/UserProvisioningFilter.java   |  4 +-
 .../james/jmap/draft/methods/GetFilterMethod.java  | 11 +++--
 .../jmap/draft/methods/GetMailboxesMethod.java     | 17 +++++---
 .../jmap/draft/methods/GetMessageListMethod.java   |  6 ++-
 .../jmap/draft/methods/GetMessagesMethod.java      | 18 ++++----
 .../draft/methods/GetVacationResponseMethod.java   | 12 +++---
 .../james/jmap/draft/methods/SendMDNProcessor.java |  2 +-
 .../james/jmap/draft/methods/SetFilterMethod.java  | 13 +++---
 .../jmap/draft/methods/SetMailboxesMethod.java     | 18 ++++----
 .../jmap/draft/methods/SetMessagesMethod.java      | 20 +++++----
 .../draft/methods/SetVacationResponseMethod.java   | 14 +++---
 24 files changed, 212 insertions(+), 80 deletions(-)

diff --git a/mailbox/event/event-rabbitmq/src/main/java/org/apache/james/mailbox/events/MailboxListenerExecutor.java b/mailbox/event/event-rabbitmq/src/main/java/org/apache/james/mailbox/events/MailboxListenerExecutor.java
index 696fa49..f96b448 100644
--- a/mailbox/event/event-rabbitmq/src/main/java/org/apache/james/mailbox/events/MailboxListenerExecutor.java
+++ b/mailbox/event/event-rabbitmq/src/main/java/org/apache/james/mailbox/events/MailboxListenerExecutor.java
@@ -36,11 +36,13 @@ public class MailboxListenerExecutor {
 
     void execute(MailboxListener listener, MDCBuilder mdcBuilder, Event event) throws Exception {
         if (listener.isHandling(event)) {
-            TimeMetric timer = metricFactory.timer(timerName(listener));
             try (Closeable mdc = buildMDC(listener, mdcBuilder, event)) {
-                listener.event(event);
-            } finally {
-                timer.stopAndPublish();
+                TimeMetric timer = metricFactory.timer(timerName(listener));
+                try {
+                    listener.event(event);
+                } finally {
+                    timer.stopAndPublish();
+                }
             }
         }
     }
diff --git a/metrics/metrics-api/src/main/java/org/apache/james/metrics/api/MetricFactory.java b/metrics/metrics-api/src/main/java/org/apache/james/metrics/api/MetricFactory.java
index a689b44..dbc8d93 100644
--- a/metrics/metrics-api/src/main/java/org/apache/james/metrics/api/MetricFactory.java
+++ b/metrics/metrics-api/src/main/java/org/apache/james/metrics/api/MetricFactory.java
@@ -19,6 +19,8 @@
 
 package org.apache.james.metrics.api;
 
+import static org.apache.james.metrics.api.TimeMetric.ExecutionResult.DEFAULT_100_MS_THRESHOLD;
+
 import java.util.function.Supplier;
 
 import org.reactivestreams.Publisher;
@@ -38,6 +40,15 @@ public interface MetricFactory {
         }
     }
 
+    default <T> T runPublishingTimerMetricLogP99(String name, Supplier<T> operation) {
+        TimeMetric timer = timer(name);
+        try {
+            return operation.get();
+        } finally {
+            timer.stopAndPublish().logWhenExceedP99(DEFAULT_100_MS_THRESHOLD);
+        }
+    }
+
     <T> Publisher<T> runPublishingTimerMetric(String name, Publisher<T> publisher);
 
     default void runPublishingTimerMetric(String name, Runnable runnable) {
diff --git a/metrics/metrics-api/src/main/java/org/apache/james/metrics/api/TimeMetric.java b/metrics/metrics-api/src/main/java/org/apache/james/metrics/api/TimeMetric.java
index 63220a7..5424203 100644
--- a/metrics/metrics-api/src/main/java/org/apache/james/metrics/api/TimeMetric.java
+++ b/metrics/metrics-api/src/main/java/org/apache/james/metrics/api/TimeMetric.java
@@ -18,10 +18,20 @@
  ****************************************************************/
 package org.apache.james.metrics.api;
 
+import java.time.Duration;
+
 public interface TimeMetric {
 
+    interface ExecutionResult {
+        Duration DEFAULT_100_MS_THRESHOLD = Duration.ofMillis(100);
+
+        Duration elasped();
+
+        ExecutionResult logWhenExceedP99(Duration thresholdInNanoSeconds);
+    }
+
     String name();
 
-    long stopAndPublish();
+    ExecutionResult stopAndPublish();
 
 }
diff --git a/metrics/metrics-dropwizard/src/main/java/org/apache/james/metrics/dropwizard/DropWizardMetricFactory.java b/metrics/metrics-dropwizard/src/main/java/org/apache/james/metrics/dropwizard/DropWizardMetricFactory.java
index 8defd20..87e7a62 100644
--- a/metrics/metrics-dropwizard/src/main/java/org/apache/james/metrics/dropwizard/DropWizardMetricFactory.java
+++ b/metrics/metrics-dropwizard/src/main/java/org/apache/james/metrics/dropwizard/DropWizardMetricFactory.java
@@ -53,7 +53,7 @@ public class DropWizardMetricFactory implements MetricFactory, Startable {
 
     @Override
     public TimeMetric timer(String name) {
-        return new DropWizardTimeMetric(name, metricRegistry.timer(name).time());
+        return new DropWizardTimeMetric(name, metricRegistry.timer(name));
     }
 
     @Override
diff --git a/metrics/metrics-dropwizard/src/main/java/org/apache/james/metrics/dropwizard/DropWizardTimeMetric.java b/metrics/metrics-dropwizard/src/main/java/org/apache/james/metrics/dropwizard/DropWizardTimeMetric.java
index e5145fd..adf2c7a 100644
--- a/metrics/metrics-dropwizard/src/main/java/org/apache/james/metrics/dropwizard/DropWizardTimeMetric.java
+++ b/metrics/metrics-dropwizard/src/main/java/org/apache/james/metrics/dropwizard/DropWizardTimeMetric.java
@@ -19,18 +19,58 @@
 
 package org.apache.james.metrics.dropwizard;
 
+import java.time.Duration;
+
 import org.apache.james.metrics.api.TimeMetric;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import com.codahale.metrics.Timer;
+import com.google.common.base.Preconditions;
 
 public class DropWizardTimeMetric implements TimeMetric {
 
+    private static final Logger LOGGER = LoggerFactory.getLogger(DropWizardTimeMetric.class);
+
+    static class DropWizardExecutionResult implements ExecutionResult {
+        private final String name;
+        private final Duration elasped;
+        private final Duration p99;
+
+        DropWizardExecutionResult(String name, Duration elasped, Duration p99) {
+            Preconditions.checkNotNull(elasped);
+            Preconditions.checkNotNull(p99);
+            Preconditions.checkNotNull(name);
+
+            this.name = name;
+            this.elasped = elasped;
+            this.p99 = p99;
+        }
+
+        @Override
+        public Duration elasped() {
+            return elasped;
+        }
+
+        @Override
+        public ExecutionResult logWhenExceedP99(Duration thresholdInNanoSeconds) {
+            Preconditions.checkNotNull(thresholdInNanoSeconds);
+            if (elasped.compareTo(p99) > 0 && elasped.compareTo(thresholdInNanoSeconds) > 0) {
+                LOGGER.info("{} metrics took {} nano seconds to complete, exceeding its {} nano seconds p99",
+                    name, elasped, p99);
+            }
+            return this;
+        }
+    }
+
     private final String name;
-    private final Timer.Context time;
+    private final Timer.Context context;
+    private final Timer timer;
 
-    public DropWizardTimeMetric(String name, Timer.Context context) {
+    public DropWizardTimeMetric(String name, Timer timer) {
         this.name = name;
-        this.time = context;
+        this.timer = timer;
+        this.context = this.timer.time();
     }
 
     @Override
@@ -39,7 +79,7 @@ public class DropWizardTimeMetric implements TimeMetric {
     }
 
     @Override
-    public long stopAndPublish() {
-        return time.stop();
+    public ExecutionResult stopAndPublish() {
+        return new DropWizardExecutionResult(name, Duration.ofNanos(context.stop()), Duration.ofNanos(Math.round(timer.getSnapshot().get999thPercentile())));
     }
 }
diff --git a/metrics/metrics-logger/src/main/java/org/apache/james/metrics/logger/DefaultTimeMetric.java b/metrics/metrics-logger/src/main/java/org/apache/james/metrics/logger/DefaultTimeMetric.java
index 13f5609..959be89 100644
--- a/metrics/metrics-logger/src/main/java/org/apache/james/metrics/logger/DefaultTimeMetric.java
+++ b/metrics/metrics-logger/src/main/java/org/apache/james/metrics/logger/DefaultTimeMetric.java
@@ -18,6 +18,7 @@
  ****************************************************************/
 package org.apache.james.metrics.logger;
 
+import java.time.Duration;
 import java.util.concurrent.TimeUnit;
 
 import org.apache.james.metrics.api.TimeMetric;
@@ -25,6 +26,23 @@ import org.apache.james.metrics.api.TimeMetric;
 import com.google.common.base.Stopwatch;
 
 public class DefaultTimeMetric implements TimeMetric {
+    static class DefaultExecutionResult implements ExecutionResult {
+        private final Duration elasped;
+
+        DefaultExecutionResult(Duration elasped) {
+            this.elasped = elasped;
+        }
+
+        @Override
+        public Duration elasped() {
+            return elasped;
+        }
+
+        @Override
+        public ExecutionResult logWhenExceedP99(Duration thresholdInNanoSeconds) {
+            return this;
+        }
+    }
 
     private final String name;
     private final Stopwatch stopwatch;
@@ -40,10 +58,10 @@ public class DefaultTimeMetric implements TimeMetric {
     }
 
     @Override
-    public long stopAndPublish() {
+    public ExecutionResult stopAndPublish() {
         long elapsed = stopwatch.elapsed(TimeUnit.MILLISECONDS);
         DefaultMetricFactory.LOGGER.info("Time spent in {}: {} ms.", name, elapsed);
-        return elapsed;
+        return new DefaultExecutionResult(Duration.ofNanos(elapsed));
     }
 
 }
diff --git a/metrics/metrics-tests/src/main/java/org/apache/james/metrics/tests/RecordingTimeMetric.java b/metrics/metrics-tests/src/main/java/org/apache/james/metrics/tests/RecordingTimeMetric.java
index 87ed8bb..f982421 100644
--- a/metrics/metrics-tests/src/main/java/org/apache/james/metrics/tests/RecordingTimeMetric.java
+++ b/metrics/metrics-tests/src/main/java/org/apache/james/metrics/tests/RecordingTimeMetric.java
@@ -28,6 +28,24 @@ import org.apache.james.metrics.api.TimeMetric;
 import com.google.common.base.Stopwatch;
 
 public class RecordingTimeMetric implements TimeMetric {
+    static class DefaultExecutionResult implements ExecutionResult {
+        private final Duration elasped;
+
+        DefaultExecutionResult(Duration elasped) {
+            this.elasped = elasped;
+        }
+
+        @Override
+        public Duration elasped() {
+            return elasped;
+        }
+
+        @Override
+        public ExecutionResult logWhenExceedP99(Duration thresholdInNanoSeconds) {
+            return this;
+        }
+    }
+
     private final String name;
     private final Stopwatch stopwatch = Stopwatch.createStarted();
     private final Consumer<Duration> publishCallback;
@@ -43,9 +61,9 @@ public class RecordingTimeMetric implements TimeMetric {
     }
 
     @Override
-    public long stopAndPublish() {
-        long elapsed = stopwatch.elapsed(TimeUnit.NANOSECONDS);
-        publishCallback.accept(Duration.ofNanos(elapsed));
-        return elapsed;
+    public ExecutionResult stopAndPublish() {
+        Duration elapsed = Duration.ofNanos(stopwatch.elapsed(TimeUnit.NANOSECONDS));
+        publishCallback.accept(elapsed);
+        return new DefaultExecutionResult(elapsed);
     }
 }
diff --git a/protocols/imap/src/main/java/org/apache/james/imap/processor/AbstractMailboxProcessor.java b/protocols/imap/src/main/java/org/apache/james/imap/processor/AbstractMailboxProcessor.java
index bba3072..487e347 100644
--- a/protocols/imap/src/main/java/org/apache/james/imap/processor/AbstractMailboxProcessor.java
+++ b/protocols/imap/src/main/java/org/apache/james/imap/processor/AbstractMailboxProcessor.java
@@ -18,6 +18,8 @@
  ****************************************************************/
 package org.apache.james.imap.processor;
 
+import static org.apache.james.metrics.api.TimeMetric.ExecutionResult.DEFAULT_100_MS_THRESHOLD;
+
 import java.util.Collection;
 import java.util.HashSet;
 import java.util.Iterator;
@@ -105,7 +107,7 @@ public abstract class AbstractMailboxProcessor<R extends ImapRequest> extends Ab
             LOGGER.error("Unexpected error during IMAP processing", unexpectedException);
             no(acceptableMessage, responder, HumanReadableText.GENERIC_FAILURE_DURING_PROCESSING);
         }
-        timeMetric.stopAndPublish();
+        timeMetric.stopAndPublish().logWhenExceedP99(DEFAULT_100_MS_THRESHOLD);
     }
 
     protected void flags(Responder responder, SelectedMailbox selected) {
diff --git a/server/mailet/mailetcontainer-camel/src/main/java/org/apache/james/mailetcontainer/impl/JamesMailSpooler.java b/server/mailet/mailetcontainer-camel/src/main/java/org/apache/james/mailetcontainer/impl/JamesMailSpooler.java
index 63a67e7..29d5395 100644
--- a/server/mailet/mailetcontainer-camel/src/main/java/org/apache/james/mailetcontainer/impl/JamesMailSpooler.java
+++ b/server/mailet/mailetcontainer-camel/src/main/java/org/apache/james/mailetcontainer/impl/JamesMailSpooler.java
@@ -19,6 +19,8 @@
 
 package org.apache.james.mailetcontainer.impl;
 
+import static org.apache.james.metrics.api.TimeMetric.ExecutionResult.DEFAULT_100_MS_THRESHOLD;
+
 import java.util.concurrent.Executors;
 import java.util.concurrent.atomic.AtomicInteger;
 
@@ -119,7 +121,7 @@ public class JamesMailSpooler implements Disposable, Configurable, MailSpoolerMB
         try {
             return Mono.fromCallable(processingActive::incrementAndGet)
                 .flatMap(ignore -> processMail(queueItem).subscribeOn(spooler))
-                .doOnSuccess(any -> timeMetric.stopAndPublish())
+                .doOnSuccess(any -> timeMetric.stopAndPublish().logWhenExceedP99(DEFAULT_100_MS_THRESHOLD))
                 .doOnSuccess(any -> processingActive.decrementAndGet());
         } catch (Throwable e) {
             return Mono.error(e);
diff --git a/server/mailet/mailetcontainer-camel/src/main/java/org/apache/james/mailetcontainer/impl/camel/CamelProcessor.java b/server/mailet/mailetcontainer-camel/src/main/java/org/apache/james/mailetcontainer/impl/camel/CamelProcessor.java
index 346e738..678b938 100644
--- a/server/mailet/mailetcontainer-camel/src/main/java/org/apache/james/mailetcontainer/impl/camel/CamelProcessor.java
+++ b/server/mailet/mailetcontainer-camel/src/main/java/org/apache/james/mailetcontainer/impl/camel/CamelProcessor.java
@@ -18,6 +18,8 @@
  ****************************************************************/
 package org.apache.james.mailetcontainer.impl.camel;
 
+import static org.apache.james.metrics.api.TimeMetric.ExecutionResult.DEFAULT_100_MS_THRESHOLD;
+
 import java.io.Closeable;
 import java.util.List;
 import java.util.Locale;
@@ -97,7 +99,7 @@ public class CamelProcessor {
             }
 
         } finally {
-            timeMetric.stopAndPublish();
+            timeMetric.stopAndPublish().logWhenExceedP99(DEFAULT_100_MS_THRESHOLD);
             MailetPipelineLogging.logEndOfMailetProcess(mailet, mail);
             List<MailetProcessorListener> listeners = processor.getListeners();
             long complete = System.currentTimeMillis() - start;
diff --git a/server/mailet/mailetcontainer-camel/src/main/java/org/apache/james/mailetcontainer/impl/camel/MatcherSplitter.java b/server/mailet/mailetcontainer-camel/src/main/java/org/apache/james/mailetcontainer/impl/camel/MatcherSplitter.java
index 044dcf2..89c8b61 100644
--- a/server/mailet/mailetcontainer-camel/src/main/java/org/apache/james/mailetcontainer/impl/camel/MatcherSplitter.java
+++ b/server/mailet/mailetcontainer-camel/src/main/java/org/apache/james/mailetcontainer/impl/camel/MatcherSplitter.java
@@ -19,6 +19,8 @@
 
 package org.apache.james.mailetcontainer.impl.camel;
 
+import static org.apache.james.metrics.api.TimeMetric.ExecutionResult.DEFAULT_100_MS_THRESHOLD;
+
 import java.io.Closeable;
 import java.util.ArrayList;
 import java.util.Collection;
@@ -174,7 +176,7 @@ public class MatcherSplitter {
 
             return mails;
         } finally {
-            timeMetric.stopAndPublish();
+            timeMetric.stopAndPublish().logWhenExceedP99(DEFAULT_100_MS_THRESHOLD);
             long complete = System.currentTimeMillis() - start;
             List<MailetProcessorListener> listeners = container.getListeners();
             for (MailetProcessorListener listener : listeners) {
diff --git a/server/mailet/mailets/src/main/java/org/apache/james/transport/mailets/remote/delivery/DeliveryRunnable.java b/server/mailet/mailets/src/main/java/org/apache/james/transport/mailets/remote/delivery/DeliveryRunnable.java
index 0fa2b96..ec38617 100644
--- a/server/mailet/mailets/src/main/java/org/apache/james/transport/mailets/remote/delivery/DeliveryRunnable.java
+++ b/server/mailet/mailets/src/main/java/org/apache/james/transport/mailets/remote/delivery/DeliveryRunnable.java
@@ -19,6 +19,8 @@
 
 package org.apache.james.transport.mailets.remote.delivery;
 
+import static org.apache.james.metrics.api.TimeMetric.ExecutionResult.DEFAULT_100_MS_THRESHOLD;
+
 import java.time.Duration;
 import java.util.Date;
 import java.util.function.Supplier;
@@ -92,7 +94,7 @@ public class DeliveryRunnable implements Disposable {
         TimeMetric timeMetric = metricFactory.timer(REMOTE_DELIVERY_TRIAL);
         try {
             return processMail(queueItem)
-                .doOnSuccess(any -> timeMetric.stopAndPublish());
+                .doOnSuccess(any -> timeMetric.stopAndPublish().logWhenExceedP99(DEFAULT_100_MS_THRESHOLD));
         } catch (Throwable e) {
             return Mono.error(e);
         }
diff --git a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/AuthenticationServlet.java b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/AuthenticationServlet.java
index fff9423..67ec0d8 100644
--- a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/AuthenticationServlet.java
+++ b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/AuthenticationServlet.java
@@ -18,6 +18,8 @@
  ****************************************************************/
 package org.apache.james.jmap.draft;
 
+import static org.apache.james.metrics.api.TimeMetric.ExecutionResult.DEFAULT_100_MS_THRESHOLD;
+
 import java.io.IOException;
 
 import javax.inject.Inject;
@@ -97,7 +99,7 @@ public class AuthenticationServlet extends HttpServlet {
             LOG.error("Internal error", e);
             resp.sendError(HttpServletResponse.SC_INTERNAL_SERVER_ERROR);
         } finally {
-            timeMetric.stopAndPublish();
+            timeMetric.stopAndPublish().logWhenExceedP99(DEFAULT_100_MS_THRESHOLD);
         }
     }
     
diff --git a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/UserProvisioningFilter.java b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/UserProvisioningFilter.java
index ac17d58..573d863 100644
--- a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/UserProvisioningFilter.java
+++ b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/UserProvisioningFilter.java
@@ -18,6 +18,8 @@
  ****************************************************************/
 package org.apache.james.jmap.draft;
 
+import static org.apache.james.metrics.api.TimeMetric.ExecutionResult.DEFAULT_100_MS_THRESHOLD;
+
 import java.io.IOException;
 import java.util.Optional;
 import java.util.UUID;
@@ -77,7 +79,7 @@ public class UserProvisioningFilter implements Filter {
         } catch (UsersRepositoryException e) {
             throw new RuntimeException(e);
         } finally {
-            timeMetric.stopAndPublish();
+            timeMetric.stopAndPublish().logWhenExceedP99(DEFAULT_100_MS_THRESHOLD);
         }
     }
 
diff --git a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetFilterMethod.java b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetFilterMethod.java
index 441cb3e..390fb69 100644
--- a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetFilterMethod.java
+++ b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetFilterMethod.java
@@ -73,10 +73,13 @@ public class GetFilterMethod implements Method {
 
         GetFilterRequest filterRequest = (GetFilterRequest) request;
 
-        return metricFactory.runPublishingTimerMetric(JMAP_PREFIX + METHOD_NAME.getName(),
-            MDCBuilder.create()
-                .addContext(MDCBuilder.ACTION, "GET_FILTER")
-                .wrapArround(() -> process(methodCallId, mailboxSession, filterRequest)));
+
+        return MDCBuilder.create()
+            .addContext(MDCBuilder.ACTION, "GET_FILTER")
+            .wrapArround(
+                () -> metricFactory.runPublishingTimerMetricLogP99(JMAP_PREFIX + METHOD_NAME.getName(),
+                    () -> process(methodCallId, mailboxSession, filterRequest)))
+            .get();
     }
 
     private Stream<JmapResponse> process(MethodCallId methodCallId, MailboxSession mailboxSession, GetFilterRequest request) {
diff --git a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetMailboxesMethod.java b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetMailboxesMethod.java
index 64623d1..375524f 100644
--- a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetMailboxesMethod.java
+++ b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetMailboxesMethod.java
@@ -91,13 +91,16 @@ public class GetMailboxesMethod implements Method {
     public Stream<JmapResponse> process(JmapRequest request, MethodCallId methodCallId, MailboxSession mailboxSession) {
         Preconditions.checkArgument(request instanceof GetMailboxesRequest);
         GetMailboxesRequest mailboxesRequest = (GetMailboxesRequest) request;
-        return metricFactory.runPublishingTimerMetric(JMAP_PREFIX + METHOD_NAME.getName(),
-            MDCBuilder.create()
-                .addContext(MDCBuilder.ACTION, "GET_MAILBOXES")
-                .addContext("accountId", mailboxesRequest.getAccountId())
-                .addContext("mailboxIds", mailboxesRequest.getIds())
-                .addContext("properties", mailboxesRequest.getProperties())
-                .wrapArround(() -> process(methodCallId, mailboxSession, mailboxesRequest)));
+
+        return MDCBuilder.create()
+            .addContext(MDCBuilder.ACTION, "GET_MAILBOXES")
+            .addContext("accountId", mailboxesRequest.getAccountId())
+            .addContext("mailboxIds", mailboxesRequest.getIds())
+            .addContext("properties", mailboxesRequest.getProperties())
+            .wrapArround(
+                () -> metricFactory.runPublishingTimerMetricLogP99(JMAP_PREFIX + METHOD_NAME.getName(),
+                    () -> process(methodCallId, mailboxSession, mailboxesRequest)))
+            .get();
     }
 
     private Stream<JmapResponse> process(MethodCallId methodCallId, MailboxSession mailboxSession, GetMailboxesRequest mailboxesRequest) {
diff --git a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetMessageListMethod.java b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetMessageListMethod.java
index 9946ae6..eb6e66e 100644
--- a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetMessageListMethod.java
+++ b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetMessageListMethod.java
@@ -94,7 +94,7 @@ public class GetMessageListMethod implements Method {
 
         GetMessageListRequest messageListRequest = (GetMessageListRequest) request;
 
-        return metricFactory.runPublishingTimerMetric(JMAP_PREFIX + METHOD_NAME.getName(), MDCBuilder.create()
+        return MDCBuilder.create()
             .addContext(MDCBuilder.ACTION, "GET_MESSAGE_LIST")
             .addContext("accountId", messageListRequest.getAccountId())
             .addContext("limit", messageListRequest.getLimit())
@@ -107,7 +107,9 @@ public class GetMessageListMethod implements Method {
             .addContext("isFetchMessage", messageListRequest.isFetchMessages())
             .addContext("isCollapseThread", messageListRequest.isCollapseThreads())
             .wrapArround(
-                () -> process(methodCallId, mailboxSession, messageListRequest)));
+                () -> metricFactory.runPublishingTimerMetricLogP99(JMAP_PREFIX + METHOD_NAME.getName(),
+                    () -> process(methodCallId, mailboxSession, messageListRequest)))
+            .get();
     }
 
     private Stream<JmapResponse> process(MethodCallId methodCallId, MailboxSession mailboxSession, GetMessageListRequest messageListRequest) {
diff --git a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetMessagesMethod.java b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetMessagesMethod.java
index a3e07e7..6602070 100644
--- a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetMessagesMethod.java
+++ b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetMessagesMethod.java
@@ -89,19 +89,21 @@ public class GetMessagesMethod implements Method {
         GetMessagesRequest getMessagesRequest = (GetMessagesRequest) request;
         MessageProperties outputProperties = getMessagesRequest.getProperties().toOutputProperties();
 
-        return metricFactory.runPublishingTimerMetric(JMAP_PREFIX + METHOD_NAME.getName(),
-            MDCBuilder.create()
-                .addContext(MDCBuilder.ACTION, "GET_MESSAGES")
-                .addContext("accountId", getMessagesRequest.getAccountId())
-                .addContext("ids", getMessagesRequest.getIds())
-                .addContext("properties", getMessagesRequest.getProperties())
-                .wrapArround(
+
+        return MDCBuilder.create()
+            .addContext(MDCBuilder.ACTION, "GET_MESSAGES")
+            .addContext("accountId", getMessagesRequest.getAccountId())
+            .addContext("ids", getMessagesRequest.getIds())
+            .addContext("properties", getMessagesRequest.getProperties())
+            .wrapArround(
+                () -> metricFactory.runPublishingTimerMetricLogP99(JMAP_PREFIX + METHOD_NAME.getName(),
                     () -> Stream.of(JmapResponse.builder().methodCallId(methodCallId)
                         .response(getMessagesResponse(mailboxSession, getMessagesRequest))
                         .responseName(RESPONSE_NAME)
                         .properties(outputProperties.getOptionalMessageProperties())
                         .filterProvider(buildOptionalHeadersFilteringFilterProvider(outputProperties))
-                        .build())));
+                        .build())))
+            .get();
     }
 
     private Optional<SimpleFilterProvider> buildOptionalHeadersFilteringFilterProvider(MessageProperties properties) {
diff --git a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetVacationResponseMethod.java b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetVacationResponseMethod.java
index ec75d41..6717312 100644
--- a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetVacationResponseMethod.java
+++ b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/GetVacationResponseMethod.java
@@ -70,15 +70,17 @@ public class GetVacationResponseMethod implements Method {
         Preconditions.checkNotNull(mailboxSession);
         Preconditions.checkArgument(request instanceof GetVacationRequest);
 
-        return metricFactory.runPublishingTimerMetric(JMAP_PREFIX + METHOD_NAME.getName(),
-            MDCBuilder.create()
-                .addContext(MDCBuilder.ACTION, "VACATION")
-                .wrapArround(
+
+        return MDCBuilder.create()
+            .addContext(MDCBuilder.ACTION, "VACATION")
+            .wrapArround(
+                () -> metricFactory.runPublishingTimerMetricLogP99(JMAP_PREFIX + METHOD_NAME.getName(),
                     () -> Stream.of(JmapResponse.builder()
                         .methodCallId(methodCallId)
                         .responseName(RESPONSE_NAME)
                         .response(process(mailboxSession))
-                        .build())));
+                        .build())))
+            .get();
     }
 
     private GetVacationResponse process(MailboxSession mailboxSession) {
diff --git a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SendMDNProcessor.java b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SendMDNProcessor.java
index 85e9068..9b782ec 100644
--- a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SendMDNProcessor.java
+++ b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SendMDNProcessor.java
@@ -84,7 +84,7 @@ public class SendMDNProcessor implements SetMessagesProcessor {
 
     @Override
     public SetMessagesResponse process(SetMessagesRequest request, MailboxSession mailboxSession) {
-        return metricFactory.runPublishingTimerMetric(JMAP_PREFIX + "SendMDN",
+        return metricFactory.runPublishingTimerMetricLogP99(JMAP_PREFIX + "SendMDN",
             () -> handleMDNCreation(request, mailboxSession));
     }
 
diff --git a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetFilterMethod.java b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetFilterMethod.java
index 57f1352..2cf6523 100644
--- a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetFilterMethod.java
+++ b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetFilterMethod.java
@@ -111,12 +111,13 @@ public class SetFilterMethod implements Method {
 
         SetFilterRequest setFilterRequest = (SetFilterRequest) request;
 
-        return metricFactory.runPublishingTimerMetric(JMAP_PREFIX + METHOD_NAME.getName(),
-            MDCBuilder.create()
-                .addContext(MDCBuilder.ACTION, "SET_FILTER")
-                .addContext("update", setFilterRequest.getSingleton())
-                .wrapArround(
-                    () -> process(methodCallId, mailboxSession, setFilterRequest)));
+        return MDCBuilder.create()
+            .addContext(MDCBuilder.ACTION, "SET_FILTER")
+            .addContext("update", setFilterRequest.getSingleton())
+            .wrapArround(
+                () -> metricFactory.runPublishingTimerMetricLogP99(JMAP_PREFIX + METHOD_NAME.getName(),
+                    () -> process(methodCallId, mailboxSession, setFilterRequest)))
+            .get();
     }
 
     private Stream<JmapResponse> process(MethodCallId methodCallId, MailboxSession mailboxSession, SetFilterRequest request) {
diff --git a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetMailboxesMethod.java b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetMailboxesMethod.java
index 7b4bf27..56f6ed9 100644
--- a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetMailboxesMethod.java
+++ b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetMailboxesMethod.java
@@ -67,18 +67,20 @@ public class SetMailboxesMethod implements Method {
 
         SetMailboxesRequest setMailboxesRequest = (SetMailboxesRequest) request;
 
-        return metricFactory.runPublishingTimerMetric(JMAP_PREFIX + METHOD_NAME.getName(),
-            MDCBuilder.create()
-                .addContext(MDCBuilder.ACTION, "SET_MAILBOXES")
-                .addContext("create", setMailboxesRequest.getCreate())
-                .addContext("update", setMailboxesRequest.getUpdate())
-                .addContext("destroy", setMailboxesRequest.getDestroy())
-                .wrapArround(
+
+        return MDCBuilder.create()
+            .addContext(MDCBuilder.ACTION, "SET_MAILBOXES")
+            .addContext("create", setMailboxesRequest.getCreate())
+            .addContext("update", setMailboxesRequest.getUpdate())
+            .addContext("destroy", setMailboxesRequest.getDestroy())
+            .wrapArround(
+                () -> metricFactory.runPublishingTimerMetricLogP99(JMAP_PREFIX + METHOD_NAME.getName(),
                     () -> Stream.of(
                         JmapResponse.builder().methodCallId(methodCallId)
                             .response(setMailboxesResponse(setMailboxesRequest, mailboxSession))
                             .responseName(RESPONSE_NAME)
-                            .build())));
+                            .build())))
+            .get();
     }
 
     private SetMailboxesResponse setMailboxesResponse(SetMailboxesRequest request, MailboxSession mailboxSession) {
diff --git a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetMessagesMethod.java b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetMessagesMethod.java
index 407a07c..886896d 100644
--- a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetMessagesMethod.java
+++ b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetMessagesMethod.java
@@ -63,19 +63,21 @@ public class SetMessagesMethod implements Method {
         Preconditions.checkArgument(request instanceof SetMessagesRequest);
         SetMessagesRequest setMessagesRequest = (SetMessagesRequest) request;
 
-        return metricFactory.runPublishingTimerMetric(JMAP_PREFIX + METHOD_NAME.getName(),
-            MDCBuilder.create()
-                .addContext(MDCBuilder.ACTION, "SET_MESSAGES")
-                .addContext("accountId", setMessagesRequest.getAccountId())
-                .addContext("create", setMessagesRequest.getCreate())
-                .addContext("destroy", setMessagesRequest.getDestroy())
-                .addContext("ifInState", setMessagesRequest.getIfInState())
-                .wrapArround(
+
+        return MDCBuilder.create()
+            .addContext(MDCBuilder.ACTION, "SET_MESSAGES")
+            .addContext("accountId", setMessagesRequest.getAccountId())
+            .addContext("create", setMessagesRequest.getCreate())
+            .addContext("destroy", setMessagesRequest.getDestroy())
+            .addContext("ifInState", setMessagesRequest.getIfInState())
+            .wrapArround(
+                () -> metricFactory.runPublishingTimerMetricLogP99(JMAP_PREFIX + METHOD_NAME.getName(),
                     () ->  Stream.of(
                         JmapResponse.builder().methodCallId(methodCallId)
                             .response(setMessagesResponse(setMessagesRequest, mailboxSession))
                             .responseName(RESPONSE_NAME)
-                            .build())));
+                            .build())))
+            .get();
     }
 
     private SetMessagesResponse setMessagesResponse(SetMessagesRequest request, MailboxSession mailboxSession) {
diff --git a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetVacationResponseMethod.java b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetVacationResponseMethod.java
index 3ee44b4..0f11529 100644
--- a/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetVacationResponseMethod.java
+++ b/server/protocols/jmap-draft/src/main/java/org/apache/james/jmap/draft/methods/SetVacationResponseMethod.java
@@ -76,12 +76,14 @@ public class SetVacationResponseMethod implements Method {
         Preconditions.checkArgument(request instanceof SetVacationRequest);
         SetVacationRequest setVacationRequest = (SetVacationRequest) request;
 
-        return metricFactory.runPublishingTimerMetric(JMAP_PREFIX + METHOD_NAME.getName(),
-            MDCBuilder.create()
-                .addContext(MDCBuilder.ACTION, "SET_VACATION")
-                .addContext("update", setVacationRequest.getUpdate())
-                .wrapArround(
-                    () -> process(methodCallId, mailboxSession, setVacationRequest)));
+
+        return MDCBuilder.create()
+            .addContext(MDCBuilder.ACTION, "SET_VACATION")
+            .addContext("update", setVacationRequest.getUpdate())
+            .wrapArround(
+                () -> metricFactory.runPublishingTimerMetricLogP99(JMAP_PREFIX + METHOD_NAME.getName(),
+                    () -> process(methodCallId, mailboxSession, setVacationRequest)))
+            .get();
     }
 
     private Stream<JmapResponse> process(MethodCallId methodCallId, MailboxSession mailboxSession, SetVacationRequest setVacationRequest) {


---------------------------------------------------------------------
To unsubscribe, e-mail: server-dev-unsubscribe@james.apache.org
For additional commands, e-mail: server-dev-help@james.apache.org