binary logging (#1443)

* field support

* tests

* makefiles

* test data too

* missing include dir

* write correct thing

* fix one test

* fix test

* omnomnomnom ram

* format

* use defined names

Co-authored-by: Matthew Kennedy <makenne@microsoft.com>

firmware/Makefile

@@ -297,6 +297,7 @@ INCDIR = $(CHIBIOS)/os/license \
 	console_util \
 	console \
 	$(PROJECT_DIR)/console/binary \
+	$(PROJECT_DIR)/console/binary_log \
 	$(PROJECT_DIR)/console/fl_binary \
 	$(PROJECT_DIR)/hw_layer \
 	$(PROJECT_DIR)/mass_storage \

firmware/bootloader/src/Makefile

@@ -242,6 +242,7 @@ INCDIR = .. $(CHIBIOS)/os/license \
 	$(PROJECT_DIR)/console_util \
 	$(PROJECT_DIR)/console \
 	$(PROJECT_DIR)/console/binary \
+	$(PROJECT_DIR)/console/binary_log \
 	$(PROJECT_DIR)/console/fl_binary \
 	$(PROJECT_DIR)/hw_layer \
 	$(PROJECT_DIR)/mass_storage \

firmware/console/binary_log/binary_logging.cpp

@@ -0,0 +1,123 @@
+
+#include "tunerstudio_configuration.h"
+#include "log_field.h"
+#include "efilib.h"
+#include "efitime.h"
+#include "crc.h"
+
+static const LogField fields[] = {
+	{tsOutputChannels.rpm, "RPM", "rpm", 0},
+	{tsOutputChannels.vehicleSpeedKph, GAUGE_NAME_VVS, "kph", 0},
+	{tsOutputChannels.internalMcuTemperature, GAUGE_NAME_CPU_TEMP, "C", 0},
+	{tsOutputChannels.coolantTemperature, "CLT", "C", 1},
+	{tsOutputChannels.intakeAirTemperature, "IAT", "C", 1},
+	{tsOutputChannels.throttlePosition, "TPS", "%", 2},
+	{tsOutputChannels.pedalPosition, GAUGE_NAME_THROTTLE_PEDAL, "%", 2},
+	{tsOutputChannels.manifoldAirPressure, "MAP", "kPa", 1},
+	{tsOutputChannels.airFuelRatio, GAUGE_NAME_AFR, "afr", 2},
+	{tsOutputChannels.vBatt, GAUGE_NAME_VBAT, "v", 2},
+	{tsOutputChannels.oilPressure, "Oil Press", "kPa", 0},
+	{tsOutputChannels.vvtPosition, GAUGE_NAME_VVT, "deg", 1},
+	{tsOutputChannels.chargeAirMass, GAUGE_NAME_AIR_MASS, "g", 3},
+	{tsOutputChannels.currentTargetAfr, GAUGE_NAME_TARGET_AFR, "afr", 2},
+	{tsOutputChannels.fuelBase, GAUGE_NAME_FUEL_BASE, "ms", 3},
+	{tsOutputChannels.fuelRunning, GAUGE_NAME_FUEL_RUNNING, "ms", 3},
+	{tsOutputChannels.actualLastInjection, GAUGE_NAME_FUEL_LAST_INJECTION, "ms", 3},
+	{tsOutputChannels.injectorDutyCycle, GAUGE_NAME_FUEL_INJ_DUTY, "%", 0},
+	{tsOutputChannels.veValue, GAUGE_NAME_FUEL_VE, "%", 1},
+	{tsOutputChannels.tCharge, "tCharge", "C", 1},
+	{tsOutputChannels.injectorLagMs, GAUGE_NAME_INJECTOR_LAG, "ms", 3},
+	{tsOutputChannels.fuelPidCorrection, GAUGE_NAME_FUEL_PID_CORR, "ms", 3},
+	{tsOutputChannels.wallFuelCorrection, GAUGE_NAME_FUEL_WALL_CORRECTION, "ms", 3},
+	{tsOutputChannels.tpsAccelFuel, GAUGE_NAME_FUEL_TPS_EXTRA, "ms", 3},
+	{tsOutputChannels.ignitionAdvance, GAUGE_NAME_TIMING_ADVANCE, "deg", 1},
+	{tsOutputChannels.sparkDwell, GAUGE_COIL_DWELL_TIME, "ms", 1},
+	{tsOutputChannels.coilDutyCycle, GAUGE_NAME_DWELL_DUTY, "%", 0},
+	{tsOutputChannels.idlePosition, GAUGE_NAME_IAC, "%", 1},
+	{tsOutputChannels.etbTarget, "ETB Target", "%", 2},
+	{tsOutputChannels.etb1DutyCycle, "ETB Duty", "%", 1},
+	{tsOutputChannels.etb1Error, "ETB Error", "%", 3},
+	{tsOutputChannels.fuelTankLevel, "fuel level", "%", 0},
+};
+
+void writeHeader(char* buffer) {
+	// File format: MLVLG\0
+	strncpy(buffer, "MLVLG", 6);
+
+	// Format version = 01
+	buffer[6] = 0;
+	buffer[7] = 1;
+
+	// Timestamp
+	buffer[8] = 0;
+	buffer[9] = 0;
+	buffer[10] = 0;
+	buffer[11] = 0;
+
+	// Info data start
+	buffer[12] = 0;
+	buffer[13] = 0;
+
+	// Data begin index - always begin at 4096 = 0x800 bytes to allow space for header
+	buffer[14] = 0;
+	buffer[15] = 0;
+	buffer[16] = 0x08;
+	buffer[17] = 0x00;
+
+	// Record length - length of a single data record: sum size of all fields
+	uint16_t recLength = 0;
+	for (size_t i = 0; i < efi::size(fields); i++) {
+		recLength += fields[i].getSize();
+	}
+
+	buffer[18] = recLength >> 8;
+	buffer[19] = recLength & 0xFF;
+
+	// Number of logger fields
+	buffer[20] = 0;
+	buffer[21] = efi::size(fields);
+
+	// Write the actual logger fields, offset 22
+	char* entryHeaders = buffer + 22;
+	for (size_t i = 0; i < efi::size(fields); i++) {
+		size_t sz = fields[i].writeHeader(entryHeaders);
+		entryHeaders += sz;
+	}
+}
+
+static uint8_t blockRollCounter = 0;
+
+size_t writeBlock(char* buffer) {
+	// Offset 0 = Block type, standard data block in this case
+	buffer[0] = 0;
+
+	// Offset 1 = rolling counter sequence number
+	buffer[1] = blockRollCounter++;
+
+	// Offset 2, size 2 = Timestamp at 10us resolution
+	uint16_t timestamp = getTimeNowUs() / 10;
+	buffer[2] = timestamp >> 8;
+	buffer[3] = timestamp & 0xFF;
+
+	// Offset 4 = field data
+	const char* dataBlockStart = buffer + 4;
+	char* dataBlock = buffer + 4;
+	for (size_t i = 0; i < efi::size(fields); i++) {
+		size_t entrySize = fields[i].writeData(dataBlock);
+
+		// Increment pointer to next entry
+		dataBlock += entrySize;
+	}
+
+	size_t dataBlockSize = dataBlock - dataBlockStart;
+
+	// "CRC" at the end is just the sum of all bytes
+	uint8_t sum = 0;
+	for (size_t i = 0; i < dataBlockSize; i++) {
+		sum += dataBlockStart[i];
+	}
+	*dataBlock = sum;
+
+	// Total size has 4 byte header + 1 byte checksum
+	return dataBlockSize + 5;
+}

firmware/console/binary_log/binary_logging.h

@@ -0,0 +1,4 @@
+#include <cstddef>
+
+void writeHeader(char* buffer);
+size_t writeBlock(char* buffer);

firmware/console/binary_log/log_field.cpp

@@ -0,0 +1,52 @@
+#include "log_field.h"
+
+#include <cstring>
+
+static void memcpy_swapend(void* dest, const void* src, size_t num) {
+	const char* src2 = reinterpret_cast<const char*>(src);
+	char* dest2 = reinterpret_cast<char*>(dest);
+	
+	for (size_t i = 0; i < num; i++) {
+		// Endian swap - copy the end to the beginning
+		dest2[i] = src2[num - 1 - i];
+	}
+}
+
+static void copyFloat(char* buffer, float value) {
+	memcpy_swapend(buffer, reinterpret_cast<char*>(&value), sizeof(float));
+}
+
+size_t LogField::writeHeader(char* buffer) const {
+	// Offset 0, length 1 = type
+	buffer[0] = static_cast<char>(m_type);
+
+	// Offset 0, length 34 = name
+	strncpy(&buffer[1], m_name, 34);
+
+	// Offset 35, length 10 = units
+	strncpy(&buffer[35], m_units, 10);
+
+	// Offset 45, length 1 = Display style
+	// value 0 -> floating point number
+	buffer[45] = 0;
+
+	// Offset 46, length 4 = Scale
+	copyFloat(buffer + 46, 1.0f / m_multiplier);
+
+	// Offset 50, length 4 = shift before scaling (always 0)
+	copyFloat(buffer + 50, 0);
+
+	// Offset 54, size 1 = digits to display (signed int)
+	buffer[54] = m_digits;
+
+	// Total size = 55
+	return 55;
+}
+
+size_t LogField::writeData(char* buffer) const {
+	size_t size = m_size;
+
+	memcpy_swapend(buffer, m_addr, size);
+
+	return size;
+}

firmware/console/binary_log/log_field.h

@@ -0,0 +1,105 @@
+#pragma once
+
+#include "scaled_channel.h"
+#include <cstdint>
+#include <cstddef>
+
+class LogField {
+public:
+	template <typename TValue, int TMult = 1>
+	LogField(const scaled_channel<TValue, TMult>& toRead, const char* name, const char* units, int8_t digits)
+		: m_type(resolveType<TValue>())
+		, m_multiplier(TMult)
+		, m_addr(reinterpret_cast<const char*>(&toRead))
+		, m_digits(digits)
+		, m_size(sizeForType(resolveType<TValue>()))
+		, m_name(name)
+		, m_units(units)
+	{
+	}
+
+	enum class Type : uint8_t {
+		U08 = 0,
+		S08 = 1,
+		U16 = 2,
+		S16 = 3,
+		U32 = 4,
+		S32 = 5,
+		S64 = 6,
+		F32 = 7,
+	};
+
+	size_t getSize() const {
+		return m_size;
+	}
+
+	// Write the header data describing this field.
+	// Returns the number of bytes written.
+	size_t writeHeader(char* buffer) const;
+
+	// Write the field's data to the buffer.
+	// Returns the number of bytes written.
+	size_t writeData(char* buffer) const;
+
+private:
+	template<typename T>
+	static Type resolveType();
+
+	static size_t sizeForType(Type t) {
+		switch (t) {
+			case Type::U08:
+			case Type::S08:
+				return 1;
+			case Type::U16:
+			case Type::S16:
+				return 2;
+			default:
+				// float, uint32, int32
+				return 4;
+		}
+	}
+
+	const Type m_type;
+	const float m_multiplier;
+	const char* const m_addr;
+	const int8_t m_digits;
+	const size_t m_size;
+
+	const char* const m_name;
+	const char* const m_units;
+};
+
+template<>
+constexpr LogField::Type LogField::resolveType<uint8_t>() {
+	return Type::U08;
+}
+
+template<>
+constexpr LogField::Type LogField::resolveType<int8_t>() {
+	return Type::S08;
+}
+
+template<>
+constexpr LogField::Type LogField::resolveType<uint16_t>() {
+	return Type::U16;
+}
+
+template<>
+constexpr LogField::Type LogField::resolveType<int16_t>() {
+	return Type::S16;
+}
+
+template<>
+constexpr LogField::Type LogField::resolveType<uint32_t>() {
+	return Type::U32;
+}
+
+template<>
+constexpr LogField::Type LogField::resolveType<int32_t>() {
+	return Type::S32;
+}
+
+template<>
+constexpr LogField::Type LogField::resolveType<float>() {
+	return Type::F32;
+}

firmware/console/console.mk

@@ -4,5 +4,7 @@ CONSOLESRC =
 CONSOLE_SRC_CPP = $(PROJECT_DIR)/console/status_loop.cpp \
 	$(PROJECT_DIR)/console/console_io.cpp \
 	$(PROJECT_DIR)/console/eficonsole.cpp \
-	$(PROJECT_DIR)/console/tooth_logger.cpp
+	$(PROJECT_DIR)/console/tooth_logger.cpp \
+	$(PROJECT_DIR)/console/binary_log/log_field.cpp \
+	$(PROJECT_DIR)/console/binary_log/binary_logging.cpp \
 

firmware/controllers/engine_controller.cpp

@@ -696,7 +696,7 @@ void initEngineContoller(Logging *sharedLogger DECLARE_ENGINE_PARAMETER_SUFFIX)
  * UNUSED_SIZE contants.
  */
 #ifndef RAM_UNUSED_SIZE
-#define RAM_UNUSED_SIZE 10900
+#define RAM_UNUSED_SIZE 10000
 #endif
 #ifndef CCM_UNUSED_SIZE
 #define CCM_UNUSED_SIZE 2900

simulator/Makefile

@@ -190,6 +190,7 @@ INCDIR = . \
           $(PROJECT_DIR)/init \
           $(PROJECT_DIR)/console \
           $(PROJECT_DIR)/console/binary \
+          $(PROJECT_DIR)/console/binary_log \
           $(PROJECT_DIR)/console/fl_binary \
           $(PROJECT_DIR)/config/engines \
           $(PROJECT_DIR)/ext_algo \

unit_tests/Makefile

@@ -141,7 +141,8 @@ CPPSRC = $(UTILSRC_CPP) \
 	$(HW_SENSORS_SRC) \
 	$(TRIGGER_SRC_CPP) \
 	$(INIT_SRC_CPP) \
-	$(PROJECT_DIR)/../unit_tests/main.cpp
+	$(PROJECT_DIR)/../unit_tests/main.cpp \
+	$(PROJECT_DIR)/console/binary_log/log_field.cpp \
 
 
 # C sources to be compiled in ARM mode regardless of the global setting.
@@ -173,6 +174,7 @@ INCDIR = . \
 	$(PROJECT_DIR)/config/engines \
 	$(CONTROLLERS_INC) \
 	$(PROJECT_DIR)/console \
+	$(PROJECT_DIR)/console/binary_log \
  	$(DEVELOPMENT_DIR) \
 	$(PROJECT_DIR)/ext_algo \
 	$(PROJECT_DIR)/hw_layer \

unit_tests/tests/test_binary_log.cpp

@@ -0,0 +1,50 @@
+#include "log_field.h"
+
+#include <gmock/gmock.h>
+
+using ::testing::ElementsAre;
+
+TEST(BinaryLogField, FieldHeader) {
+	scaled_channel<int8_t, 10> channel;
+	LogField field(channel, "name", "units", 2);
+
+	char buffer[56];
+	memset(buffer, 0xAA, sizeof(buffer));
+
+	// Should write 55 bytes
+	EXPECT_EQ(55, field.writeHeader(buffer));
+
+	// Expect correctly written header
+	EXPECT_THAT(buffer, ElementsAre(
+		1,	// type: int8_t
+		// name - 34 bytes, 0 padded
+		'n', 'a', 'm', 'e', 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0,
+		// units - 10 bytes, 0 padded
+		'u', 'n', 'i', 't', 's', 0, 0, 0, 0, 0,
+		// display style: float
+		0,
+		// Scale = 0.1 (float)
+		0x3d, 0xcc, 0xcc, 0xcd,
+		// Transform - we always use 0
+		0, 0, 0, 0,
+		// Digits - 2, as configured
+		2,
+
+		// After end should be 0xAA, not touched
+		0xAA
+	));
+}
+
+TEST(BinaryLogField, Value) {
+	scaled_channel<uint32_t, 1> testValue = 12345678;
+	LogField lf(testValue, "test", "unit", 0);
+
+	char buffer[6];
+	memset(buffer, 0xAA, sizeof(buffer));
+
+	// Should write 4 bytes
+	EXPECT_EQ(4, lf.writeData(buffer));
+
+	// Check that big endian data was written, and bytes after weren't touched
+	EXPECT_THAT(buffer, ElementsAre(0x00, 0xbc, 0x61, 0x4e, 0xAA, 0xAA));
+}

unit_tests/tests/tests.mk

@@ -55,4 +55,5 @@ TESTS_SRC_CPP = \
 	tests/test_boost.cpp \
 	tests/test_gppwm.cpp \
 	tests/test_fuel_math.cpp \
+	tests/test_binary_log.cpp \