Logging and Tracing 1 - Basic pattern logs

impulse contains a rich set of tools and mechanisms to make complex systems visible and transparent.This series of articles shall give hints and ideas how to improve your systems visibility and to dig into.

This article is based on impulse version 1.3/1.4

Using the pattern log reader

In most cases, developers have text log outputs. In the good case, all logs share the same format, but often there is a strange mix due to historical reasons. Up to a certain level, impulse can parse these mixed logs and display them in a uniform way. But it might be sometimes tricky to configure. Lets assume the following example:
    NOTE     [212 745 133.974 ns] in top.HHShell.m4_top.mDist_dsp_access.r2_top : getX4LegChangeDone happened
    WARNING  [212 745 133.974 ns] in top.HHShell.m4_top.mDist_dsp_access.r4_top : getX4LegChangeDone = 0x1008000
    ISR at 214435176 
    ERROR    [214 435 176.000 ns] in top.HHShell.m4_top.mDist_dsp_wait.entry : Kernel changed state to: OUTPUT
    # Leg ok - wait for next
    NOTE00000[216 735 876.000 ns] in top.F4.generics : Calculated load 47%
Here we got
  1. a main format with 'WARNING|NOTE|ERROR|DEBUG [time] where : information'
  2. an ISR format with just a timing information
  3. and some temporary log that shall be ignored (# Leg ok...)
     
To configure the pattern log reader , get to Preferences->Impulse->Serializers and double-click on Pattern Log. Next press Add to create a new pattern log configuration. Give it a name, select the char-set and set the time base (small enough to see all changes). Next click Add again to add the first log pattern.

Default log pattern

The main definition of a log pattern consists of a regular expression (http://docs.oracle.com/javase/tutorial/essential/regex/). To play with regular expression (not always easy) the log pattern dialogue has a field to paste log lines and test them with your expression.

The first expression is:

(WARNING|NOTE|ERROR|DEBUG)[\s0]*\[([ 0-9a-z\.]+)\]\s*in\s*([^:]*):\s*(.*)

(WARNING|NOTE|ERROR|DEBUG)
Group 1: log level - one of these options
[\s0]*
optional white-spaces and zeros
\[([ 0-9a-z\.]+)\]
Group 2: time stamp
\s*
optional white-spaces
in\s*([^:]*)
Group 3: logger (location) - starts at 'in' and ends at ':'
\s*
':' and optional white-spaces
(.*)
Group 4: text - remaining line


Select Create new log event and enter labels for each group. Use the predefined ones if possible or add your own (by typing the group label into the field). This will tell the reader to create a new log whenever a line matches the pattern. Its groups will be loaded into the labeled fields.
For the Timestamp field we need some extra information to make the reader able to parse: Select Float execution time (in this case 212745133.974 ns equals 212745133974 ps) and Parse from log line in the field Time unit. In our case the logger group contains an hierarchical name using '.' as separator. If we choose Hierarchy from group value, the reader will create a hierarchy of log signals.
Select the logger group as name group and enter '\.' (regular expression) in field Separator. To differentiate logs and nodes, type in '#' (or whatever you like) in field Leaf Prefix. This is required if a node (e.g top.HHShell) has logs but also sub nodes with logs:
NOTE [212 745 133.974 ns] in top.HHShell : a log 
NOTE [212 745 133.974 ns] in top.HHShell.m4_top : a log
The reader will create folders/scope for all hierarchy nodes and signals for all loggers.

ISR log pattern

This pattern is much more simpler than the previous:

ISR\sat\s(.*)

ISR\sat\s
fixed text and whitespaces
(.*)
Group 1: time stamp - remaining line
Select Create new log event and the label Timestamp for group 1. Select Integer execution time and 'ns' for Time unit. Select Free name as name source and type 'ISR' in field Name/Group and leave Name Extension empty. That's enough for the second pattern.

Ignore pattern

To not get a parser exception on any other line, add another log pattern. Type in '.*' as Expression ans select Ignore.
This pattern should be at the end of all patterns. The reader processes line by line and selects the first pattern that matches. If no pattern matches, the reader throws an exception !

Identification pattern

The log reader identifies files/resources as valid inputs using:
  • File extensions (default *.log - you can add other extensions under Preferences->General->Content Type->Element/Record/Pattern log record)
  • and identification pattern (files that don't match are ignored)
The identification pattern is defined as normal pattern but is applied on multiple lines at the files head. The identification pattern is selected in the pattern log configuration. You can choose First pattern or any of the pattern defined. Typical use cases are:
  • Select a default pattern if you are sure that your file starts with that pattern (in the first lines).
  • Define a special pattern , e.g. (\s*Copyright Xmos.*) if there is a special head, and select that pattern in your configuration.

That's enough for the first part, Part 2 of this series will handle extraction of numerical values from the log.