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