Rewrite tooth logger buffer management (#4317)

* s

* make it work

* put back enough maybe

* fix console composite log

* unit tests can just use a vector, why not

Co-authored-by: Matthew Kennedy <makenne@microsoft.com>
This commit is contained in:
Matthew Kennedy 2022-07-04 13:57:17 -07:00 committed by GitHub
parent b73144fef9
commit ab24c5eb35
12 changed files with 230 additions and 163 deletions

View File

@ -31,12 +31,10 @@ typedef struct __attribute__ ((packed)) {
* Engine idles around 20Hz and revs up to 140Hz, at 60/2 and 8 cylinders we have about 20Khz events
* If we can read buffer at 50Hz we want buffer to be about 400 elements.
*/
static composite_logger_s buffer[COMPOSITE_PACKET_COUNT] CCM_OPTIONAL;
static composite_logger_s *ptr_buffer_first = &buffer[0];
static composite_logger_s *ptr_buffer_second = &buffer[(COMPOSITE_PACKET_COUNT/2)-1];
static size_t NextIdx = 0;
static_assert(sizeof(composite_logger_s) == COMPOSITE_PACKET_SIZE, "composite packet size");
static volatile bool ToothLoggerEnabled = false;
static volatile bool firstBuffer = true;
static uint32_t lastEdgeTimestamp = 0;
static bool currentTrigger1 = false;
@ -47,28 +45,54 @@ static bool currentCoilState = false;
// same about injectors
static bool currentInjectorState = false;
int getCompositeRecordCount() {
return NextIdx;
}
#if EFI_UNIT_TEST
#include "logicdata.h"
int copyCompositeEvents(CompositeEvent *events) {
for (size_t i = 0; i < NextIdx; i++) {
CompositeEvent *event = &events[i];
event->timestamp = SWAP_UINT32(buffer[i].timestamp);
event->primaryTrigger = buffer[i].priLevel;
event->secondaryTrigger = buffer[i].secLevel;
event->isTDC = buffer[i].trigger;
event->sync = buffer[i].sync;
event->coil = buffer[i].coil;
event->injector = buffer[i].injector;
}
return NextIdx;
static std::vector<CompositeEvent> events;
const std::vector<CompositeEvent>& getCompositeEvents() {
return events;
}
#endif // EFI_UNIT_TEST
void SetNextCompositeEntry(efitick_t timestamp) {
CompositeEvent event;
event.timestamp = timestamp;
event.primaryTrigger = currentTrigger1;
event.secondaryTrigger = currentTrigger2;
event.isTDC = currentTdc;
event.sync = engine->triggerCentral.triggerState.getShaftSynchronized();
event.coil = currentCoilState;
event.injector = currentInjectorState;
events.push_back(event);
}
void EnableToothLogger() {
ToothLoggerEnabled = true;
events.clear();
}
void DisableToothLogger() {
ToothLoggerEnabled = false;
}
#else // not EFI_UNIT_TEST
static constexpr size_t bufferCount = 4;
static constexpr size_t entriesPerBuffer = COMPOSITE_PACKET_COUNT / bufferCount;
struct CompositeBuffer {
composite_logger_s buffer[entriesPerBuffer];
size_t nextIdx;
Timer startTime;
};
static CompositeBuffer buffers[bufferCount] CCM_OPTIONAL;
static chibios_rt::Mailbox<CompositeBuffer*, bufferCount> freeBuffers CCM_OPTIONAL;
static chibios_rt::Mailbox<CompositeBuffer*, bufferCount> filledBuffers CCM_OPTIONAL;
static CompositeBuffer* currentBuffer = nullptr;
static void setToothLogReady(bool value) {
#if EFI_TUNER_STUDIO && (EFI_PROD_CODE || EFI_SIMULATOR)
@ -76,36 +100,137 @@ static void setToothLogReady(bool value) {
#endif // EFI_TUNER_STUDIO
}
static void SetNextCompositeEntry(efitick_t timestamp) {
uint32_t nowUs = NT2US(timestamp);
// TS uses big endian, grumble
buffer[NextIdx].timestamp = SWAP_UINT32(nowUs);
buffer[NextIdx].priLevel = currentTrigger1;
buffer[NextIdx].secLevel = currentTrigger2;
buffer[NextIdx].trigger = currentTdc;
buffer[NextIdx].sync = engine->triggerCentral.triggerState.getShaftSynchronized();
buffer[NextIdx].coil = currentCoilState;
buffer[NextIdx].injector = currentInjectorState;
void EnableToothLogger() {
chibios_rt::CriticalSectionLocker csl;
NextIdx++;
static_assert(sizeof(composite_logger_s) == COMPOSITE_PACKET_SIZE, "composite packet size");
//If we hit the end, loop
if ((firstBuffer) && (NextIdx >= (COMPOSITE_PACKET_COUNT/2))) {
/* first half is full */
setToothLogReady(true);
firstBuffer = false;
}
if ((!firstBuffer) && (NextIdx >= sizeof(buffer) / sizeof(buffer[0]))) {
setToothLogReady(true);
NextIdx = 0;
firstBuffer = true;
// Reset all buffers
for (size_t i = 0; i < efi::size(buffers); i++) {
buffers[i].nextIdx = 0;
}
// Reset state
currentBuffer = nullptr;
// Empty the filled buffer list
CompositeBuffer* dummy;
while (MSG_TIMEOUT != filledBuffers.fetchI(&dummy)) ;
// Put all buffers in the free list
for (size_t i = 0; i < efi::size(buffers); i++) {
freeBuffers.postI(&buffers[i]);
}
// Reset the last edge to now - this prevents the first edge logged from being bogus
lastEdgeTimestamp = getTimeNowUs();
// Enable logging of edges as they come
ToothLoggerEnabled = true;
setToothLogReady(false);
}
void DisableToothLogger() {
ToothLoggerEnabled = false;
setToothLogReady(false);
}
expected<ToothLoggerBuffer> GetToothLoggerBuffer() {
chibios_rt::CriticalSectionLocker csl;
CompositeBuffer* buffer;
msg_t msg = filledBuffers.fetchI(&buffer);
if (msg == MSG_TIMEOUT) {
setToothLogReady(false);
return unexpected;
}
if (msg != MSG_OK) {
// What even happened if we didn't get timeout, but also didn't get OK?
return unexpected;
}
size_t entryCount = buffer->nextIdx;
buffer->nextIdx = 0;
// Return this buffer to the free list
msg = freeBuffers.postI(buffer);
efiAssert(OBD_PCM_Processor_Fault, msg == MSG_OK, "Composite logger post to free buffer fail", unexpected);
// If the used list is empty, clear the ready flag
if (filledBuffers.getUsedCountI() == 0) {
setToothLogReady(false);
}
return ToothLoggerBuffer{ reinterpret_cast<uint8_t*>(buffer->buffer), entryCount * sizeof(composite_logger_s)};
}
static CompositeBuffer* findBuffer(efitick_t timestamp) {
CompositeBuffer* buffer;
if (!currentBuffer) {
// try and find a buffer, if none available, we can't log
if (MSG_OK != freeBuffers.fetchI(&buffer)) {
return nullptr;
}
// Record the time of the last buffer swap so we can force a swap after a minimum period of time
// This ensures the user sees *something* even if they don't have enough trigger events
// to fill the buffer.
buffer->startTime.reset(timestamp);
currentBuffer = buffer;
}
return currentBuffer;
}
static void SetNextCompositeEntry(efitick_t timestamp) {
// This is called from multiple interrupts/threads, so we need a lock.
chibios_rt::CriticalSectionLocker csl;
CompositeBuffer* buffer = findBuffer(timestamp);
if (!buffer) {
// All buffers are full, nothing to do here.
return;
}
composite_logger_s* entry = &buffer->buffer[buffer->nextIdx];
uint32_t nowUs = NT2US(timestamp);
// TS uses big endian, grumble
entry->timestamp = SWAP_UINT32(nowUs);
entry->priLevel = currentTrigger1;
entry->secLevel = currentTrigger2;
entry->trigger = currentTdc;
entry->sync = engine->triggerCentral.triggerState.getShaftSynchronized();
entry->coil = currentCoilState;
entry->injector = currentInjectorState;
buffer->nextIdx++;
// if the buffer is full...
bool bufferFull = buffer->nextIdx >= efi::size(buffer->buffer);
// ... or it's been too long since the last flush
bool bufferTimedOut = buffer->startTime.hasElapsedSec(5);
// Then cycle buffers and set the ready flag.
if (bufferFull || bufferTimedOut) {
// Post to the output queue
filledBuffers.postI(buffer);
// Null the current buffer so we get a new one next time
currentBuffer = nullptr;
// Flag that we are ready
setToothLogReady(true);
}
}
#endif // EFI_UNIT_TEST
void LogTriggerTooth(trigger_event_e tooth, efitick_t timestamp) {
// bail if we aren't enabled
if (!ToothLoggerEnabled) {
@ -184,43 +309,10 @@ void LogTriggerInjectorState(efitick_t timestamp, bool state) {
//SetNextCompositeEntry(timestamp, trigger1, trigger2, trigger);
}
void EnableToothLogger() {
// Clear the buffer
memset(buffer, 0, sizeof(buffer));
// Reset the last edge to now - this prevents the first edge logged from being bogus
lastEdgeTimestamp = getTimeNowUs();
// Reset write index
NextIdx = 0;
// Enable logging of edges as they come
ToothLoggerEnabled = true;
setToothLogReady(false);
}
void EnableToothLoggerIfNotEnabled() {
if (!ToothLoggerEnabled) {
EnableToothLogger();
}
}
void DisableToothLogger() {
ToothLoggerEnabled = false;
setToothLogReady(false);
}
ToothLoggerBuffer GetToothLoggerBuffer() {
// tell TS that we do not have data until we have data again
setToothLogReady(false);
if (firstBuffer) {
return { reinterpret_cast<uint8_t*>(ptr_buffer_second), (sizeof(buffer)/2) };
} else {
return { reinterpret_cast<uint8_t*>(ptr_buffer_first), (sizeof(buffer)/2) };
}
}
#endif /* EFI_TOOTH_LOGGER */

View File

@ -11,11 +11,9 @@
#if EFI_UNIT_TEST
#include "logicdata.h"
int copyCompositeEvents(CompositeEvent *events);
const std::vector<CompositeEvent>& getCompositeEvents();
#endif // EFI_UNIT_TEST
int getCompositeRecordCount();
void EnableToothLoggerIfNotEnabled();
// Enable the tooth logger - this clears the buffer starts logging
@ -40,4 +38,5 @@ struct ToothLoggerBuffer
};
// Get a reference to the buffer
ToothLoggerBuffer GetToothLoggerBuffer();
// Returns unexpected if no buffer is available
expected<ToothLoggerBuffer> GetToothLoggerBuffer();

View File

@ -565,8 +565,6 @@ void TunerStudio::handleExecuteCommand(TsChannelBase* tsChannel, char *data, int
tsChannel->writeCrcPacket(TS_RESPONSE_COMMAND_OK, nullptr, 0);
}
static int transmitted = 0;
int TunerStudio::handleCrcCommand(TsChannelBase* tsChannel, char *data, int incomingPacketSize) {
ScopePerf perf(PE::TunerStudioHandleCrcCommand);
@ -658,41 +656,19 @@ int TunerStudio::handleCrcCommand(TsChannelBase* tsChannel, char *data, int inco
sendOkResponse(tsChannel, TS_CRC);
break;
case TS_GET_COMPOSITE_BUFFER_DONE_DIFFERENTLY:
{
EnableToothLoggerIfNotEnabled();
const uint8_t* const buffer = GetToothLoggerBuffer().Buffer;
const uint8_t* const start = buffer + COMPOSITE_PACKET_SIZE * transmitted;
int currentEnd = getCompositeRecordCount();
// set debug_mode 40
if (engineConfiguration->debugMode == DBG_COMPOSITE_LOG) {
engine->outputChannels.debugIntField1 = currentEnd;
engine->outputChannels.debugIntField2 = transmitted;
}
if (currentEnd > transmitted) {
// more normal case - tail after head
tsChannel->sendResponse(TS_CRC, start, COMPOSITE_PACKET_SIZE * (currentEnd - transmitted), true);
transmitted = currentEnd;
} else if (currentEnd == transmitted) {
tsChannel->sendResponse(TS_CRC, start, 0);
} else {
// we are here if tail of buffer has reached the end of buffer and re-started from the start of buffer
// sending end of the buffer, next transmission would take care of the rest
tsChannel->sendResponse(TS_CRC, start, COMPOSITE_PACKET_SIZE * (COMPOSITE_PACKET_COUNT - transmitted), true);
transmitted = 0;
}
}
break;
case TS_GET_COMPOSITE_BUFFER_DONE_DIFFERENTLY:
EnableToothLoggerIfNotEnabled();
// falls through
case TS_GET_LOGGER_GET_BUFFER:
{
auto toothBuffer = GetToothLoggerBuffer();
tsChannel->sendResponse(TS_CRC, toothBuffer.Buffer, toothBuffer.Length, true);
if (toothBuffer) {
tsChannel->sendResponse(TS_CRC, toothBuffer.Value.Buffer, toothBuffer.Value.Length, true);
} else {
// TS asked for a tooth logger buffer, but we don't have one to give it.
sendErrorCode(tsChannel, TS_RESPONSE_OUT_OF_RANGE);
}
}
break;

View File

@ -141,10 +141,8 @@ struct_no_prefix engine_configuration_s
#define TOOTH_PACKET_SIZE 2
#define TOOTH_DATA_LENGTH @@TOOTH_PACKET_SIZE@@*@@TOOTH_PACKET_COUNT@@
#define COMPOSITE_PACKET_COUNT 500
#define COMPOSITE_PACKET_COUNT 1000
#define COMPOSITE_PACKET_SIZE 5
#define COMPOSITE_DATA_LENGTH @@COMPOSITE_PACKET_SIZE@@*@@COMPOSITE_PACKET_COUNT@@
#define COMPOSITE_DATA_LENGTH_HALF 1250
#define MAP_ANGLE_SIZE 8
#define MAP_WINDOW_SIZE 8

View File

@ -118,8 +118,6 @@ enable2ndByteCanID = false
dataReadTimeout = 10000 ; time in ms
dataReadyCondition = { toothLogReady }
continuousRead = true
; each packet is @@COMPOSITE_PACKET_SIZE@@ and we have @@COMPOSITE_PACKET_COUNT@@ of those
dataLength = @@COMPOSITE_DATA_LENGTH_HALF@@
;tooth
; recordDef = headerLen, footerLen, recordLen

View File

@ -1,7 +1,7 @@
package com.rusefi.composite;
public class CompositeEvent {
private final int timestamp;
private final long timestamp;
private final boolean primaryTrigger;
private final boolean secondaryTrigger;
private final boolean trg;
@ -9,7 +9,7 @@ public class CompositeEvent {
private final boolean coil;
private final boolean injector;
public CompositeEvent(int timestamp, boolean primaryTrigger, boolean secondaryTrigger, boolean trg, boolean sync, boolean coil, boolean injector) {
public CompositeEvent(long timestamp, boolean primaryTrigger, boolean secondaryTrigger, boolean trg, boolean sync, boolean coil, boolean injector) {
this.timestamp = timestamp;
this.primaryTrigger = primaryTrigger;
this.secondaryTrigger = secondaryTrigger;
@ -19,7 +19,7 @@ public class CompositeEvent {
this.injector = injector;
}
public int getTimestamp() {
public long getTimestamp() {
return timestamp;
}

View File

@ -11,20 +11,22 @@ import java.util.List;
public class CompositeParser {
private static final Logging log = Logging.getLogging(CompositeParser.class);
// 1 second
private static final int maxDeltaTime = 1000000;
private static long prevTime = 0;
private static long timeAdder = 0;
public static List<CompositeEvent> parse(byte[] response) {
ByteBuffer byteBuffer = ByteBuffer.wrap(response);
byteBuffer.order(ByteOrder.BIG_ENDIAN);
int ptr = 1;
int curTime = 0, prevTime = 0;
List<CompositeEvent> events = new ArrayList<>();
while (ptr + Fields.COMPOSITE_PACKET_SIZE <= response.length) {
int timestamp = byteBuffer.getInt(ptr);
// Convert the int to a long since java can't do unsigned ints,
// so we have to use a long (but still only want 32 bits read)
long timestamp = Integer.toUnsignedLong (byteBuffer.getInt(ptr));
byte flags = byteBuffer.get(ptr + 4);
// log.debug(timestamp + " " + flags);
@ -37,20 +39,18 @@ public class CompositeParser {
ptr += Fields.COMPOSITE_PACKET_SIZE;
// 'timestamp' is an integer type for now, and sadly, but it overflows...
// this is an attempt of temporary workaround
int dt = timestamp - prevTime;
// we allow time to increment only in small amounts.
// so if any time discontinuities occur, we jump 1 sec.
if (dt < 0 || dt > maxDeltaTime)
dt = maxDeltaTime;
// we want to catch integer overflows here
curTime = Math.addExact(curTime, dt);
// If the timestamp went down, that means we just witnessed an integer overflow
if (timestamp < prevTime) {
// Add the maximum value of a uint32_t, plus one
timeAdder += 0xFFFFFFFFL + 1;
}
prevTime = timestamp;
long curTime = timeAdder + timestamp;
events.add(new CompositeEvent(curTime, primaryTrigger, secondaryTrigger, trg, sync, coil, injector));
}
return events;
}
}

View File

@ -85,10 +85,11 @@ public class LogicdataStreamFile extends StreamFile {
// we need at least 2 records
if (events == null || events.size() < 2)
return;
int firstRecordTs = events.get(1).getTimestamp();
int lastRecordTs = events.get(events.size() - 1).getTimestamp();
long firstRecordTs = events.get(1).getTimestamp();
long lastRecordTs = events.get(events.size() - 1).getTimestamp();
// we don't know the total duration, so we create a margin after the last record which equals to the duration of the first event
realDurationInSamples = lastRecordTs + firstRecordTs;
// TODO: why do we jump from timestamps to samples?
realDurationInSamples = (int)(lastRecordTs + firstRecordTs);
scaledDurationInSamples = realDurationInSamples / 4;
writeChannelDataHeader();
@ -98,10 +99,10 @@ public class LogicdataStreamFile extends StreamFile {
for (int ch = 0; ch < numChannels; ch++) {
List<Long> chDeltas = new ArrayList<>();
int chPrevState = -1;
int prevTs = 0;
long prevTs = 0;
for (CompositeEvent event : events) {
int chState = getChannelState(ch, event);
int ts = event.getTimestamp();
long ts = event.getTimestamp();
if (chPrevState == -1) {
chPrevState = chState;
@ -122,7 +123,8 @@ public class LogicdataStreamFile extends StreamFile {
}
}
writeChannelData(ch, chDeltas, chPrevState, prevTs, useLongDeltas);
// TODO: why do we pass a timestamp as a record index?
writeChannelData(ch, chDeltas, chPrevState, (int)prevTs, useLongDeltas);
}
writeChannelDataFooter();
@ -238,7 +240,7 @@ public class LogicdataStreamFile extends StreamFile {
writeId(0, 0);
write(BLOCK);
write(new int[]{ realDurationInSamples, realDurationInSamples, realDurationInSamples });
write(new int[]{ (int)realDurationInSamples, (int)realDurationInSamples, (int)realDurationInSamples });
write(0);
write(SUB);
write(0);
@ -284,7 +286,8 @@ public class LogicdataStreamFile extends StreamFile {
write(1);
write(lastRecord);
int numSamplesLeft = realDurationInSamples - lastRecord;
// todo: why do we convert from
int numSamplesLeft = (int)(realDurationInSamples - lastRecord);
write(numSamplesLeft);
write(chLastState);

View File

@ -8,7 +8,7 @@ import java.util.List;
public class TSHighSpeedLog extends StreamFile {
private final String fileName;
private int prevTime = 0;
private long prevTime = 0;
public TSHighSpeedLog(String fileName) {
this.fileName = fileName;
@ -29,7 +29,7 @@ public class TSHighSpeedLog extends StreamFile {
}
for (CompositeEvent event : events) {
writer.write(event.isPrimaryTriggerAsInt() + "," + event.isSecondaryTriggerAsInt() + "," + event.isTrgAsInt() + "," + event.isSyncAsInt() + ",");
int delta = event.getTimestamp() - prevTime;
long delta = event.getTimestamp() - prevTime;
writer.write(event.getTimestamp() / 1000.0 + "," + delta / 1000.0);
writer.write("," + event.isCoil() + "," + event.isInjector());

View File

@ -149,16 +149,14 @@ EngineTestHelper::~EngineTestHelper() {
memset(mockPinStates, 0, sizeof(mockPinStates));
}
static CompositeEvent compositeEvents[COMPOSITE_PACKET_COUNT];
void EngineTestHelper::writeEvents(const char *fileName) {
int count = copyCompositeEvents(compositeEvents);
if (count < 2) {
const auto& events = getCompositeEvents();
if (events.size() < 2) {
printf("Not enough data for %s\n", fileName);
return;
}
printf("Writing %d records to %s\n", count, fileName);
writeFile(fileName, compositeEvents, count);
printf("Writing %d records to %s\n", events.size(), fileName);
writeFile(fileName, events);
}
/**

View File

@ -372,7 +372,7 @@ static void writeChannelDataFooter() {
write(numChannels);
}
static int getChannelState(int ch, CompositeEvent *event) {
static int getChannelState(int ch, const CompositeEvent* event) {
switch (ch) {
case 0:
return event->primaryTrigger;
@ -390,7 +390,8 @@ static int getChannelState(int ch, CompositeEvent *event) {
return -1;
}
static void writeEvents(CompositeEvent *events, int count) {
static void writeEvents(const std::vector<CompositeEvent>& events) {
int count = events.size();
// we need at least 2 records
if (count < 2)
return;
@ -411,7 +412,7 @@ static void writeEvents(CompositeEvent *events, int count) {
int deltaCount = 0;
for (int i = 0; i < count; i++) {
CompositeEvent *event = &events[i];
const CompositeEvent* event = &events[i];
int chState = getChannelState(ch, event);
int ts = event->timestamp;
@ -487,12 +488,12 @@ static void writeFooter() {
writeTimingMarker();
}
void writeFile(const char * fileName, CompositeEvent *events, int count) {
void writeFile(const char * fileName, const std::vector<CompositeEvent>& events) {
ptr = fopen(fileName, "wb");
writeHeader();
writeEvents(events, count);
writeEvents(events);
writeFooter();
fclose(ptr);

View File

@ -7,6 +7,8 @@
#pragma once
#include <vector>
struct CompositeEvent {
int timestamp;
bool primaryTrigger;
@ -17,4 +19,4 @@ struct CompositeEvent {
bool injector;
};
void writeFile(const char * fileName, CompositeEvent *events, int count);
void writeFile(const char * fileName, const std::vector<CompositeEvent>& events);