From e0f3ffc21c648dac7e0a5463aeb65479dbf687d1 Mon Sep 17 00:00:00 2001 From: acidburns Date: Tue, 17 Feb 2026 01:15:35 +0100 Subject: [PATCH] Throttle hot-path debug logging for sender stability --- src/lora_transport.cpp | 31 +++++++++---------------------- src/main.cpp | 18 +++++------------- 2 files changed, 14 insertions(+), 35 deletions(-) diff --git a/src/lora_transport.cpp b/src/lora_transport.cpp index 4463629..9ccde41 100644 --- a/src/lora_transport.cpp +++ b/src/lora_transport.cpp @@ -66,17 +66,10 @@ bool lora_send(const LoraPacket &pkt) { return true; } uint32_t t0 = 0; - uint32_t t1 = 0; - uint32_t t2 = 0; - uint32_t t3 = 0; - uint32_t t4 = 0; if (SERIAL_DEBUG_MODE) { t0 = millis(); } LoRa.idle(); - if (SERIAL_DEBUG_MODE) { - t1 = millis(); - } uint8_t buffer[1 + 2 + LORA_MAX_PAYLOAD + 2]; size_t idx = 0; buffer[idx++] = static_cast(pkt.msg_kind); @@ -95,25 +88,19 @@ bool lora_send(const LoraPacket &pkt) { buffer[idx++] = static_cast(crc & 0xFF); LoRa.beginPacket(); - if (SERIAL_DEBUG_MODE) { - t2 = millis(); - } LoRa.write(buffer, idx); - if (SERIAL_DEBUG_MODE) { - t3 = millis(); - } int result = LoRa.endPacket(false); + bool ok = result == 1; if (SERIAL_DEBUG_MODE) { - t4 = millis(); - Serial.printf("lora_tx: idle=%lums begin=%lums write=%lums end=%lums total=%lums len=%u\n", - static_cast(t1 - t0), - static_cast(t2 - t1), - static_cast(t3 - t2), - static_cast(t4 - t3), - static_cast(t4 - t0), - static_cast(idx)); + uint32_t tx_ms = millis() - t0; + if (!ok || tx_ms > 2000) { + Serial.printf("lora_tx: len=%u total=%lums ok=%u\n", + static_cast(idx), + static_cast(tx_ms), + ok ? 1U : 0U); + } } - return result == 1; + return ok; } bool lora_receive(LoraPacket &pkt, uint32_t timeout_ms) { diff --git a/src/main.cpp b/src/main.cpp index 85c13b2..3ad415d 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -106,6 +106,7 @@ static uint32_t g_sender_ack_retry_total = 0; static uint32_t g_sender_ack_rtt_last_ms = 0; static uint32_t g_sender_ack_rtt_ewma_ms = 0; static uint32_t g_sender_ack_miss_streak = 0; +static uint32_t g_last_ack_window_log_ms = 0; static RxRejectReason g_sender_rx_reject_reason = RxRejectReason::None; static uint32_t g_sender_rx_reject_log_ms = 0; static RxRejectReason g_receiver_rx_reject_reason = RxRejectReason::None; @@ -813,7 +814,7 @@ static bool send_batch_payload(const uint8_t *data, size_t len, uint32_t ts_for_ note_fault(g_sender_faults, g_sender_last_error, g_sender_last_error_utc, g_sender_last_error_ms, FaultType::LoraTx); display_set_last_error(g_sender_last_error, g_sender_last_error_utc, g_sender_last_error_ms); } - if (SERIAL_DEBUG_MODE && tx_ms > 500) { + if (SERIAL_DEBUG_MODE && (!ok || tx_ms > 2000)) { serial_debug_printf("tx: chunk %u/%u took %lums ok=%u", static_cast(i + 1), static_cast(chunk_count), static_cast(tx_ms), ok ? 1 : 0); } @@ -1345,17 +1346,7 @@ static void sender_loop() { data.valid = has_snapshot; bool appended = append_meter_sample(data, meter_ok, has_snapshot); - if (SERIAL_DEBUG_MODE) { - serial_debug_printf("sample: i=%lu ok=%u appended=%u e_kwh=%.3f p1=%.1f p2=%.1f p3=%.1f ms=%lu", - static_cast(g_build_attempts), - meter_ok ? 1U : 0U, - appended ? 1U : 0U, - static_cast(data.energy_total_kwh), - static_cast(data.phase_power_w[0]), - static_cast(data.phase_power_w[1]), - static_cast(data.phase_power_w[2]), - static_cast(now_ms)); - } + (void)appended; display_set_last_meter(data); display_set_last_read(meter_ok, data.ts_utc); } @@ -1412,7 +1403,8 @@ static void sender_loop() { if (ack_window_second_ms > 5000) { ack_window_second_ms = 5000; } - if (SERIAL_DEBUG_MODE) { + if (SERIAL_DEBUG_MODE && (g_sender_ack_miss_streak > 0 || now_ms - g_last_ack_window_log_ms >= 10000)) { + g_last_ack_window_log_ms = now_ms; serial_debug_printf("ack: rx windows=%lu/%lu airtime=%lu miss_streak=%lu", static_cast(ack_window_first_ms), static_cast(ack_window_second_ms),