From 49e9e08c65d156865ef6482f481c393afc29c566 Mon Sep 17 00:00:00 2001 From: rusefi Date: Sun, 19 Jul 2020 15:47:21 -0400 Subject: [PATCH] better unit test logging --- .../engine_cycle/main_trigger_callback.cpp | 8 +++---- .../controllers/trigger/trigger_decoder.cpp | 23 ++++++++++--------- unit_tests/engine_test_helper.cpp | 5 ++++ 3 files changed, 21 insertions(+), 15 deletions(-) diff --git a/firmware/controllers/engine_cycle/main_trigger_callback.cpp b/firmware/controllers/engine_cycle/main_trigger_callback.cpp index fc51dfd6c2..17d86f2530 100644 --- a/firmware/controllers/engine_cycle/main_trigger_callback.cpp +++ b/firmware/controllers/engine_cycle/main_trigger_callback.cpp @@ -240,7 +240,7 @@ void handleFuelInjectionEvent(int injEventIndex, InjectionEvent *event, if (prevOutputName == outputName && engineConfiguration->injectionMode != IM_SIMULTANEOUS && engineConfiguration->injectionMode != IM_SINGLE_POINT) { - warning(CUSTOM_OBD_SKIPPED_FUEL, "looks like skipped fuel event %d %s", getRevolutionCounter(), outputName); + warning(CUSTOM_OBD_SKIPPED_FUEL, "looks like skipped fuel event revCounter=%d %s", getRevolutionCounter(), outputName); } prevOutputName = outputName; } @@ -248,8 +248,8 @@ void handleFuelInjectionEvent(int injEventIndex, InjectionEvent *event, #if EFI_PRINTF_FUEL_DETAILS if (printFuelDebug) { InjectorOutputPin *output = event->outputs[0]; - printf("handleFuelInjectionEvent fuelout %s duration %d total=%d\t\n", output->name, (int)durationUs, - (int)MS2US(getCrankshaftRevolutionTimeMs(GET_RPM_VALUE))); + printf("handleFuelInjectionEvent fuelout %s injection_duration %dus engineCycleDuration=%.1fms\t\n", output->name, (int)durationUs, + (int)MS2US(getCrankshaftRevolutionTimeMs(GET_RPM_VALUE)) / 1000.0); } #endif /*EFI_PRINTF_FUEL_DETAILS */ @@ -257,7 +257,7 @@ void handleFuelInjectionEvent(int injEventIndex, InjectionEvent *event, #if EFI_PRINTF_FUEL_DETAILS if (printFuelDebug) { InjectorOutputPin *output = event->outputs[0]; - printf("handleFuelInjectionEvent still used1 %s %d\r\n", output->name, (int)getTimeNowUs()); + printf("handleFuelInjectionEvent still used %s now=%.1fms\r\n", output->name, (int)getTimeNowUs() / 1000.0); } #endif /*EFI_PRINTF_FUEL_DETAILS */ return; // this InjectionEvent is still needed for an extremely long injection scheduled previously diff --git a/firmware/controllers/trigger/trigger_decoder.cpp b/firmware/controllers/trigger/trigger_decoder.cpp index cefa59b464..ec5f5ce49f 100644 --- a/firmware/controllers/trigger/trigger_decoder.cpp +++ b/firmware/controllers/trigger/trigger_decoder.cpp @@ -108,6 +108,7 @@ EXTERN_ENGINE; #if ! EFI_PROD_CODE bool printTriggerDebug = false; +bool printTriggerTrace = false; float actualSynchGap; #endif /* ! EFI_PROD_CODE */ @@ -281,7 +282,7 @@ static trigger_value_e eventType[6] = { TV_FALL, TV_RISE, TV_FALL, TV_RISE, TV_F (isFirstEvent ? 0 : (nowNt) - toothed_previous_time) #if EFI_UNIT_TEST -#define PRINT_INC_INDEX if (printTriggerDebug) {\ +#define PRINT_INC_INDEX if (printTriggerTrace) {\ printf("nextTriggerEvent index=%d\r\n", currentCycle.current_index); \ } #else @@ -430,7 +431,7 @@ void TriggerState::decodeTriggerEvent(TriggerWaveform *triggerShape, const Trigg if (needToSkipFall(type) || needToSkipRise(type) || (!considerEventForGap())) { #if EFI_UNIT_TEST - if (printTriggerDebug) { + if (printTriggerTrace) { printf("%s isLessImportant %s now=%d index=%d\r\n", getTrigger_type_e(engineConfiguration->trigger.type), getTrigger_event_e(signal), @@ -447,7 +448,7 @@ void TriggerState::decodeTriggerEvent(TriggerWaveform *triggerShape, const Trigg } else { #if EFI_UNIT_TEST - if (printTriggerDebug) { + if (printTriggerTrace) { printf("%s event %s %d\r\n", getTrigger_type_e(engineConfiguration->trigger.type), getTrigger_event_e(signal), @@ -462,7 +463,7 @@ void TriggerState::decodeTriggerEvent(TriggerWaveform *triggerShape, const Trigg // scheduleMsg(&logger, "from %.2f to %.2f %d %d", triggerConfig->syncRatioFrom, triggerConfig->syncRatioTo, toothDurations[0], shaftPositionState->toothDurations[1]); // scheduleMsg(&logger, "ratio %.2f", 1.0 * toothDurations[0]/ shaftPositionState->toothDurations[1]); #else - if (printTriggerDebug) { + if (printTriggerTrace) { printf("decodeTriggerEvent ratio %.2f: current=%d previous=%d\r\n", 1.0 * toothDurations[0] / toothDurations[1], toothDurations[0], toothDurations[1]); } @@ -559,7 +560,7 @@ void TriggerState::decodeTriggerEvent(TriggerWaveform *triggerShape, const Trigg } } #else - if (printTriggerDebug) { + if (printTriggerTrace) { float gap = 1.0 * toothDurations[0] / toothDurations[1]; for (int i = 0;igetSize()); @@ -598,8 +599,8 @@ void TriggerState::decodeTriggerEvent(TriggerWaveform *triggerShape, const Trigg isSynchronizationPoint = !shaft_is_synchronized || (currentCycle.current_index >= endOfCycleIndex); #if EFI_UNIT_TEST - if (printTriggerDebug) { - printf("decodeTriggerEvent isSynchronizationPoint=%d index=%d size=%d\r\n", + if (printTriggerTrace) { + printf("decodeTriggerEvent decodeTriggerEvent isSynchronizationPoint=%d index=%d size=%d\r\n", isSynchronizationPoint, currentCycle.current_index, triggerShape->getSize()); @@ -609,8 +610,8 @@ void TriggerState::decodeTriggerEvent(TriggerWaveform *triggerShape, const Trigg } #if EFI_UNIT_TEST - if (printTriggerDebug) { - printf("%s isSynchronizationPoint=%d index=%d %s\r\n", + if (printTriggerTrace) { + printf("decodeTriggerEvent %s isSynchronizationPoint=%d index=%d %s\r\n", getTrigger_type_e(engineConfiguration->trigger.type), isSynchronizationPoint, currentCycle.current_index, getTrigger_event_e(signal)); diff --git a/unit_tests/engine_test_helper.cpp b/unit_tests/engine_test_helper.cpp index ae37ace222..bfcf90a5ee 100644 --- a/unit_tests/engine_test_helper.cpp +++ b/unit_tests/engine_test_helper.cpp @@ -19,6 +19,8 @@ extern int timeNowUs; extern WarningCodeState unitTestWarningCodeState; extern engine_configuration_s & activeConfiguration; +extern bool printTriggerDebug; +extern bool printFuelDebug; EngineTestHelperBase::EngineTestHelperBase() { // todo: make this not a global variable, we need currentTimeProvider interface on engine @@ -138,6 +140,9 @@ void EngineTestHelper::moveTimeForwardMs(float deltaTimeMs) { } void EngineTestHelper::moveTimeForwardUs(int deltaTimeUs) { + if (printTriggerDebug || printFuelDebug) { + printf("moveTimeForwardUs %.1fms\r\n", deltaTimeUs / 1000.0); + } timeNowUs += deltaTimeUs; }