/Users/deen/code/yugabyte-db/src/yb/util/trace.h
Line | Count | Source (jump to first uncovered line) |
1 | | // Licensed to the Apache Software Foundation (ASF) under one |
2 | | // or more contributor license agreements. See the NOTICE file |
3 | | // distributed with this work for additional information |
4 | | // regarding copyright ownership. The ASF licenses this file |
5 | | // to you under the Apache License, Version 2.0 (the |
6 | | // "License"); you may not use this file except in compliance |
7 | | // with the License. You may obtain a copy of the License at |
8 | | // |
9 | | // http://www.apache.org/licenses/LICENSE-2.0 |
10 | | // |
11 | | // Unless required by applicable law or agreed to in writing, |
12 | | // software distributed under the License is distributed on an |
13 | | // "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY |
14 | | // KIND, either express or implied. See the License for the |
15 | | // specific language governing permissions and limitations |
16 | | // under the License. |
17 | | // |
18 | | // The following only applies to changes made to this file as part of YugaByte development. |
19 | | // |
20 | | // Portions Copyright (c) YugaByte, Inc. |
21 | | // |
22 | | // Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except |
23 | | // in compliance with the License. You may obtain a copy of the License at |
24 | | // |
25 | | // http://www.apache.org/licenses/LICENSE-2.0 |
26 | | // |
27 | | // Unless required by applicable law or agreed to in writing, software distributed under the License |
28 | | // is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express |
29 | | // or implied. See the License for the specific language governing permissions and limitations |
30 | | // under the License. |
31 | | // |
32 | | #ifndef YB_UTIL_TRACE_H |
33 | | #define YB_UTIL_TRACE_H |
34 | | |
35 | | #include <atomic> |
36 | | #include <functional> |
37 | | #include <iosfwd> |
38 | | #include <string> |
39 | | #include <vector> |
40 | | |
41 | | #include <gflags/gflags.h> |
42 | | |
43 | | #include "yb/gutil/macros.h" |
44 | | #include "yb/gutil/ref_counted.h" |
45 | | #include "yb/gutil/strings/stringpiece.h" |
46 | | #include "yb/gutil/strings/substitute.h" |
47 | | #include "yb/gutil/threading/thread_collision_warner.h" |
48 | | |
49 | | #include "yb/util/atomic.h" // For GetAtomicFlag |
50 | | #include "yb/util/locks.h" |
51 | | #include "yb/util/memory/arena_fwd.h" |
52 | | #include "yb/util/monotime.h" |
53 | | |
54 | | DECLARE_bool(enable_tracing); |
55 | | DECLARE_bool(use_monotime_for_traces); |
56 | | DECLARE_int32(tracing_level); |
57 | | |
58 | | // Adopt a Trace on the current thread for the duration of the current |
59 | | // scope. The old current Trace is restored when the scope is exited. |
60 | | // |
61 | | // 't' should be a Trace* pointer. |
62 | 294M | #define ADOPT_TRACE(t) yb::ScopedAdoptTrace _adopt_trace(t); |
63 | | |
64 | | // Like the above, but takes the trace pointer as an explicit argument. |
65 | | #define TRACE_TO_WITH_TIME(trace, time, format, substitutions...) \ |
66 | 728M | do { \ |
67 | 728M | if (GetAtomicFlag(&FLAGS_enable_tracing)) { \ |
68 | 567M | if ((trace)) { \ |
69 | 544M | (trace)->SubstituteAndTrace( \ |
70 | 544M | __FILE__, __LINE__, (time), (format77.3M ), ##substitutions0 ); \ |
71 | 544M | } \ |
72 | 567M | } \ |
73 | 728M | } while (0) |
74 | | |
75 | | #define VTRACE_TO(level, trace, format, substitutions...) \ |
76 | 2.80G | do { \ |
77 | 2.80G | if (GetAtomicFlag(&FLAGS_enable_tracing) && level <= GetAtomicFlag(&FLAGS_tracing_level)806M ) { \ |
78 | 399M | const bool use_fine_ts = GetAtomicFlag(&FLAGS_use_monotime_for_traces); \ |
79 | 399M | auto time = (use_fine_ts ? ToCoarse(MonoTime::Now())0 : CoarseMonoClock::Now()); \ |
80 | 399M | TRACE_TO_WITH_TIME(trace, time, format, ##substitutions); \ |
81 | 399M | } \ |
82 | 2.80G | } while (0) |
83 | | |
84 | | #define TRACE_TO(trace, format, substitutions...) \ |
85 | 794M | VTRACE_TO(0, (trace), (format), ##substitutions) |
86 | | |
87 | | // Issue a trace message, if tracing is enabled in the current thread. |
88 | | // and the current tracing level flag is >= the specified level. |
89 | | // See Trace::SubstituteAndTrace for arguments. |
90 | | // Example: |
91 | | // VTRACE(1, "Acquired timestamp $0", timestamp); |
92 | | #define VTRACE(level, format, substitutions...) \ |
93 | 1.89G | VTRACE_TO(level, Trace::CurrentTrace(), format, ##substitutions) |
94 | | |
95 | | // Issue a trace message, if tracing is enabled in the current thread. |
96 | | // See Trace::SubstituteAndTrace for arguments. |
97 | | // Example: |
98 | | // TRACE("Acquired timestamp $0", timestamp); |
99 | | #define TRACE(format, substitutions...) \ |
100 | 427M | VTRACE(0, (format), ##substitutions) |
101 | | |
102 | | #define TRACE_FUNC() \ |
103 | 31.7M | TRACE(__func__) |
104 | | |
105 | | #define PLAIN_TRACE_TO(trace, message) \ |
106 | | do { \ |
107 | | if (GetAtomicFlag(&FLAGS_enable_tracing)) { \ |
108 | | (trace)->Trace(__FILE__, __LINE__, (message)); \ |
109 | | } \ |
110 | | } while (0) |
111 | | |
112 | | // Useful for debugging, where the collected trace will be printed |
113 | | // regardless of the time it takes, or other print related flags. |
114 | | #define PRINT_THIS_TRACE() \ |
115 | | TRACE("Requesting to print this trace"); \ |
116 | | do { \ |
117 | | if (GetAtomicFlag(&FLAGS_enable_tracing)) { \ |
118 | | yb::Trace* _trace = Trace::CurrentTrace(); \ |
119 | | if (_trace) { \ |
120 | | _trace->set_must_print(true); \ |
121 | | } \ |
122 | | } \ |
123 | | } while (0) |
124 | | |
125 | | namespace yb { |
126 | | |
127 | | struct TraceEntry; |
128 | | |
129 | | // A trace for a request or other process. This supports collecting trace entries |
130 | | // from a number of threads, and later dumping the results to a stream. |
131 | | // |
132 | | // Callers should generally not add trace messages directly using the public |
133 | | // methods of this class. Rather, the TRACE(...) macros defined above should |
134 | | // be used such that file/line numbers are automatically included, etc. |
135 | | // |
136 | | // This class is thread-safe. |
137 | | class Trace : public RefCountedThreadSafe<Trace> { |
138 | | public: |
139 | | Trace(); |
140 | | |
141 | | // Logs a message into the trace buffer. |
142 | | // |
143 | | // See strings::Substitute for details. |
144 | | // |
145 | | // N.B.: the file path passed here is not copied, so should be a static |
146 | | // constant (eg __FILE__). |
147 | | void SubstituteAndTrace(const char* file_path, int line_number, |
148 | | CoarseTimePoint now, GStringPiece format, |
149 | | const strings::internal::SubstituteArg& arg0, |
150 | | const strings::internal::SubstituteArg& arg1 = |
151 | | strings::internal::SubstituteArg::NoArg, |
152 | | const strings::internal::SubstituteArg& arg2 = |
153 | | strings::internal::SubstituteArg::NoArg, |
154 | | const strings::internal::SubstituteArg& arg3 = |
155 | | strings::internal::SubstituteArg::NoArg, |
156 | | const strings::internal::SubstituteArg& arg4 = |
157 | | strings::internal::SubstituteArg::NoArg, |
158 | | const strings::internal::SubstituteArg& arg5 = |
159 | | strings::internal::SubstituteArg::NoArg, |
160 | | const strings::internal::SubstituteArg& arg6 = |
161 | | strings::internal::SubstituteArg::NoArg, |
162 | | const strings::internal::SubstituteArg& arg7 = |
163 | | strings::internal::SubstituteArg::NoArg, |
164 | | const strings::internal::SubstituteArg& arg8 = |
165 | | strings::internal::SubstituteArg::NoArg, |
166 | | const strings::internal::SubstituteArg& arg9 = |
167 | | strings::internal::SubstituteArg::NoArg); |
168 | | |
169 | | void SubstituteAndTrace( |
170 | | const char* file_path, int line_number, CoarseTimePoint now, GStringPiece format); |
171 | | |
172 | | // Dump the trace buffer to the given output stream. |
173 | | // |
174 | | // If 'include_time_deltas' is true, calculates and prints the difference between |
175 | | // successive trace messages. |
176 | | void Dump(std::ostream* out, bool include_time_deltas) const; |
177 | | void Dump(std::ostream* out, int32_t tracing_depth, bool include_time_deltas) const; |
178 | | |
179 | | // Dump the trace buffer as a string. |
180 | | std::string DumpToString(int32_t tracing_depth, bool include_time_deltas) const; |
181 | 8 | std::string DumpToString(bool include_time_deltas) const { |
182 | 8 | return DumpToString(0, include_time_deltas); |
183 | 8 | } |
184 | | |
185 | | // Attaches the given trace which will get appended at the end when Dumping. |
186 | | void AddChildTrace(Trace* child_trace); |
187 | | |
188 | | // Return the current trace attached to this thread, if there is one. |
189 | 407M | static Trace* CurrentTrace() { |
190 | 407M | return threadlocal_trace_; |
191 | 407M | } |
192 | | |
193 | | // Simple function to dump the current trace to stderr, if one is |
194 | | // available. This is meant for usage when debugging in gdb via |
195 | | // 'call yb::Trace::DumpCurrentTrace();'. |
196 | | static void DumpCurrentTrace(); |
197 | | |
198 | 143M | size_t ObjectSize() const { return sizeof(*this); } |
199 | | size_t DynamicMemoryUsage() const; |
200 | | |
201 | 92.4M | bool must_print() const { |
202 | 92.4M | std::lock_guard<simple_spinlock> l(lock_); |
203 | 92.4M | return must_print_; |
204 | 92.4M | } |
205 | | |
206 | 0 | void set_must_print(bool flag) { |
207 | 0 | std::lock_guard<simple_spinlock> l(lock_); |
208 | 0 | must_print_ = flag; |
209 | 0 | } |
210 | | |
211 | | private: |
212 | | friend class ScopedAdoptTrace; |
213 | | friend class RefCountedThreadSafe<Trace>; |
214 | | ~Trace(); |
215 | | |
216 | | ThreadSafeArena* GetAndInitArena(); |
217 | | |
218 | | // The current trace for this thread. Threads should only set this using |
219 | | // using ScopedAdoptTrace, which handles reference counting the underlying |
220 | | // object. |
221 | | static __thread Trace* threadlocal_trace_; |
222 | | |
223 | | // Allocate a new entry from the arena, with enough space to hold a |
224 | | // message of length 'len'. |
225 | | TraceEntry* NewEntry(size_t len, const char* file_path, int line_number, CoarseTimePoint now); |
226 | | |
227 | | // Add the entry to the linked list of entries. |
228 | | void AddEntry(TraceEntry* entry); |
229 | | |
230 | | std::atomic<ThreadSafeArena*> arena_ = {nullptr}; |
231 | | |
232 | | // Lock protecting the entries linked list. |
233 | | mutable simple_spinlock lock_; |
234 | | // The head of the linked list of entries (allocated inside arena_) |
235 | | TraceEntry* entries_head_ = nullptr; |
236 | | // The tail of the linked list of entries (allocated inside arena_) |
237 | | TraceEntry* entries_tail_ = nullptr; |
238 | | |
239 | | int64_t trace_start_time_usec_ = 0; |
240 | | |
241 | | // A hint to request that the collected trace be printed. |
242 | | bool must_print_ = false; |
243 | | |
244 | | std::vector<scoped_refptr<Trace> > child_traces_; |
245 | | |
246 | | DISALLOW_COPY_AND_ASSIGN(Trace); |
247 | | }; |
248 | | |
249 | | typedef scoped_refptr<Trace> TracePtr; |
250 | | |
251 | | // Adopt a Trace object into the current thread for the duration |
252 | | // of this object. |
253 | | // This should only be used on the stack (and thus created and destroyed |
254 | | // on the same thread) |
255 | | class ScopedAdoptTrace { |
256 | | public: |
257 | | explicit ScopedAdoptTrace(Trace* t); |
258 | | ~ScopedAdoptTrace(); |
259 | | |
260 | | private: |
261 | | DFAKE_MUTEX(ctor_dtor_); |
262 | | Trace* old_trace_; |
263 | | scoped_refptr<Trace> trace_; |
264 | | bool is_enabled_ = false; |
265 | | |
266 | | DISALLOW_COPY_AND_ASSIGN(ScopedAdoptTrace); |
267 | | }; |
268 | | |
269 | | // PlainTrace could be used in simple cases when we trace only up to 20 entries with const message. |
270 | | // So it does not allocate memory. |
271 | | class PlainTrace { |
272 | | public: |
273 | | static const size_t kMaxEntries = 20; |
274 | | |
275 | | PlainTrace(); |
276 | | |
277 | | void Trace(const char* file_path, int line_number, const char* message); |
278 | | void Dump(std::ostream* out, bool include_time_deltas) const; |
279 | | void Dump(std::ostream* out, int32_t tracing_depth, bool include_time_deltas) const; |
280 | | std::string DumpToString(int32_t tracing_depth, bool include_time_deltas) const; |
281 | 0 | std::string DumpToString(bool include_time_deltas) const { |
282 | 0 | return DumpToString(0, include_time_deltas); |
283 | 0 | } |
284 | | |
285 | | private: |
286 | | class Entry { |
287 | | public: |
288 | | const char* file_path; |
289 | | int line_number; |
290 | | const char* message; |
291 | | CoarseTimePoint timestamp; |
292 | | |
293 | | void Dump(std::ostream* out) const; |
294 | | }; |
295 | | |
296 | | mutable simple_spinlock mutex_; |
297 | | int64_t trace_start_time_usec_ = 0; |
298 | | size_t size_ = 0; |
299 | | Entry entries_[kMaxEntries]; |
300 | | }; |
301 | | |
302 | | } // namespace yb |
303 | | |
304 | | #endif /* YB_UTIL_TRACE_H */ |