experiment

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

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

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

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

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<int, 16> 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 */
 
 	/**

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;

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

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

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

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:

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<uint8_t>(signal));
+
 #if EFI_TOOTH_LOGGER
 	// Log to the Tunerstudio tooth logger
 	// We want to do this before anything else as we

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

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

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

firmware/development/perf_trace.h

@@ -0,0 +1,72 @@
+
+#pragma once
+
+#include <cstdint>
+
+// 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;
+};

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

firmware/hw_layer/adc_subscription.cpp

@@ -2,6 +2,7 @@
 
 #include "adc_inputs.h"
 #include "engine.h"
+#include "perf_trace.h"
 
 #include <iterator>
 
@@ -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];
 

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