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 | |
72 | is, in the context of CTF IR, that event classes hold a reference to | |
73 | their parent stream class and stream classes hold a reference to their | |
74 | parent trace. | |
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 | |
228 | loads libbabeltrace, use: | |
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 | ||
239 | `BABELTRACE_NO_DLCLOSE=1` makes libbabeltrace not close the shared | |
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 | |
285 | libbabeltrace's current log level. | |
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 PP |
364 | + |
365 | In libbabeltrace, the user can set the current run-time log level with | |
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 | ||
434 | `BT_LOGV_STR("preformatted string")`:: | |
435 | Preformatted string verbose logging statement. | |
436 | ||
437 | `BT_LOGD_STR("preformatted string")`:: | |
438 | Preformatted string debug logging statement. | |
439 | ||
440 | `BT_LOGI_STR("preformatted string")`:: | |
441 | Preformatted string info logging statement. | |
442 | ||
443 | `BT_LOGW_STR("preformatted string")`:: | |
444 | Preformatted string warning logging statement. | |
445 | ||
446 | `BT_LOGE_STR("preformatted string")`:: | |
447 | Preformatted string error logging statement. | |
448 | ||
449 | `BT_LOGF_STR("preformatted string")`:: | |
450 | Preformatted string fatal logging statement. | |
451 | ||
452 | ||
f9ded0e0 | 453 | ==== Conditional logging |
beb0fb75 PP |
454 | |
455 | `BT_LOG_IF(cond, statement)`:: | |
456 | Execute `statement` only if `cond` is true. | |
457 | + | |
458 | Example: | |
459 | + | |
460 | -- | |
461 | [source,c] | |
462 | ---- | |
463 | BT_LOG_IF(i < count / 2, BT_LOGD("Log this: i=%d", i)); | |
464 | ---- | |
465 | -- | |
466 | ||
467 | To check the <<build-time-log-level,build-time log level>>: | |
468 | ||
469 | [source,c] | |
470 | ---- | |
471 | #if BT_LOG_ENABLED_DEBUG | |
472 | ... | |
473 | #endif | |
474 | ---- | |
475 | ||
f9ded0e0 PP |
476 | This tests if the _DEBUG_ level was enabled at build-time. This means |
477 | that the current, <<run-time-log-level,dynamic log level>> _could_ be | |
478 | _DEBUG_, but it could also be higher. The rule of thumb is to use only | |
479 | logging statements at the same level in a `BT_LOG_ENABLED_*` conditional | |
480 | block. | |
beb0fb75 PP |
481 | |
482 | The available definitions for build-time conditions are: | |
483 | ||
484 | * `BT_LOG_ENABLED_VERBOSE` | |
485 | * `BT_LOG_ENABLED_DEBUG` | |
486 | * `BT_LOG_ENABLED_INFO` | |
487 | * `BT_LOG_ENABLED_WARN` | |
488 | * `BT_LOG_ENABLED_ERROR` | |
489 | * `BT_LOG_ENABLED_FATAL` | |
490 | ||
491 | To check the current, <<run-time-log-level,run-time log level>>: | |
492 | ||
493 | [source,c] | |
494 | ---- | |
495 | if (BT_LOG_ON_DEBUG) { | |
496 | ... | |
497 | } | |
498 | ---- | |
499 | ||
500 | This tests if the _DEBUG_ log level is dynamically turned on | |
501 | (implies that it's also enabled at build-time). This check could have a | |
502 | noticeable impact on performance. | |
503 | ||
504 | The available definitions for run-time conditions are: | |
505 | ||
506 | * `BT_LOG_ON_VERBOSE` | |
507 | * `BT_LOG_ON_DEBUG` | |
508 | * `BT_LOG_ON_INFO` | |
509 | * `BT_LOG_ON_WARN` | |
510 | * `BT_LOG_ON_ERROR` | |
511 | * `BT_LOG_ON_FATAL` | |
512 | ||
513 | Those macros check the subproject-specific or module-specific log level | |
514 | symbol (defined by `BT_LOG_OUTPUT_LEVEL`). | |
515 | ||
516 | Never, ever write code which would be executed only to compute the | |
517 | fields of a logging statement outside a conditional logging scope, | |
518 | for example: | |
519 | ||
520 | [source,c] | |
521 | ---- | |
522 | int number = get_number_of_event_classes_with_property_x(...); | |
523 | BT_LOGD("Bla bla: number=%d", number); | |
524 | ---- | |
525 | ||
526 | Do this instead: | |
527 | ||
528 | [source,c] | |
529 | ---- | |
530 | if (BT_LOG_ON_DEBUG) { | |
531 | int number = get_number_of_event_classes_with_property_x(...); | |
532 | BT_LOGD("Bla bla: number=%d", number); | |
533 | } | |
534 | ---- | |
535 | ||
536 | Or even this: | |
537 | ||
538 | [source,c] | |
539 | ---- | |
540 | BT_LOGD("Bla bla: number=%d", get_number_of_event_classes_with_property_x(...)); | |
541 | ---- | |
542 | ||
543 | ||
4a41523d PP |
544 | [[how-to]] |
545 | === Instrument a module | |
beb0fb75 | 546 | |
4a41523d | 547 | Follow those steps to make your module loggable: |
beb0fb75 | 548 | |
4a41523d PP |
549 | . In your module's root directory, create a `logging.c` file with |
550 | this content: | |
551 | + | |
552 | -- | |
553 | [source,c] | |
554 | ---- | |
555 | /* | |
556 | * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/> | |
557 | * | |
558 | * Permission is hereby granted, free of charge, to any person obtaining a copy | |
559 | * of this software and associated documentation files (the "Software"), to deal | |
560 | * in the Software without restriction, including without limitation the rights | |
561 | * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell | |
562 | * copies of the Software, and to permit persons to whom the Software is | |
563 | * furnished to do so, subject to the following conditions: | |
564 | * | |
565 | * The above copyright notice and this permission notice shall be included in | |
566 | * all copies or substantial portions of the Software. | |
567 | * | |
568 | * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR | |
569 | * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, | |
570 | * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE | |
571 | * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER | |
572 | * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, | |
573 | * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE | |
574 | * SOFTWARE. | |
575 | */ | |
576 | ||
577 | #define BT_LOG_OUTPUT_LEVEL my_module_log_level | |
578 | #include <babeltrace/logging-internal.h> | |
beb0fb75 | 579 | |
4a41523d PP |
580 | BT_LOG_INIT_LOG_LEVEL(my_module_log_level, "BABELTRACE_MY_MODULE_LOG_LEVEL"); |
581 | ---- | |
582 | -- | |
583 | + | |
584 | Replace `my_module_log_level` with the name of the symbol which holds | |
585 | the log level for your module (should be unique amongst all the log level | |
586 | symbols of the project). Replace `BABELTRACE_MY_MODULE_LOG_LEVEL` with | |
587 | the name of the environment variable from which to initialize your | |
588 | module's log level at construction time. `BT_LOG_INIT_LOG_LEVEL()` | |
589 | defines both the hidden log level symbol and a constructor which reads | |
590 | the environment variable and sets the log level symbol accordingly. | |
591 | ||
592 | . In your module's root directory, create a `logging.h` file with | |
593 | this content: | |
594 | + | |
595 | -- | |
beb0fb75 PP |
596 | [source,c] |
597 | ---- | |
4a41523d PP |
598 | #ifndef MY_MODULE_LOGGING_H |
599 | #define MY_MODULE_LOGGING_H | |
600 | ||
601 | /* | |
602 | * Copyright (c) 2017 EfficiOS Inc. <http://efficios.com/> | |
603 | * | |
604 | * Permission is hereby granted, free of charge, to any person obtaining a copy | |
605 | * of this software and associated documentation files (the "Software"), to deal | |
606 | * in the Software without restriction, including without limitation the rights | |
607 | * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell | |
608 | * copies of the Software, and to permit persons to whom the Software is | |
609 | * furnished to do so, subject to the following conditions: | |
610 | * | |
611 | * The above copyright notice and this permission notice shall be included in | |
612 | * all copies or substantial portions of the Software. | |
613 | * | |
614 | * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR | |
615 | * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, | |
616 | * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE | |
617 | * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER | |
618 | * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, | |
619 | * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE | |
620 | * SOFTWARE. | |
621 | */ | |
622 | ||
623 | #define BT_LOG_OUTPUT_LEVEL my_module_log_level | |
beb0fb75 | 624 | #include <babeltrace/logging-internal.h> |
4a41523d PP |
625 | |
626 | BT_LOG_LEVEL_EXTERN_SYMBOL(my_module_log_level); | |
627 | ||
628 | #endif /* MY_MODULE_LOGGING_H */ | |
beb0fb75 | 629 | ---- |
4a41523d PP |
630 | -- |
631 | + | |
f9ded0e0 | 632 | Replace `my_module_log_level` with the name of your module's |
4a41523d PP |
633 | log level symbol. |
634 | ||
635 | . Include the `logging.c` and `logging.h` in the `_SOURCES` variable | |
636 | of your module's object in your module's root `Makefile.am`. | |
beb0fb75 | 637 | |
f9ded0e0 PP |
638 | |
639 | [[logging-instrument-source]] | |
640 | ==== Instrument a C source file | |
641 | ||
4a41523d PP |
642 | To instrument a C source file (`.c`): |
643 | ||
644 | . At the top of the file, before the first `#include` line (if any), | |
645 | define your file's tag name and include the local `logging.h`: | |
646 | + | |
647 | -- | |
648 | [source,c] | |
649 | ---- | |
650 | #define BT_LOG_TAG "MY-MODULE-MY-FILE" | |
651 | #include "logging.h" | |
652 | ---- | |
653 | -- | |
654 | + | |
655 | A logging tag name is a namespace for a specific source file. Its name | |
656 | is part of every log message generated by the statements of the file. A | |
657 | logging tag name _must_ be only uppercase letters, digits, and the | |
f9ded0e0 | 658 | hyphen (`-`) character. See <<choose-a-tag,Choose a tag>> for |
4a41523d PP |
659 | a list of standard tags. |
660 | ||
661 | . Use the <<logging-statements,logging statement macros>> in the file's | |
662 | functions to instrument it. | |
663 | ||
f9ded0e0 PP |
664 | |
665 | [[logging-instrument-header]] | |
666 | ==== Instrument a C header file | |
667 | ||
4a41523d PP |
668 | To instrument a C header file (`.h`), if you have `static inline` |
669 | functions in it: | |
670 | ||
671 | . Do not include any logging header. | |
672 | . Use the <<logging-statements,logging statement macros>> in the file's | |
673 | functions to instrument it, making each of them conditional to the | |
674 | existence of the macro you're using: | |
675 | + | |
676 | -- | |
677 | [source,c] | |
678 | ---- | |
679 | static inline | |
680 | void some_function(void) | |
681 | { | |
682 | /* ... */ | |
683 | ||
684 | #ifdef BT_LOGV | |
685 | BT_LOGV(...); | |
686 | #endif | |
687 | ||
688 | /* ... */ | |
689 | ||
690 | #ifdef BT_LOGW_STR | |
691 | BT_LOGW_STR(...); | |
692 | #endif | |
693 | ||
694 | /* ... */ | |
695 | } | |
696 | ---- | |
697 | -- | |
698 | + | |
699 | The C source files which include this header file determine if logging | |
700 | is enabled or not for them (if the source file is instrumented itself), | |
701 | and the tag of the included header's logging statement is the same as | |
f9ded0e0 | 702 | the including C source file. |
beb0fb75 PP |
703 | |
704 | ||
f9ded0e0 | 705 | [[choose-a-tag]] |
93841983 | 706 | === Choose a tag |
beb0fb75 | 707 | |
93841983 PP |
708 | For plugins, the format of the tag name for a given source file _must_ |
709 | be: | |
beb0fb75 | 710 | |
93841983 PP |
711 | [verse] |
712 | PLUGIN-__PNAME__-__CCNAME__-__CCTYPE__[-__FILE__] | |
beb0fb75 | 713 | |
93841983 PP |
714 | __PNAME__:: |
715 | Plugin's name. | |
beb0fb75 | 716 | |
93841983 PP |
717 | __CCNAME__:: |
718 | Component class's name. | |
beb0fb75 | 719 | |
93841983 PP |
720 | __CCTYPE__:: |
721 | Component class's type (`SRC`, `FLT`, or `SINK`). | |
beb0fb75 | 722 | |
93841983 PP |
723 | __FILE__:: |
724 | Additional information to specify the source file name or module. | |
beb0fb75 | 725 | |
93841983 | 726 | Examples: |
beb0fb75 | 727 | |
93841983 PP |
728 | * `PLUGIN-CTF-LTTNG-LIVE-SRC` |
729 | * `PLUGIN-CTF-LTTNG-LIVE-SRC-VIEWER` | |
730 | * `PLUGIN-UTILS-MUXER-FLT` | |
beb0fb75 PP |
731 | |
732 | ||
f9ded0e0 PP |
733 | [[log-level]] |
734 | === Choose a log level | |
beb0fb75 PP |
735 | |
736 | Choosing the appropriate level for your logging statement is very | |
737 | important. | |
738 | ||
739 | [options="header,autowidth",cols="default,default,asciidoc,default"] | |
740 | |=== | |
741 | |Log level |Description |Use cases |Impact on performance | |
742 | ||
743 | |_FATAL_ | |
744 | |The program, library, or plugin cannot continue to work in this | |
745 | condition: it must be terminated immediately. | |
746 | ||
b4b9064d | 747 | A _FATAL_-level logging statement should always be followed by |
4a41523d | 748 | `abort()`. |
beb0fb75 PP |
749 | | |
750 | * Unexpected return values from system calls. | |
4a41523d PP |
751 | * Logic error in internal code, for example an unexpected value in a |
752 | `switch` statement. | |
beb0fb75 PP |
753 | |Almost none: should be executed in production. |
754 | ||
755 | |_ERROR_ | |
756 | |An important error which is somewhat not fatal, that is, the program, | |
757 | library, or plugin can continue to work after this, but you judge that | |
758 | it should be reported to the user. | |
759 | ||
760 | Usually, the program cannot recover from such an error, but it can at | |
761 | least exit cleanly. | |
762 | | | |
763 | * Memory allocation errors. | |
764 | * Failed to perform an operation which should work considering the | |
765 | implementation and the satisfied preconditions. For example, the | |
766 | failure to create an empty object (no parameters): most probably | |
767 | failed internally because of an allocation error. | |
93841983 | 768 | * Almost any error in terminal elements: CLI and plugins. |
beb0fb75 PP |
769 | |Almost none: should be executed in production. |
770 | ||
771 | |_WARN_ | |
772 | |A logic error which still allows the execution to continue. | |
6c1b33a8 PP |
773 | |
774 | _WARN_-level logging statements are for any error or weird action that | |
775 | is directly or indirectly caused by the user. For example, not having | |
4a41523d PP |
776 | enough memory is considered beyond the user's control, so we always |
777 | log memory errors with an _ERROR_ level (not _FATAL_ because we usually | |
778 | don't abort in this condition). | |
93841983 PP |
779 | |
780 | Almost all the library's errors are logged as warnings because they are | |
781 | caused by the user. | |
beb0fb75 | 782 | | |
6c1b33a8 PP |
783 | * Not honoring a public function's preconditions (NULL parameters, |
784 | index out of bounds, etc.). | |
785 | * Adding an invalid event class to a stream class which is already | |
786 | part of a trace. | |
beb0fb75 PP |
787 | + |
788 | For example, the caller tries to set a property of a frozen stream | |
789 | class. | |
790 | |Almost none: can be executed in production. | |
791 | ||
792 | |_INFO_ | |
793 | |Any useful information which a non-developer user would understand. | |
794 | | | |
795 | * Successful loading of a plugin (with name, version, etc.). | |
796 | * Successful connection to or disconnection from another system. | |
4a41523d | 797 | * An _optional_ subsystem cannot be loaded. |
beb0fb75 PP |
798 | |Very little: can be executed in production if |
799 | _INFO_ level information is desired. | |
800 | ||
801 | |_DEBUG_ | |
802 | |Something that only Babeltrace developers would be interested into. | |
803 | | | |
804 | * High-level function entry/exit. | |
805 | * Object creation, destruction, copying, and freezing. | |
f9ded0e0 PP |
806 | * The result of some computation/validation which does not |
807 | occur in a tight loop. | |
beb0fb75 PP |
808 | |Noticeable, but not as much as the _VERBOSE_ level: not executed in |
809 | production. | |
810 | ||
811 | |_VERBOSE_ | |
812 | |Low-level debugging context information. More appropriate for tracing | |
813 | in general. | |
814 | | | |
815 | * Reference count change. | |
816 | * Status of each iteration of a loop. | |
817 | * State machine's state change. | |
818 | * Data structure lookup/modification. | |
819 | * List of ELF sections found in a plugin. | |
820 | * Get or set an object's property. | |
821 | * Object comparison's intermediate results. | |
822 | |Huge: not executed in production. | |
823 | |=== | |
824 | ||
b4b9064d PP |
825 | Make sure not to use a _WARN_ (or higher) log level when the condition |
826 | leading to the logging statement can occur under normal circumstances. | |
827 | For example, a public function to get some object or property from an | |
828 | object by name or key that fails to find the value is not a warning: the | |
829 | user could legitimately use this function to check if the name/key | |
830 | exists in the object. In this case, use the _VERBOSE_ level (or do not | |
831 | log at all). If a numeric index is out of bounds, however, this | |
832 | qualifies for a _WARN_ level: such API functions have documented | |
833 | preconditions that the index must be in bounds (the user can always | |
834 | check with a count or size function). | |
835 | ||
beb0fb75 | 836 | |
b4b9064d | 837 | [[message]] |
f9ded0e0 | 838 | === Write an appropriate message |
beb0fb75 PP |
839 | |
840 | Follow those rules when you write a logging statement's message: | |
841 | ||
842 | * Use an english sentence which starts with a capital letter. Start the | |
843 | sentence with the appropriate verb tense depending on the context. For | |
844 | example: | |
845 | + | |
846 | -- | |
b4b9064d PP |
847 | ** Beginning of operation (present continuous): _Creating ..._, |
848 | _Copying ..._, _Serializing ..._, _Freezing ..._, _Destroying ..._ | |
849 | ** End of operation (simple past): _Created ..._, _Successfully created ..._, | |
850 | _Failed to create ..._, _Set ..._ (simple past of _to set_ which is | |
851 | also _set_) | |
beb0fb75 PP |
852 | -- |
853 | + | |
854 | For warning and error messages, you can start the message with _Cannot_ | |
b4b9064d | 855 | or _Failed to_ followed by a verb if it's appropriate. |
beb0fb75 PP |
856 | |
857 | * Do not include the log level in the message itself. For example, | |
858 | do not start the message with _Error while_ or _Warning:_. | |
859 | ||
860 | * Do not put newlines, tabs, or other special characters in the | |
861 | message, unless you want to log a string with such characters. Note | |
862 | that multiline log messages can be hard to parse, analyze, and filter, | |
b4b9064d PP |
863 | however, so prefer multiple `BT_LOG*()` statements over a single |
864 | statement with newlines. | |
beb0fb75 PP |
865 | |
866 | * **If there are fields that your logging statement must record**, | |
867 | follow the message with `:` followed by a space, then with the list of | |
868 | fields (more about this below). If there are no fields, end the | |
869 | sentence with a period. | |
870 | ||
871 | The statement's fields _must_ be a comma-separated list of | |
872 | +__name__=__value__+ tokens. Keep +__name__+ as simple as possible | |
b4b9064d PP |
873 | (lowercase if possible). If +__value__+ is a non-alphanumeric string, |
874 | put it between double quotes. Always use the `PRId64` and `PRIu64` | |
875 | specifiers when logging `int64_t` and `uint64_t` values. | |
beb0fb75 PP |
876 | |
877 | Example: | |
878 | ||
879 | "Cannot add event class to stream class: stream-class-addr=%p, " | |
b4b9064d | 880 | "stream-class-name=\"%s\", stream-class-id=%" PRId64 ", " |
beb0fb75 PP |
881 | "event-class-addr=%p, event-class-name=\"%s\", event-class-id=%" PRId64 |
882 | ||
883 | By following a standard format for the statement fields, it is easier | |
884 | to use tools like https://www.elastic.co/products/logstash[Logstash] | |
885 | to split fields and analyze logs. | |
886 | ||
887 | Prefer the following suffixes in field names: | |
888 | ||
889 | [options="header,autowidth"] | |
890 | |=== | |
891 | |Field name suffix |Description |Format specifier | |
892 | ||
893 | |`-addr` |Memory address |`%p` | |
894 | |`-fd` |File descriptor |`%d` | |
895 | |`-fp` |File stream (`FILE *`) |`%p` | |
896 | |`-id` |Object's ID |`%" PRId64 "` or `%" PRIu64 "` | |
897 | |`-name` |Object's name |`\"%s\"` | |
beb0fb75 PP |
898 | |=== |
899 | ||
900 | ||
f9ded0e0 | 901 | === Output |
beb0fb75 PP |
902 | |
903 | The log is printed to the standard error stream. A log line contains the | |
f9ded0e0 PP |
904 | time, the process and thread IDs, the <<log-level,log level>>, the |
905 | <<choose-a-tag,tag>>, the source's function name, file name and | |
906 | line number, and the <<message,message>>. | |
beb0fb75 | 907 | |
f9ded0e0 PP |
908 | When Babeltrace supports terminal color codes (depends on the |
909 | `BABELTRACE_TERM_COLOR` environment variable's value and what the | |
910 | standard output and error streams are plugged into), _INFO_-level lines | |
911 | are blue, _WARN_-level lines are yellow, and _ERROR_-level and | |
912 | _FATAL_-level lines are red. | |
913 | ||
914 | Log line example: | |
beb0fb75 PP |
915 | |
916 | 05-11 00:58:03.691 23402 23402 D VALUES bt_value_destroy@values.c:498 Destroying value: addr=0xb9c3eb0 | |
917 | ||
918 | You can easily filter the log with `grep` or `ag`. For example, to | |
919 | keep only the _WARN_-level log messages that the `VALUES` module | |
920 | generates: | |
921 | ||
922 | $ export BABELTRACE_LOGGING_GLOBAL_LEVEL=VERBOSE | |
923 | $ ./test_ctf_writer_complete 2>&1 | ag 'W VALUES' |