From b0c5c0baa85fba563c80ee416cecc22e9ffbf53a Mon Sep 17 00:00:00 2001
From: Xuerui Fa <xuerui.fa@mongodb.com>
Date: Mon, 27 Jan 2020 18:17:01 -0500
Subject: SERVER-43069: Condition logging for slow ops on sample rate

 create mode 100644 src/mongo/util/log_with_sampling.h
 create mode 100644 src/mongo/util/log_with_sampling_test.cpp
---
 src/mongo/db/repl/oplog_applier_impl.cpp | 19 ++++++++++++-------
 1 file changed, 12 insertions(+), 7 deletions(-)

(limited to 'src/mongo/db/repl/oplog_applier_impl.cpp')

diff --git a/src/mongo/db/repl/oplog_applier_impl.cpp b/src/mongo/db/repl/oplog_applier_impl.cpp
index 8b7d7ba3c41..1ac70f2a05e 100644
--- a/src/mongo/db/repl/oplog_applier_impl.cpp
+++ b/src/mongo/db/repl/oplog_applier_impl.cpp
@@ -48,6 +48,7 @@
 #include "mongo/platform/basic.h"
 #include "mongo/util/fail_point.h"
 #include "mongo/util/log.h"
+#include "mongo/util/log_with_sampling.h"
 #include "third_party/murmurhash3/MurmurHash3.h"
 
 namespace mongo {
@@ -96,17 +97,21 @@ NamespaceStringOrUUID getNsOrUUID(const NamespaceString& nss, const OplogEntry&
  * Used for logging a report of ops that take longer than "slowMS" to apply. This is called
  * right before returning from applyOplogEntryOrGroupedInserts, and it returns the same status.
  */
-Status finishAndLogApply(ClockSource* clockSource,
+Status finishAndLogApply(OperationContext* opCtx,
+                         ClockSource* clockSource,
                          Status finalStatus,
                          Date_t applyStartTime,
                          const OplogEntryOrGroupedInserts& entryOrGroupedInserts) {
 
     if (finalStatus.isOK()) {
         auto applyEndTime = clockSource->now();
-        auto diffMS = durationCount<Milliseconds>(applyEndTime - applyStartTime);
+        auto opDuration = durationCount<Milliseconds>(applyEndTime - applyStartTime);
 
-        // This op was slow to apply, so we should log a report of it.
-        if (diffMS > serverGlobalParams.slowMS) {
+        if (shouldLogSlowOpWithSampling(opCtx,
+                                        MONGO_LOG_DEFAULT_COMPONENT,
+                                        Milliseconds(opDuration),
+                                        Milliseconds(serverGlobalParams.slowMS))
+                .first) {
 
             StringBuilder s;
             s << "applied op: ";
@@ -118,7 +123,7 @@ Status finishAndLogApply(ClockSource* clockSource,
             }
 
             s << redact(entryOrGroupedInserts.toBSON());
-            s << ", took " << diffMS << "ms";
+            s << ", took " << opDuration << "ms";
 
             log() << s.str();
         }
@@ -971,7 +976,7 @@ Status applyOplogEntryOrGroupedInserts(OperationContext* opCtx,
                     throw;
                 }
             });
-        return finishAndLogApply(clockSource, status, applyStartTime, entryOrGroupedInserts);
+        return finishAndLogApply(opCtx, clockSource, status, applyStartTime, entryOrGroupedInserts);
     } else if (opType == OpTypeEnum::kCommand) {
         auto status =
             writeConflictRetry(opCtx, "applyOplogEntryOrGroupedInserts_command", nss.ns(), [&] {
@@ -980,7 +985,7 @@ Status applyOplogEntryOrGroupedInserts(OperationContext* opCtx,
                 incrementOpsAppliedStats();
                 return status;
             });
-        return finishAndLogApply(clockSource, status, applyStartTime, entryOrGroupedInserts);
+        return finishAndLogApply(opCtx, clockSource, status, applyStartTime, entryOrGroupedInserts);
     }
 
     MONGO_UNREACHABLE;
-- 
cgit v1.2.1