Move timing stats from logs to status response

.pre-commit-config.yaml

@@ -5,7 +5,7 @@ repos:
       - id: pylint
         # args: [--fail-on=F,E]
         args: [
-            "--disable=C0114,C0411,C0115,C0116,C0412,E0401,W0718,R1702,R0911,R0912,R0915,R1705,W0404,W0603,W0613,W0511",
+            "--disable=C0114,C0411,C0115,C0116,C0412,E0401,W0718,R1702,R0911,R0912,R0915,R1705,W0404,W0603,W0613,W0511,R0902,R1732",
           ] # example: disable missing-docstring
         additional_dependencies:
           [flask, flask-sqlalchemy, flask_jwt_extended, werkzeug]

core/src/plc_app/plc_main.c

@@ -21,8 +21,7 @@
 
 extern PLCState plc_state;
 volatile sig_atomic_t keep_running = 1;
-extern plc_timing_stats_t plc_timing_stats;
-plugin_driver_t *plugin_driver = NULL;
+plugin_driver_t *plugin_driver     = NULL;
 extern bool print_logs;
 
 void handle_sigint(int sig)
@@ -31,40 +30,6 @@ void handle_sigint(int sig)
     keep_running = 0;
 }
 
-void *print_stats_thread(void *arg)
-{
-    (void)arg;
-    while (keep_running)
-    {
-        /*
-        if (bool_output[0][0])
-        {
-            log_debug("bool_output[0][0]: %d", *bool_output[0][0]);
-        }
-        else
-        {
-            log_debug("bool_output[0][0] is NULL");
-        }
-        */
-
-        log_info("Scan Count: %lu", plc_timing_stats.scan_count);
-        log_info("Scan Time - Min: %ld us, Max: %ld us, Avg: %ld us",
-                 plc_timing_stats.scan_time_min, plc_timing_stats.scan_time_max,
-                 plc_timing_stats.scan_time_avg);
-        log_info("Cycle Time - Min: %lu us, Max: %lu us, Avg: %ld us",
-                 plc_timing_stats.cycle_time_min, plc_timing_stats.cycle_time_max,
-                 plc_timing_stats.cycle_time_avg);
-        log_info("Cycle Latency - Min: %ld us, Max: %ld us, Avg: %ld us",
-                 plc_timing_stats.cycle_latency_min, plc_timing_stats.cycle_latency_max,
-                 plc_timing_stats.cycle_latency_avg);
-        log_info("Overruns: %lu", plc_timing_stats.overruns);
-
-        // Print every 5 seconds
-        sleep(5);
-    }
-    return NULL;
-}
-
 int main(int argc, char *argv[])
 {
     // Check for --print-logs argument
@@ -110,14 +75,6 @@ int main(int argc, char *argv[])
         return -1;
     }
 
-    // Launch status printing thread
-    pthread_t stats_thread;
-    if (pthread_create(&stats_thread, NULL, print_stats_thread, NULL) != 0)
-    {
-        log_error("Failed to create stats thread");
-        return -1;
-    }
-
     // Start PLC
     if (plc_set_state(PLC_STATE_RUNNING) != true)
     {
@@ -158,6 +115,5 @@ int main(int argc, char *argv[])
     // Cleanup
     log_info("Shutting down...");
     plc_state_manager_cleanup();
-    pthread_join(stats_thread, NULL);
     return 0;
 }

core/src/plc_app/scan_cycle_manager.c

@@ -1,23 +1,24 @@
-#include <time.h>
+#include <inttypes.h>
+#include <pthread.h>
 #include <stdint.h>
 #include <stdio.h>
+#include <string.h>
+#include <time.h>
 
 #include "scan_cycle_manager.h"
 #include "utils/utils.h"
 
-static uint64_t expected_start_us = 0;
-static uint64_t last_start_us = 0;
+static uint64_t expected_start_us  = 0;
+static uint64_t last_start_us      = 0;
+static pthread_mutex_t stats_mutex = PTHREAD_MUTEX_INITIALIZER;
 
-plc_timing_stats_t plc_timing_stats = 
-{
-    .scan_time_min = INT64_MAX,
-    .cycle_latency_min = INT64_MAX,
-    .cycle_time_avg = 0,
-    .cycle_time_min = INT64_MAX,
-    .cycle_latency_avg = 0,
-    .scan_count = 0,
-    .overruns = 0
-};
+plc_timing_stats_t plc_timing_stats = {.scan_time_min     = INT64_MAX,
+                                       .cycle_latency_min = INT64_MAX,
+                                       .cycle_time_avg    = 0,
+                                       .cycle_time_min    = INT64_MAX,
+                                       .cycle_latency_avg = 0,
+                                       .scan_count        = 0,
+                                       .overruns          = 0};
 
 static uint64_t ts_now_us(void)
 {
@@ -26,18 +27,20 @@ static uint64_t ts_now_us(void)
     return (uint64_t)ts.tv_sec * 1000000ull + ts.tv_nsec / 1000;
 }
 
-
-void scan_cycle_time_start() 
+void scan_cycle_time_start()
 {
     uint64_t now_us = ts_now_us();
 
+    pthread_mutex_lock(&stats_mutex);
+
     if (plc_timing_stats.scan_count == 0)
     {
         // Ignore full calculations for the first cycle
         expected_start_us = now_us + *ext_common_ticktime__ / 1000; // Convert ns to us
-        last_start_us = now_us;
+        last_start_us     = now_us;
         plc_timing_stats.scan_count++;
 
+        pthread_mutex_unlock(&stats_mutex);
         return;
     }
 
@@ -51,7 +54,8 @@ void scan_cycle_time_start()
     {
         plc_timing_stats.cycle_time_max = cycle_time_us;
     }
-    plc_timing_stats.cycle_time_avg += (cycle_time_us - plc_timing_stats.cycle_time_avg) / plc_timing_stats.scan_count;
+    plc_timing_stats.cycle_time_avg +=
+        (cycle_time_us - plc_timing_stats.cycle_time_avg) / plc_timing_stats.scan_count;
 
     // Calculate cycle latency
     int64_t latency_us = (int64_t)(now_us - expected_start_us);
@@ -63,18 +67,23 @@ void scan_cycle_time_start()
     {
         plc_timing_stats.cycle_latency_max = latency_us;
     }
-    plc_timing_stats.cycle_latency_avg += (latency_us - plc_timing_stats.cycle_latency_avg) / plc_timing_stats.scan_count;
+    plc_timing_stats.cycle_latency_avg +=
+        (latency_us - plc_timing_stats.cycle_latency_avg) / plc_timing_stats.scan_count;
 
     last_start_us = now_us;
     expected_start_us += *ext_common_ticktime__ / 1000; // Convert ns to us
 
     plc_timing_stats.scan_count++;
+
+    pthread_mutex_unlock(&stats_mutex);
 }
 
-void scan_cycle_time_end() 
+void scan_cycle_time_end()
 {
     uint64_t now_us = ts_now_us();
 
+    pthread_mutex_lock(&stats_mutex);
+
     // Calculate scan time
     int64_t scan_time_us = now_us - last_start_us;
     if (scan_time_us < plc_timing_stats.scan_time_min)
@@ -85,11 +94,70 @@ void scan_cycle_time_end()
     {
         plc_timing_stats.scan_time_max = scan_time_us;
     }
-    plc_timing_stats.scan_time_avg += (scan_time_us - plc_timing_stats.scan_time_avg) / plc_timing_stats.scan_count;
+    plc_timing_stats.scan_time_avg +=
+        (scan_time_us - plc_timing_stats.scan_time_avg) / plc_timing_stats.scan_count;
 
     // Check for overrun
     if (now_us > expected_start_us)
     {
         plc_timing_stats.overruns++;
     }
-}
+
+    pthread_mutex_unlock(&stats_mutex);
+}
+
+bool get_timing_stats_snapshot(plc_timing_stats_t *snapshot)
+{
+    if (snapshot == NULL)
+    {
+        return false;
+    }
+
+    pthread_mutex_lock(&stats_mutex);
+    memcpy(snapshot, &plc_timing_stats, sizeof(plc_timing_stats_t));
+    pthread_mutex_unlock(&stats_mutex);
+
+    return snapshot->scan_count > 0;
+}
+
+int format_timing_stats_response(char *buffer, size_t buffer_size)
+{
+    plc_timing_stats_t snapshot;
+    bool valid = get_timing_stats_snapshot(&snapshot);
+
+    if (!valid)
+    {
+        return snprintf(buffer, buffer_size,
+                        "STATS:{"
+                        "\"scan_count\":0,"
+                        "\"scan_time_min\":null,"
+                        "\"scan_time_max\":null,"
+                        "\"scan_time_avg\":null,"
+                        "\"cycle_time_min\":null,"
+                        "\"cycle_time_max\":null,"
+                        "\"cycle_time_avg\":null,"
+                        "\"cycle_latency_min\":null,"
+                        "\"cycle_latency_max\":null,"
+                        "\"cycle_latency_avg\":null,"
+                        "\"overruns\":0"
+                        "}\n");
+    }
+
+    return snprintf(buffer, buffer_size,
+                    "STATS:{"
+                    "\"scan_count\":%" PRId64 ","
+                    "\"scan_time_min\":%" PRId64 ","
+                    "\"scan_time_max\":%" PRId64 ","
+                    "\"scan_time_avg\":%" PRId64 ","
+                    "\"cycle_time_min\":%" PRId64 ","
+                    "\"cycle_time_max\":%" PRId64 ","
+                    "\"cycle_time_avg\":%" PRId64 ","
+                    "\"cycle_latency_min\":%" PRId64 ","
+                    "\"cycle_latency_max\":%" PRId64 ","
+                    "\"cycle_latency_avg\":%" PRId64 ","
+                    "\"overruns\":%" PRId64 "}\n",
+                    snapshot.scan_count, snapshot.scan_time_min, snapshot.scan_time_max,
+                    snapshot.scan_time_avg, snapshot.cycle_time_min, snapshot.cycle_time_max,
+                    snapshot.cycle_time_avg, snapshot.cycle_latency_min, snapshot.cycle_latency_max,
+                    snapshot.cycle_latency_avg, snapshot.overruns);
+}

core/src/plc_app/scan_cycle_manager.h

@@ -1,6 +1,7 @@
 #ifndef SCAN_CYCLE_MANAGER_H
 #define SCAN_CYCLE_MANAGER_H
 
+#include <stdbool.h>
 #include <stdint.h>
 
 typedef struct
@@ -24,4 +25,12 @@ typedef struct
 void scan_cycle_time_start();
 void scan_cycle_time_end();
 
-#endif // SCAN_CYCLE_MANAGER_H
+// Thread-safe function to get a snapshot of timing stats
+// Returns true if stats are valid (scan_count > 0), false otherwise
+bool get_timing_stats_snapshot(plc_timing_stats_t *snapshot);
+
+// Format timing stats as a response string for the STATS command
+// Returns the number of characters written (excluding null terminator)
+int format_timing_stats_response(char *buffer, size_t buffer_size);
+
+#endif // SCAN_CYCLE_MANAGER_H

core/src/plc_app/unix_socket.c

@@ -11,6 +11,7 @@
 
 #include "debug_handler.h"
 #include "plc_state_manager.h"
+#include "scan_cycle_manager.h"
 #include "unix_socket.h"
 #include "utils/log.h"
 #include "utils/utils.h"
@@ -94,6 +95,11 @@ void handle_unix_socket_commands(const char *command, char *response, size_t res
             log_error("Received START command but PLC is already RUNNING");
         }
     }
+    else if (strcmp(command, "STATS") == 0)
+    {
+        log_debug("Received STATS command");
+        format_timing_stats_response(response, response_size);
+    }
     else if (strncmp(command, "DEBUG:", 6) == 0)
     {
         log_debug("Received DEBUG command");

webserver/app.py

@@ -1,14 +1,17 @@
+import json
 import os
 import shutil
 import ssl
 import threading
 from pathlib import Path
-from typing import Callable, Final
+from typing import Callable, Final, Optional
 
 import flask
 import flask_login
+
 from webserver.credentials import CertGen
 from webserver.debug_websocket import init_debug_websocket
+from webserver.logger import get_logger
 from webserver.plcapp_management import (
     MAX_FILE_SIZE,
     BuildStatus,
@@ -26,7 +29,6 @@
     restapi_bp,
 )
 from webserver.runtimemanager import RuntimeManager
-from webserver.logger import get_logger, LogParser
 
 logger, _ = get_logger("logger", use_buffer=True)
 
@@ -80,11 +82,41 @@ def handle_compilation_status(data: dict) -> dict:
     }
 
 
+def parse_timing_stats(stats_response: Optional[str]) -> Optional[dict]:
+    """
+    Parse the STATS response from the runtime.
+    Expected format: STATS:{json_object}
+    Returns the parsed JSON object or None if parsing fails.
+    """
+    if stats_response is None:
+        return None
+
+    # Remove the STATS: prefix
+    if stats_response.startswith("STATS:"):
+        json_str = stats_response[6:].strip()
+    else:
+        return None
+
+    try:
+        return json.loads(json_str)
+    except json.JSONDecodeError:
+        return None
+
+
 def handle_status(data: dict) -> dict:
     response = runtime_manager.status_plc()
     if response is None:
         return {"status": "No response from runtime"}
-    return {"status": response}
+
+    result: dict = {"status": response}
+
+    # Fetch timing stats and include them in the response
+    stats_response = runtime_manager.stats_plc()
+    timing_stats = parse_timing_stats(stats_response)
+    if timing_stats is not None:
+        result["timing_stats"] = timing_stats
+
+    return result
 
 
 def handle_ping(data: dict) -> dict: