The art of log merging: parsing strikes back

On the previous article, we solved the problem of merging logs from different measurement instruments to investigate one aspect of a problem. Now, we dive into dealing with the embedded system itself.

The controller board

Due to cost, availability, mass production and more cost issues, the product in question is based on an 8-bit taiwanese microcontroller with support for reading touch pads but no ADC. The LDR here is a latecomer, and in order to be serviced I developed a capacitor discharge based way of determining if the LDR was seeing a day condition or a night condition. The I/Os have schmitt-trigger inputs, so I charge a capacitor and let it discharge over a resistor with a known value. I then repeat the operation but this time let it discharge over the LDR. The I/O threshold is not well defined but should remain the same between two consecutive measurements, so the unknown LDR resistance can be obtained as a ratio of the discharge times (write the discharge equations, solve for the threshold voltage, equate both eqs, then solve for the unknown resistance). The error is pretty big but as we just need to tell day from night, it works (the LDR itself is a bigger error source).

The procedure is then first measuring the discharge time with the known R, estimate a maximum for the discharge time with the LDR, and if it times out then condition is night, otherwise it is day… So, since this board communicates with a main controller (which handles all the bells and whistles of the device) there is an UART in there, and so I quickly modified the firmware to output the expected time lapse, the obtained time lapse, the decision (1 for day, 0 for night), and whether the LEDs where full bright or not (remember I’ve already modded it to alternate the LEDs…). I ended logging something like this:

 30,29,1,1
30,29,1,1
30,28,1,1
30,29,1,1
30,29,1,1

The first field is the expected timeout for declaring night condition, the second one is the measured discharge time through the LDR, the third one is the decision made, and the fourth and final field is the brightness of the LEDs.

We have here two types of variables: the known analog magnitudes we already processed as real entities, and these two new “digital” variables we will process as vectors. One bit vectors, to be precise.

As you’ve probably noticed, there are no timestamps in the log. The board has no notion of real time. Though it does have a notion of time, some parts of the code required assembly programming so it was easier to let things as simple as they are and take advantage of vcdMaker; as it is capable to infer time information from line numbers. This is possible because there is a known log speed: the board logs its measurements every 500ms (two times per second).

Finally, since this is a csv format, all variables have their data in each log line, and all will share the same timestamp. Then, all definitions will have the same line tag matching the record, but we will care for just one field for each variable. Furthermore, the timestamp tag will also be the same; pay attention to how we can convert lines of text to time information using the line() function call. So, this is what I came up with for the config file:

<?xml version="1.0" encoding="UTF-8" standalone="no" ?>
<!DOCTYPE signals SYSTEM "vcdMaker.dtd">
<signals>
<vector>
<line>([[:digit:]]+),([[:digit:]]+),([[:digit:]]),([[:digit:]]).+
</line>
<timestamp>line()</timestamp>
<name>"Top.raw.t1"</name>
<value>dec(1)/3</value>
<size>8</size>
</vector>
<vector>
<line>([[:digit:]]+),([[:digit:]]+),([[:digit:]]),([[:digit:]]).+
</line>
<timestamp>line()</timestamp>
<name>"Top.raw.t2"</name>
<value>dec(2)</value>
<size>8</size>
</vector>
<vector>
<line>([[:digit:]]+),([[:digit:]]+),([[:digit:]]),([[:digit:]]).+
</line>
<timestamp>line()</timestamp>
<name>"Top.day"</name>
<value>dec(3)</value>
<size>1</size>
</vector>
<vector>
<line>([[:digit:]]+),([[:digit:]]+),([[:digit:]]),([[:digit:]]).+
</line>
<timestamp>line()</timestamp>
<name>"Top.brillo"</name>
<value>dec(4)</value>
<size>1</size>
</vector>
<real>
<line>([[:digit:]]+),([[:digit:]]+),([[:digit:]]),([[:digit:]]).+
</line>
<timestamp>line()</timestamp>
<name>"Top.R"</name>
<value>100*(3*(flt(2)/flt(1)) - 1)</value>
</real>
</signals >

Since the expected and measured times are 8-bit integers, I captured them also as vectors (observe the size keyword), and finally at the end I re-captured them as reals to calculate the resistance value. The magic numbers there come from solving the equations with a known R that is 100K. To save some pins, the first measurement is actually R paralleled to the LDR and the second one is the LDR alone, so when solving the equation one gets LDR = R(t2/t1 -1) and the LDR value we use for threshold is 200K (2 times R), then t2 > 3t1 means we are at night.

Now we go to the board and capture its log with any serial tool, preferably one that can add timestamps so we can know for sure when we actually started logging, so having just the stamp for the first line will do, since vcdMaker will do the rest.

Log start, blah blah blah

05/12/2018 06:26:01.04 [RX] - 45,45,0,0
45,45,0,0
45,45,0,0
45,45,0,0

The luminometer revisited

Since the board was outputting two records per second… 500ms units… the time base for the luminometer needed to be corrected to match the board one. As it outputs time with seconds precision, a simple multiply by 2 will do:

<?xml version="1.0" encoding="UTF-8" standalone="no" ?>
<!DOCTYPE signals SYSTEM "vcdMaker.dtd">
<signals>
<real>
<line>([[:d:]]+)\t([[:d:]]+):([[:d:]]+):([[:d:]]+)\t([[:digit:][:punct:]]+)\t([[:graph:]]+)</line>
<timestamp>2*(3600*dec(2) + 60*dec(3) + dec(4))</timestamp>
<name>"Top.Light"</name>
<value>flt(5)</value>
</real>
</signals >

The merge action

We have two different time frames. The board will start at 1 (the line number for the first line), the instrument logs real time. We already took care of converting the luminometer log to units of 500ms; matching the number of lines per second base from the board. So, we know logs can be matched but we still need to find the offsets to apply: to find the sync point and translate it to two offsets.

Since I knew when I started logging my board (it was on the log itself…), I visually inspected both logs and found the first board line whose time was coincident with a luminometer log entry.
In this case, I found that line 8 of the board log coincided with the luminometer log at time 6:26:03. Converting the time of day to “seconds from midnight” and then to units of 500ms we get the number 46326 ((6*3600 + 26*60 + 3)*2 = 46326). So, to merge both logs into one vcd file, I apply both offsets, respectively:

vcdMerge -v -o ldr_board.vcd U{ldr_board.xml},8,s,,,log_asc.txt
U{ldr_lumi_board.xml},46326,s,,,lumi2.txt

Then, I visually inspected the generated vcd file and confirmed signals changed at the right moment as I saw on each log. So, the offsets were correct. For simplicity, forgive me telling the merger those are seconds (instead of half seconds) and let’s check for 10 second windows in the graphs (remember LEDs change brightness every 5 seconds).

The analysis

Now open gtkWave, open a new tab if necessary, load your vcd file, click on Top, append your signals, and…

gtkWave showing the merged logs

We already new what was happening from the previous article, but now we can see what the board is measuring and declare guilty beyond any reasonable doubt.

Want to share this ?

Leave a Reply

Your email address will not be published. Required fields are marked *

Enter Captcha Here : *

Reload Image