xref: /6.6.0/phosphor/include/phosphor/phosphor.h (revision 26aa9a8b)
1/* -*- Mode: C++; tab-width: 4; c-basic-offset: 4; indent-tabs-mode: nil -*- */
2/*
3 *     Copyright 2016 Couchbase, Inc
4 *
5 *   Licensed under the Apache License, Version 2.0 (the "License");
6 *   you may not use this file except in compliance with the License.
7 *   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, software
12 *   distributed under the License is distributed on an "AS IS" BASIS,
13 *   WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14 *   See the License for the specific language governing permissions and
15 *   limitations under the License.
16 */
17
18#pragma once
19
20#include "phosphor-internal.h"
21#include "scoped_event_guard.h"
22#include "trace_log.h"
23
24/** \file
25 * Phosphor Event Tracing
26 *
27 * Phosphor is an event tracing framework and can be used for tracing
28 * high frequency events. This file describes the instrumentation API
29 * used for adding tracing to a user application.
30 *
31 * The management / configuration API is formed by the TraceLog and
32 * TraceConfig classes listed in trace_log.h
33 *
34 * The instrumentation API is formed by four groups of events:
35 *
36 *  - Synchronous
37 *  - Asynchronous
38 *  - Instant
39 *  - Global
40 *
41 * In addition each group will have events macros in one of three styles,
42 * either with 0 arguments, with multiple arguments or with multiple arguments
43 * and with argument names. Macros suffixed with 0, such as TRACE_EVENT_START0,
44 * can be used with 0 arguments.
45 *
46 * Macros without the 0 suffix can be given 1 or 2 arguments - they
47 * *might* work with 0 arguments but some compilers will generate
48 * warnings due to 0-argument variadic macros.
49 *
50 * Macros with either a '1' or '2' suffix can be given 1 or 2 arguments
51 * respectively, they also take an argument name (as a string literal)
52 * before each of their respective arguments. Example:
53 *
54 *     TRACE_EVENT2("category", "name", "arg_name1", 1, "arg_name2", 2);
55 *
56 * Only a limited set of data-types can be used as arguments, generally
57 * this includes most primitive data-types that are 8-bytes or less in
58 * size. In addition, string-literals or long living cstrings can be
59 * used so long as the pointer remains valid while tracing is enabled.
60 * A non-exhaustive list of these data-types include:
61 *
62 *  - boolean
63 *  - int
64 *  - unsigned int
65 *  - float
66 *  - double
67 *  - char* pointing to a cstring
68 *  - void*
69 */
70
71/**
72 * Defined to return the global singleton instance of the Phosphor TraceLog
73 */
74#define PHOSPHOR_INSTANCE phosphor::TraceLog::getInstance()
75
76/**
77 * Deprecated alias for converting pointers to a const void*. Unnecessary
78 * as Phosphor now supports arbitrary pointer types for TraceArguments.
79 */
80#define PHOSPHOR_PTR(arg) arg
81
82/**
83 * Utility for inlining up to 8 bytes of any string, including dynamically
84 * allocated strings. Accepts std::string or char* as argument. Strings
85 * longer than 8 bytes will be truncated.
86 */
87#define PHOSPHOR_INLINE_STR(arg) phosphor::inline_zstring<8>(arg)
88#define PHOSPHOR_INLINE_STR_N(arg, len) phosphor::inline_zstring<8>(arg, len)
89
90#if !defined(PHOSPHOR_DISABLED)
91#define PHOSPHOR_DISABLED 0
92#endif
93
94#define PHOSPHOR_ENABLED !PHOSPHOR_DISABLED
95
96#if !PHOSPHOR_DISABLED
97
98/**
99 * \defgroup sync Synchronous events
100 *
101 * Synchronous events are used for events that are scoped to a single
102 * thread and have a duration.
103 *
104 * Example:
105 *
106 *     TRACE_EVENT_START0('Memcached:Frontend', 'SetKey')
107 *     // Perform some expensive operation
108 *     TRACE_EVENT_END0('Memcached:Frontend', 'SetKey')
109 *
110 * @{
111 */
112#define TRACE_EVENT_START0(category, name)      \
113    PHOSPHOR_INTERNAL_TRACE_EVENT0(             \
114        category, name, phosphor::TraceEvent::Type::SyncStart)
115
116#define TRACE_EVENT_END0(category, name)        \
117    PHOSPHOR_INTERNAL_TRACE_EVENT0(             \
118        category, name, phosphor::TraceEvent::Type::SyncEnd)
119
120#define TRACE_EVENT_START1(category, name, arg1_name, arg1) \
121    PHOSPHOR_INTERNAL_TRACE_EVENT( \
122        category, \
123        name, \
124        arg1_name, \
125        "", \
126        phosphor::TraceEvent::Type::SyncStart, \
127        arg1)
128
129#define TRACE_EVENT_END1(category, name, arg1_name, arg1) \
130    PHOSPHOR_INTERNAL_TRACE_EVENT( \
131        category, \
132        name, \
133        arg1_name, \
134        "", \
135        phosphor::TraceEvent::Type::SyncEnd, \
136        arg1)
137
138#define TRACE_EVENT_START2(category, name, arg1_name, arg1, arg2_name, arg2) \
139    PHOSPHOR_INTERNAL_TRACE_EVENT( \
140        category, \
141        name, \
142        arg1_name, \
143        arg2_name, \
144        phosphor::TraceEvent::Type::SyncStart, \
145        arg1, \
146        arg2)
147
148#define TRACE_EVENT_END2(category, name, arg1_name, arg1, arg2_name, arg2) \
149    PHOSPHOR_INTERNAL_TRACE_EVENT( \
150        category, \
151        name, \
152        arg1_name, \
153        arg2_name, \
154        phosphor::TraceEvent::Type::SyncEnd, \
155        arg1, \
156        arg2)
157/** @} */
158
159/**
160 * \defgroup scoped Scoped Events
161 *
162 * Scoped events are used for events that should log synchronously both
163 * a start and an end event automatically according to a scope.
164 *
165 * They are preferred over a pair of EVENT_START / EVENT_END macros as only one
166 * trace event needs to be allocated in Phosphor instead of two.
167 *
168 * The TRACE_FUNCTION event macros are identical to the TRACE_EVENT
169 * macros except they don't accept a name parameter and the name is
170 * predefined as the function name (using `__func__`).
171 *
172 * Example:
173 *
174 *     void defragment_part(int vbucket) {
175 *         // Set up a scoped event and log the start event
176 *         TRACE_EVENT0("ep-engine:vbucket", "defragment_part", vbucket);
177 *
178 *         // Perform the de-fragmentation and take some time doing it
179 *         ...
180 *
181 *     } // Automatically log a synchronous end event on function exit
182 *       // (Through return or exception)
183 *
184 * @{
185 */
186#define TRACE_EVENT0(category, name)                                     \
187    PHOSPHOR_INTERNAL_CATEGORY_INFO                                      \
188    PHOSPHOR_INTERNAL_INITIALIZE_TRACEPOINT(category, name, "", "")      \
189    phosphor::ScopedEventGuard<phosphor::NoneType, phosphor::NoneType>   \
190            PHOSPHOR_INTERNAL_UID(guard)(                                \
191                    &PHOSPHOR_INTERNAL_UID(tpi),                         \
192                    PHOSPHOR_INTERNAL_UID(category_enabled_temp)         \
193                                    ->load(std::memory_order_acquire) != \
194                            phosphor::CategoryStatus::Disabled,          \
195                    phosphor::NoneType(),                                \
196                    phosphor::NoneType());
197
198#define TRACE_EVENT1(category, name, arg1_name, arg1)                      \
199    PHOSPHOR_INTERNAL_CATEGORY_INFO                                        \
200    PHOSPHOR_INTERNAL_INITIALIZE_TRACEPOINT(category, name, arg1_name, "") \
201    phosphor::ScopedEventGuard<decltype(arg1), phosphor::NoneType>         \
202            PHOSPHOR_INTERNAL_UID(guard)(                                  \
203                    &PHOSPHOR_INTERNAL_UID(tpi),                           \
204                    PHOSPHOR_INTERNAL_UID(category_enabled_temp)           \
205                                    ->load(std::memory_order_acquire) !=   \
206                            phosphor::CategoryStatus::Disabled,            \
207                    arg1,                                                  \
208                    phosphor::NoneType());
209
210#define TRACE_EVENT2(category, name, arg1_name, arg1, arg2_name, arg2)   \
211    PHOSPHOR_INTERNAL_CATEGORY_INFO                                      \
212    PHOSPHOR_INTERNAL_INITIALIZE_TRACEPOINT(                             \
213            category, name, arg1_name, arg2_name)                        \
214    phosphor::ScopedEventGuard<decltype(arg1), decltype(arg2)>           \
215            PHOSPHOR_INTERNAL_UID(guard)(                                \
216                    &PHOSPHOR_INTERNAL_UID(tpi),                         \
217                    PHOSPHOR_INTERNAL_UID(category_enabled_temp)         \
218                                    ->load(std::memory_order_acquire) != \
219                            phosphor::CategoryStatus::Disabled,          \
220                    arg1,                                                \
221                    arg2);
222
223#define TRACE_FUNCTION0(category) \
224    TRACE_EVENT0(category, __func__)
225
226#define TRACE_FUNCTION1(category, arg1_name, arg1) \
227    TRACE_EVENT1(category, __func__, arg1_name, arg1)
228
229#define TRACE_FUNCTION2(category, arg1_name, arg1, arg2_name, arg2) \
230    TRACE_EVENT2(category, __func__, arg1_name, arg1, arg2_name, arg2)
231/** @} */
232
233/**
234 * \defgroup scoped Lock Events
235 *
236 * The TRACE_LOCKGUARD macro measures for a given mutex both the duration
237 * waiting to acquire the lock and the duration the lock is held.  This is
238 * achieved by issuing two TRACE_EVENT events.
239 *
240 * Example:
241 *
242 *    TRACE_LOCKGUARD(mutex, "category", "lock_name");
243 *
244 * This example will acquire the given lock; unlocking it when the guard
245 * goes out of scope (same as std::lock_guard). Additionally it will produce
246 * the following 2 events:
247 *
248 * 1) TRACE_EVENT "cat" = "category" "name" = "lock_name.wait"
249 * 2) START_EVENT "cat" = "category" "name" = "lock_name.held"
250 *
251 *
252 * The TRACE_LOCKGUARD_TIMED is similar to TRACE_LOCKGUARD, except that
253 * the trace events are only recorded if the wait or held durations exceed
254 * the specified value, otherwise no events are recorded. In the event either
255 * stage of the lock takes longer than the limit, *both* events are recorded.
256 *
257 * This is intended for profiling locks which are /normally/ quick; but
258 * exhibit occasional slowness; therefore it would be too costly (in terms of
259 * trace storage space) to unconditionally log them.
260 *
261 * Example:
262 *
263 *    TRACE_LOCKGUARD_TIMED(mutex, "category", "lock_name",
264 *                          std::chrono::milliseconds(10));
265 *
266 * If either of the acquire or held durations exceed 10ms, then trace events
267 * are recorded.
268 *
269 * @{
270 */
271#define TRACE_LOCKGUARD(mutex, category, name)                                 \
272    PHOSPHOR_INTERNAL_CATEGORY_INFO                                            \
273    PHOSPHOR_INTERNAL_INITIALIZE_TPI(tpi_wait, category, name ".wait", "", "") \
274    PHOSPHOR_INTERNAL_INITIALIZE_TPI(tpi_held, category, name ".held", "", "") \
275    PHOSPHOR_INTERNAL_INITIALIZE_CATEGORY_ENABLED(category)                    \
276    phosphor::MutexEventGuard<decltype(mutex)> PHOSPHOR_INTERNAL_UID(guard)(   \
277            &PHOSPHOR_INTERNAL_UID(tpi_wait),                                  \
278            &PHOSPHOR_INTERNAL_UID(tpi_held),                                  \
279            PHOSPHOR_INTERNAL_UID(category_enabled_temp)                       \
280                            ->load(std::memory_order_acquire) !=               \
281                    phosphor::CategoryStatus::Disabled,                        \
282            mutex);
283
284#define TRACE_LOCKGUARD_TIMED(mutex, category, name, limit)                  \
285    PHOSPHOR_INTERNAL_CATEGORY_INFO                                          \
286    PHOSPHOR_INTERNAL_INITIALIZE_TPI(                                        \
287            tpi_wait, category, name ".wait", "this", "");                   \
288    PHOSPHOR_INTERNAL_INITIALIZE_TPI(                                        \
289            tpi_held, category, name ".held", "", "");                       \
290    PHOSPHOR_INTERNAL_INITIALIZE_CATEGORY_ENABLED(category)                  \
291    phosphor::MutexEventGuard<decltype(mutex)> PHOSPHOR_INTERNAL_UID(guard)( \
292            &PHOSPHOR_INTERNAL_UID(tpi_wait),                                \
293            &PHOSPHOR_INTERNAL_UID(tpi_held),                                \
294            PHOSPHOR_INTERNAL_UID(category_enabled_temp)                     \
295                            ->load(std::memory_order_acquire) !=             \
296                    phosphor::CategoryStatus::Disabled,                      \
297            mutex,                                                           \
298            limit);
299
300/** @} */
301
302/**
303 * \defgroup async Asynchronous Events
304 *
305 * Asynchronous events are used for events that are not scoped to a
306 * single thread and have duration. They have an additional 'id'
307 * argument which is used to match up the START and END events.
308 *
309 * Example:
310 *
311 *     // Thread 1
312 *     TRACE_ASYNC_START0('Memcached:Frontend', 'EWOULDBLOCK', 123)
313 *
314 *     // Thread 2
315 *     TRACE_ASYNC_END0('Memcached:Frontend', 'EWOULDBLOCK', 123)
316 *
317 * @{
318 */
319#define TRACE_ASYNC_START0(category, name, id)  \
320     PHOSPHOR_INTERNAL_TRACE_EVENT( \
321        category, \
322        name, \
323        "id", \
324        "", \
325        phosphor::TraceEvent::Type::AsyncStart, \
326        id)
327
328#define TRACE_ASYNC_START1(category, name, id, arg1_name, arg1) \
329     PHOSPHOR_INTERNAL_TRACE_EVENT( \
330        category, \
331        name, \
332        "id", \
333        arg1_name, \
334        phosphor::TraceEvent::Type::AsyncStart, \
335        id, \
336        arg1)
337
338#define TRACE_ASYNC_END0(category, name, id)    \
339     PHOSPHOR_INTERNAL_TRACE_EVENT( \
340        category, \
341        name, \
342        "id_end", \
343        "", \
344        phosphor::TraceEvent::Type::AsyncEnd, \
345        id)
346
347#define TRACE_ASYNC_END1(category, name, id, arg1_name, arg1) \
348     PHOSPHOR_INTERNAL_TRACE_EVENT( \
349        category, \
350        name, \
351        "id_end", \
352        arg1_name, \
353        phosphor::TraceEvent::Type::AsyncEnd, \
354        id, \
355        arg1)
356/** @} */
357
358/**
359 * \defgroup inst Instant Events
360 *
361 * Instant events are used for events that are scoped to a thread but
362 * do not conceptually have a duration.
363 *
364 * Example:
365 *
366 *     TRACE_INSTANT0("Memcached:Frontend", "StatsReset")
367 *
368 *  @{
369 */
370#define TRACE_INSTANT0(category, name)          \
371    PHOSPHOR_INTERNAL_TRACE_EVENT0(             \
372        category, name, phosphor::TraceEvent::Type::Instant)
373
374#define TRACE_INSTANT1(category, name, arg1_name, arg1) \
375     PHOSPHOR_INTERNAL_TRACE_EVENT( \
376        category, \
377        name, \
378        arg1_name, \
379        "", \
380        phosphor::TraceEvent::Type::Instant, \
381        arg1)
382
383#define TRACE_INSTANT2(category, name, arg1_name, arg1, arg2_name, arg2) \
384     PHOSPHOR_INTERNAL_TRACE_EVENT( \
385        category, \
386        name, \
387        arg1_name, \
388        arg2_name, \
389        phosphor::TraceEvent::Type::Instant, \
390        arg1, \
391        arg2)
392/** @} */
393
394/**
395 * \defgroup glob Global Events
396 *
397 * Global events are used for events that are not scoped to a thread
398 * and do not conceptually have a duration. Examples of this might include
399 * the initiation of a system shutdown.
400 *
401 * Example:
402 *
403 *     TRACE_GLOBAL0("Memcached", "Shutdown")
404 *
405 *  @{
406 */
407#define TRACE_GLOBAL0(category, name)           \
408    PHOSPHOR_INTERNAL_TRACE_EVENT0(             \
409        category, name, phosphor::TraceEvent::Type::GlobalInstant)
410
411
412#define TRACE_GLOBAL1(category, name, arg1_name, arg1) \
413     PHOSPHOR_INTERNAL_TRACE_EVENT( \
414        category, \
415        name, \
416        arg1_name, \
417        "", \
418        phosphor::TraceEvent::Type::GlobalInstant, \
419        arg1)
420
421#define TRACE_GLOBAL2(category, name, arg1_name, arg1, arg2_name, arg2) \
422     PHOSPHOR_INTERNAL_TRACE_EVENT( \
423        category, \
424        name, \
425        arg1_name, \
426        arg2_name, \
427        phosphor::TraceEvent::Type::GlobalInstant, \
428        arg1, \
429        arg2)
430/** @} */
431
432/**
433 * \defgroup sync Complete events
434 *
435 * Complete events logically combine a pair of SyncStart and SyncEnd events
436 * into a single event.
437 *
438 * Note: You typically don't want to use these low-level macros - consider
439 *       TRACE_EVENT*() / TRACE_FUNCTION*() instead.
440 *
441 * Their are two main use-cases over individual SyncStart / SyncEnd events:
442 * 1. Space-efficiency - only a single Complete event is needed instead of
443 *    a pair of SyncStart / SyncEnd events.
444 * 2. Deferring trace decision until the end of an operation - for example
445 *    you can measure the duration of an operation, but only emit a trace
446 *    event if it exceeded some limit.
447 *
448 * The caller must first record a start time; which is then provided to the
449 * macro.
450 *
451 * Example:
452 *
453 *     const auto start = std::chrono::steady_clock::now();
454 *     // Perform some operation ...
455 *     const auto end = std::chrono::steady_clock::now();
456 *     TRACE_COMPLETE("Memcached:Frontend", "SetKey", start, end);
457 *
458 * Or with arguments:
459 *
460 *     TRACE_COMPLETE("my_category", "name", start, end, "vbid", 0);
461 * @{
462 */
463#define TRACE_COMPLETE0(category, name, start, end) \
464    PHOSPHOR_INTERNAL_TRACE_EVENT(category, name, "", "", start, (end - start))
465
466#define TRACE_COMPLETE1(category, name, start, end, arg1_name, arg1) \
467    PHOSPHOR_INTERNAL_TRACE_EVENT(                                   \
468            category, name, arg1_name, "", start, (end - start), arg1)
469
470#define TRACE_COMPLETE2(                                              \
471        category, name, start, end, arg1_name, arg1, arg2_name, arg2) \
472    PHOSPHOR_INTERNAL_TRACE_EVENT(category,                           \
473                                  name,                               \
474                                  arg1_name,                          \
475                                  arg2_name,                          \
476                                  start,                              \
477                                  (end - start),                      \
478                                  arg1,                               \
479                                  arg2)
480/** @} */
481
482#else // if: defined(PHOSPHOR_DISABLED) && PHOSPHOR_DISABLED != 0
483
484#define TRACE_EVENT_START0(category, name)
485#define TRACE_EVENT_START1(category, name, arg1_name, arg1)
486#define TRACE_EVENT_START2(category, name, arg1_name, arg1, arg2_name, arg2)
487#define TRACE_EVENT_END0(category, name)
488#define TRACE_EVENT_END1(category, name, arg1_name, arg1)
489#define TRACE_EVENT_END2(category, name, arg1_name, arg1, arg2_name, arg2)
490
491#define TRACE_EVENT0(category, name)
492#define TRACE_EVENT1(category, name, arg1_name, arg1)
493#define TRACE_EVENT2(category, name, arg1_name, arg1, arg2_name, arg2)
494
495#define TRACE_FUNCTION0(category)
496#define TRACE_FUNCTION1(category, name, arg1_name, arg1)
497#define TRACE_FUNCTION2(category, name, arg1_name, arg1, arg2_name, arg2)
498
499#define TRACE_LOCKGUARD(mutex, category, name) \
500    std::lock_guard<decltype(mutex)> PHOSPHOR_INTERNAL_UID(guard)(mutex);
501#define TRACE_LOCKGUARD_TIMED(mutex, category, name, limit) \
502    std::lock_guard<decltype(mutex)> PHOSPHOR_INTERNAL_UID(guard)(mutex);
503
504#define TRACE_ASYNC_START0(category, name, id)
505#define TRACE_ASYNC_START1(category, name, id, arg1_name, arg1)
506#define TRACE_ASYNC_END0(category, name, id)
507#define TRACE_ASYNC_END1(category, name, id, arg1_name, arg1)
508
509#define TRACE_INSTANT0(category, name)
510#define TRACE_INSTANT1(category, name, arg1_name, arg1)
511#define TRACE_INSTANT2(category, name, arg1_name, arg1, arg2_name, arg2)
512
513#define TRACE_GLOBAL0(category, name)
514#define TRACE_GLOBAL1(category, name, arg1_name, arg1)
515#define TRACE_GLOBAL2(category, name, arg1_name, arg1, arg2_name, arg2)
516
517#define TRACE_COMPLETE0(category, name, start, end)
518#define TRACE_COMPLETE1(category, name, start, end, arg1_name, arg1)
519#define TRACE_COMPLETE2( \
520        category, name, start, end, arg1_name, arg1, arg2_name, arg2)
521
522#endif // PHOSPHOR_DISABLED
523