Commit | Line | Data |
---|---|---|
cd4aac1e PP |
1 | // Render with Asciidoctor |
2 | ||
3 | = Babeltrace contributor's guide | |
f9ded0e0 | 4 | Jérémie Galarneau, Philippe Proulx |
cd4aac1e | 5 | v0.2, 19 June 2019 |
beb0fb75 PP |
6 | :toc: |
7 | :toclevels: 5 | |
8 | ||
beb0fb75 | 9 | |
f9ded0e0 PP |
10 | This is a partial contributor's guide for the |
11 | http://diamon.org/babeltrace[Babeltrace] project. If you have any | |
cd4aac1e PP |
12 | questions that are not answered by this guide, please post them on |
13 | https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev[Babeltrace's | |
14 | mailing list]. | |
15 | ||
beb0fb75 | 16 | |
cd4aac1e | 17 | == Babeltrace library |
f9ded0e0 | 18 | |
cd4aac1e | 19 | === Object reference counting and lifetime |
f9ded0e0 PP |
20 | |
21 | This section covers the rationale behind the design of Babeltrace's | |
cd4aac1e PP |
22 | object lifetime management. This applies to the Babeltrace library, as |
23 | well as to the CTF writer library (although the public reference | |
24 | counting functions are not named the same way). | |
f9ded0e0 | 25 | |
cd4aac1e | 26 | Starting from Babeltrace 2.0, all publicly exposed objects inherit a |
f9ded0e0 PP |
27 | common base: `bt_object`. This base provides a number of facilities to |
28 | all objects, chief amongst which are lifetime management functions. | |
29 | ||
cd4aac1e PP |
30 | The lifetime of some public objects is managed by reference counting. In |
31 | this case, the API offers the `+bt_*_get_ref()+` and `+bt_*_put_ref()+` | |
32 | functions which respectively increment and decrement an object's | |
33 | reference count. | |
f9ded0e0 PP |
34 | |
35 | As far as lifetime management in concerned, Babeltrace makes a clear | |
36 | distinction between regular objects, which have a single parent, and | |
37 | root objects, which don't. | |
38 | ||
39 | ||
cd4aac1e | 40 | ==== The problem |
f9ded0e0 PP |
41 | |
42 | Let us consider a problematic case to illustrate the need for this | |
43 | distinction. | |
44 | ||
cd4aac1e PP |
45 | A user of the Babeltrace library creates a trace class, which _has_ a |
46 | stream class (the class of a stream) and that stream class, in turn, | |
47 | _has_ an event class (the class of an event). | |
f9ded0e0 PP |
48 | |
49 | Nothing prevents this user from releasing his reference on any one of | |
50 | these objects in any order. However, all objects in the | |
51 | __trace--stream class--event class__ hierarchy can be retrieved | |
52 | from any other. | |
53 | ||
54 | For instance, the user could discard his reference on both the event | |
cd4aac1e PP |
55 | class and the stream class, only keeping a reference on the trace class. |
56 | From this trace class reference, stream classes can be enumerated, | |
57 | providing the user with a new reference to the stream class he discarded | |
58 | earlier. Event classes can also be enumerated from stream classes, | |
59 | providing the user with references to the individual event classes. | |
f9ded0e0 PP |
60 | |
61 | Conversely, the user could also hold a reference to an event class and | |
cd4aac1e | 62 | retrieve its parent stream class. The trace class, in turn, can then be |
f9ded0e0 PP |
63 | retrieved from the stream class. |
64 | ||
65 | This example illustrates what could be interpreted as a circular | |
66 | reference dependency existing between these objects. Of course, if the | |
67 | objects in such a scenario were to hold references to each other (in | |
68 | both directions), we would be in presence of a circular ownership | |
69 | resulting in a leak of both objects as their reference counts would | |
70 | never reach zero. | |
71 | ||
72 | Nonetheless, the API must offer the guarantee that holding a node to any | |
73 | node of the graph keeps all other reachable nodes alive. | |
74 | ||
75 | ||
cd4aac1e | 76 | ==== The solution |
f9ded0e0 PP |
77 | |
78 | The scheme employed in Babeltrace to break this cycle consists in the | |
cd4aac1e | 79 | "children" holding _reverse component references_ to their parents. That |
56e18c4c PP |
80 | is, in the context of the trace IR, that event classes hold a reference |
81 | to their parent stream class and stream classes hold a reference to | |
cd4aac1e | 82 | their parent trace class. |
f9ded0e0 | 83 | |
cd4aac1e | 84 | On the other hand, parents hold _claiming aggregation references_ to |
f9ded0e0 PP |
85 | their children. A claiming aggregation reference means that the object |
86 | being referenced should not be deleted as long as the reference still | |
87 | exists. In this respect, it can be said that parents truly hold the | |
88 | ownership of their children, since they control their lifetime. | |
89 | Conversely, the reference counting mechanism is leveraged by children to | |
90 | notify parents that no other child indirectly exposes the parent. | |
91 | ||
92 | When a parented object's reference count reaches zero, it invokes | |
cd4aac1e PP |
93 | `+bt_*_put_ref()+` on its parent and does _not_ free itself. However, |
94 | from that point, the object depends on its parent to signal the moment | |
95 | when it can be safely reclaimed. | |
96 | ||
97 | The invocation of `+bt_*_put_ref()+` by the last children holding a | |
98 | reference to its parent might trigger a cascade of `+bt_*_put_ref()+` | |
99 | from child to parent. Eventually, a **root** object is reached. At that | |
100 | point, if this orphaned object's reference count reaches zero, the | |
101 | object invokes the destructor method defined by everyone of its children | |
102 | as part of their base `struct bt_object`. The key point here is that the | |
103 | cascade of destructor will necessarily originate from the root and | |
104 | propagate in preorder to the children. These children will propagate the | |
105 | destruction to their own children before reclaiming their own memory. | |
106 | This ensures that a node's pointer to its parent is _always_ valid since | |
107 | the parent has the responsibility of tearing-down their children before | |
108 | cleaning themselves up. | |
109 | ||
110 | Assuming a reference to an object is _acquired_ by calling | |
111 | `+bt_*_get_ref()+` while its reference count is zero, the object | |
112 | acquires, in turn, a reference on its parent using `+bt_*_get_ref()+`. | |
113 | At that point, the child can be thought of as having converted its weak | |
114 | reference to its parent into a regular reference. That is why this | |
115 | reference is referred to as a _claiming_ aggregation reference. | |
116 | ||
117 | ||
118 | ==== Caveats | |
f9ded0e0 PP |
119 | |
120 | This scheme imposes a number of strict rules defining the relation | |
121 | between objects: | |
122 | ||
123 | * Objects may only have one parent. | |
124 | * Objects, beside the root, are only retrievable from their direct | |
125 | parent or children. | |
126 | ||
127 | ||
cd4aac1e | 128 | ==== Example |
f9ded0e0 | 129 | |
cd4aac1e PP |
130 | The initial situation is rather simple: **User{nbsp}A** is holding a |
131 | reference to a trace class, **TC1**. As per the rules previously | |
132 | enounced, stream classes **SC1** and **SC2** don't hold a reference to | |
133 | **TC1** since their own reference counts are zero. The same holds true | |
134 | for **EC1**, **EC2** and **EC3** with respect to **SC1** and **SC2**. | |
f9ded0e0 PP |
135 | |
136 | image::doc/contributing-images/bt-ref01.png[] | |
137 | ||
cd4aac1e PP |
138 | In this second step, we can see that **User{nbsp}A** has acquired a |
139 | reference on **SC2** through the trace class, **TC1**. | |
f9ded0e0 PP |
140 | |
141 | The stream class's reference count transitions from zero to one, | |
142 | triggering the acquisition of a strong reference on **TC1** from | |
143 | **SC2**. | |
144 | ||
cd4aac1e PP |
145 | Hence, at this point, the trace class's ownership is shared by |
146 | **User{nbsp}A** and **SC2**. | |
f9ded0e0 PP |
147 | |
148 | image::doc/contributing-images/bt-ref02.png[] | |
149 | ||
cd4aac1e PP |
150 | Next, **User{nbsp}A** acquires a reference on the **EC3** event class |
151 | through its parent stream class, **SC2**. Again, the transition of an | |
152 | object's reference count from 0 to 1 triggers the acquisition of a | |
153 | reference on its parent. | |
f9ded0e0 | 154 | |
cd4aac1e | 155 | Note that SC2's reference count was incremented to 2. The trace class's |
f9ded0e0 PP |
156 | reference count remains unchanged. |
157 | ||
158 | image::doc/contributing-images/bt-ref03.png[] | |
159 | ||
cd4aac1e PP |
160 | **User{nbsp}A** decides to drop its reference on **SC2**. **SC2**'s |
161 | reference count returns back to 1, everything else remaining unchanged. | |
f9ded0e0 PP |
162 | |
163 | image::doc/contributing-images/bt-ref04.png[] | |
164 | ||
cd4aac1e PP |
165 | **User{nbsp}A** can then decide to drop its reference on the trace |
166 | class. This results in a reversal of the initial situation: | |
167 | **User{nbsp}A** now owns an event, **EC3**, which is keeping everything | |
168 | else alive and reachable. | |
f9ded0e0 PP |
169 | |
170 | image::doc/contributing-images/bt-ref05.png[] | |
171 | ||
cd4aac1e | 172 | If another object, **User{nbsp}B**, enters the picture and acquires a |
f9ded0e0 PP |
173 | reference on the **SC1** stream class, we see that **SC1**'s reference |
174 | count transitioned from 0 to 1, triggering the acquisition of a | |
175 | reference on **TC1**. | |
176 | ||
177 | image::doc/contributing-images/bt-ref06.png[] | |
178 | ||
cd4aac1e PP |
179 | **User{nbsp}B** hands off a reference to **EC1**, acquired through |
180 | **SC1**, to another object, **User{nbsp}C**. The acquisition of a | |
181 | reference on **EC1**, which transitions from 0 to 1, triggers the | |
182 | acquisition of a reference on its parent, **SC1**. | |
f9ded0e0 PP |
183 | |
184 | image::doc/contributing-images/bt-ref07.png[] | |
185 | ||
cd4aac1e | 186 | At some point, **User{nbsp}A** releases its reference on **EC3**. Since |
f9ded0e0 PP |
187 | **EC3**'s reference count transitions to zero, it releases its reference |
188 | on **SC2**. **SC2**'s reference count, in turn, reaches zero and it | |
189 | releases its reference to **TC1**. | |
190 | ||
191 | **TC1**'s reference count is now 1 and no further action is taken. | |
192 | ||
193 | image::doc/contributing-images/bt-ref08.png[] | |
194 | ||
cd4aac1e PP |
195 | **User{nbsp}B** releases its reference on **SC1**. **User{nbsp}C** |
196 | becomes the sole owner of the whole hierarchy through his ownership of | |
197 | **EC1**. | |
f9ded0e0 PP |
198 | |
199 | image::doc/contributing-images/bt-ref09.png[] | |
200 | ||
cd4aac1e PP |
201 | Finally, **User{nbsp}C** releases his ownership of **EC1**, triggering |
202 | the release of the whole hierarchy. Let's walk through the reclamation | |
203 | of the whole graph. | |
f9ded0e0 | 204 | |
cd4aac1e PP |
205 | Mirroring what happened when **User{nbsp}A** released its last reference |
206 | on **EC3**, the release of **EC1** by **User{nbsp}C** causes its | |
207 | reference count to fall to zero. | |
f9ded0e0 PP |
208 | |
209 | This transition to zero causes **EC1** to release its reference on | |
210 | **SC1**. **SC1**'s reference count reaching zero causes it to release | |
211 | its reference on **TC1**. | |
212 | ||
213 | image::doc/contributing-images/bt-ref10.png[] | |
214 | ||
215 | Since the reference count of **TC1**, a root object, has reached zero, | |
216 | it invokes the destructor method on its children. This method is | |
217 | recursive and causes the stream classes to call the destructor method on | |
218 | their event classes. | |
219 | ||
220 | The event classes are reached and, having no children of their own, are | |
221 | reclaimed. | |
222 | ||
223 | image::doc/contributing-images/bt-ref11.png[] | |
224 | ||
225 | The stream classes having destroyed their children, are then reclaimed | |
cd4aac1e | 226 | by the trace class. |
f9ded0e0 PP |
227 | |
228 | image::doc/contributing-images/bt-ref12.png[] | |
229 | ||
230 | Finally, the stream classes having been reclaimed, **TC1** is reclaimed. | |
231 | ||
232 | image::doc/contributing-images/bt-ref13.png[] | |
233 | ||
234 | ||
f9ded0e0 | 235 | == Logging |
beb0fb75 PP |
236 | |
237 | Logging is a great instrument for a developer to be able to collect | |
238 | information about a running software. | |
239 | ||
240 | Babeltrace is a complex software with many layers. When a Babeltrace | |
241 | graph fails to run, what caused the failure? It could be caused by any | |
cd4aac1e PP |
242 | component, any message iterator, and any deeply nested validation of a |
243 | CTF IR object (within the `ctf` plugin), for example. With the | |
244 | appropriate logging statements manually placed in the source code, we | |
245 | can find the cause of a bug faster. | |
beb0fb75 | 246 | |
cd4aac1e PP |
247 | While <<choose-a-log-level,care must be taken>> when placing _DEBUG_ to |
248 | _FATAL_ logging statements, you should liberally instrument your | |
ef267d12 | 249 | Babeltrace module with _TRACE_ logging statements to help future you |
cd4aac1e | 250 | and other developers understand what's happening at run time. |
beb0fb75 PP |
251 | |
252 | ||
f9ded0e0 | 253 | === Logging API |
beb0fb75 PP |
254 | |
255 | The Babeltrace logging API is internal: it is not exposed to the users | |
cd4aac1e | 256 | of the library; only to their developers. The only thing that a library |
4a41523d | 257 | user can control is the current log level of the library itself with |
beb0fb75 | 258 | `bt_logging_set_global_level()` and the initial library's log level with |
cd4aac1e | 259 | the `LIBBABELTRACE2_INIT_LOG_LEVEL` environment variable. |
beb0fb75 PP |
260 | |
261 | This API is based on https://github.com/wonder-mice/zf_log[zf_log], a | |
262 | lightweight, yet featureful, MIT-licensed core logging library for C and | |
cd4aac1e PP |
263 | pass:[C++]. The zf_log source files were modified to have the `BT_` and |
264 | `bt_` prefixes, and other small changes, like color support and using | |
265 | the project's `BT_DEBUG_MODE` definition instead of the standard | |
266 | `NDEBUG`. | |
beb0fb75 PP |
267 | |
268 | The logging functions are implemented in the logging convenience | |
cd4aac1e | 269 | library (`src/logging` directory). |
beb0fb75 PP |
270 | |
271 | ||
cd4aac1e | 272 | [[logging-headers]] |
f9ded0e0 | 273 | ==== Headers |
beb0fb75 PP |
274 | |
275 | The logging API headers are: | |
276 | ||
3fadfbc0 | 277 | `<babeltrace2/logging.h>`:: |
cd4aac1e | 278 | Public header which a library user can use to set and get |
a12f3d62 | 279 | libbabeltrace2's current log level. |
beb0fb75 | 280 | |
cd4aac1e | 281 | `"logging/log.h"`:: |
beb0fb75 | 282 | Internal, generic logging API which you can use in any Babeltrace |
cd4aac1e PP |
283 | module. This is the translation of `zf_log.h`. |
284 | + | |
285 | This header offers the <<gen-logging-statements,generic logging | |
286 | statement macros>>. | |
beb0fb75 | 287 | |
cd4aac1e PP |
288 | `"lib/logging.h"`:: |
289 | Specific internal header to use within the library. | |
290 | + | |
291 | This header defines `BT_LOG_OUTPUT_LEVEL` to a custom, library-wide | |
292 | hidden symbol which is the library's current log level before including | |
293 | `"logging/log.h"`. | |
294 | + | |
295 | This header offers the <<lib-logging-statements,library-specific logging | |
296 | statement macros>>. | |
beb0fb75 | 297 | |
cd4aac1e PP |
298 | `"plugins/comp-logging.h"`:: |
299 | Specific internal header to use within a component class. | |
300 | + | |
301 | This header offers the <<comp-logging-statements,component-specific | |
302 | logging statement macros>>. | |
beb0fb75 | 303 | |
b4b9064d | 304 | |
cd4aac1e | 305 | [[log-levels]] |
f9ded0e0 | 306 | ==== Log levels |
beb0fb75 | 307 | |
cd4aac1e PP |
308 | The internal logging API offers the following log levels, in ascending |
309 | order of severity: | |
beb0fb75 | 310 | |
cd4aac1e PP |
311 | [options="header,autowidth",cols="4"] |
312 | |=== | |
313 | |Log level name | |
314 | |Log level short name | |
315 | |Internal API enumerator | |
316 | |Public API enumerator | |
317 | ||
ef267d12 PP |
318 | |_TRACE_ |
319 | |`T` | |
320 | |`BT_LOG_TRACE` | |
321 | |`BT_LOGGING_LEVEL_TRACE` | |
cd4aac1e PP |
322 | |
323 | |_DEBUG_ | |
324 | |`D` | |
325 | |`BT_LOG_DEBUG` | |
326 | |`BT_LOGGING_LEVEL_DEBUG` | |
327 | ||
328 | |_INFO_ | |
329 | |`I` | |
330 | |`BT_LOG_INFO` | |
331 | |`BT_LOGGING_LEVEL_INFO` | |
332 | ||
333 | |_WARN_ | |
334 | |`W` | |
335 | |`BT_LOG_WARN` | |
336 | |`BT_LOGGING_LEVEL_WARN` | |
337 | ||
338 | |_ERROR_ | |
339 | |`E` | |
340 | |`BT_LOG_ERROR` | |
341 | |`BT_LOGGING_LEVEL_ERROR` | |
342 | ||
343 | |_FATAL_ | |
344 | |`F` | |
345 | |`BT_LOG_FATAL` | |
346 | |`BT_LOGGING_LEVEL_FATAL` | |
347 | ||
348 | |_NONE_ | |
349 | |`N` | |
350 | |`BT_LOG_NONE` | |
351 | |`BT_LOGGING_LEVEL_NONE` | |
352 | |=== | |
353 | ||
354 | The short name is accepted by the log level environment variables and by | |
355 | the CLI's `--log-level` options. | |
beb0fb75 | 356 | |
cd4aac1e | 357 | See <<choose-a-log-level,how to decide which one to use>> below. |
beb0fb75 | 358 | |
cd4aac1e | 359 | There are two important log level expressions: |
beb0fb75 PP |
360 | |
361 | [[build-time-log-level]]Build-time, minimal log level:: | |
cd4aac1e PP |
362 | The minimal log level, or build-time log level, is set at build time |
363 | and determines the minimal log level of the logging statements which | |
364 | can be executed. This applies to all the modules (CLI, library, | |
365 | plugins, bindings, etc.). | |
beb0fb75 PP |
366 | + |
367 | All the logging statements with a level below this level are **not built | |
368 | at all**. All the logging statements with a level equal to or greater | |
f9ded0e0 PP |
369 | than this level _can_ be executed, depending on the |
370 | <<run-time-log-level,run-time log level>>. | |
beb0fb75 PP |
371 | + |
372 | You can set this level at configuration time with the | |
373 | `BABELTRACE_MINIMAL_LOG_LEVEL` environment variable, for example: | |
374 | + | |
375 | -- | |
376 | ---- | |
377 | $ BABELTRACE_MINIMAL_LOG_LEVEL=WARN ./configure | |
378 | ---- | |
379 | -- | |
380 | + | |
cd4aac1e PP |
381 | The default build-time log level is `DEBUG`. For optimal performance, |
382 | set it to `INFO`, which effectively disables all fast path logging in | |
dd22a91f PP |
383 | all the Babeltrace modules. You can't set it to `WARN`, `ERROR`, |
384 | `FATAL`, or `NONE` because the impact on performance is minuscule | |
385 | starting from the _INFO_ log level anyway and we want any Babeltrace | |
386 | build to always be able to print _INFO_-level logs. | |
beb0fb75 PP |
387 | + |
388 | The library's public API provides `bt_logging_get_minimal_level()` to | |
389 | get the configured minimal log level. | |
390 | ||
391 | [[run-time-log-level]]Run-time, dynamic log level:: | |
cd4aac1e PP |
392 | The dynamic log level is set at run time and determines the current, |
393 | _active_ log level. All the logging statements with a level below | |
394 | this level are not executed, **but they still evaluate the | |
395 | condition**. All the logging statements with a level equal to or | |
396 | greater than this level are executed, provided that their level is | |
397 | also <<build-time-log-level,enabled at build time>>. | |
beb0fb75 | 398 | + |
f9ded0e0 PP |
399 | `zf_log` has a concept of a global run-time log level which uses the |
400 | `_bt_log_global_output_lvl` symbol. In practice, we never use this | |
401 | symbol, and always make sure that `BT_LOG_OUTPUT_LEVEL` is defined to a | |
cd4aac1e PP |
402 | module-wise expression before including `"logging/log.h"`. |
403 | + | |
404 | In the library, `"lib/logging.h"` defines its own | |
405 | `BT_LOG_OUTPUT_LEVEL` to the library's log level symbol before it | |
406 | includes `"logging/log.h"` itself. | |
beb0fb75 | 407 | + |
a12f3d62 | 408 | In libbabeltrace2, the user can set the current run-time log level with |
beb0fb75 PP |
409 | the `bt_logging_set_global_level()` function, for example: |
410 | + | |
411 | -- | |
412 | [source,c] | |
413 | ---- | |
414 | bt_logging_set_global_level(BT_LOGGING_LEVEL_INFO); | |
415 | ---- | |
416 | -- | |
417 | + | |
418 | The library's initial run-time log level is defined by the | |
cd4aac1e PP |
419 | `LIBBABELTRACE2_INIT_LOG_LEVEL` environment variable, or set to _NONE_ |
420 | if this environment variable is undefined. | |
421 | + | |
422 | Other modules have their own way of setting their run-time log level. | |
423 | + | |
424 | For example, the CLI uses the `BABELTRACE_CLI_LOG_LEVEL` environment | |
425 | variable, as well as its global `--log-level` option: | |
426 | + | |
427 | ---- | |
428 | $ babeltrace2 --log-level=I ... | |
429 | ---- | |
430 | + | |
431 | The components use their own log level (as returned by | |
432 | `bt_component_get_logging_level()`). With the CLI, you can set a | |
433 | specific component's log level with its own, position-dependent | |
434 | `--log-level` option: | |
435 | + | |
436 | ---- | |
437 | $ babeltrace2 /path/to/trace -c sink.ctf.fs --log-level=D | |
438 | ---- | |
439 | + | |
440 | Code which is common to the whole project, for example `src/common` | |
441 | and `src/compat`, use function parameters to get its run-time log | |
442 | level, for example: | |
443 | + | |
444 | [source,c] | |
445 | ---- | |
446 | BT_HIDDEN | |
447 | char *bt_common_get_home_plugin_path(int log_level); | |
448 | ---- | |
beb0fb75 | 449 | + |
cd4aac1e PP |
450 | Typically, when a logging-enabled module calls such a function, it |
451 | passes its own log level expression directly (`BT_LOG_OUTPUT_LEVEL`): | |
beb0fb75 | 452 | + |
cd4aac1e PP |
453 | [source,c] |
454 | ---- | |
455 | path = bt_common_get_home_plugin_path(BT_LOG_OUTPUT_LEVEL); | |
456 | ---- | |
457 | + | |
458 | Otherwise, just pass `BT_LOG_NONE`: | |
459 | + | |
460 | ---- | |
461 | path = bt_common_get_home_plugin_path(BT_LOG_NONE); | |
462 | ---- | |
463 | ||
464 | ||
465 | [[gen-logging-statements]] | |
466 | ==== Generic logging statement macros | |
467 | ||
468 | The Babeltrace logging statement macros work just like `printf()` | |
469 | (except the `+BT_LOG*_STR()+` ones) and contain their <<log-levels,log | |
470 | level>> (short name) in their name. | |
beb0fb75 | 471 | |
cd4aac1e PP |
472 | Each of the following macros evaluate the |
473 | <<build-time-log-level,build-time log level>> definition and | |
474 | <<run-time-log-level,run-time log level>> expression (as defined by | |
475 | `BT_LOG_OUTPUT_LEVEL`) to log conditionally. | |
beb0fb75 | 476 | |
cd4aac1e PP |
477 | See <<logging-instrument-c-file-gen,Instrument a C source file |
478 | (generic)>> and <<logging-instrument-h-file-gen,Instrument a C header | |
479 | file (generic)>> to learn how to be able to use the following macros. | |
beb0fb75 | 480 | |
ef267d12 PP |
481 | `+BT_LOGT("format string", ...)+`:: |
482 | Generic trace logging statement. | |
beb0fb75 | 483 | |
cd4aac1e PP |
484 | `+BT_LOGD("format string", ...)+`:: |
485 | Generic debug logging statement. | |
beb0fb75 | 486 | |
cd4aac1e PP |
487 | `+BT_LOGI("format string", ...)+`:: |
488 | Generic info logging statement. | |
beb0fb75 | 489 | |
cd4aac1e PP |
490 | `+BT_LOGW("format string", ...)+`:: |
491 | Generic warning logging statement. | |
beb0fb75 | 492 | |
cd4aac1e PP |
493 | `+BT_LOGE("format string", ...)+`:: |
494 | Generic error logging statement. | |
beb0fb75 | 495 | |
cd4aac1e PP |
496 | `+BT_LOGF("format string", ...)+`:: |
497 | Generic fatal logging statement. | |
beb0fb75 | 498 | |
ef267d12 PP |
499 | `+BT_LOGT_STR("preformatted string")+`:: |
500 | Generic preformatted string trace logging statement. | |
beb0fb75 | 501 | |
cd4aac1e PP |
502 | `+BT_LOGD_STR("preformatted string")+`:: |
503 | Generic preformatted string debug logging statement. | |
beb0fb75 | 504 | |
cd4aac1e PP |
505 | `+BT_LOGI_STR("preformatted string")+`:: |
506 | Generic preformatted string info logging statement. | |
beb0fb75 | 507 | |
cd4aac1e PP |
508 | `+BT_LOGW_STR("preformatted string")+`:: |
509 | Generic preformatted string warning logging statement. | |
beb0fb75 | 510 | |
cd4aac1e PP |
511 | `+BT_LOGE_STR("preformatted string")+`:: |
512 | Generic preformatted string error logging statement. | |
beb0fb75 | 513 | |
cd4aac1e PP |
514 | `+BT_LOGF_STR("preformatted string")+`:: |
515 | Generic preformatted string fatal logging statement. | |
beb0fb75 | 516 | |
ef267d12 PP |
517 | `+BT_LOGT_MEM(data_ptr, data_size, "format string", ...)+`:: |
518 | Generic memory trace logging statement. | |
beb0fb75 | 519 | |
cd4aac1e PP |
520 | `+BT_LOGD_MEM(data_ptr, data_size, "format string", ...)+`:: |
521 | Generic memory debug logging statement. | |
b81626f9 | 522 | |
cd4aac1e PP |
523 | `+BT_LOGI_MEM(data_ptr, data_size, "format string", ...)+`:: |
524 | Generic memory info logging statement. | |
b81626f9 | 525 | |
cd4aac1e PP |
526 | `+BT_LOGW_MEM(data_ptr, data_size, "format string", ...)+`:: |
527 | Generic memory warning logging statement. | |
b81626f9 | 528 | |
cd4aac1e PP |
529 | `+BT_LOGE_MEM(data_ptr, data_size, "format string", ...)+`:: |
530 | Generic memory error logging statement. | |
b81626f9 | 531 | |
cd4aac1e PP |
532 | `+BT_LOGF_MEM(data_ptr, data_size, "format string", ...)+`:: |
533 | Generic memory fatal logging statement. | |
b81626f9 | 534 | |
ef267d12 PP |
535 | `+BT_LOGT_ERRNO("initial message", "format string", ...)+`:: |
536 | Generic `errno` string trace logging statement. | |
b81626f9 | 537 | |
cd4aac1e PP |
538 | `+BT_LOGD_ERRNO("initial message", "format string", ...)+`:: |
539 | Generic `errno` string debug logging statement. | |
beb0fb75 | 540 | |
cd4aac1e PP |
541 | `+BT_LOGI_ERRNO("initial message", "format string", ...)+`:: |
542 | Generic `errno` string info logging statement. | |
beb0fb75 | 543 | |
cd4aac1e PP |
544 | `+BT_LOGW_ERRNO("initial message", "format string", ...)+`:: |
545 | Generic `errno` string warning logging statement. | |
beb0fb75 | 546 | |
cd4aac1e PP |
547 | `+BT_LOGE_ERRNO("initial message", "format string", ...)+`:: |
548 | Generic `errno` string error logging statement. | |
beb0fb75 | 549 | |
cd4aac1e PP |
550 | `+BT_LOGF_ERRNO("initial message", "format string", ...)+`:: |
551 | Generic `errno` string fatal logging statement. | |
beb0fb75 | 552 | |
cd4aac1e PP |
553 | |
554 | [[lib-logging-statements]] | |
555 | ==== Library-specific logging statement macros | |
556 | ||
557 | The Babeltrace library contains an internal logging API based on the | |
558 | generic logging framework. You can use it to log known Babeltrace | |
559 | objects without having to manually log each member. | |
560 | ||
561 | See <<logging-instrument-c-file-lib,Instrument a library C source file>> | |
562 | and <<logging-instrument-h-file-lib,Instrument a library C header file>> to | |
563 | learn how to be able to use the following macros. | |
564 | ||
565 | The library logging statement macros are named `+BT_LIB_LOG*()+` instead | |
566 | of `+BT_LOG*()+`: | |
567 | ||
ef267d12 PP |
568 | `+BT_LIB_LOGT("format string", ...)+`:: |
569 | Library trace logging statement. | |
cd4aac1e PP |
570 | |
571 | `+BT_LIB_LOGD("format string", ...)+`:: | |
572 | Library debug logging statement. | |
573 | ||
574 | `+BT_LIB_LOGI("format string", ...)+`:: | |
575 | Library info logging statement. | |
576 | ||
577 | `+BT_LIB_LOGW("format string", ...)+`:: | |
578 | Library warning logging statement. | |
579 | ||
580 | `+BT_LIB_LOGE("format string", ...)+`:: | |
581 | Library error logging statement. | |
582 | ||
583 | `+BT_LIB_LOGF("format string", ...)+`:: | |
584 | Library fatal logging statement. | |
585 | ||
586 | The macros above accept the typical `printf()` conversion specifiers | |
587 | with the following limitations: | |
588 | ||
589 | * The `+*+` width specifier is not accepted. | |
590 | * The `+*+` precision specifier is not accepted. | |
591 | * The `j` and `t` length modifiers are not accepted. | |
592 | * The `n` format specifier is not accepted. | |
593 | * The format specifiers defined in `<inttypes.h>` are not accepted, | |
594 | except for `PRId64`, `PRIu64`, `PRIx64`, `PRIX64`, `PRIo64`, and | |
595 | `PRIi64`. | |
596 | ||
597 | The Babeltrace library custom conversion specifier is accepted. Its | |
598 | syntax is either `%!u` to format a UUID (`bt_uuid` type), or: | |
599 | ||
600 | . Introductory `%!` sequence. | |
601 | ||
602 | . **Optional**: `[` followed by a custom prefix for the printed fields | |
603 | of this specifier, followed by `]`. The standard form is to end this | |
604 | prefix with `-` so that, for example, with the prefix `tc-`, the | |
605 | complete field name becomes `tc-addr`. | |
606 | ||
607 | . **Optional**: `pass:[+]` to print extended object members. This | |
608 | depends on the provided format specifier. | |
609 | ||
610 | . Format specifier (see below). | |
611 | ||
612 | The available format specifiers are: | |
613 | ||
614 | [options="header,autowidth",cols="3"] | |
615 | |=== | |
616 | |Specifier | |
617 | |Object | |
618 | |Expected C type | |
619 | ||
620 | |`F` | |
621 | |Trace IR field class | |
622 | |`+struct bt_field_class *+` | |
623 | ||
624 | |`f` | |
625 | |Trace IR field | |
626 | |`+struct bt_field *+` | |
627 | ||
628 | |`P` | |
629 | |Trace IR field path | |
630 | |`+struct bt_field_path *+` | |
631 | ||
632 | |`E` | |
633 | |Trace IR event class | |
634 | |`+struct bt_event_class *+` | |
635 | ||
636 | |`e` | |
637 | |Trace IR event | |
638 | |`+struct bt_event *+` | |
639 | ||
640 | |`S` | |
641 | |Trace IR stream class. | |
642 | |`+struct bt_stream_class *+` | |
643 | ||
644 | |`s` | |
645 | |Trace IR stream | |
646 | |`+struct bt_stream *+` | |
647 | ||
648 | |`a` | |
649 | |Trace IR packet | |
650 | |`+struct bt_packet *+` | |
651 | ||
652 | |`T` | |
653 | |Trace IR trace class | |
654 | |`+struct bt_trace_class *+` | |
655 | ||
656 | |`t` | |
657 | |Trace IR trace | |
658 | |`+struct bt_trace *+` | |
659 | ||
660 | |`K` | |
661 | |Trace IR clock class | |
662 | |`+struct bt_clock_class *+` | |
663 | ||
664 | |`k` | |
665 | |Trace IR clock snapshot | |
666 | |`+struct bt_clock_snapshot *+` | |
667 | ||
668 | |`v` | |
669 | |Value object | |
670 | |`+struct bt_value *+` | |
671 | ||
672 | |`n` | |
673 | |Message | |
674 | |`+struct bt_message *+` | |
675 | ||
676 | |`i` | |
677 | |Message iterator | |
678 | |`struct bt_message_iterator *` | |
679 | ||
680 | |`C` | |
681 | |Component class | |
682 | |`struct bt_component_class *` | |
683 | ||
684 | |`c` | |
685 | |Component | |
686 | |`+struct bt_component *+` | |
687 | ||
688 | |`p` | |
689 | |Port | |
690 | |`+struct bt_port *+` | |
691 | ||
692 | |`x` | |
693 | |Connection | |
694 | |`+struct bt_connection *+` | |
695 | ||
696 | |`g` | |
697 | |Graph | |
698 | |`+struct bt_graph *+` | |
699 | ||
700 | |`l` | |
701 | |Plugin | |
702 | |`const struct bt_plugin *` | |
703 | ||
553c4bab PP |
704 | |`r` |
705 | |Error cause | |
706 | |`const struct bt_error_cause *` | |
707 | ||
cd4aac1e PP |
708 | |`o` |
709 | |Object pool | |
710 | |`+struct bt_object_pool *+` | |
711 | ||
712 | |`O` | |
713 | |Object | |
714 | |`+struct bt_object *+` | |
715 | |=== | |
716 | ||
717 | Conversion specifier examples: | |
718 | ||
719 | * `%!f` | |
720 | * `%![my-event-]+e` | |
721 | * `%!t` | |
722 | * `%!+F` | |
723 | ||
724 | The ``, `` string (comma and space) is printed between individual | |
725 | fields, but **not after the last one**. Therefore, you must put this | |
726 | separator in the format string between two conversion specifiers, for | |
727 | example: | |
728 | ||
729 | [source,c] | |
730 | ---- | |
731 | BT_LIB_LOGW("Message: count=%u, %!E, %!+K", count, event_class, clock_class); | |
732 | ---- | |
733 | ||
734 | Example with a custom prefix: | |
735 | ||
736 | [source,c] | |
737 | ---- | |
738 | BT_LIB_LOGI("Some message: %![ec-a-]e, %![ec-b-]+e", ec_a, ec_b); | |
739 | ---- | |
740 | ||
741 | It is safe to pass `NULL` as any Babeltrace object parameter: the macros | |
742 | only print its null address. | |
743 | ||
744 | WARNING: Build-time `printf()` format checks are disabled for the | |
745 | `+BT_LIB_LOG*()+` macros because there are custom conversion specifiers, | |
746 | so make sure to test your logging statements. | |
747 | ||
748 | ||
749 | [[comp-logging-statements]] | |
750 | ==== Component-specific logging statement macros | |
751 | ||
752 | There are available logging macros for components. They prepend a prefix | |
753 | including the component's name to the logging message. | |
754 | ||
755 | See <<logging-instrument-c-file-compcls,Instrument a component class C | |
756 | source file>> and <<logging-instrument-h-file-compcls,Instrument a | |
757 | component class C header file>> to learn how to be able to use the | |
758 | following macros. | |
759 | ||
760 | The component logging statement macros are named `+BT_COMP_LOG*()+` | |
761 | instead of `+BT_LOG*()+`: | |
762 | ||
ef267d12 PP |
763 | `+BT_COMP_LOGT("format string", ...)+`:: |
764 | Component trace logging statement. | |
cd4aac1e PP |
765 | |
766 | `+BT_COMP_LOGD("format string", ...)+`:: | |
767 | Component debug logging statement. | |
768 | ||
769 | `+BT_COMP_LOGI("format string", ...)+`:: | |
770 | Component info logging statement. | |
771 | ||
772 | `+BT_COMP_LOGW("format string", ...)+`:: | |
773 | Component warning logging statement. | |
774 | ||
775 | `+BT_COMP_LOGE("format string", ...)+`:: | |
776 | Component error logging statement. | |
777 | ||
778 | `+BT_COMP_LOGF("format string", ...)+`:: | |
779 | Component fatal logging statement. | |
780 | ||
ef267d12 PP |
781 | `+BT_COMP_LOGT_STR("preformatted string")+`:: |
782 | Component preformatted string trace logging statement. | |
cd4aac1e PP |
783 | |
784 | `+BT_COMP_LOGD_STR("preformatted string")+`:: | |
785 | Component preformatted string debug logging statement. | |
786 | ||
787 | `+BT_COMP_LOGI_STR("preformatted string")+`:: | |
788 | Component preformatted string info logging statement. | |
789 | ||
790 | `+BT_COMP_LOGW_STR("preformatted string")+`:: | |
791 | Component preformatted string warning logging statement. | |
792 | ||
793 | `+BT_COMP_LOGE_STR("preformatted string")+`:: | |
794 | Component preformatted string error logging statement. | |
795 | ||
796 | `+BT_COMP_LOGF_STR("preformatted string")+`:: | |
797 | Component preformatted string fatal logging statement. | |
798 | ||
ef267d12 PP |
799 | `+BT_COMP_LOGT_ERRNO("initial message", "format string", ...)+`:: |
800 | Component `errno` string trace logging statement. | |
cd4aac1e PP |
801 | |
802 | `+BT_COMP_LOGD_ERRNO("initial message", "format string", ...)+`:: | |
803 | Component `errno` string debug logging statement. | |
804 | ||
805 | `+BT_COMP_LOGI_ERRNO("initial message", "format string", ...)+`:: | |
806 | Component `errno` string info logging statement. | |
807 | ||
808 | `+BT_COMP_LOGW_ERRNO("initial message", "format string", ...)+`:: | |
809 | Component `errno` string warning logging statement. | |
810 | ||
811 | `+BT_COMP_LOGE_ERRNO("initial message", "format string", ...)+`:: | |
812 | Component `errno` string error logging statement. | |
813 | ||
814 | `+BT_COMP_LOGF_ERRNO("initial message", "format string", ...)+`:: | |
815 | Component `errno` string fatal logging statement. | |
816 | ||
ef267d12 PP |
817 | `+BT_COMP_LOGT_MEM(data_ptr, data_size, "format string", ...)+`:: |
818 | Component memory trace logging statement. | |
cd4aac1e PP |
819 | |
820 | `+BT_COMP_LOGD_MEM(data_ptr, data_size, "format string", ...)+`:: | |
821 | Component memory debug logging statement. | |
822 | ||
823 | `+BT_COMP_LOGI_MEM(data_ptr, data_size, "format string", ...)+`:: | |
824 | Component memory info logging statement. | |
825 | ||
826 | `+BT_COMP_LOGW_MEM(data_ptr, data_size, "format string", ...)+`:: | |
827 | Component memory warning logging statement. | |
828 | ||
829 | `+BT_COMP_LOGE_MEM(data_ptr, data_size, "format string", ...)+`:: | |
830 | Component memory error logging statement. | |
831 | ||
832 | `+BT_COMP_LOGF_MEM(data_ptr, data_size, "format string", ...)+`:: | |
833 | Component memory fatal logging statement. | |
beb0fb75 PP |
834 | |
835 | ||
f9ded0e0 | 836 | ==== Conditional logging |
beb0fb75 | 837 | |
cd4aac1e | 838 | `+BT_LOG_IF(cond, statement)+`:: |
beb0fb75 PP |
839 | Execute `statement` only if `cond` is true. |
840 | + | |
841 | Example: | |
842 | + | |
843 | -- | |
844 | [source,c] | |
845 | ---- | |
846 | BT_LOG_IF(i < count / 2, BT_LOGD("Log this: i=%d", i)); | |
847 | ---- | |
848 | -- | |
849 | ||
850 | To check the <<build-time-log-level,build-time log level>>: | |
851 | ||
852 | [source,c] | |
853 | ---- | |
854 | #if BT_LOG_ENABLED_DEBUG | |
855 | ... | |
856 | #endif | |
857 | ---- | |
858 | ||
cd4aac1e PP |
859 | This tests if the _DEBUG_ level was enabled at build time. This means |
860 | that the current, <<run-time-log-level,run-time log level>> _could_ be | |
f9ded0e0 PP |
861 | _DEBUG_, but it could also be higher. The rule of thumb is to use only |
862 | logging statements at the same level in a `BT_LOG_ENABLED_*` conditional | |
863 | block. | |
beb0fb75 PP |
864 | |
865 | The available definitions for build-time conditions are: | |
866 | ||
ef267d12 | 867 | * `BT_LOG_ENABLED_TRACE` |
beb0fb75 PP |
868 | * `BT_LOG_ENABLED_DEBUG` |
869 | * `BT_LOG_ENABLED_INFO` | |
870 | * `BT_LOG_ENABLED_WARN` | |
871 | * `BT_LOG_ENABLED_ERROR` | |
872 | * `BT_LOG_ENABLED_FATAL` | |
873 | ||
874 | To check the current, <<run-time-log-level,run-time log level>>: | |
875 | ||
876 | [source,c] | |
877 | ---- | |
878 | if (BT_LOG_ON_DEBUG) { | |
879 | ... | |
880 | } | |
881 | ---- | |
882 | ||
883 | This tests if the _DEBUG_ log level is dynamically turned on | |
cd4aac1e | 884 | (implies that it's also enabled at build time). This check could have a |
beb0fb75 PP |
885 | noticeable impact on performance. |
886 | ||
887 | The available definitions for run-time conditions are: | |
888 | ||
ef267d12 | 889 | * `BT_LOG_ON_TRACE` |
beb0fb75 PP |
890 | * `BT_LOG_ON_DEBUG` |
891 | * `BT_LOG_ON_INFO` | |
892 | * `BT_LOG_ON_WARN` | |
893 | * `BT_LOG_ON_ERROR` | |
894 | * `BT_LOG_ON_FATAL` | |
895 | ||
cd4aac1e PP |
896 | Those macros check the module-specific log level symbol (defined by |
897 | `BT_LOG_OUTPUT_LEVEL`). | |
beb0fb75 PP |
898 | |
899 | Never, ever write code which would be executed only to compute the | |
900 | fields of a logging statement outside a conditional logging scope, | |
901 | for example: | |
902 | ||
903 | [source,c] | |
904 | ---- | |
905 | int number = get_number_of_event_classes_with_property_x(...); | |
906 | BT_LOGD("Bla bla: number=%d", number); | |
907 | ---- | |
908 | ||
909 | Do this instead: | |
910 | ||
911 | [source,c] | |
912 | ---- | |
913 | if (BT_LOG_ON_DEBUG) { | |
914 | int number = get_number_of_event_classes_with_property_x(...); | |
915 | BT_LOGD("Bla bla: number=%d", number); | |
916 | } | |
917 | ---- | |
918 | ||
919 | Or even this: | |
920 | ||
921 | [source,c] | |
922 | ---- | |
923 | BT_LOGD("Bla bla: number=%d", get_number_of_event_classes_with_property_x(...)); | |
924 | ---- | |
925 | ||
926 | ||
cd4aac1e | 927 | === Guides |
beb0fb75 | 928 | |
cd4aac1e PP |
929 | [[logging-instrument-c-file-gen]] |
930 | ==== Instrument a C source file (generic) | |
beb0fb75 | 931 | |
cd4aac1e PP |
932 | To instrument a C source file (`.c`): |
933 | ||
934 | . At the top of the file, before the first `#include` line (if any), | |
935 | define your file's <<choose-a-logging-tag,logging tag>> name: | |
4a41523d PP |
936 | + |
937 | -- | |
938 | [source,c] | |
939 | ---- | |
cd4aac1e | 940 | #define BT_LOG_TAG "SUBSYS/MY-MODULE/MY-FILE" |
4a41523d PP |
941 | ---- |
942 | -- | |
cd4aac1e PP |
943 | |
944 | . Below the line above, define the source file's log level expression, | |
945 | `BT_LOG_OUTPUT_LEVEL`. This expression is evaluated for each | |
946 | <<gen-logging-statements,logging statement>> to know the current | |
947 | <<run-time-log-level,run-time log level>>. | |
948 | + | |
949 | Examples: | |
950 | + | |
951 | [source,c] | |
952 | ---- | |
953 | /* Global log level variable */ | |
954 | #define BT_LOG_OUTPUT_LEVEL module_global_log_level | |
955 | ---- | |
4a41523d | 956 | + |
cd4aac1e PP |
957 | [source,c] |
958 | ---- | |
959 | /* Local log level variable; must exist where you use BT_LOG*() */ | |
960 | #define BT_LOG_OUTPUT_LEVEL log_level | |
961 | ---- | |
962 | + | |
963 | [source,c] | |
964 | ---- | |
965 | /* Object's log level; `obj` must exist where you use BT_LOG*() */ | |
966 | #define BT_LOG_OUTPUT_LEVEL (obj->log_level) | |
967 | ---- | |
4a41523d | 968 | |
cd4aac1e | 969 | . Include `"logging/log.h"`: |
4a41523d | 970 | + |
beb0fb75 PP |
971 | [source,c] |
972 | ---- | |
578e048b | 973 | #include "logging/log.h" |
cd4aac1e | 974 | ---- |
4a41523d | 975 | |
cd4aac1e PP |
976 | . In the file, instrument your code with the |
977 | <<gen-logging-statements,generic logging statement macros>>. | |
4a41523d | 978 | |
cd4aac1e PP |
979 | |
980 | [[logging-instrument-h-file-gen]] | |
981 | ==== Instrument a C header file (generic) | |
982 | ||
983 | To instrument a C header file (`.h`), if you have `static inline` | |
984 | functions in it: | |
985 | ||
986 | . Do not include `"logging/log.h"`! | |
987 | ||
988 | . Do one of: | |
989 | ||
990 | .. In the file, instrument your code with the | |
991 | <<gen-logging-statements,generic logging statement macros>>, making | |
992 | each of them conditional to the existence of the macro you're using: | |
4a41523d | 993 | + |
cd4aac1e PP |
994 | [source,c] |
995 | ---- | |
996 | static inline | |
997 | int some_function(int x) | |
998 | { | |
999 | /* ... */ | |
4a41523d | 1000 | |
ef267d12 PP |
1001 | #ifdef BT_LOGT |
1002 | BT_LOGT(...); | |
cd4aac1e | 1003 | #endif |
beb0fb75 | 1004 | |
cd4aac1e | 1005 | /* ... */ |
6470c171 | 1006 | |
cd4aac1e PP |
1007 | #ifdef BT_LOGW_STR |
1008 | BT_LOGW_STR(...); | |
1009 | #endif | |
f9ded0e0 | 1010 | |
cd4aac1e PP |
1011 | /* ... */ |
1012 | } | |
1013 | ---- | |
1014 | + | |
1015 | The C source files which include this header file determine if logging | |
1016 | is enabled or not for them, and if so, what is their | |
1017 | <<choose-a-logging-tag,logging tag>> and <<run-time-log-level,run-time | |
1018 | log level>> expression. | |
f9ded0e0 | 1019 | |
cd4aac1e PP |
1020 | .. Require that logging be enabled: |
1021 | + | |
1022 | [source,c] | |
1023 | ---- | |
1024 | /* Protection: this file uses BT_LOG*() macros directly */ | |
1025 | #ifndef BT_LOG_SUPPORTED | |
1026 | # error Please include "logging/log.h" before including this file. | |
1027 | #endif | |
1028 | ---- | |
1029 | + | |
1030 | Then, in the file, instrument your code with the | |
1031 | <<gen-logging-statements,generic logging statement macros>>. | |
1032 | ||
1033 | ||
1034 | [[logging-instrument-c-file-lib]] | |
1035 | ==== Instrument a library C source file | |
1036 | ||
1037 | To instrument a library C source file (`.c`): | |
4a41523d PP |
1038 | |
1039 | . At the top of the file, before the first `#include` line (if any), | |
cd4aac1e PP |
1040 | define your file's <<choose-a-logging-tag,logging tag>> name (this |
1041 | tag must start with `LIB/`): | |
4a41523d PP |
1042 | + |
1043 | -- | |
1044 | [source,c] | |
1045 | ---- | |
cd4aac1e | 1046 | #define BT_LOG_TAG "LIB/THE-FILE" |
4a41523d PP |
1047 | ---- |
1048 | -- | |
cd4aac1e PP |
1049 | |
1050 | . Include `"lib/logging.h"`: | |
4a41523d | 1051 | + |
cd4aac1e PP |
1052 | [source,c] |
1053 | ---- | |
1054 | #include "lib/logging.h" | |
1055 | ---- | |
4a41523d | 1056 | |
cd4aac1e PP |
1057 | . In the file, instrument your code with the |
1058 | <<lib-logging-statements,library logging statement macros>> or with | |
1059 | the <<gen-logging-statements,generic logging statement macros>>. | |
4a41523d | 1060 | |
f9ded0e0 | 1061 | |
cd4aac1e PP |
1062 | [[logging-instrument-h-file-lib]] |
1063 | ==== Instrument a library C header file | |
1064 | ||
1065 | To instrument a library C header file (`.h`), if you have `static | |
1066 | inline` functions in it: | |
1067 | ||
1068 | . Do not include `"lib/logging.h"`! | |
1069 | ||
1070 | . Require that library logging be enabled: | |
1071 | + | |
1072 | [source,c] | |
1073 | ---- | |
1074 | /* Protection: this file uses BT_LIB_LOG*() macros directly */ | |
1075 | #ifndef BT_LIB_LOG_SUPPORTED | |
1076 | # error Please include "lib/logging.h" before including this file. | |
1077 | #endif | |
1078 | ---- | |
1079 | ||
1080 | . In the file, instrument your code with the | |
1081 | <<lib-logging-statements,library logging statement macros>> or with | |
1082 | the <<gen-logging-statements,generic logging statement macros>>. | |
f9ded0e0 | 1083 | |
4a41523d | 1084 | |
cd4aac1e PP |
1085 | [[logging-instrument-c-file-compcls]] |
1086 | ==== Instrument a component class C source file | |
1087 | ||
1088 | To instrument a component class C source file (`.c`): | |
1089 | ||
1090 | . At the top of the file, before the first `#include` line (if any), | |
1091 | define your file's <<choose-a-logging-tag,logging tag>> name (this tag | |
1092 | must start with `PLUGIN/` followed by the component class identifier): | |
4a41523d PP |
1093 | + |
1094 | -- | |
1095 | [source,c] | |
1096 | ---- | |
cd4aac1e PP |
1097 | #define BT_LOG_TAG "PLUGIN/SRC.MY-PLUGIN.MY-SRC" |
1098 | ---- | |
1099 | -- | |
4a41523d | 1100 | |
cd4aac1e PP |
1101 | . Below the line above, define the source file's log level expression, |
1102 | `BT_LOG_OUTPUT_LEVEL`. This expression is evaluated for each | |
1103 | <<comp-logging-statements,logging statement>> to know the current | |
1104 | <<run-time-log-level,run-time log level>>. | |
1105 | + | |
1106 | For a component class file, it is usually a member of a local component | |
1107 | private structure variable: | |
1108 | + | |
1109 | [source,c] | |
1110 | ---- | |
1111 | #define BT_LOG_OUTPUT_LEVEL (my_comp->log_level) | |
1112 | ---- | |
4a41523d | 1113 | |
cd4aac1e PP |
1114 | . Below the line above, define `BT_COMP_LOG_SELF_COMP` to an expression |
1115 | which, evaluated in the context of the | |
1116 | <<comp-logging-statements,logging statements>>, evaluates to the self | |
1117 | component address (`+bt_self_component *+`) of the component. | |
1118 | + | |
1119 | This is usually a member of a local component private structure | |
1120 | variable: | |
1121 | + | |
1122 | [source,c] | |
1123 | ---- | |
1124 | #define BT_COMP_LOG_SELF_COMP (my_comp->self_comp) | |
1125 | ---- | |
1126 | ||
1127 | . Include `"plugins/comp-logging.h"`: | |
1128 | + | |
1129 | [source,c] | |
1130 | ---- | |
1131 | #include "plugins/comp-logging.h" | |
1132 | ---- | |
1133 | ||
1134 | . In the component initialization method, make sure to set the | |
1135 | component private structure's log level member to the initial | |
1136 | component's log level: | |
1137 | + | |
1138 | [source,c] | |
1139 | ---- | |
1140 | struct my_comp { | |
1141 | bt_logging_level log_level; | |
4a41523d | 1142 | /* ... */ |
cd4aac1e | 1143 | }; |
4a41523d | 1144 | |
cd4aac1e PP |
1145 | BT_HIDDEN |
1146 | bt_self_component_status my_comp_init( | |
1147 | bt_self_component_source *self_comp_src, | |
1148 | bt_value *params, void *init_method_data) | |
1149 | { | |
1150 | struct my_comp *my_comp = g_new0(struct my_comp, 1); | |
1151 | bt_self_component *self_comp = | |
1152 | bt_self_component_source_as_self_component(self_comp_src); | |
1153 | const bt_component *comp = bt_self_component_as_component(self_comp); | |
1154 | ||
1155 | BT_ASSERT(my_comp); | |
1156 | my_comp->log_level = bt_component_get_logging_level(comp); | |
4a41523d PP |
1157 | |
1158 | /* ... */ | |
1159 | } | |
1160 | ---- | |
cd4aac1e PP |
1161 | |
1162 | . In the file, instrument your code with the | |
1163 | <<comp-logging-statements,component logging statement macros>>. | |
1164 | ||
1165 | ||
1166 | [[logging-instrument-h-file-compcls]] | |
1167 | ==== Instrument a component class C header file | |
1168 | ||
1169 | To instrument a component class C header file (`.h`), if you have | |
1170 | `static inline` functions in it: | |
1171 | ||
1172 | . Do not include `"plugins/comp-logging.h"`! | |
1173 | ||
1174 | . Require that component logging be enabled: | |
4a41523d | 1175 | + |
cd4aac1e PP |
1176 | [source,c] |
1177 | ---- | |
1178 | /* Protection: this file uses BT_COMP_LOG*() macros directly */ | |
1179 | #ifndef BT_COMP_LOG_SUPPORTED | |
1180 | # error Please include "plugins/comp-logging.h" before including this file. | |
1181 | #endif | |
1182 | ---- | |
1183 | ||
1184 | . In the file, instrument your code with the | |
1185 | <<comp-logging-statements,component logging statement macros>>. | |
1186 | ||
1187 | ||
1188 | [[choose-a-logging-tag]] | |
1189 | ==== Choose a logging tag | |
beb0fb75 | 1190 | |
cd4aac1e PP |
1191 | Each logging-enabled C source file must define `BT_LOG_TAG` to a logging |
1192 | tag. A logging tag is a namespace to identify the logging messages of | |
1193 | this specific source file. | |
beb0fb75 | 1194 | |
cd4aac1e PP |
1195 | In general, a logging tag name _must_ be only uppercase letters, digits, |
1196 | and the `-`, `.`, and `/` characters. | |
beb0fb75 | 1197 | |
cd4aac1e PP |
1198 | Use `/` to show the subsystem to source file hierarchy. |
1199 | ||
1200 | For the Babeltrace library, start with `LIB/`. | |
1201 | ||
1202 | For the CTF writer library, start with `CTF-WRITER/`. | |
1203 | ||
1204 | For component classes, use: | |
beb0fb75 | 1205 | |
93841983 | 1206 | [verse] |
cd4aac1e PP |
1207 | `PLUGIN/__CCTYPE__.__PNAME__.__CCNAME__[/__FILE__]` |
1208 | ||
1209 | With: | |
1210 | ||
1211 | `__CCTYPE__`:: | |
1212 | Component class's type (`SRC`, `FLT`, or `SINK`). | |
beb0fb75 | 1213 | |
cd4aac1e | 1214 | `__PNAME__`:: |
93841983 | 1215 | Plugin's name. |
beb0fb75 | 1216 | |
cd4aac1e | 1217 | `__CCNAME__`:: |
93841983 | 1218 | Component class's name. |
beb0fb75 | 1219 | |
cd4aac1e | 1220 | `__FILE__`:: |
93841983 | 1221 | Additional information to specify the source file name or module. |
beb0fb75 | 1222 | |
cd4aac1e | 1223 | For plugins (files common to many component classes), use: |
beb0fb75 | 1224 | |
cd4aac1e PP |
1225 | [verse] |
1226 | `PLUGIN/__PNAME__[/__FILE__]` | |
beb0fb75 | 1227 | |
cd4aac1e | 1228 | With: |
beb0fb75 | 1229 | |
cd4aac1e PP |
1230 | `__PNAME__`:: |
1231 | Plugin's name. | |
1232 | ||
1233 | `__FILE__`:: | |
1234 | Additional information to specify the source file name or module. | |
1235 | ||
1236 | ||
1237 | [[choose-a-log-level]] | |
1238 | ==== Choose a log level | |
beb0fb75 PP |
1239 | |
1240 | Choosing the appropriate level for your logging statement is very | |
1241 | important. | |
1242 | ||
cd4aac1e | 1243 | [options="header,autowidth",cols="1,2,3a,4"] |
beb0fb75 | 1244 | |=== |
cd4aac1e | 1245 | |Log level |Description |Use cases |Expected impact on performance |
beb0fb75 PP |
1246 | |
1247 | |_FATAL_ | |
cd4aac1e PP |
1248 | | |
1249 | The program, library, or plugin cannot continue to work in this | |
beb0fb75 PP |
1250 | condition: it must be terminated immediately. |
1251 | ||
b4b9064d | 1252 | A _FATAL_-level logging statement should always be followed by |
4a41523d | 1253 | `abort()`. |
beb0fb75 PP |
1254 | | |
1255 | * Unexpected return values from system calls. | |
4a41523d PP |
1256 | * Logic error in internal code, for example an unexpected value in a |
1257 | `switch` statement. | |
cd4aac1e PP |
1258 | * Failed assertion (within `BT_ASSERT()`). |
1259 | * Unsatisfied library precondition (within `BT_ASSERT_PRE()`). | |
1f9f5b4d | 1260 | * Unsatisfied library postcondition (within `BT_ASSERT_POST()`). |
dd22a91f | 1261 | |Almost none: always enabled. |
beb0fb75 PP |
1262 | |
1263 | |_ERROR_ | |
cd4aac1e PP |
1264 | | |
1265 | An important error which is somewhat not fatal, that is, the program, | |
beb0fb75 PP |
1266 | library, or plugin can continue to work after this, but you judge that |
1267 | it should be reported to the user. | |
1268 | ||
1269 | Usually, the program cannot recover from such an error, but it can at | |
1270 | least exit cleanly. | |
1271 | | | |
1272 | * Memory allocation errors. | |
cd4aac1e PP |
1273 | * Wrong component initialization parameters. |
1274 | * Corrupted, unrecoverable trace data. | |
beb0fb75 PP |
1275 | * Failed to perform an operation which should work considering the |
1276 | implementation and the satisfied preconditions. For example, the | |
1277 | failure to create an empty object (no parameters): most probably | |
1278 | failed internally because of an allocation error. | |
93841983 | 1279 | * Almost any error in terminal elements: CLI and plugins. |
dd22a91f | 1280 | |Almost none: always enabled. |
beb0fb75 PP |
1281 | |
1282 | |_WARN_ | |
cd4aac1e PP |
1283 | | |
1284 | An error which still allows the execution to continue, but you judge | |
1285 | that it should be reported to the user. | |
6c1b33a8 PP |
1286 | |
1287 | _WARN_-level logging statements are for any error or weird action that | |
cd4aac1e PP |
1288 | is directly or indirectly caused by the user, often through some bad |
1289 | input data. For example, not having enough memory is considered beyond | |
1290 | the user's control, so we always log memory errors with an _ERROR_ level | |
1291 | (not _FATAL_ because we usually don't abort in this condition). | |
beb0fb75 | 1292 | | |
cd4aac1e PP |
1293 | * Missing data within something that is expected to have it, but there's |
1294 | an alternative. | |
1295 | * Invalid file, but recoverable/fixable. | |
dd22a91f | 1296 | |Almost none: always enabled. |
beb0fb75 PP |
1297 | |
1298 | |_INFO_ | |
beb0fb75 | 1299 | | |
cd4aac1e PP |
1300 | Any useful information which a non-developer user would possibly |
1301 | understand. | |
1302 | ||
1303 | Anything logged with this level must _not_ happen repetitively on the | |
1304 | fast path, that is, nothing related to each message, for example. This | |
1305 | level is used for sporadic and one-shot events. | |
1306 | | | |
1307 | * CLI or component configuration report. | |
1308 | * Successful plugin, component, or message iterator initialization. | |
1309 | * In the library: anything related to plugins, graphs, component | |
1310 | classes, components, message iterators, connections, and ports which | |
1311 | is not on the fast path. | |
beb0fb75 | 1312 | * Successful connection to or disconnection from another system. |
4a41523d | 1313 | * An _optional_ subsystem cannot be loaded. |
cd4aac1e PP |
1314 | * An _optional_ field/datum cannot be found. |
1315 | | | |
dd22a91f | 1316 | Very little: always enabled. |
beb0fb75 PP |
1317 | |
1318 | |_DEBUG_ | |
beb0fb75 | 1319 | | |
cd4aac1e PP |
1320 | Something that only Babeltrace developers would be interested into, |
1321 | which can occur on the fast path, but not more often than once per | |
1322 | message. | |
1323 | ||
1324 | The _DEBUG_ level is the default <<build-time-log-level,build-time log | |
1325 | level>> as, since it's not _too_ verbose, the performance is similar to | |
1326 | an _INFO_ build. | |
1327 | | | |
1328 | * Object construction and destruction. | |
1329 | * Object recycling (except fields). | |
1330 | * Object copying (except fields and values). | |
1331 | * Object freezing (whatever the type, as freezing only occurs in | |
1332 | developer mode). | |
1333 | * Object cancellation. | |
1334 | * Calling user methods and logging the result. | |
1335 | * Setting object properties (except fields and values). | |
1336 | | | |
ef267d12 | 1337 | Noticeable, but not as much as the _TRACE_ level: could be executed |
cd4aac1e PP |
1338 | in production if you're going to need a thorough log for support |
1339 | tickets without having to rebuild the project. | |
beb0fb75 | 1340 | |
ef267d12 | 1341 | |_TRACE_ |
cd4aac1e PP |
1342 | | |
1343 | Low-level debugging context information (anything that does not fit the | |
1344 | other log levels). More appropriate for tracing in general. | |
beb0fb75 PP |
1345 | | |
1346 | * Reference count change. | |
cd4aac1e | 1347 | * Fast path, low level state machine's state change. |
beb0fb75 PP |
1348 | * Get or set an object's property. |
1349 | * Object comparison's intermediate results. | |
1350 | |Huge: not executed in production. | |
1351 | |=== | |
1352 | ||
cd4aac1e PP |
1353 | [IMPORTANT] |
1354 | -- | |
1355 | Make sure not to use a _WARN_ (or higher) log level when the | |
1356 | condition leading to the logging statement can occur under normal | |
1357 | circumstances. | |
1358 | ||
1359 | For example, a public function to get some object or | |
1360 | property from an object by name or key that fails to find the value is | |
1361 | not a warning scenario: the user could legitimately use this function to | |
1362 | check if the name/key exists in the object. In this case, use the | |
ef267d12 | 1363 | _TRACE_ level (or do not log at all). |
cd4aac1e | 1364 | -- |
b4b9064d | 1365 | |
beb0fb75 | 1366 | |
b4b9064d | 1367 | [[message]] |
cd4aac1e | 1368 | ==== Write an appropriate message |
beb0fb75 PP |
1369 | |
1370 | Follow those rules when you write a logging statement's message: | |
1371 | ||
cd4aac1e PP |
1372 | * Use an English sentence which starts with a capital letter. |
1373 | ||
1374 | * Start the sentence with the appropriate verb tense depending on the | |
1375 | context. For example: | |
beb0fb75 PP |
1376 | + |
1377 | -- | |
b4b9064d PP |
1378 | ** Beginning of operation (present continuous): _Creating ..._, |
1379 | _Copying ..._, _Serializing ..._, _Freezing ..._, _Destroying ..._ | |
1380 | ** End of operation (simple past): _Created ..._, _Successfully created ..._, | |
1381 | _Failed to create ..._, _Set ..._ (simple past of _to set_ which is | |
1382 | also _set_) | |
beb0fb75 PP |
1383 | -- |
1384 | + | |
1385 | For warning and error messages, you can start the message with _Cannot_ | |
b4b9064d | 1386 | or _Failed to_ followed by a verb if it's appropriate. |
beb0fb75 PP |
1387 | |
1388 | * Do not include the log level in the message itself. For example, | |
1389 | do not start the message with _Error while_ or _Warning:_. | |
1390 | ||
cd4aac1e PP |
1391 | * Do not put newlines, tabs, or other special characters in the message, |
1392 | unless you want to log a string with such characters. Note that | |
1393 | multiline logging messages can be hard to parse, analyze, and filter, | |
1394 | however, so prefer multiple logging statements over a single statement | |
1395 | with newlines. | |
beb0fb75 PP |
1396 | |
1397 | * **If there are fields that your logging statement must record**, | |
1398 | follow the message with `:` followed by a space, then with the list of | |
1399 | fields (more about this below). If there are no fields, end the | |
1400 | sentence with a period. | |
1401 | ||
1402 | The statement's fields _must_ be a comma-separated list of | |
cd4aac1e PP |
1403 | `__name__=__value__` tokens. Keep `__name__` as simple as possible; use |
1404 | kebab case if possible. If `__value__` is a non-alphanumeric string, put | |
1405 | it between double quotes (`"%s"` specifier). Always use the `PRId64` and | |
1406 | `PRIu64` specifiers to log an `int64_t` or an `uint64_t` value. Use `%d` | |
1407 | to log a boolean value. | |
beb0fb75 PP |
1408 | |
1409 | Example: | |
1410 | ||
cd4aac1e PP |
1411 | "Cannot read stream data for indexing: path=\"%s\", name=\"%s\", " |
1412 | "stream-id=%" PRIu64 ", stream-fd=%d, " | |
1413 | "index=%" PRIu64 ", status=%s, is-mapped=%d" | |
beb0fb75 | 1414 | |
cd4aac1e PP |
1415 | By following a standard format for the statement fields, it is easier to |
1416 | use tools like https://www.elastic.co/products/logstash[Logstash] or | |
1417 | even https://www.splunk.com/[Splunk] to split fields and analyze logs. | |
beb0fb75 PP |
1418 | |
1419 | Prefer the following suffixes in field names: | |
1420 | ||
1421 | [options="header,autowidth"] | |
1422 | |=== | |
1423 | |Field name suffix |Description |Format specifier | |
1424 | ||
1425 | |`-addr` |Memory address |`%p` | |
1426 | |`-fd` |File descriptor |`%d` | |
cd4aac1e PP |
1427 | |`-fp` |File stream (`+FILE *+`) |`%p` |
1428 | |`-id` |Object's ID |`%" PRIu64 "` | |
1429 | |`-index` |Index |`%" PRIu64 "` | |
beb0fb75 | 1430 | |`-name` |Object's name |`\"%s\"` |
beb0fb75 PP |
1431 | |=== |
1432 | ||
1433 | ||
f9ded0e0 | 1434 | === Output |
beb0fb75 PP |
1435 | |
1436 | The log is printed to the standard error stream. A log line contains the | |
cd4aac1e PP |
1437 | time, the process and thread IDs, the <<log-levels,log level>>, the |
1438 | <<choose-a-logging-tag,logging tag>>, the source's function name, file | |
1439 | name and line number, and the <<message,message>>. | |
beb0fb75 | 1440 | |
f9ded0e0 PP |
1441 | When Babeltrace supports terminal color codes (depends on the |
1442 | `BABELTRACE_TERM_COLOR` environment variable's value and what the | |
1443 | standard output and error streams are plugged into), _INFO_-level lines | |
1444 | are blue, _WARN_-level lines are yellow, and _ERROR_-level and | |
1445 | _FATAL_-level lines are red. | |
1446 | ||
1447 | Log line example: | |
beb0fb75 | 1448 | |
cd4aac1e PP |
1449 | ---- |
1450 | 05-11 00:58:03.691 23402 23402 D VALUES bt_value_destroy@values.c:498 Destroying value: addr=0xb9c3eb0 | |
1451 | ---- | |
beb0fb75 | 1452 | |
cd4aac1e PP |
1453 | You can easily filter the log with `grep` or `ag`. For example, to keep |
1454 | only the _DEBUG_-level logging messages that the `FIELD-CLASS` module | |
beb0fb75 PP |
1455 | generates: |
1456 | ||
cd4aac1e PP |
1457 | ---- |
1458 | $ babeltrace2 --log-level=D /path/to/trace |& ag 'D FIELD-CLASS' | |
1459 | ---- | |
1460 | ||
1461 | ||
1462 | == Valgrind | |
1463 | ||
1464 | To use Valgrind on an application (for example, the CLI or a test) which | |
1465 | loads libbabeltrace2, use: | |
1466 | ||
1467 | ---- | |
1468 | $ G_SLICE=always-malloc G_DEBUG=gc-friendly PYTHONMALLOC=malloc \ | |
16b7b5e7 | 1469 | LIBBABELTRACE2_NO_DLCLOSE=1 valgrind --leak-check=full \ |
cd4aac1e PP |
1470 | --suppressions=/path/to/babeltrace/extras/valgrind/popt.supp app |
1471 | ---- | |
1472 | ||
1473 | `G_SLICE=always-malloc` and `G_DEBUG=gc-friendly` is for GLib and | |
1474 | `PYTHONMALLOC=malloc` is for the Python interpreter, if it is used by | |
1475 | the Python plugin provider (Valgrind will probably show a lot of errors | |
1476 | which originate from the Python interpreter anyway). | |
1477 | ||
16b7b5e7 | 1478 | `LIBBABELTRACE2_NO_DLCLOSE=1` makes libbabeltrace2 not close the shared |
cd4aac1e PP |
1479 | libraries (plugins) which it loads. You need this to see the appropriate |
1480 | backtrace when Valgrind shows errors. | |
c637d729 FD |
1481 | |
1482 | == Testing | |
1483 | ||
1484 | === Python Bindings | |
1485 | ||
1486 | To run all the `bt2` Python package tests use: | |
1487 | ||
1488 | ---- | |
1489 | $ BT_TESTS_BUILDDIR=/path/to/build/babeltrace/tests \ | |
1490 | ./tests/bindings/python/bt2/test_python_bt2 | |
1491 | ---- | |
1492 | ||
1493 | To run all the tests in a test module (e.g. `test_event.py`) use: | |
1494 | ||
1495 | ---- | |
1496 | $ BT_TESTS_BUILDDIR=/path/to/build/babeltrace/tests \ | |
1497 | ./tests/utils/run_python_bt2 python3 ./tests/utils/python/testrunner.py \ | |
1498 | -t test_event \ | |
1499 | ./tests/bindings/python/bt2/ | |
1500 | ---- | |
1501 | ||
1502 | To run a specific test (e.g. `EventTestCase.test_clock_value`) in a test module | |
1503 | (e.g. `test_event.py`) use: | |
1504 | ||
1505 | ---- | |
1506 | $ BT_TESTS_BUILDDIR=/path/to/build/babeltrace/tests \ | |
1507 | ./tests/utils/run_python_bt2 python3 ./tests/utils/python/testrunner.py \ | |
1508 | -t test_event.EventTestCase.test_clock_value \ | |
1509 | ./tests/bindings/python/bt2/ | |
1510 | ---- |