Refactor key life log to last seen mechanics.

Author: kareltucek

right/src/debug.h

@@ -28,11 +28,26 @@
 
 #define DEBUG_BLE_LATENCY_STATS false
 
+#include <stdint.h>
+#include "timer.h"
+
+// Last-seen timestamps of the key event pipeline stages; printed by Hid_DumpTransportState.
+typedef struct {
+    uint32_t scan;
+    uint32_t queued;
+    uint32_t forceQueued;
+    uint32_t applied;
+    uint32_t action;
+    uint32_t delivered;
+} key_life_times_t;
+
+extern key_life_times_t KeyLifeTimes;
+
 #define DEBUG_KEY_LIFE_ENABLED true
 #if DEBUG_KEY_LIFE_ENABLED
-#define DEBUG_KEY_LIFE(ARG) ARG
+#define DEBUG_KEY_LIFE(STAGE) (KeyLifeTimes.STAGE = Timer_GetCurrentTime())
 #else
-#define DEBUG_KEY_LIFE(ARG)
+#define DEBUG_KEY_LIFE(STAGE)
 #endif
 
 #ifdef __ZEPHYR__

right/src/hid/transport.cpp

@@ -61,6 +61,10 @@ extern "C" void Hid_DumpTransportState(void)
         (int)command_app::usb_handle().has_transport());
     c2usb_log("  powerMode=%d usbUp=%d usbAwake=%d\n",
         (int)CurrentPowerMode, (int)UsbState_IsTransportUp(), (int)UsbState_IsAwake());
+    uint32_t now = Timer_GetCurrentTime();
+    c2usb_log("  key life (ms ago): scan=%u queued=%u/forceQueued=%u/applied=%u action=%u delivered=%u\n",
+        now - KeyLifeTimes.scan, now - KeyLifeTimes.queued, now - KeyLifeTimes.forceQueued,
+        now - KeyLifeTimes.applied, now - KeyLifeTimes.action, now - KeyLifeTimes.delivered);
     c2usb_log("  semaphore (inFlight/retries/needsResend): kb=%d/%d/%d ctl=%d/%d/%d mouse=%d/%d/%d givenUp=%d\n",
         (int)UsbSemaphore.keyboard.inFlight, (int)UsbSemaphore.keyboard.retries, (int)UsbSemaphore.keyboard.needsResending,
         (int)UsbSemaphore.controls.inFlight, (int)UsbSemaphore.controls.retries, (int)UsbSemaphore.controls.needsResending,

right/src/main.c

@@ -116,7 +116,7 @@ void CopyRightKeystateMatrix(void)
         }
 
         if (KeyStates[SlotId_RightKeyboardHalf][targetKeyId].hardwareSwitchState != RightKeyMatrix.keyStates[keyId]) {
-            DEBUG_KEY_LIFE(LOG_INF("%s %d scan\n", Utils_KeyStateToKeyAbbreviation(Utils_KeyIdToKeyState(targetKeyId)), RightKeyMatrix.keyStates[keyId]));
+            DEBUG_KEY_LIFE(scan);
             KeyStates[SlotId_RightKeyboardHalf][targetKeyId].hardwareSwitchState = RightKeyMatrix.keyStates[keyId];
             stateChanged = true;
         }

right/src/slave_drivers/uhk_module_driver.c

@@ -173,7 +173,7 @@ void UhkModuleSlaveDriver_ProcessKeystates(uint8_t uhkModuleDriverId, uhk_module
         }
 
         if (KeyStates[slotId][targetKeyId].hardwareSwitchState != keyStatesBuffer[keyId]) {
-            DEBUG_KEY_LIFE(LOG_INF("%s %d scan\n", Utils_KeyStateToKeyAbbreviation(Utils_KeyIdToKeyState(slotId*64 + targetKeyId)), keyStatesBuffer[keyId]));
+            DEBUG_KEY_LIFE(scan);
             KeyStates[slotId][targetKeyId].hardwareSwitchState = keyStatesBuffer[keyId];
             stateChanged = true;
         }

right/src/trace.c

@@ -50,7 +50,7 @@ void Trace_Print(log_target_t additionalLogTargets, const char* reason) {
     LogTo(targetDeviceId, targetInterface, "Uptime: %d ms, Last main: %d ms ago\n", currentTime, lastMain);
 
 #ifndef __ZEPHYR__
-    Trace_PrintUhk60ReasonRegisters(targetDeviceId, targetInterface);
+    // Trace_PrintUhk60ReasonRegisters(targetDeviceId, targetInterface);
 #endif
 
     LogTo(targetDeviceId, targetInterface, "Trace:\n");

right/src/usb_report_updater.c

@@ -75,6 +75,8 @@ static key_action_cached_t actionCache[SLOT_COUNT][MAX_KEY_COUNT_PER_MODULE];
 uint32_t UsbReportUpdater_LastActivityTime;
 uint32_t UsbReportUpdater_LastMouseActivityTime;
 
+key_life_times_t KeyLifeTimes;
+
 
 
 
@@ -638,15 +640,13 @@ static void commitKeyState(key_state_t *keyState, bool active, uint8_t pressTime
 
     if (PostponerCore_EventsShouldBeQueued() || forcePostponer) {
         PostponerCore_TrackKeyEvent(keyState, active, 255);
-        if (DEBUG_KEY_LIFE_ENABLED) {
-            if (forcePostponer) {
-                LOG_INF("  %s %d force queued\n", Utils_KeyStateToKeyAbbreviation(keyState), active);
-            } else {
-                LOG_INF("  %s %d queued\n", Utils_KeyStateToKeyAbbreviation(keyState), active);
-            }
+        if (forcePostponer) {
+            DEBUG_KEY_LIFE(forceQueued);
+        } else {
+            DEBUG_KEY_LIFE(queued);
         }
     } else {
-        DEBUG_KEY_LIFE(LOG_INF("  %s %d applied\n", Utils_KeyStateToKeyAbbreviation(keyState), active));
+        DEBUG_KEY_LIFE(applied);
         KEY_TIMING(KeyTiming_RecordKeystroke(keyState, active, Timer_GetCurrentTime(), Timer_GetCurrentTime()));
         keyState->current = active;
     }
@@ -759,13 +759,8 @@ static void updateActionStates() {
             if (KeyState_NonZero(keyState)) {
                 Trace_Printc("w2");
 
-                if (DEBUG_KEY_LIFE_ENABLED) {
-                    if (KeyState_ActivatedNow(keyState)) {
-                        LOG_INF("    %s %d action\n", Utils_KeyStateToKeyAbbreviation(keyState), 1);
-                    }
-                    if (KeyState_DeactivatedNow(keyState)) {
-                        LOG_INF("    %s %d action\n", Utils_KeyStateToKeyAbbreviation(keyState), 0);
-                    }
+                if (KeyState_ActivatedNow(keyState) || KeyState_DeactivatedNow(keyState)) {
+                    DEBUG_KEY_LIFE(action);
                 }
 
                 if (KeyState_ActivatedNow(keyState)) {

right/src/usb_semaphore.c

@@ -51,8 +51,8 @@ void UsbSemaphore_Clear(void) {
 }
 
 void UsbSemaphore_Release(report_send_state_t* st) {
-    if (DEBUG_KEY_LIFE_ENABLED && st == &UsbSemaphore.keyboard) {
-        LOG_INF("      '%s' delivered\n", Utils_GetUsbReportString(ActiveKeyboardReport));
+    if (st == &UsbSemaphore.keyboard) {
+        DEBUG_KEY_LIFE(delivered);
     }
 
     st->switchActiveReport();