Logging and Tracing 1 - Basic pattern logs
impulse contains a rich set of tools and mechanisms to make complex systems visible and transparent. But there are not always easy to understand and utilize. This series of article 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 readerIn 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
- a main format with 'WARNING|NOTE|ERROR|DEBUG [time] where : information'
- an ISR format with just a timing information
- and some temporary log that shall be ignored (# Leg ok...)
Default log patternThe 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:
- Group 1: log level - one of these options
- optional white-spaces and zeros
- \[([ 0-9a-z\.]+)\]
- Group 2: time stamp
- optional white-spaces
- Group 3: logger (location) - starts at 'in' and ends at ':'
- ':' 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 logThe reader will create folders/scope for all hierarchy nodes and signals for all loggers.
ISR log patternThis pattern is much more simpler than the previous:
- fixed text and whitespaces
- Group 1: time stamp - remaining line
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 patternThe 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)
- 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.