diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 7ba3f4de..a4d74cba 100644 --- a/.pre-commit-config.yaml +++ b/.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] diff --git a/core/src/plc_app/plc_main.c b/core/src/plc_app/plc_main.c index 6fcaac7f..646e1ebf 100644 --- a/core/src/plc_app/plc_main.c +++ b/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; } diff --git a/core/src/plc_app/scan_cycle_manager.c b/core/src/plc_app/scan_cycle_manager.c index e52c8aef..78ef6534 100644 --- a/core/src/plc_app/scan_cycle_manager.c +++ b/core/src/plc_app/scan_cycle_manager.c @@ -1,23 +1,24 @@ -#include +#include +#include #include #include +#include +#include #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++; } -} \ No newline at end of file + + 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); +} diff --git a/core/src/plc_app/scan_cycle_manager.h b/core/src/plc_app/scan_cycle_manager.h index 5d78b791..c624fe2e 100644 --- a/core/src/plc_app/scan_cycle_manager.h +++ b/core/src/plc_app/scan_cycle_manager.h @@ -1,6 +1,7 @@ #ifndef SCAN_CYCLE_MANAGER_H #define SCAN_CYCLE_MANAGER_H +#include #include typedef struct @@ -24,4 +25,12 @@ typedef struct void scan_cycle_time_start(); void scan_cycle_time_end(); -#endif // SCAN_CYCLE_MANAGER_H \ No newline at end of file +// 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 diff --git a/core/src/plc_app/unix_socket.c b/core/src/plc_app/unix_socket.c index 8505c031..e9b00968 100644 --- a/core/src/plc_app/unix_socket.c +++ b/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"); diff --git a/webserver/app.py b/webserver/app.py index 95ec2db4..8d48707f 100644 --- a/webserver/app.py +++ b/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: diff --git a/webserver/runtimemanager.py b/webserver/runtimemanager.py index 979cb7b3..bcee5a32 100644 --- a/webserver/runtimemanager.py +++ b/webserver/runtimemanager.py @@ -5,9 +5,10 @@ import time import psutil -from webserver.unixserver import UnixLogServer + +from webserver.logger import get_logger from webserver.unixclient import SyncUnixClient -from webserver.logger import get_logger, LogParser +from webserver.unixserver import UnixLogServer logger, buffer = get_logger("logger", use_buffer=True) @@ -31,17 +32,13 @@ def find_running_process(self): for proc in psutil.process_iter(["pid", "exe", "cmdline"]): try: # First try to match by executable path (most reliable) - if proc.info["exe"] and os.path.samefile( - proc.info["exe"], self.runtime_path - ): + if proc.info["exe"] and os.path.samefile(proc.info["exe"], self.runtime_path): return proc # Alternatively, match by command line (fallback) cmdline = proc.info.get("cmdline") if cmdline and isinstance(cmdline, (list, tuple)) and len(cmdline) > 0: - cmdline_str = " ".join( - str(arg) for arg in cmdline if arg is not None - ) + cmdline_str = " ".join(str(arg) for arg in cmdline if arg is not None) if self.runtime_path in cmdline_str: return proc @@ -110,9 +107,7 @@ def start(self): # Start runtime process if not already running running_process = self.find_running_process() if running_process: - logger.info( - "Found existing PLC runtime process with PID %d", running_process.pid - ) + logger.info("Found existing PLC runtime process with PID %d", running_process.pid) self.process = running_process self._safe_start_log_server() self._safe_connect_runtime_socket() @@ -139,10 +134,7 @@ def is_runtime_alive(self): if self.process is None: return False if isinstance(self.process, psutil.Process): - if ( - self.process.is_running() - and self.process.status() != psutil.STATUS_ZOMBIE - ): + if self.process.is_running() and self.process.status() != psutil.STATUS_ZOMBIE: return True elif isinstance(self.process, subprocess.Popen): if self.process.poll() is None: @@ -255,6 +247,7 @@ def stop_plc(self): return "STOP:ERROR\n" except Exception as e: logger.error("Failed to stop PLC runtime (unexpected): %s", e) + return "STOP:ERROR\n" def status_plc(self): """ @@ -268,3 +261,16 @@ def status_plc(self): except Exception as e: logger.error("Failed to get PLC status (unexpected): %s", e) return "STATUS:ERROR\n" + + def stats_plc(self): + """ + Send STATS command to get timing statistics + """ + try: + return self.runtime_socket.send_and_receive("STATS\n") + except (OSError, socket.error) as e: + logger.error("Failed to get PLC stats: %s", e) + return None + except Exception as e: + logger.error("Failed to get PLC stats (unexpected): %s", e) + return None