Examining logged data with kvmlib and Python

May 29, 2015
Magnus Carlsson

This blog uses now deprecated functions, see blog “Improved API in Python canlib v1.5” for more information.

Today we take a look at how to read logged data and how to relate the data to our watch using kvmlib. We do this by recording some sample data and then try and analyze it using the Python wrapper.

1.1 Generate and record the data.

Let us begin by generating some data. We use the t sample program histogram_stimuli.t, which is included in the CANlib SDK (Samples\tScript\histogram\histogram_stimuli.t). This t program uses four messages; ECM_001, ECM_003, ECM_004 and LIM_002. These messages contains the signals EngineSpeed, EngineTemp, Fuel and Load.

Table 1: Used signals and their main attributes
Signal Name	Type	Min	Max	Unit	Message Name	CAN Id
EngineSpeed	Unsigned	0	6000	rpm	ECM_001	501
EngineTemp	Float	-60	200	°C	ECM_003	503
Fuel	Float	0	300	l/100 km	ECM_004	504
Load	Float	0	100	metric ton	LIM_002	402

The t program generates random values and delays between messages (within the ranges set up in init_stimuli_ctrl()). Now configure an Eagle to “Log everything”, start the t program and let it record for a few minutes.

1.2 When was the engine temperature at about 161°C?

The first question we would like to answer is “When was the engine temperature at 161°C?”. (This is perhaps not the most engineering-like question in the real world, but since our data is completely random I believe it is good enough to visualize how we get the absolute time when reading the log file.)If we had known the question from the beginning, we could have added a couple of triggers that would have started logging whenever the engine temperature was between say 159°C to 163°C (and stopped logging when it was outside this range). But now let us read out all logged data and print out when engine temperature was between 159°C and 163°C.Before running the program ¹ let us go through the main parts. We start by defining a function that finds the device we would like to talk to and open it to get some handles.

def readEventsFromDevice(ean, channel, msgId):
# Read all events from device matching ean, channel and msgId
print "Open device..."
# Create a device with the selected EAN number
dev = kvDevice.kvDevice(ean=ean)
# Open a device that matches our criteria (EAN)
dev.memoOpen()
# Mount the log files so we can acces them
dev.memo.deviceMountKmf()
# Read out how many log files that are availible on the card
fileCount = dev.memo.logFileGetCount()
print "Found %d file%s on card:" % (fileCount, "s" if fileCount > 1 else "")

As can be seen in the above code snippet, we first define our device using the kvDevice helper module and open a handle to it. Then we open a kvmhandle to the device (using memoOpen()) before we get hold of the log files on the device with deviceMountKmf(). We then read out the number of log files that reside on the card.²

       # Now we read all events from each file found on the card.
       for fileIndx in range (fileCount):
           # When mounting the logfile, we get an aproximate value back
           eventCount = dev.memo.logFileMount(fileIndx)
           print "File %3d: Contains less than %d events" % (fileIndx, eventCount)
           # We read out when the logging was started
           startTime = dev.memo.logFileGetStartTime()
           print "Logging started at %s\n" % startTime

We loop through each log file and mount it.³ Mounting a log file also returns an event count which holds “The approximate number of events in the log file”.⁴ We then read out the time the log file was started, remembering this for later.</

           while True:
               # Read events from the log file, when no more events are availible,
               # 'None' will be returned
               event = dev.memo.logReadEventEx()
               if event is None:
                   break

We now read out the events one by one in a loop until no more events are available.

               # We are only interested in events that are log messages
               if type(event) is kvmlib.logMsg:
                   # Also filter on message id and channel number
                   if event.id == msgId and event.channel == channel:

Since we are only interested in one type of log messages we filter those out.⁵ We also filter out the channel number on the card we are interested in.⁶

                       # We know the message data is a float, so convert it to a
                       # more usable format
                       value = raw2float(event.data)
                       # Now filter on the value
                       if value > 159 and value < 163:
                           # Get the time of the event
                           eventTime = getEventTime(startTime, event)
                           print "%s, Msg id %d value %f on channel %d:" % (eventTime, msgId, value, channel)
                           #print event

We convert the raw value to a float in the function raw2float(). Looking at the database we see that this is a straight forward mapping (type float, format Intel, start bit 0, length 32, factor 1 offset 0). If the value was between 159 and 163, we calculate the absolute time of the event in the function getEventTime() and finally print out the data.

           print "n"
           # Dismount to free up resources
           dev.memo.logFileDismount()
       # We are done, close the kvmlib handle to device
       dev.memoClose()

When all events have been read, we dismount the log file and continue with the next. After all log files have been read, we close the handle to the device.

The absolute time of the event is calculated in the function getEventTime() by adding the start time of the log file to the time stamp of the event.

   def getEventTime(startTime, event):
       # The event timestamp is given in nanoseconds. This function converts it to
       # seconds, and returns the sum of startTime and event time (as a Python
       # datetime object).
       offsetInSeconds = event.timeStamp/1000000000.0
       return startTime + datetime.timedelta(seconds=offsetInSeconds)

Note that the time stamp is given in nanoseconds so we need to convert it to seconds before using the Python datetime package to add it to the start time of the log file.

   # Read all events with message id 503, on the first channel, from the first
   # device with EAN 73-30130-00567-9.
   readEventsFromDevice(ean="73-30130-00567-9", channel=0, msgId=503)

Calling our function as shown in the above code results in the following output:

Open device...
Found 1 file on card:

File   0: Contains less than 960 events
Logging started at 2015-05-17 12:48:26

2015-05-17 12:49:07.510234, Msg id 503 value 160.418518 on channel 0:
2015-05-17 12:49:39.647368, Msg id 503 value 159.750595 on channel 0:
2015-05-17 12:49:44.642380, Msg id 503 value 161.818268 on channel 0:
2015-05-17 12:49:59.753440, Msg id 503 value 160.477036 on channel 0:
2015-05-17 12:50:10.433490, Msg id 503 value 162.389267 on channel 0:
2015-05-17 12:50:16.684522, Msg id 503 value 159.377579 on channel 0:
2015-05-17 12:50:53.411675, Msg id 503 value 160.748947 on channel 0:
2015-05-17 12:51:00.961706, Msg id 503 value 159.282867 on channel 0:

In the printout, we can see that 160.477°C have been noted at 2015-05-17 12:49:59.753440.

Another way, if we do not have too much data, is to extract to .csv and sort the columns to find the correct values. Let us do this now since this will give us some more insight in the realm of time…

Connect your Memorator to the PC.
Start the appropriate Kvaser Memorator Config Tool (e.g. use the Eagle shortcut) and connect to your device.
Go to the tab Log files.
Click “List files” to refresh the list.
Click “Extract files…”.
Set file destination and file name options, click “Next”.
Set the format of the extracted files to “Selected signals in CSV format”, click “Next”.
Click Add Database and select histogram.dbc (found in SamplestScript histogramhistogram.dbc).
Double click on the signal “EngineTemp”, click Next.
Make sure that “Time stamp offset” is set to “Start of measurement” and that “High resolution AbsTime” is checked (under CSV file options, see Figure 1). If you, like me, have a non-English version of MS Excel, adjust the “Separator character” (;) and “Decimal separator” (,) as appropriate so the spread sheet program picks up the values as numbers (and not text). Click Finish.

Figure 1: Last step of the extraction wizard in the Kvaser Memorator Config Tool.

Open up the exported .csv in a spread sheet program, sort on the column containing EngineTemp and scroll down to when the EngineTemp was reported as 160°C, see Figure 2. Reading the AbsTime column we can now see that the EngineTemp was e.g. 160.477°C at 2015-05-17T11:49:59.6651.

Figure 2: A part of the resulting .csv file after extracting with “High resolution AbsTime” enabled.

But hey, didn’t our Python program say “12:49:59.753440”? Yes, great spotted, that is correct.
First, the hour between 11:49 and 12:49 is due to Unix time vs local time. Unix time is “the number of seconds that have elapsed since 00:00:00 Coordinated Universal Time (UTC), Thursday, 1 January 1970”.⁷ This means that both time zones and daylight saving times should be considered when doing the conversion from Unix time to local time. The real time clock in the Memorator is set in Unix time and Python is trying to be nice to us and serve the time as local time. The .csv sheet is also in UTC time but no-one told that to the spreadsheet program and hence the one hour difference.

So what about the remaining 883 ms difference? This is due to time stamp offset. Let us look at the first raw values in our file by extracting to “CAN frames in plain text format” and set “Time stamp offset” to “Start of measurement”. We now get the following:

                                Kvaser Memorator Log
                                ====================

  Converted from Memorator Binary format at:  5/19/2015 07:41:03

  Settings:
     Format of data field: DEC
     Format of id field:   DEC
     Timestamp Offset:     0,000000 s
     CAN channel:          1 2

          Time        CAN Identifier  Flags  DLC Data                          Counter
  =====================================================================================
  DateTime: 2015-05-17 11:48:26
      0,088284  Trigger (type=0x1, active=0x00, pre-trigger=0, post-trigger=-1)
     18,323147  1         503    Rx         8    8 206  37  66   0   0   0   0     1
     18,430094  1         501    Rx         8  202  19   0   0   0   0   0   0     2
     18,516129  1         503    Rx         8  206 208   2  67   0   0   0   0     3
     18,529129  1         503    Rx         8   60 184 254  66   0   0   0   0     4

Note that the first Trigger event arrives after 883 ms. Now, compensate for this by once again extracting to “CAN frames in plain text format” and set “Time stamp offset” to “First trigger”. We now get the following:

                                Kvaser Memorator Log
                                ====================

  Converted from Memorator Binary format at:  5/19/2015 07:40:51

  Settings:
     Format of data field: DEC
     Format of id field:   DEC
     Timestamp Offset:     -0,088284 s
     CAN channel:          1 2

          Time        CAN Identifier  Flags  DLC Data                          Counter
  =====================================================================================
  DateTime: 2015-05-17 11:48:26
      0,000000  Trigger (type=0x1, active=0x00, pre-trigger=0, post-trigger=-1)
     18,234863  1         503    Rx         8    8 206  37  66   0   0   0   0     1
     18,341810  1         501    Rx         8  202  19   0   0   0   0   0   0     2
     18,427845  1         503    Rx         8  206 208   2  67   0   0   0   0     3
     18,440845  1         503    Rx         8   60 184 254  66   0   0   0   0     4

Now we have a “Timestamp Offset” of -883 ms and all our time stamps have been adjusted by this amount. So why did we not compensate for this in the Python program? The real time clock have an accuracy of 2 s (±1 s) so it would really be overkill to compensate for some tenths of a second in this case.

1.3 What were the values at 12:49:15?

Let us assume that someone said that “the driver noted a sound when his clock showed 12:49:15, what were the values of the EngineTemp at that time?” Yet again, if we had known that the driver needed to mark something, we would have given him a button to press. This button would have been connected to the trigger input of the Memorator, as shown in Figure 2, and given us an easy to find trigger whenever pressed.

Figure 3: Example of how to connect a push button to the External trigger input of the Memorator.

Before we dive into the log file, we must think about the time the driver noted, 12:49:15. Since he said he looked at the clock, this is in local time and knowing that the Python kvmlib wrapper converts the time stamp into local time, let us write a small program to output relevant data. We also know that the accuracy is 2 s, so let us look at the interval 12:49:10 – 12:49:20. The program is very much as before, except that we filter on time stamp instead of on the recorded value.

   # Filter out log messages that are outside of our time range
   time = startTime + datetime.timedelta(seconds=event.timeStamp/1000000000.0)
   if time >= firstTime and time <= lastTime:       #
       msgId = event.id
       # We know the message data is a float, so convert it to a
       # more usable format
       value = raw2float(event.data)
       # Get the time of the event
       eventTime = getEventTime(startTime, event)
       print "%s, Msg id %d value %f on channel %d:" % (eventTime, msgId, value, channel)

This time we name the function readTimedEventsFromDevice() and calls it as shown below.

   # Read all events with message id 503, on the first channel, from the first
   # device with EAN 73-30130-00567-9 that was recorded between 2015-05-17 12:49:10
   # and 2015-05-17 12:49:20.
   startTime = datetime.datetime.strptime("2015-05-17 12:49:10", "%Y-%m-%d %H:%M:%S")
   endTime = datetime.datetime.strptime("2015-05-17 12:49:20", "%Y-%m-%d %H:%M:%S")
   print "nLooking at %s - %s" % (startTime,endTime)
   readTimedEventsFromDevice(ean="73-30130-00567-9", channel=0, msgId=503, firstTime=startTime, lastTime=endTime)

Calling that function results in the following printout:

Looking at 2015-05-17 12:49:10 - 2015-05-17 12:49:20
Open device...
Found 1 file on card:

File   0: Contains less than 960 events
Logging started at 2015-05-17 12:48:26

2015-05-17 12:49:10.189224, Msg id 503 value 8.356499 on channel 0:
2015-05-17 12:49:10.425245, Msg id 503 value 148.579849 on channel 0:
2015-05-17 12:49:10.683234, Msg id 503 value -21.685257 on channel 0:
2015-05-17 12:49:10.853234, Msg id 503 value 33.064117 on channel 0:
2015-05-17 12:49:10.935236, Msg id 503 value -29.684952 on channel 0:
2015-05-17 12:49:11.320254, Msg id 503 value 54.329140 on channel 0:
2015-05-17 12:49:11.692243, Msg id 503 value -28.083881 on channel 0:
2015-05-17 12:49:11.770270, Msg id 503 value -48.805271 on channel 0:
2015-05-17 12:49:12.234247, Msg id 503 value 117.977112 on channel 0:
2015-05-17 12:49:12.294250, Msg id 503 value 72.071869 on channel 0:
2015-05-17 12:49:12.690248, Msg id 503 value 26.443817 on channel 0:
2015-05-17 12:49:13.132250, Msg id 503 value 74.562210 on channel 0:
2015-05-17 12:49:13.146244, Msg id 503 value 84.493378 on channel 0:
2015-05-17 12:49:13.184243, Msg id 503 value -30.005280 on channel 0:
2015-05-17 12:49:13.375251, Msg id 503 value -10.720951 on channel 0:
2015-05-17 12:49:13.821248, Msg id 503 value 58.475220 on channel 0:
2015-05-17 12:49:14.184254, Msg id 503 value 176.979965 on channel 0:
2015-05-17 12:49:14.427251, Msg id 503 value -37.418663 on channel 0:
2015-05-17 12:49:14.624254, Msg id 503 value 197.064117 on channel 0:
2015-05-17 12:49:14.646256, Msg id 503 value 175.246704 on channel 0:
2015-05-17 12:49:14.715250, Msg id 503 value -54.334503 on channel 0:
2015-05-17 12:49:15.017257, Msg id 503 value 18.197182 on channel 0:
2015-05-17 12:49:15.303258, Msg id 503 value 110.723022 on channel 0:
2015-05-17 12:49:15.337259, Msg id 503 value 86.609604 on channel 0:
2015-05-17 12:49:15.758269, Msg id 503 value 40.770157 on channel 0:
2015-05-17 12:49:15.975262, Msg id 503 value 71.019363 on channel 0:
2015-05-17 12:49:16.342263, Msg id 503 value 95.364639 on channel 0:
2015-05-17 12:49:16.475266, Msg id 503 value 124.447952 on channel 0:
2015-05-17 12:49:16.740282, Msg id 503 value 81.019073 on channel 0:
2015-05-17 12:49:16.796267, Msg id 503 value 171.284988 on channel 0:
2015-05-17 12:49:16.911271, Msg id 503 value 189.340149 on channel 0:
2015-05-17 12:49:16.984273, Msg id 503 value 163.904785 on channel 0:
2015-05-17 12:49:17.276268, Msg id 503 value -33.255932 on channel 0:
2015-05-17 12:49:17.434269, Msg id 503 value -52.797394 on channel 0:
2015-05-17 12:49:17.470280, Msg id 503 value -10.525452 on channel 0:
2015-05-17 12:49:17.929274, Msg id 503 value 49.282883 on channel 0:
2015-05-17 12:49:17.973638, Msg id 503 value 184.748627 on channel 0:
2015-05-17 12:49:18.109271, Msg id 503 value 36.713226 on channel 0:
2015-05-17 12:49:18.543270, Msg id 503 value -41.598648 on channel 0:
2015-05-17 12:49:18.617276, Msg id 503 value 172.797897 on channel 0:
2015-05-17 12:49:18.686271, Msg id 503 value 19.661766 on channel 0:
2015-05-17 12:49:18.974271, Msg id 503 value 187.943726 on channel 0:
2015-05-17 12:49:19.374277, Msg id 503 value 39.316628 on channel 0:
2015-05-17 12:49:19.657277, Msg id 503 value 79.659393 on channel 0:

So, there we have it, all values of the EngineTemp between 12:49:10 and 12:49:20.

Footnotes:

1 The full program listings are available on http://github.com/Kvaser/developer-blog

2 The number of log files is not the same as the number of .kmf containers (log000000.kmf, log000001.kmf, etc) that can be seen on the SD card if we where to move the SD-card to a SD-card reader and look at the contents via our PC. A new log file is created every time a trigger starts logging. In our case, since we have used the configuration option “Log everything”, a new log file will be created each time we apply CAN power (while having the USB disconnected).

3 Note that the naming of the functions in kvmlib have changed in the latest release to make them more uniform and hopefully easier to understand. The naming in the Python kvmlib wrapper have not yet fully been adapted.

4 What we actually read is the number of sectors this log file uses on the disk and knowing how many events we can have in a sector we convert and return this as a number of events.

5 In our case, we filter on message id 503 since that is where our signal EngineTemp is kept. The variable msgId is actually set in the main code and passed as a parameter.

6 I usually have both channels on the device connected to the same CAN bus in my test setup and filtering on the channel number will reduce the redundancy of logged CAN messages.

7 See http://en.wikipedia.org/wiki/Unix_time for more information about Unix time.

Magnus Carlsson

Magnus Carlsson is a Software Developer for Kvaser AB and has developed firmware and software for Kvaser products since 2007. He has also written a number of articles for Kvaser’s Developer Blog dealing with the popular Python language.