Overdwell at times around syncloss while cranking #6349

hopefully bugfix - do not start dwell in case of out-of-order

firmware/controllers/algo/event_registry.h

@@ -45,6 +45,10 @@ public:
 	scheduling_s dwellStartTimer;
 	AngleBasedEvent sparkEvent;
 
+#if EFI_UNIT_TEST
+  bool bailedOnDwell = false;
+#endif
+
 	scheduling_s trailingSparkCharge;
 	scheduling_s trailingSparkFire;
 

firmware/controllers/engine_cycle/spark_logic.cpp

@@ -42,7 +42,11 @@ static void fireSparkBySettingPinLow(IgnitionEvent *event, IgnitionOutputPin *ou
 	output->signalFallSparkId = event->sparkCounter;
 
 	if (!output->currentLogicValue && !event->wasSparkLimited) {
+#if SPARK_EXTREME_LOGGING
+		printf("out-of-order coil off %s", output->getName());
+#endif /* SPARK_EXTREME_LOGGING */
 		warning(ObdCode::CUSTOM_OUT_OF_ORDER_COIL, "out-of-order coil off %s", output->getName());
+		// todo: drop this year 2016 outOfOrder in favor of 2024 [tag] #6349 handling?
 		output->outOfOrder = true;
 	}
 	output->setLow();
@@ -271,7 +275,7 @@ if (engineConfiguration->debugMode == DBG_DWELL_METRIC) {
 	engine->onSparkFireKnockSense(event->coilIndex, nowNt);
 }
 
-static void startDwellByTurningSparkPinHigh(IgnitionEvent *event, IgnitionOutputPin *output) {
+static bool startDwellByTurningSparkPinHigh(IgnitionEvent *event, IgnitionOutputPin *output) {
 	// todo: no reason for this to be disabled in unit_test mode?!
 #if ! EFI_UNIT_TEST
 
@@ -290,15 +294,35 @@ static void startDwellByTurningSparkPinHigh(IgnitionEvent *event, IgnitionOutput
 			output->currentLogicValue, output->outOfOrder, event->sparkCounter);
 #endif /* SPARK_EXTREME_LOGGING */
 
+		if (output->signalFallSparkId >= event->sparkCounter) {
+		  /**
+		   * fact: we schedule both start of dwell and spark firing using a combination of time and trigger event domain
+		   * in case of bad/noisy signal we can get unexpected trigger events and a small time delay for spark firing before
+		   * we even start dwell if it scheduled with a longer time-only delay with fewer trigger events
+		   *
+		   * here we are detecting such out-of-order processing and choose the safer route of not even starting dwell
+		   * [tag] #6349
+		   */
+
+#if SPARK_EXTREME_LOGGING
+			efiPrintf("[%s] bail spark dwell\n", output->getName());
+#endif /* SPARK_EXTREME_LOGGING */
+			// let's save this coil if things do not look right
+			engine->engineState.sparkOutOfOrderCounter++;
+			return true;
+		}
+
 	if (output->outOfOrder) {
 		output->outOfOrder = false;
 		if (output->signalFallSparkId == event->sparkCounter) {
 			// let's save this coil if things do not look right
-			return;
+			engine->engineState.sparkOutOfOrderCounter++;
+			return true;
 		}
 	}
 
 	output->setHigh();
+	return false;
 }
 
 void turnSparkPinHighStartCharging(IgnitionEvent *event) {
@@ -306,23 +330,33 @@ void turnSparkPinHighStartCharging(IgnitionEvent *event) {
 
 	efitick_t nowNt = getTimeNowNt();
 
-#if EFI_UNIT_TEST
-	if (engine->onIgnitionEvent) {
-		engine->onIgnitionEvent(event, true);
-	}
-#endif
-
-#if EFI_TOOTH_LOGGER
-	LogTriggerCoilState(nowNt, true);
-#endif // EFI_TOOTH_LOGGER
-
+  bool skippedDwellDueToTriggerNoised = false;
 	for (int i = 0; i< MAX_OUTPUTS_FOR_IGNITION;i++) {
 		IgnitionOutputPin *output = event->outputs[i];
 		if (output != NULL) {
-			startDwellByTurningSparkPinHigh(event, output);
+			skippedDwellDueToTriggerNoised |= startDwellByTurningSparkPinHigh(event, output);
 		}
 	}
 
+#if EFI_UNIT_TEST
+  event->bailedOnDwell = skippedDwellDueToTriggerNoised;
+#endif
+
+
+  if (!skippedDwellDueToTriggerNoised) {
+
+#if EFI_UNIT_TEST
+  	if (engine->onIgnitionEvent) {
+  		engine->onIgnitionEvent(event, true);
+	  }
+#endif
+
+#if EFI_TOOTH_LOGGER
+	  LogTriggerCoilState(nowNt, true);
+#endif // EFI_TOOTH_LOGGER
+  }
+
+
 	if (engineConfiguration->enableTrailingSparks) {
 		IgnitionOutputPin *output = &enginePins.trailingCoils[event->coilIndex];
 		// Trailing sparks are enabled - schedule an event for the corresponding trailing coil

unit_tests/tests/trigger/test_real_4g93.cpp

@@ -134,5 +134,5 @@ TEST(real4g93, crankingCamOnly) {
 	ASSERT_TRUE(gotRpm);
 	ASSERT_TRUE(gotSync);
 
-	ASSERT_EQ(0, eth.recentWarnings()->getCount());
+	ASSERT_EQ(1, eth.recentWarnings()->getCount());
 }

unit_tests/tests/trigger/test_real_noisy_trigger.cpp

@@ -73,5 +73,5 @@ TEST(RealNoisyTrigger, AvoidOverdwell3NoInstant) {
 }
 
 TEST(RealNoisyTrigger, AvoidOverdwell3WithInstant) {
-//	testNoOverdwell("tests/trigger/resources/noisy-trigger-3.csv", true);
+	testNoOverdwell("tests/trigger/resources/noisy-trigger-3.csv", true);
 }

unit_tests/tests/trigger/test_trigger_decoder.cpp

@@ -1036,6 +1036,7 @@ TEST(big, testSparkReverseOrderBug319) {
 	ASSERT_EQ( 8,  engine->executor.size()) << "testSparkReverseOrderBug319: queue size";
 	eth.executeActions();
 	printf("***************************************************\r\n");
+	ASSERT_EQ( 0,  engine->engineState.sparkOutOfOrderCounter) << "out-of-order #1";
 
 
 	eth.fireRise(20);
@@ -1047,13 +1048,12 @@ TEST(big, testSparkReverseOrderBug319) {
 	eth.fireFall(0.1); // executing new signal too early
 	eth.executeActions();
 
-	ASSERT_EQ( 1,  enginePins.coils[3].outOfOrder) << "out-of-order #1";
 
 
 	eth.moveTimeForwardUs(MS2US(200)); // moving time forward to execute all pending actions
 	eth.executeActions();
 
-	ASSERT_EQ( 0,  enginePins.coils[3].outOfOrder) << "out-of-order #2";
+	ASSERT_EQ( 1,  engine->engineState.sparkOutOfOrderCounter) << "out-of-order #2";
 
 	printf("*************************************************** now let's have a good engine cycle and confirm things work\r\n");
 
@@ -1063,12 +1063,12 @@ TEST(big, testSparkReverseOrderBug319) {
 
 	ASSERT_EQ( 545,  round(Sensor::getOrZero(SensorType::Rpm))) << "RPM#2";
 
-	ASSERT_EQ( 0,  enginePins.coils[3].outOfOrder) << "out-of-order #3";
+	ASSERT_EQ( 1,  engine->engineState.sparkOutOfOrderCounter) << "out-of-order #3";
 
 
 	eth.fireFall(20);
 	eth.executeActions();
-	ASSERT_EQ( 1,  enginePins.coils[3].outOfOrder) << "out-of-order #4";
+	ASSERT_EQ( 1,  engine->engineState.sparkOutOfOrderCounter) << "out-of-order #4";
 
 	printf("*************************************************** (rpm is back) now let's have a good engine cycle and confirm things work\r\n");
 
@@ -1077,12 +1077,12 @@ TEST(big, testSparkReverseOrderBug319) {
 
 	ASSERT_EQ( 3000,  round(Sensor::getOrZero(SensorType::Rpm))) << "RPM#3";
 
-	ASSERT_EQ( 1,  enginePins.coils[3].outOfOrder) << "out-of-order #5 on c4";
+	ASSERT_EQ( 1,  engine->engineState.sparkOutOfOrderCounter) << "out-of-order #5 on c4";
 
 
 	eth.fireFall(20);
 	eth.executeActions();
-	ASSERT_EQ( 1,  enginePins.coils[3].outOfOrder) << "out-of-order #6 on c4";
+	ASSERT_EQ( 1,  engine->engineState.sparkOutOfOrderCounter) << "out-of-order #6 on c4";
 
 	printf("*************************************************** (rpm is back 2) now let's have a good engine cycle and confirm things work\r\n");
 
@@ -1091,12 +1091,12 @@ TEST(big, testSparkReverseOrderBug319) {
 
 	ASSERT_EQ( 3000,  round(Sensor::getOrZero(SensorType::Rpm))) << "RPM#4";
 
-	ASSERT_EQ( 1,  enginePins.coils[3].outOfOrder) << "out-of-order #7";
+	ASSERT_EQ( 1,  engine->engineState.sparkOutOfOrderCounter) << "out-of-order #7";
 
 
 	eth.fireFall(20);
 	eth.executeActions();
-	ASSERT_EQ( 0,  enginePins.coils[3].outOfOrder) << "out-of-order #8";
+	ASSERT_EQ( 1,  engine->engineState.sparkOutOfOrderCounter) << "out-of-order #8";
 	ASSERT_EQ( 2,  unitTestWarningCodeState.recentWarnings.getCount()) << "warningCounter#SparkReverseOrderBug319";
 	ASSERT_EQ(ObdCode::CUSTOM_DWELL_TOO_LONG, unitTestWarningCodeState.recentWarnings.get(0).Code) << "warning @0";
 	ASSERT_EQ(ObdCode::CUSTOM_OUT_OF_ORDER_COIL, unitTestWarningCodeState.recentWarnings.get(1).Code);