Commit | Line | Data |
---|---|---|
f9ded0e0 PP |
1 | = Babeltrace's contributor's guide |
2 | Jérémie Galarneau, Philippe Proulx | |
3 | v0.1, 6 September 2017 | |
beb0fb75 PP |
4 | :toc: |
5 | :toclevels: 5 | |
6 | ||
beb0fb75 | 7 | |
f9ded0e0 PP |
8 | This is a partial contributor's guide for the |
9 | http://diamon.org/babeltrace[Babeltrace] project. If you have any | |
10 | questions that are not answered in this guide, please post them | |
11 | on https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev[Babeltrace's mailing list]. | |
beb0fb75 | 12 | |
f9ded0e0 PP |
13 | |
14 | == Object reference counting and lifetime | |
15 | ||
16 | This section covers the rationale behind the design of Babeltrace's | |
17 | object lifetime management. | |
18 | ||
19 | Starting from Babeltrace 2.x, all publicly exposed objects inherit a | |
20 | common base: `bt_object`. This base provides a number of facilities to | |
21 | all objects, chief amongst which are lifetime management functions. | |
22 | ||
23 | The reference count of all public objects is controlled by invoking the | |
24 | `bt_get()` and `bt_put()` functions which respectively increment and | |
25 | decrement an object's reference count. | |
26 | ||
27 | As far as lifetime management in concerned, Babeltrace makes a clear | |
28 | distinction between regular objects, which have a single parent, and | |
29 | root objects, which don't. | |
30 | ||
31 | ||
32 | === The problem | |
33 | ||
34 | Let us consider a problematic case to illustrate the need for this | |
35 | distinction. | |
36 | ||
37 | A user of the CTF Writer library declares a trace, which *has* a | |
38 | stream class (the declaration of a stream) and that stream class, in | |
39 | turn, *has* an event class (the declaration of an event). | |
40 | ||
41 | Nothing prevents this user from releasing his reference on any one of | |
42 | these objects in any order. However, all objects in the | |
43 | __trace--stream class--event class__ hierarchy can be retrieved | |
44 | from any other. | |
45 | ||
46 | For instance, the user could discard his reference on both the event | |
47 | class and the stream class, only keeping a reference on the trace. From | |
48 | this trace reference, stream classes can be enumerated, providing the | |
49 | user with a new reference to the stream class he discarded earlier. | |
50 | event classes can also be enumerated from stream classes, providing the | |
51 | user with references to the individual event classes. | |
52 | ||
53 | Conversely, the user could also hold a reference to an event class and | |
54 | retrieve its parent stream class. The trace, in turn, can then be | |
55 | retrieved from the stream class. | |
56 | ||
57 | This example illustrates what could be interpreted as a circular | |
58 | reference dependency existing between these objects. Of course, if the | |
59 | objects in such a scenario were to hold references to each other (in | |
60 | both directions), we would be in presence of a circular ownership | |
61 | resulting in a leak of both objects as their reference counts would | |
62 | never reach zero. | |
63 | ||
64 | Nonetheless, the API must offer the guarantee that holding a node to any | |
65 | node of the graph keeps all other reachable nodes alive. | |
66 | ||
67 | ||
68 | === The solution | |
69 | ||
70 | The scheme employed in Babeltrace to break this cycle consists in the | |
71 | "children" holding *reverse component references* to their parents. That | |
56e18c4c PP |
72 | is, in the context of the trace IR, that event classes hold a reference |
73 | to their parent stream class and stream classes hold a reference to | |
74 | their parent trace. | |
f9ded0e0 PP |
75 | |
76 | On the other hand, parents hold *claiming aggregation references* to | |
77 | their children. A claiming aggregation reference means that the object | |
78 | being referenced should not be deleted as long as the reference still | |
79 | exists. In this respect, it can be said that parents truly hold the | |
80 | ownership of their children, since they control their lifetime. | |
81 | Conversely, the reference counting mechanism is leveraged by children to | |
82 | notify parents that no other child indirectly exposes the parent. | |
83 | ||
84 | When a parented object's reference count reaches zero, it invokes | |
85 | `bt_put()` on its parent and does **not** free itself. However, from | |
86 | that point, the object depends on its parent to signal the moment when | |
87 | it can be safely reclaimed. | |
88 | ||
89 | The invocation of `bt_put()` by the last children holding a reference to | |
90 | its parent might trigger a cascade of `bt_put()` from child to parent. | |
91 | Eventually, a **root** object is reached. At that point, if this | |
92 | orphaned object's reference count reaches zero, the object invokes the | |
93 | destructor method defined by everyone of its children as part of their | |
94 | base `struct bt_object`. The key point here is that the cascade of | |
95 | destructor will necessarily originate from the root and propagate in | |
96 | preorder to the children. These children will propagate the destruction | |
97 | to their own children before reclaiming their own memory. This ensures | |
98 | that a node's pointer to its parent is *always* valid since the parent | |
99 | has the responsibility of tearing-down their children before cleaning | |
100 | themselves up. | |
101 | ||
102 | Assuming a reference to an object is *acquired* by calling `bt_get()` | |
103 | while its reference count is zero, the object acquires, in turn, a | |
104 | reference on its parent using `bt_get()`. At that point, the child can | |
105 | be thought of as having converted its weak reference to its parent into | |
106 | a regular reference. That is why this reference is referred to as a | |
107 | *claiming* aggregation reference. | |
108 | ||
109 | ||
110 | === Caveats | |
111 | ||
112 | This scheme imposes a number of strict rules defining the relation | |
113 | between objects: | |
114 | ||
115 | * Objects may only have one parent. | |
116 | * Objects, beside the root, are only retrievable from their direct | |
117 | parent or children. | |
118 | ||
119 | ||
120 | === Example | |
121 | ||
122 | The initial situation is rather simple: **User A** is holding a | |
123 | reference to a trace, **TC1**. As per the rules previously enounced, | |
124 | stream classes **SC1** and **SC2** don't hold a reference to **TC1** | |
125 | since their own reference counts are zero. The same holds true for | |
126 | **EC1**, **EC2** and **EC3** with respect to **SC1** and **SC2**. | |
127 | ||
128 | image::doc/contributing-images/bt-ref01.png[] | |
129 | ||
130 | In this second step, we can see that **User A** has acquired a reference | |
131 | on **SC2** through the trace, **TC1**. | |
132 | ||
133 | The stream class's reference count transitions from zero to one, | |
134 | triggering the acquisition of a strong reference on **TC1** from | |
135 | **SC2**. | |
136 | ||
137 | Hence, at this point, the trace's ownership is shared by **User A** and | |
138 | **SC2**. | |
139 | ||
140 | image::doc/contributing-images/bt-ref02.png[] | |
141 | ||
142 | Next, **User A** acquires a reference on the **EC3** event class through | |
143 | its parent stream class, **SC2**. Again, the transition of an object's | |
144 | reference count from 0 to 1 triggers the acquisition of a reference on | |
145 | its parent. | |
146 | ||
147 | Note that SC2's reference count was incremented to 2. The trace's | |
148 | reference count remains unchanged. | |
149 | ||
150 | image::doc/contributing-images/bt-ref03.png[] | |
151 | ||
152 | **User A** decides to drop its reference on **SC2**. **SC2**'s reference | |
153 | count returns back to 1, everything else remaining unchanged. | |
154 | ||
155 | image::doc/contributing-images/bt-ref04.png[] | |
156 | ||
157 | **User A** can then decide to drop its reference on the trace. This | |
158 | results in a reversal of the initial situation: **User A** now owns an | |
159 | event, **EC3**, which is keeping everything else alive and reachable. | |
160 | ||
161 | image::doc/contributing-images/bt-ref05.png[] | |
162 | ||
163 | If another object, **User B**, enters the picture and acquires a | |
164 | reference on the **SC1** stream class, we see that **SC1**'s reference | |
165 | count transitioned from 0 to 1, triggering the acquisition of a | |
166 | reference on **TC1**. | |
167 | ||
168 | image::doc/contributing-images/bt-ref06.png[] | |
169 | ||
170 | **User B** hands off a reference to **EC1**, acquired through **SC1**, | |
171 | to another object, **User C**. The acquisition of a reference on | |
172 | **EC1**, which transitions from 0 to 1, triggers the acquisition of a | |
173 | reference on its parent, **SC1**. | |
174 | ||
175 | image::doc/contributing-images/bt-ref07.png[] | |
176 | ||
177 | At some point, **User A** releases its reference on **EC3**. Since | |
178 | **EC3**'s reference count transitions to zero, it releases its reference | |
179 | on **SC2**. **SC2**'s reference count, in turn, reaches zero and it | |
180 | releases its reference to **TC1**. | |
181 | ||
182 | **TC1**'s reference count is now 1 and no further action is taken. | |
183 | ||
184 | image::doc/contributing-images/bt-ref08.png[] | |
185 | ||
186 | **User B** releases its reference on **SC1**. **User C** becomes the | |
187 | sole owner of the whole hierarchy through his ownership of **EC1**. | |
188 | ||
189 | image::doc/contributing-images/bt-ref09.png[] | |
190 | ||
191 | Finally, **User C** releases his ownership of **EC1**, triggering the | |
192 | release of the whole hierarchy. Let's walk through the reclamation of | |
193 | the whole graph. | |
194 | ||
195 | Mirroring what happened when **User A** released its last reference on | |
196 | **EC3**, the release of **EC1** by **User C** causes its reference count | |
197 | to fall to zero. | |
198 | ||
199 | This transition to zero causes **EC1** to release its reference on | |
200 | **SC1**. **SC1**'s reference count reaching zero causes it to release | |
201 | its reference on **TC1**. | |
202 | ||
203 | image::doc/contributing-images/bt-ref10.png[] | |
204 | ||
205 | Since the reference count of **TC1**, a root object, has reached zero, | |
206 | it invokes the destructor method on its children. This method is | |
207 | recursive and causes the stream classes to call the destructor method on | |
208 | their event classes. | |
209 | ||
210 | The event classes are reached and, having no children of their own, are | |
211 | reclaimed. | |
212 | ||
213 | image::doc/contributing-images/bt-ref11.png[] | |
214 | ||
215 | The stream classes having destroyed their children, are then reclaimed | |
216 | by the trace. | |
217 | ||
218 | image::doc/contributing-images/bt-ref12.png[] | |
219 | ||
220 | Finally, the stream classes having been reclaimed, **TC1** is reclaimed. | |
221 | ||
222 | image::doc/contributing-images/bt-ref13.png[] | |
223 | ||
224 | ||
225 | == Valgrind | |
226 | ||
227 | To use Valgrind on an application (for example, the CLI or a test) which | |
a12f3d62 | 228 | loads libbabeltrace2, use: |
f9ded0e0 PP |
229 | |
230 | $ G_SLICE=always-malloc G_DEBUG=gc-friendly PYTHONMALLOC=malloc \ | |
231 | BABELTRACE_NO_DLCLOSE=1 valgrind --leak-check=full \ | |
232 | --suppressions=/path/to/babeltrace/extras/valgrind/popt.supp app | |
233 | ||
234 | `G_SLICE=always-malloc` and `G_DEBUG=gc-friendly` is for GLib and | |
235 | `PYTHONMALLOC=malloc` is for the Python interpreter, if it is used by | |
236 | the Python plugin provider (Valgrind will probably show a lot of errors | |
237 | which originate from Python interpreter anyway). | |
238 | ||
a12f3d62 | 239 | `BABELTRACE_NO_DLCLOSE=1` makes libbabeltrace2 not close the shared |
f9ded0e0 PP |
240 | libraries (plugins) which it loads. This is needed to see the |
241 | appropriate backtrace when Valgrind shows errors. | |
242 | ||
243 | ||
244 | == Logging | |
beb0fb75 PP |
245 | |
246 | Logging is a great instrument for a developer to be able to collect | |
247 | information about a running software. | |
248 | ||
249 | Babeltrace is a complex software with many layers. When a Babeltrace | |
250 | graph fails to run, what caused the failure? It could be caused by any | |
251 | component, any notification iterator, and any deeply nested validation | |
252 | of a CTR IR object, for example. With the appropriate logging statements | |
253 | manually placed in the source code, we can find the cause of a bug | |
254 | faster. | |
255 | ||
f9ded0e0 PP |
256 | While <<log-level,care must be taken>> when placing _INFO_ to _FATAL_ |
257 | logging statements, you should liberally instrument your Babeltrace | |
258 | module with _DEBUG_ and _VERBOSE_ logging statements to help future you | |
259 | and other developers understand what's happening at run-time. | |
beb0fb75 PP |
260 | |
261 | ||
f9ded0e0 | 262 | === Logging API |
beb0fb75 PP |
263 | |
264 | The Babeltrace logging API is internal: it is not exposed to the users | |
265 | of the library, only to their developers. The only thing that a library | |
4a41523d | 266 | user can control is the current log level of the library itself with |
beb0fb75 PP |
267 | `bt_logging_set_global_level()` and the initial library's log level with |
268 | the `BABELTRACE_LOGGING_GLOBAL_LEVEL` environment variable. | |
269 | ||
270 | This API is based on https://github.com/wonder-mice/zf_log[zf_log], a | |
271 | lightweight, yet featureful, MIT-licensed core logging library for C and | |
272 | $$C++$$. The zf_log source files were modified to have the `BT_` and | |
f9ded0e0 | 273 | `bt_` prefixes, and other small changes, like color support. |
beb0fb75 PP |
274 | |
275 | The logging functions are implemented in the logging convenience | |
276 | library (`logging` directory). | |
277 | ||
278 | ||
f9ded0e0 | 279 | ==== Headers |
beb0fb75 PP |
280 | |
281 | The logging API headers are: | |
282 | ||
283 | `<babeltrace/logging.h>`:: | |
284 | Public header which a library user can use to control and read | |
a12f3d62 | 285 | libbabeltrace2's current log level. |
beb0fb75 PP |
286 | |
287 | `<babeltrace/logging-internal.h>`:: | |
288 | Internal, generic logging API which you can use in any Babeltrace | |
289 | subproject. This is the translation of `zf_log.h`. | |
290 | ||
291 | `<babeltrace/lib-logging-internal.h>`:: | |
292 | Specific internal header to use within the library. This header | |
293 | defines `BT_LOG_OUTPUT_LEVEL` to a custom, library-wide hidden | |
294 | symbol which is the library's current log level before including | |
295 | `<babeltrace/logging-internal.h>`. | |
296 | ||
297 | Do not include `<babeltrace/logging-internal.h>` or | |
298 | `<babeltrace/lib-logging-internal.h>` in a header which contains logging | |
299 | statements: this header could be included in source files which define a | |
f9ded0e0 PP |
300 | different <<choose-a-tag,tag>>, for example. See |
301 | <<logging-instrument-header, Instrument a C header file>>. | |
beb0fb75 | 302 | |
b4b9064d | 303 | |
f9ded0e0 | 304 | ==== Log levels |
beb0fb75 PP |
305 | |
306 | The API offers the following log levels: | |
307 | ||
308 | * _VERBOSE_ | |
309 | * _DEBUG_ | |
310 | * _INFO_ | |
311 | * _WARN_ | |
312 | * _ERROR_ | |
313 | * _FATAL_ | |
314 | ||
f9ded0e0 | 315 | See <<log-level,how to decide which one to use>> below. |
beb0fb75 PP |
316 | |
317 | There are two important log level variables: | |
318 | ||
319 | [[build-time-log-level]]Build-time, minimal log level:: | |
320 | The minimal log level, or build-time log level, is set at build | |
321 | time and determines the minimal log level which can be executed. | |
322 | This applies to all the subprojects and modules (CLI, library, | |
323 | plugins, etc.). | |
324 | + | |
325 | All the logging statements with a level below this level are **not built | |
326 | at all**. All the logging statements with a level equal to or greater | |
f9ded0e0 PP |
327 | than this level _can_ be executed, depending on the |
328 | <<run-time-log-level,run-time log level>>. | |
beb0fb75 PP |
329 | + |
330 | You can set this level at configuration time with the | |
331 | `BABELTRACE_MINIMAL_LOG_LEVEL` environment variable, for example: | |
332 | + | |
333 | -- | |
334 | ---- | |
335 | $ BABELTRACE_MINIMAL_LOG_LEVEL=WARN ./configure | |
336 | ---- | |
337 | -- | |
338 | + | |
f9ded0e0 | 339 | The default build-time log level is `VERBOSE`. For optimal performance, |
beb0fb75 PP |
340 | set it to `NONE`, which effectively disables all logging in all the |
341 | Babeltrace subprojects. | |
342 | + | |
343 | The library's public API provides `bt_logging_get_minimal_level()` to | |
344 | get the configured minimal log level. | |
345 | ||
346 | [[run-time-log-level]]Run-time, dynamic log level:: | |
347 | The dynamic log level is set at run-time and determines the current, | |
348 | active log level. All the logging statements with a level below this | |
349 | level are not executed, but they evaluate the condition. All the | |
350 | logging statements with a level equal to or greater than this level | |
f9ded0e0 PP |
351 | are executed, provided that their level is also |
352 | <<build-time-log-level,enabled at build time>>. | |
beb0fb75 | 353 | + |
f9ded0e0 PP |
354 | `zf_log` has a concept of a global run-time log level which uses the |
355 | `_bt_log_global_output_lvl` symbol. In practice, we never use this | |
356 | symbol, and always make sure that `BT_LOG_OUTPUT_LEVEL` is defined to a | |
357 | module-wise or subproject-wise hidden symbol before including | |
beb0fb75 | 358 | `<babeltrace/logging-internal.h>`. In the library, |
f9ded0e0 PP |
359 | `<babeltrace/lib-logging-internal.h>` does this job: just include this |
360 | header which defines `BT_LOG_OUTPUT_LEVEL` to the appropriate symbol | |
361 | before it includes `<babeltrace/logging-internal.h>`. In plugins, for | |
362 | example, there is one log level per component class, which makes log | |
363 | filtering easier during execution. | |
beb0fb75 | 364 | + |
a12f3d62 | 365 | In libbabeltrace2, the user can set the current run-time log level with |
beb0fb75 PP |
366 | the `bt_logging_set_global_level()` function, for example: |
367 | + | |
368 | -- | |
369 | [source,c] | |
370 | ---- | |
371 | bt_logging_set_global_level(BT_LOGGING_LEVEL_INFO); | |
372 | ---- | |
373 | -- | |
374 | + | |
375 | The library's initial run-time log level is defined by the | |
376 | `BABELTRACE_LOGGING_GLOBAL_LEVEL` environment variable (`VERBOSE`, `DEBUG`, | |
377 | `INFO`, `WARN`, `ERROR`, `FATAL`, or `NONE`), or set to _NONE_ if this | |
378 | environment variable is undefined. | |
379 | + | |
380 | Other subprojects have their own way of setting their run-time log | |
381 | level. For example, the CLI uses the `BABELTRACE_CLI_LOG_LEVEL` | |
f9ded0e0 | 382 | environment variable, and the `filter.utils.muxer` component class |
beb0fb75 | 383 | initializes its log level thanks to the |
f9ded0e0 | 384 | `BABELTRACE_PLUGIN_UTILS_MUXER_FLT_LOG_LEVEL` environment variable |
beb0fb75 PP |
385 | (also _NONE_ by default). |
386 | + | |
387 | Make sure that there is a documented way to initialize or modify the | |
388 | log level of your subproject or module, and that it's set to _NONE_ | |
389 | by default. | |
390 | ||
391 | ||
4a41523d | 392 | [[logging-statements]] |
f9ded0e0 | 393 | ==== Logging statement macros |
beb0fb75 PP |
394 | |
395 | The Babeltrace logging statement macros work just like `printf()` and | |
396 | contain their log level in their name: | |
397 | ||
398 | `BT_LOGV("format string", ...)`:: | |
399 | Standard verbose logging statement. | |
400 | ||
401 | `BT_LOGD("format string", ...)`:: | |
402 | Standard debug logging statement. | |
403 | ||
404 | `BT_LOGI("format string", ...)`:: | |
405 | Standard info logging statement. | |
406 | ||
407 | `BT_LOGW("format string", ...)`:: | |
408 | Standard warning logging statement. | |
409 | ||
410 | `BT_LOGE("format string", ...)`:: | |
411 | Standard error logging statement. | |
412 | ||
413 | `BT_LOGF("format string", ...)`:: | |
414 | Standard fatal logging statement. | |
415 | ||
416 | `BT_LOGV_MEM(data_ptr, data_size, "format string", ...)`:: | |
417 | Memory verbose logging statement. | |
418 | ||
419 | `BT_LOGD_MEM(data_ptr, data_size, "format string", ...)`:: | |
420 | Memory debug logging statement. | |
421 | ||
422 | `BT_LOGI_MEM(data_ptr, data_size, "format string", ...)`:: | |
423 | Memory info logging statement. | |
424 | ||
425 | `BT_LOGW_MEM(data_ptr, data_size, "format string", ...)`:: | |
426 | Memory warning logging statement. | |
427 | ||
428 | `BT_LOGE_MEM(data_ptr, data_size, "format string", ...)`:: | |
429 | Memory error logging statement. | |
430 | ||
431 | `BT_LOGF_MEM(data_ptr, data_size, "format string", ...)`:: | |
432 | Memory fatal logging statement. | |
433 | ||
b81626f9 PP |
434 | `BT_LOGV_ERRNO("initial message", "format string", ...)`:: |
435 | `errno` string verbose logging statement. | |
436 | ||
437 | `BT_LOGD_ERRNO("initial message", "format string", ...)`:: | |
438 | `errno` string debug logging statement. | |
439 | ||
440 | `BT_LOGI_ERRNO("initial message", "format string", ...)`:: | |
441 | `errno` string info logging statement. | |
442 | ||
443 | `BT_LOGW_ERRNO("initial message", "format string", ...)`:: | |
444 | `errno` string warning logging statement. | |
445 | ||
446 | `BT_LOGE_ERRNO("initial message", "format string", ...)`:: | |
447 | `errno` string error logging statement. | |
448 | ||
449 | `BT_LOGF_ERRNO("initial message", "format string", ...)`:: | |
450 | `errno` string fatal logging statement. | |
451 | ||
beb0fb75 PP |
452 | `BT_LOGV_STR("preformatted string")`:: |
453 | Preformatted string verbose logging statement. | |
454 | ||
455 | `BT_LOGD_STR("preformatted string")`:: | |
456 | Preformatted string debug logging statement. | |
457 | ||
458 | `BT_LOGI_STR("preformatted string")`:: | |
459 | Preformatted string info logging statement. | |
460 | ||
461 | `BT_LOGW_STR("preformatted string")`:: | |
462 | Preformatted string warning logging statement. | |
463 | ||
464 | `BT_LOGE_STR("preformatted string")`:: | |
465 | Preformatted string error logging statement. | |
466 | ||
467 | `BT_LOGF_STR("preformatted string")`:: | |
468 | Preformatted string fatal logging statement. | |
469 | ||
470 | ||
f9ded0e0 | 471 | ==== Conditional logging |
beb0fb75 PP |
472 | |
473 | `BT_LOG_IF(cond, statement)`:: | |
474 | Execute `statement` only if `cond` is true. | |
475 | + | |
476 | Example: | |
477 | + | |
478 | -- | |
479 | [source,c] | |
480 | ---- | |
481 | BT_LOG_IF(i < count / 2, BT_LOGD("Log this: i=%d", i)); | |
482 | ---- | |
483 | -- | |
484 | ||
485 | To check the <<build-time-log-level,build-time log level>>: | |
486 | ||
487 | [source,c] | |
488 | ---- | |
489 | #if BT_LOG_ENABLED_DEBUG | |
490 | ... | |
491 | #endif | |
492 | ---- | |
493 | ||
f9ded0e0 PP |
494 | This tests if the _DEBUG_ level was enabled at build-time. This means |
495 | that the current, <<run-time-log-level,dynamic log level>> _could_ be | |
496 | _DEBUG_, but it could also be higher. The rule of thumb is to use only | |
497 | logging statements at the same level in a `BT_LOG_ENABLED_*` conditional | |
498 | block. | |
beb0fb75 PP |
499 | |
500 | The available definitions for build-time conditions are: | |
501 | ||
502 | * `BT_LOG_ENABLED_VERBOSE` | |
503 | * `BT_LOG_ENABLED_DEBUG` | |
504 | * `BT_LOG_ENABLED_INFO` | |
505 | * `BT_LOG_ENABLED_WARN` | |
506 | * `BT_LOG_ENABLED_ERROR` | |
507 | * `BT_LOG_ENABLED_FATAL` | |
508 | ||
509 | To check the current, <<run-time-log-level,run-time log level>>: | |
510 | ||
511 | [source,c] | |
512 | ---- | |
513 | if (BT_LOG_ON_DEBUG) { | |
514 | ... | |
515 | } | |
516 | ---- | |
517 | ||
518 | This tests if the _DEBUG_ log level is dynamically turned on | |
519 | (implies that it's also enabled at build-time). This check could have a | |
520 | noticeable impact on performance. | |
521 | ||
522 | The available definitions for run-time conditions are: | |
523 | ||
524 | * `BT_LOG_ON_VERBOSE` | |
525 | * `BT_LOG_ON_DEBUG` | |
526 | * `BT_LOG_ON_INFO` | |
527 | * `BT_LOG_ON_WARN` | |
528 | * `BT_LOG_ON_ERROR` | |
529 | * `BT_LOG_ON_FATAL` | |
530 | ||
531 | Those macros check the subproject-specific or module-specific log level | |
532 | symbol (defined by `BT_LOG_OUTPUT_LEVEL`). | |
533 | ||
534 | Never, ever write code which would be executed only to compute the | |
535 | fields of a logging statement outside a conditional logging scope, | |
536 | for example: | |
537 | ||
538 | [source,c] | |
539 | ---- | |
540 | int number = get_number_of_event_classes_with_property_x(...); | |
541 | BT_LOGD("Bla bla: number=%d", number); | |
542 | ---- | |
543 | ||
544 | Do this instead: | |
545 | ||
546 | [source,c] | |
547 | ---- | |
548 | if (BT_LOG_ON_DEBUG) { | |
549 | int number = get_number_of_event_classes_with_property_x(...); | |
550 | BT_LOGD("Bla bla: number=%d", number); | |
551 | } | |
552 | ---- | |
553 | ||
554 | Or even this: | |
555 | ||
556 | [source,c] | |
557 | ---- | |
558 | BT_LOGD("Bla bla: number=%d", get_number_of_event_classes_with_property_x(...)); | |
559 | ---- | |
560 | ||
561 | ||
4a41523d PP |
562 | [[how-to]] |
563 | === Instrument a module | |
beb0fb75 | 564 | |
4a41523d | 565 | Follow those steps to make your module loggable: |
beb0fb75 | 566 | |
4a41523d PP |
567 | . In your module's root directory, create a `logging.c` file with |
568 | this content: | |
569 | + | |
570 | -- | |
571 | [source,c] | |
572 | ---- | |
573 | /* | |
574 | * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/> | |
575 | * | |
576 | * Permission is hereby granted, free of charge, to any person obtaining a copy | |
577 | * of this software and associated documentation files (the "Software"), to deal | |
578 | * in the Software without restriction, including without limitation the rights | |
579 | * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell | |
580 | * copies of the Software, and to permit persons to whom the Software is | |
581 | * furnished to do so, subject to the following conditions: | |
582 | * | |
583 | * The above copyright notice and this permission notice shall be included in | |
584 | * all copies or substantial portions of the Software. | |
585 | * | |
586 | * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR | |
587 | * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, | |
588 | * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE | |
589 | * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER | |
590 | * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, | |
591 | * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE | |
592 | * SOFTWARE. | |
593 | */ | |
594 | ||
595 | #define BT_LOG_OUTPUT_LEVEL my_module_log_level | |
596 | #include <babeltrace/logging-internal.h> | |
beb0fb75 | 597 | |
4a41523d PP |
598 | BT_LOG_INIT_LOG_LEVEL(my_module_log_level, "BABELTRACE_MY_MODULE_LOG_LEVEL"); |
599 | ---- | |
600 | -- | |
601 | + | |
602 | Replace `my_module_log_level` with the name of the symbol which holds | |
603 | the log level for your module (should be unique amongst all the log level | |
604 | symbols of the project). Replace `BABELTRACE_MY_MODULE_LOG_LEVEL` with | |
605 | the name of the environment variable from which to initialize your | |
606 | module's log level at construction time. `BT_LOG_INIT_LOG_LEVEL()` | |
607 | defines both the hidden log level symbol and a constructor which reads | |
608 | the environment variable and sets the log level symbol accordingly. | |
609 | ||
610 | . In your module's root directory, create a `logging.h` file with | |
611 | this content: | |
612 | + | |
613 | -- | |
beb0fb75 PP |
614 | [source,c] |
615 | ---- | |
971e1e8b PP |
616 | #ifndef BABELTRACE_MY_MODULE_LOGGING_H |
617 | #define BABELTRACE_MY_MODULE_LOGGING_H | |
4a41523d PP |
618 | |
619 | /* | |
620 | * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/> | |
621 | * | |
622 | * Permission is hereby granted, free of charge, to any person obtaining a copy | |
623 | * of this software and associated documentation files (the "Software"), to deal | |
624 | * in the Software without restriction, including without limitation the rights | |
625 | * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell | |
626 | * copies of the Software, and to permit persons to whom the Software is | |
627 | * furnished to do so, subject to the following conditions: | |
628 | * | |
629 | * The above copyright notice and this permission notice shall be included in | |
630 | * all copies or substantial portions of the Software. | |
631 | * | |
632 | * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR | |
633 | * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, | |
634 | * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE | |
635 | * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER | |
636 | * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, | |
637 | * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE | |
638 | * SOFTWARE. | |
639 | */ | |
640 | ||
641 | #define BT_LOG_OUTPUT_LEVEL my_module_log_level | |
beb0fb75 | 642 | #include <babeltrace/logging-internal.h> |
4a41523d PP |
643 | |
644 | BT_LOG_LEVEL_EXTERN_SYMBOL(my_module_log_level); | |
645 | ||
971e1e8b | 646 | #endif /* BABELTRACE_MY_MODULE_LOGGING_H */ |
beb0fb75 | 647 | ---- |
4a41523d PP |
648 | -- |
649 | + | |
f9ded0e0 | 650 | Replace `my_module_log_level` with the name of your module's |
4a41523d PP |
651 | log level symbol. |
652 | ||
653 | . Include the `logging.c` and `logging.h` in the `_SOURCES` variable | |
654 | of your module's object in your module's root `Makefile.am`. | |
beb0fb75 | 655 | |
6470c171 | 656 | . Add the log level initializing environment variable name to the |
a12f3d62 | 657 | `log_level_env_var_names` array in `cli/babeltrace2.c`. |
6470c171 | 658 | |
f9ded0e0 PP |
659 | |
660 | [[logging-instrument-source]] | |
661 | ==== Instrument a C source file | |
662 | ||
4a41523d PP |
663 | To instrument a C source file (`.c`): |
664 | ||
665 | . At the top of the file, before the first `#include` line (if any), | |
666 | define your file's tag name and include the local `logging.h`: | |
667 | + | |
668 | -- | |
669 | [source,c] | |
670 | ---- | |
671 | #define BT_LOG_TAG "MY-MODULE-MY-FILE" | |
672 | #include "logging.h" | |
673 | ---- | |
674 | -- | |
675 | + | |
676 | A logging tag name is a namespace for a specific source file. Its name | |
677 | is part of every log message generated by the statements of the file. A | |
678 | logging tag name _must_ be only uppercase letters, digits, and the | |
f9ded0e0 | 679 | hyphen (`-`) character. See <<choose-a-tag,Choose a tag>> for |
4a41523d PP |
680 | a list of standard tags. |
681 | ||
682 | . Use the <<logging-statements,logging statement macros>> in the file's | |
683 | functions to instrument it. | |
684 | ||
f9ded0e0 PP |
685 | |
686 | [[logging-instrument-header]] | |
687 | ==== Instrument a C header file | |
688 | ||
4a41523d PP |
689 | To instrument a C header file (`.h`), if you have `static inline` |
690 | functions in it: | |
691 | ||
692 | . Do not include any logging header. | |
693 | . Use the <<logging-statements,logging statement macros>> in the file's | |
694 | functions to instrument it, making each of them conditional to the | |
695 | existence of the macro you're using: | |
696 | + | |
697 | -- | |
698 | [source,c] | |
699 | ---- | |
700 | static inline | |
701 | void some_function(void) | |
702 | { | |
703 | /* ... */ | |
704 | ||
705 | #ifdef BT_LOGV | |
706 | BT_LOGV(...); | |
707 | #endif | |
708 | ||
709 | /* ... */ | |
710 | ||
711 | #ifdef BT_LOGW_STR | |
712 | BT_LOGW_STR(...); | |
713 | #endif | |
714 | ||
715 | /* ... */ | |
716 | } | |
717 | ---- | |
718 | -- | |
719 | + | |
720 | The C source files which include this header file determine if logging | |
721 | is enabled or not for them (if the source file is instrumented itself), | |
722 | and the tag of the included header's logging statement is the same as | |
f9ded0e0 | 723 | the including C source file. |
beb0fb75 PP |
724 | |
725 | ||
f9ded0e0 | 726 | [[choose-a-tag]] |
93841983 | 727 | === Choose a tag |
beb0fb75 | 728 | |
93841983 PP |
729 | For plugins, the format of the tag name for a given source file _must_ |
730 | be: | |
beb0fb75 | 731 | |
93841983 PP |
732 | [verse] |
733 | PLUGIN-__PNAME__-__CCNAME__-__CCTYPE__[-__FILE__] | |
beb0fb75 | 734 | |
93841983 PP |
735 | __PNAME__:: |
736 | Plugin's name. | |
beb0fb75 | 737 | |
93841983 PP |
738 | __CCNAME__:: |
739 | Component class's name. | |
beb0fb75 | 740 | |
93841983 PP |
741 | __CCTYPE__:: |
742 | Component class's type (`SRC`, `FLT`, or `SINK`). | |
beb0fb75 | 743 | |
93841983 PP |
744 | __FILE__:: |
745 | Additional information to specify the source file name or module. | |
beb0fb75 | 746 | |
93841983 | 747 | Examples: |
beb0fb75 | 748 | |
93841983 PP |
749 | * `PLUGIN-CTF-LTTNG-LIVE-SRC` |
750 | * `PLUGIN-CTF-LTTNG-LIVE-SRC-VIEWER` | |
751 | * `PLUGIN-UTILS-MUXER-FLT` | |
beb0fb75 PP |
752 | |
753 | ||
f9ded0e0 PP |
754 | [[log-level]] |
755 | === Choose a log level | |
beb0fb75 PP |
756 | |
757 | Choosing the appropriate level for your logging statement is very | |
758 | important. | |
759 | ||
760 | [options="header,autowidth",cols="default,default,asciidoc,default"] | |
761 | |=== | |
762 | |Log level |Description |Use cases |Impact on performance | |
763 | ||
764 | |_FATAL_ | |
765 | |The program, library, or plugin cannot continue to work in this | |
766 | condition: it must be terminated immediately. | |
767 | ||
b4b9064d | 768 | A _FATAL_-level logging statement should always be followed by |
4a41523d | 769 | `abort()`. |
beb0fb75 PP |
770 | | |
771 | * Unexpected return values from system calls. | |
4a41523d PP |
772 | * Logic error in internal code, for example an unexpected value in a |
773 | `switch` statement. | |
beb0fb75 PP |
774 | |Almost none: should be executed in production. |
775 | ||
776 | |_ERROR_ | |
777 | |An important error which is somewhat not fatal, that is, the program, | |
778 | library, or plugin can continue to work after this, but you judge that | |
779 | it should be reported to the user. | |
780 | ||
781 | Usually, the program cannot recover from such an error, but it can at | |
782 | least exit cleanly. | |
783 | | | |
784 | * Memory allocation errors. | |
785 | * Failed to perform an operation which should work considering the | |
786 | implementation and the satisfied preconditions. For example, the | |
787 | failure to create an empty object (no parameters): most probably | |
788 | failed internally because of an allocation error. | |
93841983 | 789 | * Almost any error in terminal elements: CLI and plugins. |
beb0fb75 PP |
790 | |Almost none: should be executed in production. |
791 | ||
792 | |_WARN_ | |
793 | |A logic error which still allows the execution to continue. | |
6c1b33a8 PP |
794 | |
795 | _WARN_-level logging statements are for any error or weird action that | |
796 | is directly or indirectly caused by the user. For example, not having | |
4a41523d PP |
797 | enough memory is considered beyond the user's control, so we always |
798 | log memory errors with an _ERROR_ level (not _FATAL_ because we usually | |
799 | don't abort in this condition). | |
93841983 PP |
800 | |
801 | Almost all the library's errors are logged as warnings because they are | |
802 | caused by the user. | |
beb0fb75 | 803 | | |
6c1b33a8 PP |
804 | * Not honoring a public function's preconditions (NULL parameters, |
805 | index out of bounds, etc.). | |
806 | * Adding an invalid event class to a stream class which is already | |
807 | part of a trace. | |
beb0fb75 PP |
808 | + |
809 | For example, the caller tries to set a property of a frozen stream | |
810 | class. | |
811 | |Almost none: can be executed in production. | |
812 | ||
813 | |_INFO_ | |
814 | |Any useful information which a non-developer user would understand. | |
815 | | | |
816 | * Successful loading of a plugin (with name, version, etc.). | |
817 | * Successful connection to or disconnection from another system. | |
4a41523d | 818 | * An _optional_ subsystem cannot be loaded. |
beb0fb75 PP |
819 | |Very little: can be executed in production if |
820 | _INFO_ level information is desired. | |
821 | ||
822 | |_DEBUG_ | |
823 | |Something that only Babeltrace developers would be interested into. | |
824 | | | |
825 | * High-level function entry/exit. | |
826 | * Object creation, destruction, copying, and freezing. | |
f9ded0e0 PP |
827 | * The result of some computation/validation which does not |
828 | occur in a tight loop. | |
beb0fb75 PP |
829 | |Noticeable, but not as much as the _VERBOSE_ level: not executed in |
830 | production. | |
831 | ||
832 | |_VERBOSE_ | |
833 | |Low-level debugging context information. More appropriate for tracing | |
834 | in general. | |
835 | | | |
836 | * Reference count change. | |
837 | * Status of each iteration of a loop. | |
838 | * State machine's state change. | |
839 | * Data structure lookup/modification. | |
840 | * List of ELF sections found in a plugin. | |
841 | * Get or set an object's property. | |
842 | * Object comparison's intermediate results. | |
843 | |Huge: not executed in production. | |
844 | |=== | |
845 | ||
b4b9064d PP |
846 | Make sure not to use a _WARN_ (or higher) log level when the condition |
847 | leading to the logging statement can occur under normal circumstances. | |
848 | For example, a public function to get some object or property from an | |
849 | object by name or key that fails to find the value is not a warning: the | |
850 | user could legitimately use this function to check if the name/key | |
851 | exists in the object. In this case, use the _VERBOSE_ level (or do not | |
852 | log at all). If a numeric index is out of bounds, however, this | |
853 | qualifies for a _WARN_ level: such API functions have documented | |
854 | preconditions that the index must be in bounds (the user can always | |
855 | check with a count or size function). | |
856 | ||
beb0fb75 | 857 | |
b4b9064d | 858 | [[message]] |
f9ded0e0 | 859 | === Write an appropriate message |
beb0fb75 PP |
860 | |
861 | Follow those rules when you write a logging statement's message: | |
862 | ||
863 | * Use an english sentence which starts with a capital letter. Start the | |
864 | sentence with the appropriate verb tense depending on the context. For | |
865 | example: | |
866 | + | |
867 | -- | |
b4b9064d PP |
868 | ** Beginning of operation (present continuous): _Creating ..._, |
869 | _Copying ..._, _Serializing ..._, _Freezing ..._, _Destroying ..._ | |
870 | ** End of operation (simple past): _Created ..._, _Successfully created ..._, | |
871 | _Failed to create ..._, _Set ..._ (simple past of _to set_ which is | |
872 | also _set_) | |
beb0fb75 PP |
873 | -- |
874 | + | |
875 | For warning and error messages, you can start the message with _Cannot_ | |
b4b9064d | 876 | or _Failed to_ followed by a verb if it's appropriate. |
beb0fb75 PP |
877 | |
878 | * Do not include the log level in the message itself. For example, | |
879 | do not start the message with _Error while_ or _Warning:_. | |
880 | ||
881 | * Do not put newlines, tabs, or other special characters in the | |
882 | message, unless you want to log a string with such characters. Note | |
883 | that multiline log messages can be hard to parse, analyze, and filter, | |
b4b9064d PP |
884 | however, so prefer multiple `BT_LOG*()` statements over a single |
885 | statement with newlines. | |
beb0fb75 PP |
886 | |
887 | * **If there are fields that your logging statement must record**, | |
888 | follow the message with `:` followed by a space, then with the list of | |
889 | fields (more about this below). If there are no fields, end the | |
890 | sentence with a period. | |
891 | ||
892 | The statement's fields _must_ be a comma-separated list of | |
893 | +__name__=__value__+ tokens. Keep +__name__+ as simple as possible | |
b4b9064d PP |
894 | (lowercase if possible). If +__value__+ is a non-alphanumeric string, |
895 | put it between double quotes. Always use the `PRId64` and `PRIu64` | |
896 | specifiers when logging `int64_t` and `uint64_t` values. | |
beb0fb75 PP |
897 | |
898 | Example: | |
899 | ||
900 | "Cannot add event class to stream class: stream-class-addr=%p, " | |
b4b9064d | 901 | "stream-class-name=\"%s\", stream-class-id=%" PRId64 ", " |
beb0fb75 PP |
902 | "event-class-addr=%p, event-class-name=\"%s\", event-class-id=%" PRId64 |
903 | ||
904 | By following a standard format for the statement fields, it is easier | |
905 | to use tools like https://www.elastic.co/products/logstash[Logstash] | |
906 | to split fields and analyze logs. | |
907 | ||
908 | Prefer the following suffixes in field names: | |
909 | ||
910 | [options="header,autowidth"] | |
911 | |=== | |
912 | |Field name suffix |Description |Format specifier | |
913 | ||
914 | |`-addr` |Memory address |`%p` | |
915 | |`-fd` |File descriptor |`%d` | |
916 | |`-fp` |File stream (`FILE *`) |`%p` | |
917 | |`-id` |Object's ID |`%" PRId64 "` or `%" PRIu64 "` | |
918 | |`-name` |Object's name |`\"%s\"` | |
beb0fb75 PP |
919 | |=== |
920 | ||
921 | ||
f9ded0e0 | 922 | === Output |
beb0fb75 PP |
923 | |
924 | The log is printed to the standard error stream. A log line contains the | |
f9ded0e0 PP |
925 | time, the process and thread IDs, the <<log-level,log level>>, the |
926 | <<choose-a-tag,tag>>, the source's function name, file name and | |
927 | line number, and the <<message,message>>. | |
beb0fb75 | 928 | |
f9ded0e0 PP |
929 | When Babeltrace supports terminal color codes (depends on the |
930 | `BABELTRACE_TERM_COLOR` environment variable's value and what the | |
931 | standard output and error streams are plugged into), _INFO_-level lines | |
932 | are blue, _WARN_-level lines are yellow, and _ERROR_-level and | |
933 | _FATAL_-level lines are red. | |
934 | ||
935 | Log line example: | |
beb0fb75 PP |
936 | |
937 | 05-11 00:58:03.691 23402 23402 D VALUES bt_value_destroy@values.c:498 Destroying value: addr=0xb9c3eb0 | |
938 | ||
939 | You can easily filter the log with `grep` or `ag`. For example, to | |
940 | keep only the _WARN_-level log messages that the `VALUES` module | |
941 | generates: | |
942 | ||
943 | $ export BABELTRACE_LOGGING_GLOBAL_LEVEL=VERBOSE | |
944 | $ ./test_ctf_writer_complete 2>&1 | ag 'W VALUES' |