1
// Copyright (c) 2017-2024 Cloudflare, Inc.
2
// Licensed under the Apache 2.0 license found in the LICENSE file or at:
3
//     https://opensource.org/licenses/Apache-2.0
4
 
5
#pragma once
6
 
7
#include <kj/debug.h>
8
#include <kj/string.h>
9
#include <kj/time.h>
10
 
11
namespace workerd::util {
12
 
13
// This is a utility class for instantiating a timer, which will log if it's destructed after a
14
// specified time. This works by relying on RAII (Scope-Bound Resource Management) to check how
15
// much time has elapsed when the object is destructed. This ensures that the time is checked when
16
// the timer object goes out of scope, thereby timing everything after the initialization of the
17
// timer until the end of the scope where it was instantiated.
18
//
19
// For the simple case (no extra parameters), construct directly:
20
//
21
//   DurationExceededLogger logger(clock, 5 * kj::SECONDS, "operation slow");
22
//
23
// To include lazily-evaluated extra parameters (avoiding heap allocation when the duration
24
// threshold is not exceeded), use the DURATION_EXCEEDED_LOG macro instead:
25
//
26
//   DURATION_EXCEEDED_LOG(logger, clock, 5 * kj::SECONDS, "operation slow", requestId, size);
27
//
28
// The extra parameters are formatted in the same style as KJ_LOG (name = value), and are only
29
// stringified if the duration threshold is actually exceeded.
30
 
31
class DurationExceededLogger {
32
 public:
33
  DurationExceededLogger(
34
      const kj::MonotonicClock& clock, kj::Duration warningDuration, kj::StringPtr logMessage)
35
      : warningDuration(warningDuration),
36
        logMessage(logMessage),
37
        start(clock.now()),
38
        clock(clock) {}
39
 
40
  KJ_DISALLOW_COPY_AND_MOVE(DurationExceededLogger);
41
 
42
  ~DurationExceededLogger() noexcept(false) {
43
    kj::Duration actualDuration = clock.now() - start;
44
    if (actualDuration >= warningDuration) {
45
      KJ_LOG(WARNING, kj::str("NOSENTRY ", logMessage), warningDuration, actualDuration);
46
    }
47
  }
48
 
49
 private:
50
  kj::Duration warningDuration;
51
  kj::StringPtr logMessage;
52
  kj::TimePoint start;
53
  const kj::MonotonicClock& clock;
54
};
55
 
56
// Template variant of DurationExceededLogger that supports lazily-evaluated extra parameters.
57
// Do not use this class directly; use the DURATION_EXCEEDED_LOG macro which creates the
58
// appropriate lambda and template instantiation.
59
template <typename ExtraArgsFunc>
60
class DurationExceededLoggerWithExtras {
61
 public:
62
  DurationExceededLoggerWithExtras(const kj::MonotonicClock& clock,
63
      kj::Duration warningDuration,
64
      kj::StringPtr logMessage,
65
      ExtraArgsFunc& extraArgsFunc)
66
      : warningDuration(warningDuration),
67
        logMessage(logMessage),
68
        start(clock.now()),
69
        clock(clock),
70
        extraArgsFunc(extraArgsFunc) {}
71
 
72
  KJ_DISALLOW_COPY_AND_MOVE(DurationExceededLoggerWithExtras);
73
 
74
  ~DurationExceededLoggerWithExtras() noexcept(false) {
75
    kj::Duration actualDuration = clock.now() - start;
76
    if (actualDuration >= warningDuration) {
77
      auto extra = extraArgsFunc();
78
      if (extra.size() > 0) {
79
        KJ_LOG(WARNING, kj::str("NOSENTRY ", logMessage, "; ", extra), warningDuration,
80
            actualDuration);
81
      } else {
82
        KJ_LOG(WARNING, kj::str("NOSENTRY ", logMessage), warningDuration, actualDuration);
83
      }
84
    }
85
  }
86
 
87
 private:
88
  kj::Duration warningDuration;
89
  kj::StringPtr logMessage;
90
  kj::TimePoint start;
91
  const kj::MonotonicClock& clock;
92
  ExtraArgsFunc& extraArgsFunc;
93
};
94
 
95
// Macro for creating a DurationExceededLogger with lazily-evaluated extra parameters.
96
// Extra parameters are only stringified if the duration threshold is actually exceeded,
97
// avoiding unnecessary heap allocations in the common case where the operation completes quickly.
98
//
99
// Parameters are formatted in the same style as KJ_LOG: name = value; name2 = value2
100
//
101
// Example:
102
//   DURATION_EXCEEDED_LOG(logger, clock, 5 * kj::SECONDS, "operation slow", requestId, size);
103
//
104
// If triggered, logs something like:
105
//   NOSENTRY operation slow; requestId = abc; size = 4096; warningDuration = 5s; actualDuration = 12s
106
//
107
// The macro also works without extra parameters, behaving identically to DurationExceededLogger:
108
//   DURATION_EXCEEDED_LOG(logger, clock, 5 * kj::SECONDS, "operation slow");
109
#if KJ_MSVC_TRADITIONAL_CPP
110
#define DURATION_EXCEEDED_LOG(name, clock, warningDuration, logMessage, ...)                       \
111
  auto KJ_UNIQUE_NAME(_delExtraArgsFunc) = [&]() -> kj::String {                                   \
112
    return ::kj::_::Debug::makeDescription("" #__VA_ARGS__, __VA_ARGS__);                          \
113
  };                                                                                               \
114
  ::workerd::util::DurationExceededLoggerWithExtras<decltype(KJ_UNIQUE_NAME(_delExtraArgsFunc))>   \
115
  name(clock, warningDuration, logMessage, KJ_UNIQUE_NAME(_delExtraArgsFunc))
116
#else
117
#define DURATION_EXCEEDED_LOG(name, clock, warningDuration, logMessage, ...)                       \
118
  auto KJ_UNIQUE_NAME(_delExtraArgsFunc) = [&]() -> kj::String {                                   \
119
    return ::kj::_::Debug::makeDescription(#__VA_ARGS__, ##__VA_ARGS__);                           \
120
  };                                                                                               \
121
  ::workerd::util::DurationExceededLoggerWithExtras<decltype(KJ_UNIQUE_NAME(_delExtraArgsFunc))>   \
122
  name(clock, warningDuration, logMessage, KJ_UNIQUE_NAME(_delExtraArgsFunc))
123
#endif
124
 
125
}  // namespace workerd::util