profile all the things

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__ */

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();                                                           \
 }
 
 /**

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++;
 

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;

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 ?

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
 	/**

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);

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
 	 */

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
+
+		{
+			ScopePerf perf2(PE::EventQueueExecuteCallback);
 			current->callback(current->param);
+		}
+
 		// even with overflow it's safe to subtract here
 		lastEventCallbackDuration = getTimeNowLowerNt() - before;
 		if (lastEventCallbackDuration > maxEventCallbackDuration)

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");
 

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;
 }
 

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<uint16_t>(this->brainPin));
-
 #else /* EFI_PROD_CODE */
 	setPinValue(this, eValue, logicValue);
 #endif /* EFI_PROD_CODE */

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();

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;

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 */

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;
 };

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");