From member methods

Then sending-primitives can be used, such as:

?info("Hello world!")

or:

?info_fmt("The value ~B is the answer.",[MyValue])

Many API variations exist (see class_TraceEmitter.hrl), to account for the various trace content, contexts, etc., but ?S(Message) and ?S_fmt(MessageFormat,MessageValues), for S corresponding to a trace severity (e.g. S being notice), are by far the most frequently used.

From constructors

Note that for example ?debug(Message) is a macro that (if Traces is enabled) expands (literally) to:

class_TraceEmitter:send(debug,State,Message)

As a result, the availability of a State variable in the scope of this macro is expected. Moreover, this WOOPER state variable shall be the one of a class_TraceEmitter instance (either directly or, more probably, through inheritance).

This is not a problem in the most common case, when using traces in member methods (as by design they should be offering such a State), yet in constructors the initial state (i.e. the State variable directly fed to the construct operator of this class) is generally not the one of a trace emitter already (it is a blank state).

As a result, an instance will not be able to send traces until the completion of its own class_TraceEmitter constructor, and then it shall rely on that resulting state (for example named TraceState). Sending a trace of severity S from that point should be done using a send_S macro (e.g. ?send_debug(TraceState,Message)) - so that an appropriate state is used.

An example of some class Foobar inheriting directly from TraceEmitter will be clearer:

-module(class_Foobar).

construct(State,TraceEmitterName) ->
  TraceState = class_TraceEmitter:construct(State,TraceEmitterName),
  % Cannot use here ?info("Hello!), as it would use 'State',
  % which is not a trace emitter yet! So:
  ?send_info(TraceState,"Hello!"),
  [...]
  FinalState.

Trace Categorisation

In addition to browsing the produced traces per emitter, origin, theme, wallclock or applicative timestamps, etc. it is often useful to be able to sort them per emitter categorisation, such a categorisation allowing to encompass multiple emitter instances of multiple emitter types.

Categories are arbitrary, and are to be nested from the most general ones to the least (a bit like directories), knowing that subcategories are to be delimited by a dot character, like in: Art.Painting.Hopper. As a consequence, any string can account for a category, keeping in mind dots have a specific meaning.

Hierarchical categorisation allows to select more easily a scope of interest for the traces to be browsed.

For example, should birds, cats and dogs be involved, introducing following emitter categorisations might be of help:

• Animals
• Animals.Birds
• Animals.Cats
• Animals.Dogs

If wanting all traces sent by all cats to be gathered in the Animals.Cats trace category, one shall introduce in class_Cat following define before the aforementioned class_TraceEmitter.hrl include:

-define(trace_emitter_categorization,"Animals.Cats").

and use it in the constructor like the following example, where class_Cat inherits directly from class_Creature [3] - supposingly itself a child class of class_TraceEmitter:

-module(class_Cat).

-define(trace_emitter_categorization,"Animals.Cats").
-include("class_TraceEmitter.hrl").

construct(State,TraceEmitterName) ->
  TraceState = class_Creature:construct(State,
                 ?trace_categorize(TraceEmitterName)),
  % Cannot use ?warning("Hello!), as it would use 'State',
  % which is not a trace emitter yet! So:
  ?send_warning(TraceState,"Cat on the loose!"),
  [...]
  FinalState.

Then all traces sent by all cats will be automatically registered with this trace emitter category.

The purpose of the trace_categorize macro used in the above example is to register the trace categorisation defined through the inheritance tree so that, right from the start, the most precise category is used for all emitted traces [4].

Sometimes a very large number of trace emitters exist, to the point that selecting them becomes tedious. One workaround is to sort them according to their prefixes (first characters), for an easier browsing thereof.

For example, instead of having, under a "characters" trace categorization , "John-Paul", "John-Mark", "John-Eric", etc., a "characters.John-" trace categorization could be preferred so that it groups all the characters named accordingly.

This can be done by replacing the use of the trace_categorize/1 macro (defined in class_TraceEmitter.hrl) above with a pair whose first element is the actual emitter name and second element is its original categorization augmented of a prefix obtained from its name (here this pair would simply be {"John-Mark", "characters.John-"}).

Refer to class_TraceEmitter:subcategorize/1 for an example where an additional grouping level is introduced, based on the first character of the trace emitter name. Then if a specified emitter name would have been "some.prefix.foobar", this function ensures that "some.prefix.f.foobar" is used, resulting in an alphabetical dispatching of emitter names (and this emitter being sorted among all the ones whose name starts with f).

Activation / Desactivation

The trace macros used above can be fully toggled at build-time, on a per-module basis (if disabled, they incur zero runtime overhead, and no source change is required).

See the ENABLE_TRACES make variable in GNUmakevars.inc for that, and do not forget to recompile all classes and modules that shall observe this newer setting.

Note that an error-like trace severity will not be impacted by this setting, as such traces shall remain always available (never muted).

Doing so incurs a very low runtime overhead anyway (supposing of course that sending these failure-related messages happens rather infrequently), as the cost of a mostly idle trace aggregator (which is spawned in all cases) is mostly negligible - knowing that runtime resource consumption happens only when/if emitting actual traces.

Switching from Basic Console Traces

In some cases, it may be convenient to have first one's lower-level, debugging traces be directly output on the console.

Then, once the most basic bugs are fixed (e.g. the program is not crashing anymore), the full power of this Traces layer can be best used, by switching the initial basic traces to the more advanced traces presented here.

To output (basic) console traces, one may use the trace_utils module of the Myriad layer. For example:

trace_utils:debug_fmt("Hello world #~B",[2])

Then switching to the more advanced traces discussed here is just a matter of replacing, for a given trace type T (e.g. debug), trace_utils:T with ?T, like in:

?debug_fmt("Hello world #~B",[2])

(with no further change in the trace parameters).

Yet now, as already mentioned, there is a better way of doing so (not requiring trace primitives to be changed once specified), through the use of the trace_bridge module - which is also provided by the Myriad layer - instead.

It allows all Erlang code, including the one of lower-level libraries, to rely ultimately either on basic traces (i.e. the ones offered by Myriad in trace_utils) or on more advanced ones (typically the ones discussed here, offered by Traces - or any other respecting the same conventions) transparently (i.e. with no further change, once the emitter process is registered).

See trace_bridging_test.erl for an example of use thereof.

The Traceable Interface

This interface has been introduced so that other interfaces can depend on it rather than having their instances necessarily be a full-blown TraceEmitter.

In practice this interface, defined in class_Traceable.erl and class_Traceable.hrl, offers the same basic macros for trace sending as class_TraceEmitter, yet can be used by any WOOPER instance - be it a trace emitter or not, and, in this last case, whether or not having a trace bridge set; the relevant trace emission option is transparently used whenever having to emit an actual trace.

Trace Format Type

Traces may be browsed thanks to either of the following supervision solutions (see class_TraceSupervisor.erl):

• text_traces, itself available in two variations:
  • text_only if wanting to have traces be directly written to disk as pure, yet human-readable, text
  • pdf, if wanting to read finally the traces in a generated PDF file (hence the actual text includes a relevant mark-up, and as such is less readable directly before a PDF is generated out of it)
• advanced_traces, for smarter log tools such as LogMX (the default), as discussed below

Trace Rotation

Note also that trace rotation can be enabled: when requested, it is performed (in a synchronous or asynchronous manner, see the rotateTraceFile/1 oneway and the rotateTraceFileSync/1 request of the trace aggregator) unconditionally or based on a threshold in the size of the trace file (the default; see also the setMinimumTraceFileSizeForRotation/2 oneway).

Such trace rotation is typically meant to be triggered by a scheduler, on a regular basis (doing so is more relevant than for example checking a criterion at each trace addition).

If the current trace file is my_file.traces, its rotated version will be an XZ archive named for example my_file.traces.8.2021-1-17-at-22h-14m-00s.xz (the count, here 8, allows to keep track of a series of rotation archives, while the timestamp corresponds to the time at which the log rotation was done), located in the same directory.

General Mode of Operation

All processes are able to emit traces, either by using standalone trace sending primitives (mostly for plain Erlang processes), or by inheriting from the TraceEmitter class, in the (general) case of WOOPER-based processes.

In the vast majority of cases, all these emitters send their traces to a single trace aggregator, in charge of collecting them and storing them on-disk (for most uses, their memory footprint would be quickly too large for RAM), according to an adequate trace format.

This trace format can be parsed by various trace supervisors, the most popular being LogMX.

Various measures have been taken in order to reduce the overhead induced by the overall trace system.

Notably normal traces (as opposed to error-like ones) are sent in a "fire and forget", non-blocking manner (thanks to oneways, which are not specifically acknowledged). The number of messages exchanged is thus reduced, at the cost of a lesser synchronization of the traces (i.e. there is no strong guarantee that the traces will be ultimately recorded and displayed in the order of their emission in wallclock-time, as they will be directly and sequentially stored in their actual order of receiving by the trace aggregator [7], an order that depends itself on the potentially varied network latencies experienced from the potential multiple sources to the trace aggregator).

Trace Emitters

Any class deriving, directly or not, from class_TraceEmitter, is, once constructed as a trace emitter, able to send traces.

Lowering the Trace-Induced Overhead

In addition to the general efficiency measures already taken, an (optional) "preformatted" mode has been introduced in order to further lower the cost induced by the processing of traces; this mode can be freely used in parallel to the normal, "legacy" mode, in the same program.

At the expense of supporting only our "advanced" trace supervision type (as opposed to the "text" one typically useful for PDF generation), this mode strives to:

• reduce the volume of data sent for each trace (from a richer tuple per trace to a single, compact binary)
• increase overall concurrency by, as much as possible, offsetting the load from the trace aggregator (which by design is a singleton) to the many trace emitters

Using this mode is transparent, and, in case of heavy trace sending, a significant decrease in resource usage could be measured.

To enable/disable this mode, refer to the traces_are_preformatted define, which is now set by default (see the TRACES_OPT_FLAGS variable in GNUmakevars.inc).

LogMX-related Hints

One can find here various elements in order to better integrate LogMX (e.g. parser, configuration files, etc.).

An important setting is how much memory (RAM) is allowed for that tool (see the MAX_MEMORY entry in startup.conf).

Internal Trace Format

(for the most curious users)

Each trace line is a raw text (hence not a binary content) made of a series of predefined fields, separated by the pipe (|) delimiter character.

The text message included in a trace can contain any number of instances of this field delimiter.

Example of a raw trace line (end of lines added for readability):

<0.45.0>|I am a test emitter of traces|TraceEmitter.Test|none|
2016/6/13 14:21:16|trace_management_run-paul@hurricane.foobar.org|
MyTest.SomeCategory|6|Hello debug world!

or:

<9097.51.0>|Instance tracker|Core.Tracker.Instances|14875|
2016/6/10 15:43:31|My_application_case-john@hurricane.foobar.org|
Execution.Uncategorized|4|Creating a new root instance tracker
whose troubleshooting mode is enabled.

Using Cutting-Edge GIT

This is the installation method that we use and recommend; the Traces master branch is meant to stick to the latest stable version: we try to ensure that this main line always stays functional (sorry for the pun). Evolutions are to take place in feature branches and to be merged only when ready.

Once Erlang is available, it should be just a matter of executing:

$ git clone https://github.com/Olivier-Boudeville/Ceylan-Myriad myriad
$ cd myriad && make all && cd ..

$ git clone https://github.com/Olivier-Boudeville/Ceylan-WOOPER wooper
$ cd wooper && make all && cd ..

$ git clone https://github.com/Olivier-Boudeville/Ceylan-Traces traces
$ cd traces && make all

(for OTP compliance, using short names, such as myriad, wooper and traces, for clones rather than long ones, such as Ceylan-Myriad, Ceylan-WOOPER and Ceylan-Traces, is recommended)

Running a corresponding test just then boils down to:

$ cd test && make trace_management_run CMD_LINE_OPT="--batch"

Should LogMX be installed and available in the PATH, the test may simply become:

$ make trace_management_run

Using OTP-Related Conventions

$ git clone https://github.com/Olivier-Boudeville/Ceylan-Traces.git traces
$ cd traces
$ rebar3 compile

Lost Traces

If having sent traces that cannot be found through the trace supervision (or that even disappear live!), most probably that they were properly sent, collected and stored, but that they were too numerous to be displayed.

In LogMX, this can be seen in the bottom-right status bar, where a fully-filled red rectangle shows the percentage of the maximum number of entries currently met: 100% most likely means that too many traces were to be displayed for the current settings, and thus that latter traces replaced former ones.

A solution is either to send less traces, or to increase that display threshold, either directly in to the LogMX interface (by entering an higher value on the left of said rectangle), or in the logmx.properties configuration file, by setting its autoRefreshEntriesLimit attribute to an higher value.

A related setting is the max memory that the (Java) configuration of LogMX allows.

Duplicated Traces

In rather rare contexts (typically when requesting LogMX to focus on the last entries, whereas dozens of thousands of them are added), the trace supervision may show duplicated traces.

For example, an emitter that sent 6 traces will be marked as having sent 8 of them, and a pair of successive traces will be shown twice (first that pair, then other traces may interleave, then the pair will be listed again), with non-duplicated IDs (as shown in the leftmost LogMX column).

It is just an artefact due to this specific execution of LogMX though: one can check that reading this file again, but this time as a whole (instead of live) does not show duplicated traces anymore; indeed these traces were actually stored by Ceylan-Traces in the *.traces file only once.

Lost LogMX Settings

LogMX will write its configuration files (notably logmx.properties) when shutdown. So before modifying any of these files, ensure first that no LogMX instance is still running (otherwise one's changes will be overwritten).

Lost Traces

If having sent traces that cannot be found through the trace supervision (or that even disappear live!), most probably that they were properly sent, collected and stored, but that they were too numerous to be displayed.

In LogMX, this can be seen in the bottom-right status bar, where a fully-filled red rectangle shows the percentage of the maximum number of entries currently met: 100% most likely means that too many traces were to be displayed for the current settings, and thus that latter traces replaced former ones.

A solution is either to send less traces, or to increase that display threshold, either directly in to the LogMX interface (by entering an higher value on the left of said rectangle), or in the logmx.properties configuration file, by setting its autoRefreshEntriesLimit attribute to an higher value.

A related setting is the max memory that the (Java) configuration of LogMX allows.

Duplicated Traces

In rather rare contexts (typically when requesting LogMX to focus on the last entries, whereas dozens of thousands of them are added), the trace supervision may show duplicated traces.

For example, an emitter that sent 6 traces will be marked as having sent 8 of them, and a pair of successive traces will be shown twice (first that pair, then other traces may interleave, then the pair will be listed again), with non-duplicated IDs (as shown in the leftmost LogMX column).

It is just an artefact due to this specific execution of LogMX though: one can check that reading this file again, but this time as a whole (instead of live) does not show duplicated traces anymore; indeed these traces were actually stored by Ceylan-Traces in the *.traces file only once.

Lost LogMX Settings

LogMX will write its configuration files (notably logmx.properties) when shutdown. So before modifying any of these files, ensure first that no LogMX instance is still running (otherwise one's changes will be overwritten).

Java Error When Launching LogMX

One may check that Java is installed and available from the PATH, that it is a sufficiently recent one (e.g. Java 11; more recent ones like Java 21 will work of course) and that it is at least a JRE (a complete JDK will be fine as well) and a full (non-headless [8]) version thereof.

One may use check with:

$ type java
java is /usr/bin/java

$ java -version
openjdk version "21" 2023-09-19
OpenJDK Runtime Environment (build 21+35)
OpenJDK 64-Bit Server VM (build 21+35, mixed mode, sharing)

Arch users may also install a relevant Java with pacman -Sy jre-openjdk and run archlinux-java status to check which version shall be used (then possibly archlinux-java set java-21-openjdk to select it).