From 763b17fb50fcd7190361722bfa83c2c9bb228ce9 Mon Sep 17 00:00:00 2001 From: Matthew Kennedy Date: Fri, 11 Oct 2019 17:43:21 -0700 Subject: [PATCH 1/4] experiment --- firmware/config/chconf_common.h | 8 +- firmware/config/stm32f4ems/chconf.h | 14 +-- firmware/controllers/algo/engine.cpp | 4 + firmware/controllers/algo/engine2.cpp | 4 + firmware/controllers/engine_controller.cpp | 45 ++++------ .../controllers/scheduling/event_queue.cpp | 6 ++ .../scheduling/single_timer_executor.cpp | 5 +- firmware/controllers/system/efi_gpio.cpp | 3 + firmware/controllers/system/periodic_task.cpp | 7 +- .../system/periodic_thread_controller.h | 10 ++- .../controllers/trigger/trigger_central.cpp | 4 + .../controllers/trigger/trigger_decoder.cpp | 3 + firmware/development/development.mk | 3 +- firmware/development/perf_trace.cpp | 86 +++++++++++++++++++ firmware/development/perf_trace.h | 72 ++++++++++++++++ firmware/hw_layer/adc_inputs.cpp | 14 ++- firmware/hw_layer/adc_subscription.cpp | 3 + firmware/hw_layer/hardware.cpp | 6 ++ 18 files changed, 253 insertions(+), 44 deletions(-) create mode 100644 firmware/development/perf_trace.cpp create mode 100644 firmware/development/perf_trace.h diff --git a/firmware/config/chconf_common.h b/firmware/config/chconf_common.h index fe31300cc2..f5cf6661d2 100644 --- a/firmware/config/chconf_common.h +++ b/firmware/config/chconf_common.h @@ -18,12 +18,18 @@ extern "C" #endif /* __cplusplus */ #ifndef __ASSEMBLER__ void firmwareError(obd_code_e code, const char *fmt, ...); - #if EFI_CLOCK_LOCKS + #if ENABLE_PERF_TRACE void irqEnterHook(void); void irqExitHook(void); + void idleEnterHook(void); + void idleExitHook(void); + void contextSwitchHook(void); #else /* EFI_CLOCK_LOCKS */ #define irqEnterHook() {} #define irqExitHook() {} + #define idleEnterHook() {} + #define idleExitHook() {} + #define contextSwitchHook() {} #endif /*EFI_CLOCK_LOCKS */ #endif /* __ASSEMBLER__ */ #ifdef __cplusplus diff --git a/firmware/config/stm32f4ems/chconf.h b/firmware/config/stm32f4ems/chconf.h index 3cf817cdb6..7c0730f73b 100644 --- a/firmware/config/stm32f4ems/chconf.h +++ b/firmware/config/stm32f4ems/chconf.h @@ -50,10 +50,10 @@ #define CHPRINTF_USE_FLOAT TRUE -#if !defined(EFI_CLOCK_LOCKS) || defined(__DOXYGEN__) +#if !defined(ENABLE_PERF_TRACE) || defined(__DOXYGEN__) // looks like this value could not be defined in efifeatures.h - please define either externally or just change the value here - #define EFI_CLOCK_LOCKS FALSE -#endif /* EFI_CLOCK_LOCKS */ + #define ENABLE_PERF_TRACE TRUE +#endif /* ENABLE_PERF_TRACE */ #include "chconf_common.h" @@ -565,7 +565,7 @@ * @note The default is @p FALSE. */ #ifndef CH_DBG_ENABLE_TRACE -#define CH_DBG_ENABLE_TRACE TRUE +#define CH_DBG_ENABLE_TRACE FALSE #endif /** @@ -670,7 +670,7 @@ * @details This hook is invoked just before switching between threads. */ #define CH_CFG_CONTEXT_SWITCH_HOOK(ntp, otp) { \ - /* Context switch code here.*/ \ + contextSwitchHook(); \ } /** @@ -696,7 +696,7 @@ * @note This macro can be used to activate a power saving mode. */ #define CH_CFG_IDLE_ENTER_HOOK() { \ - /* Idle-enter code here.*/ \ + idleEnterHook(); \ } /** @@ -706,7 +706,7 @@ * @note This macro can be used to deactivate a power saving mode. */ #define CH_CFG_IDLE_LEAVE_HOOK() { \ - /* Idle-leave code here.*/ \ + idleExitHook(); \ } /** diff --git a/firmware/controllers/algo/engine.cpp b/firmware/controllers/algo/engine.cpp index 7d14c191bc..9e7b10e6cf 100644 --- a/firmware/controllers/algo/engine.cpp +++ b/firmware/controllers/algo/engine.cpp @@ -24,6 +24,7 @@ #include "aux_valves.h" #include "map_averaging.h" #include "fsio_impl.h" +#include "perf_trace.h" #if EFI_PROD_CODE #include "injector_central.h" @@ -116,6 +117,8 @@ static void cylinderCleanupControl(DECLARE_ENGINE_PARAMETER_SIGNATURE) { static efitick_t tle8888CrankingResetTime = 0; void Engine::periodicSlowCallback(DECLARE_ENGINE_PARAMETER_SIGNATURE) { + ScopePerf perf(PE::EnginePeriodicSlowCallback); + watchdog(); updateSlowSensors(PASS_ENGINE_PARAMETER_SIGNATURE); checkShutdown(); @@ -363,6 +366,7 @@ operation_mode_e Engine::getOperationMode(DECLARE_ENGINE_PARAMETER_SIGNATURE) { * so that trigger event handler/IO scheduler tasks are faster. */ void Engine::periodicFastCallback(DECLARE_ENGINE_PARAMETER_SIGNATURE) { + ScopePerf pc(PE::EnginePeriodicFastCallback); #if EFI_MAP_AVERAGING refreshMapAveragingPreCalc(PASS_ENGINE_PARAMETER_SIGNATURE); diff --git a/firmware/controllers/algo/engine2.cpp b/firmware/controllers/algo/engine2.cpp index 28c71b01a1..d92377b486 100644 --- a/firmware/controllers/algo/engine2.cpp +++ b/firmware/controllers/algo/engine2.cpp @@ -15,6 +15,8 @@ #include "engine_math.h" #include "advance_map.h" #include "aux_valves.h" +#include "perf_trace.h" + #if EFI_PROD_CODE #include "svnversion.h" #endif @@ -139,6 +141,8 @@ void EngineState::updateSlowSensors(DECLARE_ENGINE_PARAMETER_SIGNATURE) { } void EngineState::periodicFastCallback(DECLARE_ENGINE_PARAMETER_SIGNATURE) { + ScopePerf perf(PE::EngineStatePeriodicFastCallback); + #if EFI_ENGINE_CONTROL if (!engine->slowCallBackWasInvoked) { warning(CUSTOM_ERR_6696, "Slow not invoked yet"); diff --git a/firmware/controllers/engine_controller.cpp b/firmware/controllers/engine_controller.cpp index dd64d509fb..7eed5e9a6a 100644 --- a/firmware/controllers/engine_controller.cpp +++ b/firmware/controllers/engine_controller.cpp @@ -59,6 +59,7 @@ #include "aux_pid.h" #include "accelerometer.h" #include "counter64.h" +#include "perf_trace.h" #if HAL_USE_ADC #include "AdcConfiguration.h" @@ -284,39 +285,30 @@ static void resetAccel(void) { static int previousSecond; -#if EFI_CLOCK_LOCKS - -typedef FLStack irq_enter_timestamps_t; - -static irq_enter_timestamps_t irqEnterTimestamps; +#if ENABLE_PERF_TRACE void irqEnterHook(void) { - irqEnterTimestamps.push(getTimeNowLowerNt()); + perfEventBegin(PE::ISR); } -static int currentIrqDurationAccumulator = 0; -static int currentIrqCounter = 0; -/** - * See also maxLockedDuration - */ -int perSecondIrqDuration = 0; -int perSecondIrqCounter = 0; void irqExitHook(void) { - int enterTime = irqEnterTimestamps.pop(); - currentIrqDurationAccumulator += (getTimeNowLowerNt() - enterTime); - currentIrqCounter++; + perfEventEnd(PE::ISR); } -#endif /* EFI_CLOCK_LOCKS */ -static void invokePerSecond(void) { -#if EFI_CLOCK_LOCKS - // this data transfer is not atomic but should be totally good enough - perSecondIrqDuration = currentIrqDurationAccumulator; - perSecondIrqCounter = currentIrqCounter; - currentIrqDurationAccumulator = currentIrqCounter = 0; -#endif /* EFI_CLOCK_LOCKS */ +void idleEnterHook(void) { + perfEventBegin(PE::Idle); } +void idleExitHook(void) { + perfEventEnd(PE::Idle); +} + +void contextSwitchHook() { + perfEventInstantGlobal(PE::ContextSwitch); +} + +#endif /* ENABLE_PERF_TRACE */ + static void doPeriodicSlowCallback(DECLARE_ENGINE_PARAMETER_SIGNATURE) { #if EFI_ENGINE_CONTROL && EFI_SHAFT_POSITION_INPUT efiAssertVoid(CUSTOM_ERR_6661, getCurrentRemainingStack() > 64, "lowStckOnEv"); @@ -329,11 +321,6 @@ static void doPeriodicSlowCallback(DECLARE_ENGINE_PARAMETER_SIGNATURE) { updateAndSet(&halTime.state, getTimeNowLowerNt()); /* Leaving the critical zone.*/ chSysRestoreStatusX(sts); - int timeSeconds = getTimeNowSeconds(); - if (previousSecond != timeSeconds) { - previousSecond = timeSeconds; - invokePerSecond(); - } #endif /* EFI_PROD_CODE */ /** diff --git a/firmware/controllers/scheduling/event_queue.cpp b/firmware/controllers/scheduling/event_queue.cpp index 5eefa697ab..fb9e791d2e 100644 --- a/firmware/controllers/scheduling/event_queue.cpp +++ b/firmware/controllers/scheduling/event_queue.cpp @@ -16,6 +16,7 @@ #include "event_queue.h" #include "efitime.h" #include "os_util.h" +#include "perf_trace.h" #if EFI_UNIT_TEST extern bool verboseMode; @@ -36,6 +37,8 @@ bool EventQueue::checkIfPending(scheduling_s *scheduling) { * @return true if inserted into the head of the list */ bool EventQueue::insertTask(scheduling_s *scheduling, efitime_t timeX, schfunc_t callback, void *param) { + ScopePerf perf(PE::EventQueueInsertTask); + #if EFI_UNIT_TEST assertListIsSorted(); #endif /* EFI_UNIT_TEST */ @@ -118,6 +121,9 @@ static uint32_t lastEventCallbackDuration; * @return number of executed actions */ int EventQueue::executeAll(efitime_t now) { + ScopePerf perf(PE::EventQueueExecuteAll); + + scheduling_s * current, *tmp; scheduling_s * executionList = nullptr; diff --git a/firmware/controllers/scheduling/single_timer_executor.cpp b/firmware/controllers/scheduling/single_timer_executor.cpp index 5ee285ca2d..e0e7bf91f2 100644 --- a/firmware/controllers/scheduling/single_timer_executor.cpp +++ b/firmware/controllers/scheduling/single_timer_executor.cpp @@ -24,7 +24,7 @@ #include "os_access.h" #include "single_timer_executor.h" #include "efitime.h" - +#include "perf_trace.h" #if EFI_SIGNAL_EXECUTOR_ONE_TIMER @@ -114,6 +114,8 @@ void SingleTimerExecutor::onTimerCallback() { * this private method is executed under lock */ void SingleTimerExecutor::doExecute() { + ScopePerf perf(PE::SingleTimerExecutorDoExecute); + doExecuteCounter++; /** * Let's execute actions we should execute at this point. @@ -159,6 +161,7 @@ void SingleTimerExecutor::scheduleTimerCallback() { int32_t hwAlarmTime = NT2US((int32_t)nextEventTimeNt - (int32_t)nowNt); uint32_t beforeHwSetTimer = getTimeNowLowerNt(); setHardwareUsTimer(hwAlarmTime == 0 ? 1 : hwAlarmTime); + perfEventInstantGlobal(PE::SingleTimerExecutorScheduleTimerCallback); hwSetTimerDuration = getTimeNowLowerNt() - beforeHwSetTimer; } diff --git a/firmware/controllers/system/efi_gpio.cpp b/firmware/controllers/system/efi_gpio.cpp index 172e0ece9f..9dd6ef5cba 100644 --- a/firmware/controllers/system/efi_gpio.cpp +++ b/firmware/controllers/system/efi_gpio.cpp @@ -10,6 +10,7 @@ #include "engine.h" #include "efi_gpio.h" #include "drivers/gpio/gpio_ext.h" +#include "perf_trace.h" #if EFI_GPIO_HARDWARE #include "pin_repository.h" @@ -345,6 +346,8 @@ void OutputPin::setValue(int logicValue) { } #endif + perfEventInstantGlobal(PE::OutputPinSetValue, static_cast(this->brainPin)); + #else /* EFI_PROD_CODE */ setPinValue(this, eValue, logicValue); #endif /* EFI_PROD_CODE */ diff --git a/firmware/controllers/system/periodic_task.cpp b/firmware/controllers/system/periodic_task.cpp index 8047bd7072..1b8ffe89b0 100644 --- a/firmware/controllers/system/periodic_task.cpp +++ b/firmware/controllers/system/periodic_task.cpp @@ -7,10 +7,15 @@ #include "periodic_task.h" #include "os_util.h" +#include "perf_trace.h" void runAndScheduleNext(PeriodicTimerController *controller) { #if !EFI_UNIT_TEST - controller->PeriodicTask(); + { + ScopePerf perf(PE::PeriodicTimerControllerPeriodicTask); + controller->PeriodicTask(); + } + chVTSetAny(&controller->timer, TIME_MS2I(controller->getPeriodMs()), (vtfunc_t) &runAndScheduleNext, controller); #endif /* EFI_UNIT_TEST */ } diff --git a/firmware/controllers/system/periodic_thread_controller.h b/firmware/controllers/system/periodic_thread_controller.h index 33c27cc885..d9981a848b 100644 --- a/firmware/controllers/system/periodic_thread_controller.h +++ b/firmware/controllers/system/periodic_thread_controller.h @@ -9,7 +9,7 @@ #include "thread_controller.h" #include "efitime.h" - +#include "perf_trace.h" /** * @brief Base class for a controller that needs to run periodically to perform work. @@ -65,8 +65,12 @@ private: systime_t before = chVTGetSystemTime(); efitime_t nowNt = getTimeNowNt(); - // Run the controller's periodic work - PeriodicTask(nowNt); + { + ScopePerf perf(PE::PeriodicControllerPeriodicTask); + + // Run the controller's periodic work + PeriodicTask(nowNt); + } // This ensures the loop _actually_ runs at the desired frequency. // Suppose we want a loop speed of 500hz: diff --git a/firmware/controllers/trigger/trigger_central.cpp b/firmware/controllers/trigger/trigger_central.cpp index 846f57a708..1a24f1dd27 100644 --- a/firmware/controllers/trigger/trigger_central.cpp +++ b/firmware/controllers/trigger/trigger_central.cpp @@ -26,6 +26,8 @@ #include "rpm_calculator.h" +#include "perf_trace.h" + #if EFI_PROD_CODE #include "pin_repository.h" #endif /* EFI_PROD_CODE */ @@ -197,6 +199,8 @@ static bool isInsideTriggerHandler = false; void hwHandleShaftSignal(trigger_event_e signal) { + ScopePerf perf(PE::HandleShaftSignal, static_cast(signal)); + #if EFI_TOOTH_LOGGER // Log to the Tunerstudio tooth logger // We want to do this before anything else as we diff --git a/firmware/controllers/trigger/trigger_decoder.cpp b/firmware/controllers/trigger/trigger_decoder.cpp index 88174c9ba9..b901fcfba9 100644 --- a/firmware/controllers/trigger/trigger_decoder.cpp +++ b/firmware/controllers/trigger/trigger_decoder.cpp @@ -35,6 +35,7 @@ #include "engine_math.h" #include "trigger_central.h" #include "trigger_simulator.h" +#include "perf_trace.h" #if EFI_SENSOR_CHART #include "sensor_chart.h" @@ -418,6 +419,8 @@ void TriggerState::onShaftSynchronization(efitime_t nowNt, trigger_wheel_e trigg * @param nowNt current time */ void TriggerState::decodeTriggerEvent(trigger_event_e const signal, efitime_t nowNt DECLARE_ENGINE_PARAMETER_SUFFIX) { + ScopePerf perf(PE::DecodeTriggerEvent, static_cast(signal)); + bool useOnlyRisingEdgeForTrigger = CONFIG(useOnlyRisingEdgeForTrigger); // todo: use 'triggerShape' instead of TRIGGER_SHAPE in order to decouple this method from engine #635 TriggerShape *triggerShape = &ENGINE(triggerCentral.triggerShape); diff --git a/firmware/development/development.mk b/firmware/development/development.mk index 4217acd2f2..5e3634a7d9 100644 --- a/firmware/development/development.mk +++ b/firmware/development/development.mk @@ -8,6 +8,7 @@ DEV_SRC_CPP = development/trigger_emulator.cpp \ development/rfi_perftest.cpp \ development/engine_emulator.cpp \ $(PROJECT_DIR)/development/engine_sniffer.cpp \ - development/wave_analyzer.cpp + development/wave_analyzer.cpp \ + $(PROJECT_DIR)/development/perf_trace.cpp DEV_SIMULATOR_SRC_CPP = $(PROJECT_DIR)/development/engine_sniffer.cpp \ No newline at end of file diff --git a/firmware/development/perf_trace.cpp b/firmware/development/perf_trace.cpp new file mode 100644 index 0000000000..02f0d2e257 --- /dev/null +++ b/firmware/development/perf_trace.cpp @@ -0,0 +1,86 @@ + +#include "perf_trace.h" +#include "efitime.h" +#include "efifeatures.h" +#include "os_util.h" + +#define TRACE_BUFFER_LENGTH 4096 + +enum class Phase : char +{ + Start, + End, + InstantThread, + InstantGlobal, + +}; + +struct TraceEntry +{ + PE Event; + Phase Type; + uint8_t Data; + uint8_t ThreadId; + uint32_t Timestamp; +}; + +static_assert(sizeof(TraceEntry) == 8); + +static TraceEntry s_traceBuffer[TRACE_BUFFER_LENGTH]; +static size_t s_nextIdx = 0; + +void perfEventImpl(PE event, Phase type, uint8_t data) +{ + if constexpr (!ENABLE_PERF_TRACE) + { + return; + } + + uint32_t timestamp = getTimeNowLowerNt(); + + size_t idx; + + // Critical section: reserve index under lock + { + bool wasLocked = lockAnyContext(); + + idx = s_nextIdx++; + if (s_nextIdx >= TRACE_BUFFER_LENGTH) + { + s_nextIdx = 0; + } + + if (!wasLocked) { + unlockAnyContext(); + } + } + + // We can safely write data out of the lock, our spot is reserved + TraceEntry& entry = s_traceBuffer[idx]; + + entry.Event = event; + entry.Type = type; + entry.ThreadId = 0; // TODO + entry.Timestamp = timestamp; + entry.Data = data; +} + +void perfEventBegin(PE event, uint8_t data) +{ + perfEventImpl(event, Phase::Start, data); +} + +void perfEventEnd(PE event, uint8_t data) +{ + perfEventImpl(event, Phase::End, data); +} + +void perfEventInstantThread(PE event, uint8_t data) +{ + perfEventImpl(event, Phase::InstantThread, data); +} + +void perfEventInstantGlobal(PE event, uint8_t data) +{ + perfEventImpl(event, Phase::InstantGlobal, data); +} diff --git a/firmware/development/perf_trace.h b/firmware/development/perf_trace.h new file mode 100644 index 0000000000..6f4688a387 --- /dev/null +++ b/firmware/development/perf_trace.h @@ -0,0 +1,72 @@ + +#pragma once + +#include + +// Defines different events we want to trace. These can be an interval (begin -> end), or an +// instant. Instants can be global, or specific to one thread. You probably don't want to use +// each element in PE more than once, as they should each indicate that a specific thing began, +// ended, or occured. +enum class PE : uint8_t { + ISR, + Idle, + ContextSwitch, + OutputPinSetValue, + DecodeTriggerEvent, + EnginePeriodicFastCallback, + EnginePeriodicSlowCallback, + EngineStatePeriodicFastCallback, + HandleShaftSignal, + EventQueueInsertTask, + EventQueueExecuteAll, + SingleTimerExecutorDoExecute, + SingleTimerExecutorScheduleTimerCallback, + PeriodicControllerPeriodicTask, + PeriodicTimerControllerPeriodicTask, + AdcCallbackFast, + AdcCallbackSlow, + AdcConversionSlow, + AdcConversionFast, + AdcSubscriptionUpdateSubscribers, +}; + +void perfEventBegin(PE event, uint8_t data); +void perfEventEnd(PE event, uint8_t data); +void perfEventInstantThread(PE event, uint8_t data); +void perfEventInstantGlobal(PE event, uint8_t data); + +inline void perfEventBegin(PE event) { + perfEventBegin(event, 0); +} + +inline void perfEventEnd(PE event) { + perfEventEnd(event, 0); +} + +inline void perfEventInstantThread(PE event) { + perfEventInstantThread(event, 0); +} + +inline void perfEventInstantGlobal(PE event) { + perfEventInstantGlobal(event, 0); +} + + +class ScopePerf +{ +public: + ScopePerf(PE event) : ScopePerf(event, 0) {} + + ScopePerf(PE event, uint8_t data) : m_event(event) + { + perfEventBegin(event, data); + } + + ~ScopePerf() + { + perfEventEnd(m_event, 0); + } + +private: + const PE m_event; +}; diff --git a/firmware/hw_layer/adc_inputs.cpp b/firmware/hw_layer/adc_inputs.cpp index 79b1727cbb..337f8d35b3 100644 --- a/firmware/hw_layer/adc_inputs.cpp +++ b/firmware/hw_layer/adc_inputs.cpp @@ -35,7 +35,7 @@ #include "engine_math.h" #include "engine_controller.h" #include "maf.h" -//#include "biquad.h" +#include "perf_trace.h" /* Depth of the conversion buffer, channels are sampled X times each.*/ #define ADC_BUF_DEPTH_SLOW 8 @@ -227,6 +227,10 @@ void doSlowAdc(void) { ; return; } + + // This event ends in the conversion callback + perfEventBegin(PE::AdcConversionSlow, 0); + adcStartConversionI(&ADC_SLOW_DEVICE, &adcgrpcfgSlow, slowAdc.samples, ADC_BUF_DEPTH_SLOW); chSysUnlockFromISR() ; @@ -260,6 +264,10 @@ static void pwmpcb_fast(PWMDriver *pwmp) { ; return; } + + // This event ends in the conversion callback + perfEventBegin(PE::AdcConversionFast, 0); + adcStartConversionI(&ADC_FAST_DEVICE, &adcgrpcfg_fast, fastAdc.samples, ADC_BUF_DEPTH_FAST); chSysUnlockFromISR() ; @@ -459,9 +467,13 @@ static void adc_callback_slow(ADCDriver *adcp, adcsample_t *buffer, size_t n) { (void) buffer; (void) n; + ScopePerf perf(PE::AdcCallbackSlow); + /* Note, only in the ADC_COMPLETE state because the ADC driver fires * an intermediate callback when the buffer is half full. */ if (adcp->state == ADC_COMPLETE) { + perfEventEnd(PE::AdcConversionSlow, 0); + slowAdc.invalidateSamplesCache(); efiAssertVoid(CUSTOM_ERR_6671, getCurrentRemainingStack() > 128, "lowstck#9c"); diff --git a/firmware/hw_layer/adc_subscription.cpp b/firmware/hw_layer/adc_subscription.cpp index 5e8eb55d86..5ab2ee8b82 100644 --- a/firmware/hw_layer/adc_subscription.cpp +++ b/firmware/hw_layer/adc_subscription.cpp @@ -2,6 +2,7 @@ #include "adc_inputs.h" #include "engine.h" +#include "perf_trace.h" #include @@ -46,6 +47,8 @@ void AdcSubscription::SubscribeSensor(FunctionalSensor &sensor, } void AdcSubscription::UpdateSubscribers() { + ScopePerf perf(PE::AdcSubscriptionUpdateSubscribers); + for (size_t i = 0; i < s_nextEntry; i++) { auto &entry = s_entries[i]; diff --git a/firmware/hw_layer/hardware.cpp b/firmware/hw_layer/hardware.cpp index 55d8ce5c7d..0d89f82389 100644 --- a/firmware/hw_layer/hardware.cpp +++ b/firmware/hw_layer/hardware.cpp @@ -47,6 +47,7 @@ #include "svnversion.h" #include "engine_configuration.h" #include "aux_pid.h" +#include "perf_trace.h" #if EFI_MC33816 #include "mc33816.h" @@ -197,11 +198,16 @@ extern AdcDevice fastAdc; void adc_callback_fast(ADCDriver *adcp, adcsample_t *buffer, size_t n) { (void) buffer; (void) n; + + ScopePerf perf(PE::AdcCallbackFast); + /** * Note, only in the ADC_COMPLETE state because the ADC driver fires an * intermediate callback when the buffer is half full. * */ if (adcp->state == ADC_COMPLETE) { + perfEventEnd(PE::AdcConversionFast, 0); + fastAdc.invalidateSamplesCache(); /** From f52bdecb803f0060075bbbfc8c91194624549ffa Mon Sep 17 00:00:00 2001 From: Matthew Kennedy Date: Sun, 13 Oct 2019 13:14:08 -0700 Subject: [PATCH 2/4] profile all the things --- firmware/config/chconf_common.h | 4 ---- firmware/config/stm32f4ems/chconf.h | 2 -- firmware/console/binary/tunerstudio.cpp | 4 ++++ .../controllers/algo/accel_enrichment.cpp | 5 ++++ firmware/controllers/algo/fuel_math.cpp | 7 ++++++ firmware/controllers/engine_controller.cpp | 10 +------- firmware/controllers/map_averaging.cpp | 4 ++++ firmware/controllers/math/speed_density.cpp | 3 +++ .../controllers/scheduling/event_queue.cpp | 7 +++++- .../scheduling/pwm_generator_logic.cpp | 3 +++ .../scheduling/single_timer_executor.cpp | 5 +++- firmware/controllers/system/efi_gpio.cpp | 4 ++-- .../trigger/main_trigger_callback.cpp | 5 ++++ firmware/controllers/trigger/spark_logic.cpp | 3 +++ .../controllers/trigger/trigger_central.cpp | 2 ++ firmware/development/perf_trace.h | 24 ++++++++++++++++--- firmware/hw_layer/adc_inputs.cpp | 8 ------- 17 files changed, 70 insertions(+), 30 deletions(-) diff --git a/firmware/config/chconf_common.h b/firmware/config/chconf_common.h index f5cf6661d2..abfc5ea1b2 100644 --- a/firmware/config/chconf_common.h +++ b/firmware/config/chconf_common.h @@ -21,14 +21,10 @@ extern "C" #if ENABLE_PERF_TRACE void irqEnterHook(void); void irqExitHook(void); - void idleEnterHook(void); - void idleExitHook(void); void contextSwitchHook(void); #else /* EFI_CLOCK_LOCKS */ #define irqEnterHook() {} #define irqExitHook() {} - #define idleEnterHook() {} - #define idleExitHook() {} #define contextSwitchHook() {} #endif /*EFI_CLOCK_LOCKS */ #endif /* __ASSEMBLER__ */ diff --git a/firmware/config/stm32f4ems/chconf.h b/firmware/config/stm32f4ems/chconf.h index 7c0730f73b..4cbf9c6e96 100644 --- a/firmware/config/stm32f4ems/chconf.h +++ b/firmware/config/stm32f4ems/chconf.h @@ -696,7 +696,6 @@ * @note This macro can be used to activate a power saving mode. */ #define CH_CFG_IDLE_ENTER_HOOK() { \ - idleEnterHook(); \ } /** @@ -706,7 +705,6 @@ * @note This macro can be used to deactivate a power saving mode. */ #define CH_CFG_IDLE_LEAVE_HOOK() { \ - idleExitHook(); \ } /** diff --git a/firmware/console/binary/tunerstudio.cpp b/firmware/console/binary/tunerstudio.cpp index 50476cfc3e..bf29739778 100644 --- a/firmware/console/binary/tunerstudio.cpp +++ b/firmware/console/binary/tunerstudio.cpp @@ -84,6 +84,8 @@ #include "loggingcentral.h" #include "status_loop.h" #include "mmc_card.h" +#include "perf_trace.h" + #if EFI_SIMULATOR #include "rusEfiFunctionalTest.h" #endif @@ -749,6 +751,8 @@ bool handlePlainCommand(ts_channel_s *tsChannel, uint8_t command) { int tunerStudioHandleCrcCommand(ts_channel_s *tsChannel, char *data, int incomingPacketSize) { + ScopePerf perf(PE::TunerStudioHandleCrcCommand); + char command = data[0]; data++; diff --git a/firmware/controllers/algo/accel_enrichment.cpp b/firmware/controllers/algo/accel_enrichment.cpp index 7c70af06a0..c420c95cb4 100644 --- a/firmware/controllers/algo/accel_enrichment.cpp +++ b/firmware/controllers/algo/accel_enrichment.cpp @@ -27,6 +27,7 @@ #include "accel_enrichment.h" #include "allsensors.h" #include "engine_math.h" +#include "perf_trace.h" #if EFI_TUNER_STUDIO #include "tunerstudio_configuration.h" #endif /* EFI_TUNER_STUDIO */ @@ -56,6 +57,8 @@ floatms_t WallFuel::adjust(int injectorIndex, floatms_t desiredFuel DECLARE_ENGI return desiredFuel; } + ScopePerf perf(PE::WallFuelAdjust); + /* this math is based on SAE 810494 by C. F. Aquino @@ -171,6 +174,8 @@ float AccelEnrichment::getMaxDelta(DECLARE_ENGINE_PARAMETER_SIGNATURE) { // todo: eliminate code duplication between these two methods! Some pointer magic would help. floatms_t TpsAccelEnrichment::getTpsEnrichment(DECLARE_ENGINE_PARAMETER_SIGNATURE) { + ScopePerf perf(PE::GetTpsEnrichment); + int maxDeltaIndex = getMaxDeltaIndex(PASS_ENGINE_PARAMETER_SIGNATURE); // FuelSchedule *fs = engineConfiguration->injectionEvents; diff --git a/firmware/controllers/algo/fuel_math.cpp b/firmware/controllers/algo/fuel_math.cpp index d6b2633120..76e40636c2 100644 --- a/firmware/controllers/algo/fuel_math.cpp +++ b/firmware/controllers/algo/fuel_math.cpp @@ -29,6 +29,7 @@ #include "engine_math.h" #include "rpm_calculator.h" #include "speed_density.h" +#include "perf_trace.h" EXTERN_ENGINE ; @@ -87,6 +88,8 @@ DISPLAY(DISPLAY_IF(isCrankingState)) floatms_t getCrankingFuel3(float coolantTem /* DISPLAY_ELSE */ floatms_t getRunningFuel(floatms_t baseFuel DECLARE_ENGINE_PARAMETER_SUFFIX) { + ScopePerf perf(PE::GetRunningFuel); + DISPLAY_TEXT(Base_fuel); ENGINE(engineState.DISPLAY_PREFIX(running).DISPLAY_FIELD(baseFuel)) = baseFuel; DISPLAY_TEXT(eol); @@ -154,6 +157,8 @@ float getRealMafFuel(float airSpeed, int rpm DECLARE_ENGINE_PARAMETER_SUFFIX) { * todo: rename this method since it's now base+TPSaccel */ floatms_t getBaseFuel(int rpm DECLARE_ENGINE_PARAMETER_SUFFIX) { + ScopePerf perf(PE::GetBaseFuel); + floatms_t tpsAccelEnrich = ENGINE(tpsAccelEnrichment.getTpsEnrichment(PASS_ENGINE_PARAMETER_SIGNATURE)); efiAssert(CUSTOM_ERR_ASSERT, !cisnan(tpsAccelEnrich), "NaN tpsAccelEnrich", 0); ENGINE(engineState.tpsAccelEnrich) = tpsAccelEnrich; @@ -228,6 +233,8 @@ percent_t getInjectorDutyCycle(int rpm DECLARE_ENGINE_PARAMETER_SUFFIX) { * in case of single point injection mode the amount of fuel into all cylinders, otherwise the amount for one cylinder */ floatms_t getInjectionDuration(int rpm DECLARE_ENGINE_PARAMETER_SUFFIX) { + ScopePerf perf(PE::GetInjectionDuration); + #if EFI_ENGINE_CONTROL && EFI_SHAFT_POSITION_INPUT bool isCranking = ENGINE(rpmCalculator).isCranking(PASS_ENGINE_PARAMETER_SIGNATURE); injection_mode_e mode = isCranking ? diff --git a/firmware/controllers/engine_controller.cpp b/firmware/controllers/engine_controller.cpp index 7eed5e9a6a..8fab794066 100644 --- a/firmware/controllers/engine_controller.cpp +++ b/firmware/controllers/engine_controller.cpp @@ -295,14 +295,6 @@ void irqExitHook(void) { perfEventEnd(PE::ISR); } -void idleEnterHook(void) { - perfEventBegin(PE::Idle); -} - -void idleExitHook(void) { - perfEventEnd(PE::Idle); -} - void contextSwitchHook() { perfEventInstantGlobal(PE::ContextSwitch); } @@ -310,7 +302,7 @@ void contextSwitchHook() { #endif /* ENABLE_PERF_TRACE */ static void doPeriodicSlowCallback(DECLARE_ENGINE_PARAMETER_SIGNATURE) { -#if EFI_ENGINE_CONTROL && EFI_SHAFT_POSITION_INPUT + #if EFI_ENGINE_CONTROL && EFI_SHAFT_POSITION_INPUT efiAssertVoid(CUSTOM_ERR_6661, getCurrentRemainingStack() > 64, "lowStckOnEv"); #if EFI_PROD_CODE /** diff --git a/firmware/controllers/map_averaging.cpp b/firmware/controllers/map_averaging.cpp index cc781f6e30..b0284e5341 100644 --- a/firmware/controllers/map_averaging.cpp +++ b/firmware/controllers/map_averaging.cpp @@ -36,6 +36,7 @@ #include "interpolation.h" #include "engine.h" #include "engine_math.h" +#include "perf_trace.h" #if EFI_SENSOR_CHART #include "sensor_chart.h" @@ -255,6 +256,9 @@ void refreshMapAveragingPreCalc(DECLARE_ENGINE_PARAMETER_SIGNATURE) { */ static void mapAveragingTriggerCallback(trigger_event_e ckpEventType, uint32_t index DECLARE_ENGINE_PARAMETER_SUFFIX) { + + ScopePerf perf(PE::MapAveragingTriggerCallback); + #if EFI_ENGINE_CONTROL // this callback is invoked on interrupt thread UNUSED(ckpEventType); diff --git a/firmware/controllers/math/speed_density.cpp b/firmware/controllers/math/speed_density.cpp index a1b892daf4..6c84f32bb6 100644 --- a/firmware/controllers/math/speed_density.cpp +++ b/firmware/controllers/math/speed_density.cpp @@ -15,6 +15,7 @@ #include "engine_math.h" #include "maf2map.h" #include "config_engine_specs.h" +#include "perf_trace.h" #if defined(HAS_OS_ACCESS) #error "Unexpected OS ACCESS HERE" @@ -137,6 +138,8 @@ EXTERN_ENGINE; * @return per cylinder injection time, in Milliseconds */ floatms_t getSpeedDensityFuel(float map DECLARE_GLOBAL_SUFFIX) { + ScopePerf perf(PE::GetSpeedDensityFuel); + /** * most of the values are pre-calculated for performance reasons */ diff --git a/firmware/controllers/scheduling/event_queue.cpp b/firmware/controllers/scheduling/event_queue.cpp index fb9e791d2e..d39cba69b5 100644 --- a/firmware/controllers/scheduling/event_queue.cpp +++ b/firmware/controllers/scheduling/event_queue.cpp @@ -177,7 +177,12 @@ int EventQueue::executeAll(efitime_t now) { #if EFI_UNIT_TEST printf("QUEUE: execute current=%d param=%d\r\n", (long)current, (long)current->param); #endif - current->callback(current->param); + + { + ScopePerf perf2(PE::EventQueueExecuteCallback); + current->callback(current->param); + } + // even with overflow it's safe to subtract here lastEventCallbackDuration = getTimeNowLowerNt() - before; if (lastEventCallbackDuration > maxEventCallbackDuration) diff --git a/firmware/controllers/scheduling/pwm_generator_logic.cpp b/firmware/controllers/scheduling/pwm_generator_logic.cpp index 7fbdc1b520..3c79edc1a7 100644 --- a/firmware/controllers/scheduling/pwm_generator_logic.cpp +++ b/firmware/controllers/scheduling/pwm_generator_logic.cpp @@ -13,6 +13,7 @@ #include "pwm_generator_logic.h" #include "pwm_generator.h" #include "error_handling.h" +#include "perf_trace.h" /** * We need to limit the number of iterations in order to avoid precision loss while calculating @@ -225,6 +226,8 @@ efitimeus_t PwmConfig::togglePwmState() { * First invocation happens on application thread */ static void timerCallback(PwmConfig *state) { + ScopePerf perf(PE::PwmGeneratorCallback); + state->dbgNestingLevel++; efiAssertVoid(CUSTOM_ERR_6581, state->dbgNestingLevel < 25, "PWM nesting issue"); diff --git a/firmware/controllers/scheduling/single_timer_executor.cpp b/firmware/controllers/scheduling/single_timer_executor.cpp index e0e7bf91f2..05809e6976 100644 --- a/firmware/controllers/scheduling/single_timer_executor.cpp +++ b/firmware/controllers/scheduling/single_timer_executor.cpp @@ -84,6 +84,8 @@ void SingleTimerExecutor::scheduleForLater(scheduling_s *scheduling, int delayUs */ void SingleTimerExecutor::scheduleByTimestamp(scheduling_s *scheduling, efitimeus_t timeUs, schfunc_t callback, void *param) { + ScopePerf perf(PE::SingleTimerExecutorScheduleByTimestamp); + scheduleCounter++; bool alreadyLocked = true; if (!reentrantFlag) { @@ -150,6 +152,8 @@ void SingleTimerExecutor::doExecute() { * This method is always invoked under a lock */ void SingleTimerExecutor::scheduleTimerCallback() { + ScopePerf perf(PE::SingleTimerExecutorScheduleTimerCallback); + /** * Let's grab fresh time value */ @@ -161,7 +165,6 @@ void SingleTimerExecutor::scheduleTimerCallback() { int32_t hwAlarmTime = NT2US((int32_t)nextEventTimeNt - (int32_t)nowNt); uint32_t beforeHwSetTimer = getTimeNowLowerNt(); setHardwareUsTimer(hwAlarmTime == 0 ? 1 : hwAlarmTime); - perfEventInstantGlobal(PE::SingleTimerExecutorScheduleTimerCallback); hwSetTimerDuration = getTimeNowLowerNt() - beforeHwSetTimer; } diff --git a/firmware/controllers/system/efi_gpio.cpp b/firmware/controllers/system/efi_gpio.cpp index 9dd6ef5cba..21cec712f1 100644 --- a/firmware/controllers/system/efi_gpio.cpp +++ b/firmware/controllers/system/efi_gpio.cpp @@ -322,6 +322,8 @@ void OutputPin::toggle() { } void OutputPin::setValue(int logicValue) { + ScopePerf perf(PE::OutputPinSetValue); + #if EFI_PROD_CODE efiAssertVoid(CUSTOM_ERR_6621, modePtr!=NULL, "pin mode not initialized"); pin_output_mode_e mode = *modePtr; @@ -346,8 +348,6 @@ void OutputPin::setValue(int logicValue) { } #endif - perfEventInstantGlobal(PE::OutputPinSetValue, static_cast(this->brainPin)); - #else /* EFI_PROD_CODE */ setPinValue(this, eValue, logicValue); #endif /* EFI_PROD_CODE */ diff --git a/firmware/controllers/trigger/main_trigger_callback.cpp b/firmware/controllers/trigger/main_trigger_callback.cpp index 61727a5878..63dd496d95 100644 --- a/firmware/controllers/trigger/main_trigger_callback.cpp +++ b/firmware/controllers/trigger/main_trigger_callback.cpp @@ -52,6 +52,7 @@ #include "local_version_holder.h" #include "event_queue.h" #include "engine.h" +#include "perf_trace.h" #include "aux_valves.h" #include "backup_ram.h" @@ -359,6 +360,8 @@ static void fuelClosedLoopCorrection(DECLARE_ENGINE_PARAMETER_SIGNATURE) { static ALWAYS_INLINE void handleFuel(const bool limitedFuel, uint32_t trgEventIndex, int rpm DECLARE_ENGINE_PARAMETER_SUFFIX) { + ScopePerf perf(PE::HandleFuel); + efiAssertVoid(CUSTOM_STACK_6627, getCurrentRemainingStack() > 128, "lowstck#3"); efiAssertVoid(CUSTOM_ERR_6628, trgEventIndex < engine->engineCycleEventCount, "handleFuel/event index"); @@ -429,6 +432,8 @@ uint32_t *cyccnt = (uint32_t*) &DWT->CYCCNT; * Both injection and ignition are controlled from this method. */ void mainTriggerCallback(trigger_event_e ckpSignalType, uint32_t trgEventIndex DECLARE_ENGINE_PARAMETER_SUFFIX) { + ScopePerf perf(PE::MainTriggerCallback); + (void) ckpSignalType; ENGINE(m.beforeMainTrigger) = getTimeNowLowerNt(); diff --git a/firmware/controllers/trigger/spark_logic.cpp b/firmware/controllers/trigger/spark_logic.cpp index 314973f559..041f4f58a2 100644 --- a/firmware/controllers/trigger/spark_logic.cpp +++ b/firmware/controllers/trigger/spark_logic.cpp @@ -11,6 +11,7 @@ #include "utlist.h" #include "event_queue.h" +#include "perf_trace.h" #if EFI_TUNER_STUDIO #include "tunerstudio_configuration.h" @@ -396,6 +397,8 @@ static void scheduleAllSparkEventsUntilNextTriggerTooth(uint32_t trgEventIndex D void onTriggerEventSparkLogic(bool limitedSpark, uint32_t trgEventIndex, int rpm DECLARE_ENGINE_PARAMETER_SUFFIX) { + ScopePerf perf(PE::OnTriggerEventSparkLogic); + if (!isValidRpm(rpm) || !CONFIG(isIgnitionEnabled)) { // this might happen for instance in case of a single trigger event after a pause return; diff --git a/firmware/controllers/trigger/trigger_central.cpp b/firmware/controllers/trigger/trigger_central.cpp index 1a24f1dd27..81141bc3f5 100644 --- a/firmware/controllers/trigger/trigger_central.cpp +++ b/firmware/controllers/trigger/trigger_central.cpp @@ -394,6 +394,8 @@ void TriggerCentral::handleShaftSignal(trigger_event_e signal DECLARE_ENGINE_PAR } if (triggerState.isValidIndex(PASS_ENGINE_PARAMETER_SIGNATURE)) { + ScopePerf perf(PE::ShaftPositionListeners); + #if TRIGGER_EXTREME_LOGGING scheduleMsg(logger, "trigger %d %d %d", triggerIndexForListeners, getRevolutionCounter(), (int)getTimeNowUs()); #endif /* FUEL_MATH_EXTREME_LOGGING */ diff --git a/firmware/development/perf_trace.h b/firmware/development/perf_trace.h index 6f4688a387..0e5dfa9c99 100644 --- a/firmware/development/perf_trace.h +++ b/firmware/development/perf_trace.h @@ -8,8 +8,8 @@ // each element in PE more than once, as they should each indicate that a specific thing began, // ended, or occured. enum class PE : uint8_t { + INVALID, ISR, - Idle, ContextSwitch, OutputPinSetValue, DecodeTriggerEvent, @@ -28,6 +28,23 @@ enum class PE : uint8_t { AdcConversionSlow, AdcConversionFast, AdcSubscriptionUpdateSubscribers, + GetRunningFuel, + GetInjectionDuration, + HandleFuel, + MainTriggerCallback, + OnTriggerEventSparkLogic, + ShaftPositionListeners, + GetBaseFuel, + GetTpsEnrichment, + GetSpeedDensityFuel, + WallFuelAdjust, + MapAveragingTriggerCallback, + AdcCallbackFastComplete, + SingleTimerExecutorScheduleByTimestamp, + ScheduleByAngle, + EventQueueExecuteCallback, + PwmGeneratorCallback, + TunerStudioHandleCrcCommand }; void perfEventBegin(PE event, uint8_t data); @@ -57,16 +74,17 @@ class ScopePerf public: ScopePerf(PE event) : ScopePerf(event, 0) {} - ScopePerf(PE event, uint8_t data) : m_event(event) + ScopePerf(PE event, uint8_t data) : m_event(event), m_data(data) { perfEventBegin(event, data); } ~ScopePerf() { - perfEventEnd(m_event, 0); + perfEventEnd(m_event, m_data); } private: const PE m_event; + const uint8_t m_data; }; diff --git a/firmware/hw_layer/adc_inputs.cpp b/firmware/hw_layer/adc_inputs.cpp index 337f8d35b3..0bfccbd935 100644 --- a/firmware/hw_layer/adc_inputs.cpp +++ b/firmware/hw_layer/adc_inputs.cpp @@ -228,9 +228,6 @@ void doSlowAdc(void) { return; } - // This event ends in the conversion callback - perfEventBegin(PE::AdcConversionSlow, 0); - adcStartConversionI(&ADC_SLOW_DEVICE, &adcgrpcfgSlow, slowAdc.samples, ADC_BUF_DEPTH_SLOW); chSysUnlockFromISR() ; @@ -265,9 +262,6 @@ static void pwmpcb_fast(PWMDriver *pwmp) { return; } - // This event ends in the conversion callback - perfEventBegin(PE::AdcConversionFast, 0); - adcStartConversionI(&ADC_FAST_DEVICE, &adcgrpcfg_fast, fastAdc.samples, ADC_BUF_DEPTH_FAST); chSysUnlockFromISR() ; @@ -472,8 +466,6 @@ static void adc_callback_slow(ADCDriver *adcp, adcsample_t *buffer, size_t n) { /* Note, only in the ADC_COMPLETE state because the ADC driver fires * an intermediate callback when the buffer is half full. */ if (adcp->state == ADC_COMPLETE) { - perfEventEnd(PE::AdcConversionSlow, 0); - slowAdc.invalidateSamplesCache(); efiAssertVoid(CUSTOM_ERR_6671, getCurrentRemainingStack() > 128, "lowstck#9c"); From d76670d94616e5ba9b5c7bd2ebeead474a06f0c4 Mon Sep 17 00:00:00 2001 From: Matthew Kennedy Date: Mon, 14 Oct 2019 23:34:12 -0700 Subject: [PATCH 3/4] trace all the things --- .../scheduling/pwm_generator_logic.cpp | 7 ++- .../controllers/trigger/rpm_calculator.cpp | 4 ++ firmware/development/perf_trace.cpp | 56 ++++++++++--------- firmware/development/perf_trace.h | 14 +++-- firmware/hw_layer/hardware.cpp | 2 +- 5 files changed, 50 insertions(+), 33 deletions(-) diff --git a/firmware/controllers/scheduling/pwm_generator_logic.cpp b/firmware/controllers/scheduling/pwm_generator_logic.cpp index 3c79edc1a7..86f2cec52e 100644 --- a/firmware/controllers/scheduling/pwm_generator_logic.cpp +++ b/firmware/controllers/scheduling/pwm_generator_logic.cpp @@ -152,6 +152,8 @@ void PwmConfig::handleCycleStart() { * @return Next time for signal toggle */ efitimeus_t PwmConfig::togglePwmState() { + ScopePerf perf(PE::PwmConfigTogglePwmState); + #if DEBUG_PWM scheduleMsg(&logger, "togglePwmState phaseIndex=%d iteration=%d", safe.phaseIndex, safe.iteration); scheduleMsg(&logger, "period=%.2f safe.period=%.2f", period, safe.periodNt); @@ -186,7 +188,10 @@ efitimeus_t PwmConfig::togglePwmState() { cbStateIndex = 1; } - stateChangeCallback(cbStateIndex, arg); + { + ScopePerf perf(PE::PwmConfigStateChangeCallback); + stateChangeCallback(cbStateIndex, arg); + } efitimeus_t nextSwitchTimeUs = getNextSwitchTimeUs(this); #if DEBUG_PWM diff --git a/firmware/controllers/trigger/rpm_calculator.cpp b/firmware/controllers/trigger/rpm_calculator.cpp index 2927627e39..20f813323d 100644 --- a/firmware/controllers/trigger/rpm_calculator.cpp +++ b/firmware/controllers/trigger/rpm_calculator.cpp @@ -18,6 +18,7 @@ #include "trigger_central.h" #include "engine_configuration.h" #include "engine_math.h" +#include "perf_trace.h" #if EFI_PROD_CODE #include "os_util.h" @@ -370,6 +371,9 @@ void initRpmCalculator(Logging *sharedLogger DECLARE_ENGINE_PARAMETER_SUFFIX) { void scheduleByAngle(int rpm, scheduling_s *timer, angle_t angle, schfunc_t callback, void *param, RpmCalculator *calc DECLARE_ENGINE_PARAMETER_SUFFIX) { UNUSED(rpm); + + ScopePerf perf(PE::ScheduleByAngle); + efiAssertVoid(CUSTOM_ANGLE_NAN, !cisnan(angle), "NaN angle?"); efiAssertVoid(CUSTOM_ERR_6634, isValidRpm(rpm), "RPM check expected"); float delayUs = calc->oneDegreeUs * angle; diff --git a/firmware/development/perf_trace.cpp b/firmware/development/perf_trace.cpp index 02f0d2e257..a83f7f46ad 100644 --- a/firmware/development/perf_trace.cpp +++ b/firmware/development/perf_trace.cpp @@ -1,24 +1,23 @@ +#include "efifeatures.h" #include "perf_trace.h" #include "efitime.h" -#include "efifeatures.h" #include "os_util.h" -#define TRACE_BUFFER_LENGTH 4096 +#define TRACE_BUFFER_LENGTH 2048 -enum class Phase : char +enum class EPhase : char { Start, End, InstantThread, InstantGlobal, - }; struct TraceEntry { PE Event; - Phase Type; + EPhase Phase; uint8_t Data; uint8_t ThreadId; uint32_t Timestamp; @@ -29,10 +28,15 @@ static_assert(sizeof(TraceEntry) == 8); static TraceEntry s_traceBuffer[TRACE_BUFFER_LENGTH]; static size_t s_nextIdx = 0; -void perfEventImpl(PE event, Phase type, uint8_t data) +static bool s_isTracing = true; + +void perfEventImpl(PE event, EPhase phase, uint8_t data) { - if constexpr (!ENABLE_PERF_TRACE) - { + if constexpr (!ENABLE_PERF_TRACE) { + return; + } + + if (!s_isTracing) { return; } @@ -45,9 +49,9 @@ void perfEventImpl(PE event, Phase type, uint8_t data) bool wasLocked = lockAnyContext(); idx = s_nextIdx++; - if (s_nextIdx >= TRACE_BUFFER_LENGTH) - { + if (s_nextIdx >= TRACE_BUFFER_LENGTH) { s_nextIdx = 0; + s_isTracing = false; } if (!wasLocked) { @@ -56,31 +60,33 @@ void perfEventImpl(PE event, Phase type, uint8_t data) } // We can safely write data out of the lock, our spot is reserved - TraceEntry& entry = s_traceBuffer[idx]; + volatile TraceEntry& entry = s_traceBuffer[idx]; entry.Event = event; - entry.Type = type; - entry.ThreadId = 0; // TODO + entry.Phase = phase; + entry.ThreadId = static_cast(SCB->ICSR & SCB_ICSR_VECTACTIVE_Msk); entry.Timestamp = timestamp; entry.Data = data; } -void perfEventBegin(PE event, uint8_t data) -{ - perfEventImpl(event, Phase::Start, data); +void perfEventBegin(PE event, uint8_t data) { + perfEventImpl(event, EPhase::Start, data); } -void perfEventEnd(PE event, uint8_t data) -{ - perfEventImpl(event, Phase::End, data); +void perfEventEnd(PE event, uint8_t data) { + perfEventImpl(event, EPhase::End, data); } -void perfEventInstantThread(PE event, uint8_t data) -{ - perfEventImpl(event, Phase::InstantThread, data); +void perfEventInstantGlobal(PE event, uint8_t data) { + perfEventImpl(event, EPhase::InstantGlobal, data); } -void perfEventInstantGlobal(PE event, uint8_t data) -{ - perfEventImpl(event, Phase::InstantGlobal, data); +size_t perfTraceEnable() { + s_isTracing = true; + + return sizeof(s_traceBuffer); +} + +const uint8_t* getTraceBuffer() { + return reinterpret_cast(s_traceBuffer); } diff --git a/firmware/development/perf_trace.h b/firmware/development/perf_trace.h index 0e5dfa9c99..758ac1b958 100644 --- a/firmware/development/perf_trace.h +++ b/firmware/development/perf_trace.h @@ -2,6 +2,7 @@ #pragma once #include +#include // Defines different events we want to trace. These can be an interval (begin -> end), or an // instant. Instants can be global, or specific to one thread. You probably don't want to use @@ -44,12 +45,13 @@ enum class PE : uint8_t { ScheduleByAngle, EventQueueExecuteCallback, PwmGeneratorCallback, - TunerStudioHandleCrcCommand + TunerStudioHandleCrcCommand, + PwmConfigTogglePwmState, + PwmConfigStateChangeCallback, }; void perfEventBegin(PE event, uint8_t data); void perfEventEnd(PE event, uint8_t data); -void perfEventInstantThread(PE event, uint8_t data); void perfEventInstantGlobal(PE event, uint8_t data); inline void perfEventBegin(PE event) { @@ -60,14 +62,14 @@ inline void perfEventEnd(PE event) { perfEventEnd(event, 0); } -inline void perfEventInstantThread(PE event) { - perfEventInstantThread(event, 0); -} - inline void perfEventInstantGlobal(PE event) { perfEventInstantGlobal(event, 0); } +// Enable one buffer's worth of perf tracing, and retrieve the buffer size in bytes +size_t perfTraceEnable(); +// Retrieve the trace buffer +const uint8_t* getTraceBuffer(); class ScopePerf { diff --git a/firmware/hw_layer/hardware.cpp b/firmware/hw_layer/hardware.cpp index 0d89f82389..ceee92ffd7 100644 --- a/firmware/hw_layer/hardware.cpp +++ b/firmware/hw_layer/hardware.cpp @@ -206,7 +206,7 @@ void adc_callback_fast(ADCDriver *adcp, adcsample_t *buffer, size_t n) { * intermediate callback when the buffer is half full. * */ if (adcp->state == ADC_COMPLETE) { - perfEventEnd(PE::AdcConversionFast, 0); + ScopePerf perf(PE::AdcCallbackFastComplete); fastAdc.invalidateSamplesCache(); From fe82bc846851cdc736663697247f06575a7b90df Mon Sep 17 00:00:00 2001 From: Matthew Kennedy Date: Mon, 14 Oct 2019 23:40:51 -0700 Subject: [PATCH 4/4] hook up TS commands --- firmware/console/binary/tunerstudio.cpp | 8 ++++++++ firmware/console/binary/tunerstudio_io.h | 4 ++++ firmware/development/perf_trace.cpp | 11 ++++++----- firmware/development/perf_trace.h | 11 +++++++++-- 4 files changed, 27 insertions(+), 7 deletions(-) diff --git a/firmware/console/binary/tunerstudio.cpp b/firmware/console/binary/tunerstudio.cpp index bf29739778..9606e439de 100644 --- a/firmware/console/binary/tunerstudio.cpp +++ b/firmware/console/binary/tunerstudio.cpp @@ -850,6 +850,14 @@ int tunerStudioHandleCrcCommand(ts_channel_s *tsChannel, char *data, int incomin } break; + case TS_PERF_TRACE_BEGIN: + perfTraceEnable(); + break; + case TS_PERF_TRACE_GET_BUFFER: + { + auto trace = perfTraceGetBuffer(); + sr5SendResponse(tsChannel, TS_CRC, trace.Buffer, trace.Size); + } #endif /* EFI_TOOTH_LOGGER */ default: tunerStudioError("ERROR: ignoring unexpected command"); diff --git a/firmware/console/binary/tunerstudio_io.h b/firmware/console/binary/tunerstudio_io.h index fe50ca6d64..41d716a749 100644 --- a/firmware/console/binary/tunerstudio_io.h +++ b/firmware/console/binary/tunerstudio_io.h @@ -73,6 +73,10 @@ typedef struct { #define TS_SET_LOGGER_MODE 'l' #define TS_GET_LOGGER_BUFFER 'L' +// Performance tracing +#define TS_PERF_TRACE_BEGIN 'r' +#define TS_PERF_TRACE_GET_BUFFER 'b' + #define TS_SINGLE_WRITE_COMMAND 'W' // 0x57 pageValueWrite #define TS_CHUNK_WRITE_COMMAND 'C' // 0x43 pageChunkWrite #define TS_BURN_COMMAND 'B' // 0x42 burnCommand diff --git a/firmware/development/perf_trace.cpp b/firmware/development/perf_trace.cpp index a83f7f46ad..71abb7af28 100644 --- a/firmware/development/perf_trace.cpp +++ b/firmware/development/perf_trace.cpp @@ -81,12 +81,13 @@ void perfEventInstantGlobal(PE event, uint8_t data) { perfEventImpl(event, EPhase::InstantGlobal, data); } -size_t perfTraceEnable() { +void perfTraceEnable() { s_isTracing = true; - - return sizeof(s_traceBuffer); } -const uint8_t* getTraceBuffer() { - return reinterpret_cast(s_traceBuffer); +const TraceBufferResult perfTraceGetBuffer() { + // stop tracing if you try to get the buffer early + s_isTracing = false; + + return {reinterpret_cast(s_traceBuffer), sizeof(s_traceBuffer)}; } diff --git a/firmware/development/perf_trace.h b/firmware/development/perf_trace.h index 758ac1b958..f0f545e0df 100644 --- a/firmware/development/perf_trace.h +++ b/firmware/development/perf_trace.h @@ -67,9 +67,16 @@ inline void perfEventInstantGlobal(PE event) { } // Enable one buffer's worth of perf tracing, and retrieve the buffer size in bytes -size_t perfTraceEnable(); +void perfTraceEnable(); + +struct TraceBufferResult +{ + const uint8_t* const Buffer; + const size_t Size; +}; + // Retrieve the trace buffer -const uint8_t* getTraceBuffer(); +const TraceBufferResult perfTraceGetBuffer(); class ScopePerf {