xref: /6.0.3/phosphor/include/phosphor/phosphor.h (revision c00373e2)
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
113#define TRACE_EVENT_START(category, name, ...)  \
114    PHOSPHOR_INTERNAL_TRACE_EVENT( \
115        category, \
116        name, \
117        "arg1", \
118        "arg2", \
119        phosphor::TraceEvent::Type::SyncStart, \
120        __VA_ARGS__)
121
122#define TRACE_EVENT_START0(category, name)      \
123    PHOSPHOR_INTERNAL_TRACE_EVENT0(             \
124        category, name, phosphor::TraceEvent::Type::SyncStart)
125
126#define TRACE_EVENT_END(category, name, ...)    \
127    PHOSPHOR_INTERNAL_TRACE_EVENT( \
128        category, \
129        name, \
130        "arg1_end", \
131        "arg2_end", \
132        phosphor::TraceEvent::Type::SyncEnd, \
133        __VA_ARGS__)
134
135#define TRACE_EVENT_END0(category, name)        \
136    PHOSPHOR_INTERNAL_TRACE_EVENT0(             \
137        category, name, phosphor::TraceEvent::Type::SyncEnd)
138
139#define TRACE_EVENT_START1(category, name, arg1_name, arg1) \
140    PHOSPHOR_INTERNAL_TRACE_EVENT( \
141        category, \
142        name, \
143        arg1_name, \
144        "", \
145        phosphor::TraceEvent::Type::SyncStart, \
146        arg1)
147
148#define TRACE_EVENT_END1(category, name, arg1_name, arg1) \
149    PHOSPHOR_INTERNAL_TRACE_EVENT( \
150        category, \
151        name, \
152        arg1_name, \
153        "", \
154        phosphor::TraceEvent::Type::SyncEnd, \
155        arg1)
156
157#define TRACE_EVENT_START2(category, name, arg1_name, arg1, arg2_name, arg2) \
158    PHOSPHOR_INTERNAL_TRACE_EVENT( \
159        category, \
160        name, \
161        arg1_name, \
162        arg2_name, \
163        phosphor::TraceEvent::Type::SyncStart, \
164        arg1, \
165        arg2)
166
167#define TRACE_EVENT_END2(category, name, arg1_name, arg1, arg2_name, arg2) \
168    PHOSPHOR_INTERNAL_TRACE_EVENT( \
169        category, \
170        name, \
171        arg1_name, \
172        arg2_name, \
173        phosphor::TraceEvent::Type::SyncEnd, \
174        arg1, \
175        arg2)
176/** @} */
177
178/**
179 * \defgroup scoped Scoped Events
180 *
181 * Scoped events are used for events that should log synchronously both
182 * a start and an end event automatically according to a scope.
183 *
184 * They are preferred over a pair of EVENT_START / EVENT_END macros as only one
185 * trace event needs to be allocated in Phosphor instead of two.
186 *
187 * The TRACE_FUNCTION event macros are identical to the TRACE_EVENT
188 * macros except they don't accept a name parameter and the name is
189 * predefined as the function name (using `__func__`).
190 *
191 * Example:
192 *
193 *     void defragment_part(int vbucket) {
194 *         // Set up a scoped event and log the start event
195 *         TRACE_EVENT0("ep-engine:vbucket", "defragment_part", vbucket);
196 *
197 *         // Perform the de-fragmentation and take some time doing it
198 *         ...
199 *
200 *     } // Automatically log a synchronous end event on function exit
201 *       // (Through return or exception)
202 *
203 * @{
204 */
205#define TRACE_EVENT0(category, name)                                     \
206    PHOSPHOR_INTERNAL_CATEGORY_INFO                                      \
207    PHOSPHOR_INTERNAL_INITIALIZE_TRACEPOINT(category, name, "", "")      \
208    phosphor::ScopedEventGuard<phosphor::NoneType, phosphor::NoneType>   \
209            PHOSPHOR_INTERNAL_UID(guard)(                                \
210                    &PHOSPHOR_INTERNAL_UID(tpi),                         \
211                    PHOSPHOR_INTERNAL_UID(category_enabled_temp)         \
212                                    ->load(std::memory_order_acquire) != \
213                            phosphor::CategoryStatus::Disabled,          \
214                    phosphor::NoneType(),                                \
215                    phosphor::NoneType());
216
217#define TRACE_EVENT1(category, name, arg1_name, arg1)                      \
218    PHOSPHOR_INTERNAL_CATEGORY_INFO                                        \
219    PHOSPHOR_INTERNAL_INITIALIZE_TRACEPOINT(category, name, arg1_name, "") \
220    phosphor::ScopedEventGuard<decltype(arg1), phosphor::NoneType>         \
221            PHOSPHOR_INTERNAL_UID(guard)(                                  \
222                    &PHOSPHOR_INTERNAL_UID(tpi),                           \
223                    PHOSPHOR_INTERNAL_UID(category_enabled_temp)           \
224                                    ->load(std::memory_order_acquire) !=   \
225                            phosphor::CategoryStatus::Disabled,            \
226                    arg1,                                                  \
227                    phosphor::NoneType());
228
229#define TRACE_EVENT2(category, name, arg1_name, arg1, arg2_name, arg2)   \
230    PHOSPHOR_INTERNAL_CATEGORY_INFO                                      \
231    PHOSPHOR_INTERNAL_INITIALIZE_TRACEPOINT(                             \
232            category, name, arg1_name, arg2_name)                        \
233    phosphor::ScopedEventGuard<decltype(arg1), decltype(arg2)>           \
234            PHOSPHOR_INTERNAL_UID(guard)(                                \
235                    &PHOSPHOR_INTERNAL_UID(tpi),                         \
236                    PHOSPHOR_INTERNAL_UID(category_enabled_temp)         \
237                                    ->load(std::memory_order_acquire) != \
238                            phosphor::CategoryStatus::Disabled,          \
239                    arg1,                                                \
240                    arg2);
241
242#define TRACE_FUNCTION0(category) \
243    TRACE_EVENT0(category, __func__)
244
245#define TRACE_FUNCTION1(category, arg1_name, arg1) \
246    TRACE_EVENT1(category, __func__, arg1_name, arg1)
247
248#define TRACE_FUNCTION2(category, arg1_name, arg1, arg2_name, arg2) \
249    TRACE_EVENT2(category, __func__, arg1_name, arg1, arg2_name, arg2)
250/** @} */
251
252/**
253 * \defgroup scoped Lock Events
254 *
255 * The TRACE_LOCKGUARD macro measures for a given mutex both the duration for
256 * acquiring the lock and the duration the lock is held.  This is achieved
257 * by issuing two TRACE_EVENT events.
258 *
259 * Example:
260 *
261 *    TRACE_LOCKGUARD(mutex, "category", "lock_name");
262 *
263 * This example will acquire the given lock; unlocking it when the guard
264 * goes out of scope (same as std::lock_guard). Additionally it will produce
265 * the following 2 events:
266 *
267 * 1) TRACE_EVENT "cat" = "category" "name" = "lock_name.acquire"
268 * 2) START_EVENT "cat" = "category" "name" = "lock_name.held"
269 *
270 * @{
271 */
272#define TRACE_LOCKGUARD(mutex, category, name)                         \
273    static decltype(mutex)& PHOSPHOR_INTERNAL_UID(lk)(mutex);          \
274    const auto PHOSPHOR_INTERNAL_UID(start) =                          \
275            std::chrono::steady_clock::now();                          \
276    PHOSPHOR_INTERNAL_UID(lk).lock();                                  \
277    struct PHOSPHOR_INTERNAL_UID(scoped_trace_t) {                     \
278        PHOSPHOR_INTERNAL_UID(scoped_trace_t)                          \
279        (std::chrono::steady_clock::time_point start)                  \
280            : start(start), locked(std::chrono::steady_clock::now()) { \
281            TRACE_COMPLETE0(category, name ".acquire", start, locked); \
282        }                                                              \
283        ~PHOSPHOR_INTERNAL_UID(scoped_trace_t)() {                     \
284            PHOSPHOR_INTERNAL_UID(lk).unlock();                        \
285            TRACE_COMPLETE0(category,                                  \
286                            name ".held",                              \
287                            locked,                                    \
288                            std::chrono::steady_clock::now());         \
289        }                                                              \
290        const std::chrono::steady_clock::time_point start;             \
291        const std::chrono::steady_clock::time_point locked;            \
292    } PHOSPHOR_INTERNAL_UID(scoped_trace_inst)(PHOSPHOR_INTERNAL_UID(start));
293/** @} */
294
295/**
296 * \defgroup async Asynchronous Events
297 *
298 * Asynchronous events are used for events that are not scoped to a
299 * single thread and have duration. They have an additional 'id'
300 * argument which is used to match up the START and END events.
301 *
302 * Example:
303 *
304 *     // Thread 1
305 *     TRACE_ASYNC_START0('Memcached:Frontend', 'EWOULDBLOCK', 123)
306 *
307 *     // Thread 2
308 *     TRACE_ASYNC_END0('Memcached:Frontend', 'EWOULDBLOCK', 123)
309 *
310 * @{
311 */
312#define TRACE_ASYNC_START(category, name, id, ...) \
313     PHOSPHOR_INTERNAL_TRACE_EVENT( \
314        category, \
315        name, \
316        "id", \
317        "arg1", \
318        phosphor::TraceEvent::Type::AsyncStart, \
319        id, \
320        __VA_ARGS__)
321
322#define TRACE_ASYNC_START0(category, name, id)  \
323     PHOSPHOR_INTERNAL_TRACE_EVENT( \
324        category, \
325        name, \
326        "id", \
327        "", \
328        phosphor::TraceEvent::Type::AsyncStart, \
329        id)
330
331#define TRACE_ASYNC_START1(category, name, id, arg1_name, arg1) \
332     PHOSPHOR_INTERNAL_TRACE_EVENT( \
333        category, \
334        name, \
335        "id", \
336        arg1_name, \
337        phosphor::TraceEvent::Type::AsyncStart, \
338        id, \
339        arg1)
340
341#define TRACE_ASYNC_END(category, name, id, ...) \
342     PHOSPHOR_INTERNAL_TRACE_EVENT( \
343        category, \
344        name, \
345        "id_end", \
346        "arg1_end", \
347        phosphor::TraceEvent::Type::AsyncEnd, \
348        id, \
349        __VA_ARGS__)
350
351#define TRACE_ASYNC_END0(category, name, id)    \
352     PHOSPHOR_INTERNAL_TRACE_EVENT( \
353        category, \
354        name, \
355        "id_end", \
356        "", \
357        phosphor::TraceEvent::Type::AsyncEnd, \
358        id)
359
360#define TRACE_ASYNC_END1(category, name, id, arg1_name, arg1) \
361     PHOSPHOR_INTERNAL_TRACE_EVENT( \
362        category, \
363        name, \
364        "id_end", \
365        arg1_name, \
366        phosphor::TraceEvent::Type::AsyncEnd, \
367        id, \
368        arg1)
369/** @} */
370
371/**
372 * \defgroup inst Instant Events
373 *
374 * Instant events are used for events that are scoped to a thread but
375 * do not conceptually have a duration.
376 *
377 * Example:
378 *
379 *     TRACE_INSTANT0("Memcached:Frontend", "StatsReset")
380 *
381 *  @{
382 */
383#define TRACE_INSTANT(category, name, ...) \
384    PHOSPHOR_INTERNAL_TRACE_EVENT( \
385        category, \
386        name, \
387        "arg1", \
388        "arg2", \
389        phosphor::TraceEvent::Type::Instant, \
390        __VA_ARGS__)
391
392#define TRACE_INSTANT0(category, name)          \
393    PHOSPHOR_INTERNAL_TRACE_EVENT0(             \
394        category, name, phosphor::TraceEvent::Type::Instant)
395
396#define TRACE_INSTANT1(category, name, arg1_name, arg1) \
397     PHOSPHOR_INTERNAL_TRACE_EVENT( \
398        category, \
399        name, \
400        arg1_name, \
401        "", \
402        phosphor::TraceEvent::Type::Instant, \
403        arg1)
404
405#define TRACE_INSTANT2(category, name, arg1_name, arg1, arg2_name, arg2) \
406     PHOSPHOR_INTERNAL_TRACE_EVENT( \
407        category, \
408        name, \
409        arg1_name, \
410        arg2_name, \
411        phosphor::TraceEvent::Type::Instant, \
412        arg1, \
413        arg2)
414/** @} */
415
416/**
417 * \defgroup glob Global Events
418 *
419 * Global events are used for events that are not scoped to a thread
420 * and do not conceptually have a duration. Examples of this might include
421 * the initiation of a system shutdown.
422 *
423 * Example:
424 *
425 *     TRACE_GLOBAL0("Memcached", "Shutdown")
426 *
427 *  @{
428 */
429#define TRACE_GLOBAL(category, name, ...)          \
430    PHOSPHOR_INTERNAL_TRACE_EVENT( \
431        category, \
432        name, \
433        "arg1", \
434        "arg2", \
435        phosphor::TraceEvent::Type::GlobalInstant, \
436        __VA_ARGS__)
437
438#define TRACE_GLOBAL0(category, name)           \
439    PHOSPHOR_INTERNAL_TRACE_EVENT0(             \
440        category, name, phosphor::TraceEvent::Type::GlobalInstant)
441
442
443#define TRACE_GLOBAL1(category, name, arg1_name, arg1) \
444     PHOSPHOR_INTERNAL_TRACE_EVENT( \
445        category, \
446        name, \
447        arg1_name, \
448        "", \
449        phosphor::TraceEvent::Type::GlobalInstant, \
450        arg1)
451
452#define TRACE_GLOBAL2(category, name, arg1_name, arg1, arg2_name, arg2) \
453     PHOSPHOR_INTERNAL_TRACE_EVENT( \
454        category, \
455        name, \
456        arg1_name, \
457        arg2_name, \
458        phosphor::TraceEvent::Type::GlobalInstant, \
459        arg1, \
460        arg2)
461/** @} */
462
463/**
464 * \defgroup sync Complete events
465 *
466 * Complete events logically combine a pair of SyncStart and SyncEnd events
467 * into a single event.
468 *
469 * Note: You typically don't want to use these low-level macros - consider
470 *       TRACE_EVENT*() / TRACE_FUNCTION*() instead.
471 *
472 * Their are two main use-cases over individual SyncStart / SyncEnd events:
473 * 1. Space-efficiency - only a single Complete event is needed instead of
474 *    a pair of SyncStart / SyncEnd events.
475 * 2. Deferring trace decision until the end of an operation - for example
476 *    you can measure the duration of an operation, but only emit a trace
477 *    event if it exceeded some limit.
478 *
479 * The caller must first record a start time; which is then provided to the
480 * macro.
481 *
482 * Example:
483 *
484 *     const auto start = std::chrono::steady_clock::now();
485 *     // Perform some operation ...
486 *     const auto end = std::chrono::steady_clock::now();
487 *     TRACE_COMPLETE("Memcached:Frontend", "SetKey", start, end);
488 *
489 * Or with arguments:
490 *
491 *     TRACE_COMPLETE("my_category", "name", start, end, "vbid", 0);
492 * @{
493 */
494#define TRACE_COMPLETE(category, name, start, end, ...) \
495    PHOSPHOR_INTERNAL_TRACE_EVENT(                      \
496            category, name, "arg1", "arg2", start, (end - start), __VA_ARGS__)
497
498#define TRACE_COMPLETE0(category, name, start, end) \
499    PHOSPHOR_INTERNAL_TRACE_EVENT(category, name, "", "", start, (end - start))
500
501#define TRACE_COMPLETE1(category, name, start, end, arg1_name, arg1) \
502    PHOSPHOR_INTERNAL_TRACE_EVENT(                                   \
503            category, name, arg1_name, "", start, (end - start), arg1)
504
505#define TRACE_COMPLETE2(                                              \
506        category, name, start, end, arg1_name, arg1, arg2_name, arg2) \
507    PHOSPHOR_INTERNAL_TRACE_EVENT(category,                           \
508                                  name,                               \
509                                  arg1_name,                          \
510                                  arg2_name,                          \
511                                  start,                              \
512                                  (end - start),                      \
513                                  arg1,                               \
514                                  arg2)
515/** @} */
516
517#else // if: defined(PHOSPHOR_DISABLED) && PHOSPHOR_DISABLED != 0
518
519#define TRACE_EVENT_START(category, name, ...)
520#define TRACE_EVENT_START0(category, name)
521#define TRACE_EVENT_START1(category, name, arg1_name, arg1)
522#define TRACE_EVENT_START2(category, name, arg1_name, arg1, arg2_name, arg2)
523#define TRACE_EVENT_END(category, name, ...)
524#define TRACE_EVENT_END0(category, name)
525#define TRACE_EVENT_END1(category, name, arg1_name, arg1)
526#define TRACE_EVENT_END2(category, name, arg1_name, arg1, arg2_name, arg2)
527
528#define TRACE_EVENT(category, name, ...)
529#define TRACE_EVENT0(category, name)
530#define TRACE_EVENT1(category, name, arg1_name, arg1)
531#define TRACE_EVENT2(category, name, arg1_name, arg1, arg2_name, arg2)
532
533#define TRACE_FUNCTION(category, ...)
534#define TRACE_FUNCTION0(category)
535#define TRACE_FUNCTION1(category, name, arg1_name, arg1)
536#define TRACE_FUNCTION2(category, name, arg1_name, arg1, arg2_name, arg2)
537
538#define TRACE_LOCKGUARD(mutex, category, name)
539
540#define TRACE_ASYNC_START(category, name, id, ...)
541#define TRACE_ASYNC_START0(category, name, id)
542#define TRACE_ASYNC_START1(category, name, id, arg1_name, arg1)
543#define TRACE_ASYNC_END(category, name, id, ...)
544#define TRACE_ASYNC_END0(category, name, id)
545#define TRACE_ASYNC_END1(category, name, id, arg1_name, arg1)
546
547#define TRACE_INSTANT(category, name, ...)
548#define TRACE_INSTANT0(category, name)
549#define TRACE_INSTANT1(category, name, arg1_name, arg1)
550#define TRACE_INSTANT2(category, name, arg1_name, arg1, arg2_name, arg2)
551
552#define TRACE_GLOBAL(category, name, ...)
553#define TRACE_GLOBAL0(category, name)
554#define TRACE_GLOBAL1(category, name, arg1_name, arg1)
555#define TRACE_GLOBAL2(category, name, arg1_name, arg1, arg2_name, arg2)
556
557#define TRACE_COMPLETE(category, name, start, end, ...)
558#define TRACE_COMPLETE0(category, name, start, end)
559#define TRACE_COMPLETE1(category, name, start, end, arg1_name, arg1)
560#define TRACE_COMPLETE2( \
561        category, name, start, end, arg1_name, arg1, arg2_name, arg2)
562
563#endif // PHOSPHOR_DISABLED
564