From 85ba2a5d3f1f321f3aed45be7ec565e55c01a77e Mon Sep 17 00:00:00 2001 From: Patrick Schurig Date: Sat, 5 Sep 2026 10:25:48 +0200 Subject: [PATCH] =?UTF-8?q?docs(upstream):=20la=20journalisation=20ne=20vo?= =?UTF-8?q?le=20pas=20de=20temps=20au=20cycle=20=E2=80=94=20mesur=C3=A9,?= =?UTF-8?q?=20pas=20d=C3=A9duit?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit L'hypothèse était que chaque qCInfo bloquait le thread de décision sur une écriture SQLite sous verrou. Mesurée sur la cible, elle ne tient pas — et deux de ses prémisses étaient fausses. CE QUI ÉTAIT FAUX. (1) `qCInfo` ne passe PAS par le LogEngine : il va au gestionnaire de messages, qui écrit sur stdout. Le chemin `Logger::log()` → `logEvent()` est celui des états et actions journalisés, déclenché par des changements d'état. Deux chemins, deux coûts. (2) Le LogEngine de la cible est LogEngineInfluxDB : `logEvent()` empile dans m_writeQueue et poste en asynchrone. Rien n'y bloque le thread appelant. Le .sqlite du rapport était celui du harnais de test, pas de la box. MESURÉ sur Pi Zero 2 W, banc croisé arm64 lié à libnymea, gestionnaire de nymea installé, stdout sur la socket journald — les conditions de nymead : · catégorie active, vers journald : 69,4 µs / ligne · catégorie active, vers /dev/null : 61,9 µs / ligne · catégorie éteinte : 0,0045 µs / ligne L'I/O n'est pas le coût : 8 µs sur 70. Le reste est du formatage. Et le cycle d'arbitrage tourne à 60 s exactement pour ~30 lignes — soit 2,1 ms par cycle, 0,0035 %. Il faudrait 143 lignes par seconde soutenues pour atteindre 1 %. Donc : ce n'était pas un argument pour le rapport, et l'y mettre sans mesurer l'aurait affaibli. Une première estimation en Python donnait 11 µs/ligne — six fois trop bas, parce qu'elle ne mesurait que l'écriture et pas le formatage. Le banc en Qt, lié à la vraie bibliothèque, était le seul moyen d'avoir le chiffre. MAIS UN DÉFAUT RÉEL EN SORT, petit et chiffré. nymeaLogMessageHandler construit `messageString` — dont un QDateTime::toString — POUR CHAQUE MESSAGE, alors qu'elle ne sert que si un fichier journal est ouvert. Mesuré isolément : 28,0 µs, soit 40 % du coût d'une ligne. Et nymead tourne sans fichier journal dans le service livré (`ExecStart=/usr/bin/nymead -n`, aucun descripteur .log ouvert) : ces 28 µs sont jetés à chaque message, sur toute installation en configuration par défaut. Correctif d'une accolade : construire messageString sous `if (s_logFile.isOpen())`. Ajouté en troisième demande du rapport, explicitement indépendante du plantage. --- docs/upstream/RAPPORT_nymea_logger_sigsegv.md | 68 +++++++++++++++++++ 1 file changed, 68 insertions(+) diff --git a/docs/upstream/RAPPORT_nymea_logger_sigsegv.md b/docs/upstream/RAPPORT_nymea_logger_sigsegv.md index b66d3ed..819a411 100644 --- a/docs/upstream/RAPPORT_nymea_logger_sigsegv.md +++ b/docs/upstream/RAPPORT_nymea_logger_sigsegv.md @@ -135,9 +135,77 @@ gdb -batch -q --core= -ex "info all-registers rdi" # > vidage. La résolution **par offset** dans les bibliothèques, elle, reste valide — leurs > identifiants correspondent, et c'est tout ce dont la conclusion a besoin. +## Second point, MESURÉ : le coût d'un `qCInfo`, et une chaîne construite pour rien + +Ouvert sur l'hypothèse que la journalisation volerait du temps à la boucle de décision. +**La mesure ne la soutient pas** — et deux prémisses étaient fausses. On le consigne quand même, +parce qu'il en reste un défaut réel, petit et chiffré. + +### Ce qui était faux dans l'hypothèse + +1. **`qCInfo` ne passe PAS par le `LogEngine`.** Il va au gestionnaire de messages + (`nymeaLogMessageHandler`), qui écrit sur `stdout` avec `fflush` par ligne. Le chemin + `Logger::log()` → `LogEngine::logEvent()` est celui des états et actions **journalisés**, + déclenché par des changements d'état, pas par les traces de code. Deux chemins, deux coûts. +2. **Le `LogEngine` de la cible ne fait pas d'I/O synchrone.** C'est `LogEngineInfluxDB` : + `logEvent()` empile dans `m_writeQueue` et `QNetworkAccessManager::post()` part en asynchrone. + Rien n'y bloque le thread appelant. (Le `.sqlite` cité plus haut est celui du harnais de test.) + +### Ce qui est mesuré, sur la cible + +Banc croisé arm64, lié à `libnymea`, gestionnaire de nymea installé, `stdout` sur la socket +journald — les conditions de `nymead`. Raspberry Pi Zero 2 W, 5 000 lignes par essai, trois essais. + +| condition | coût par ligne | +|---|---| +| catégorie ACTIVE, `stdout` → journald | **69,4 µs** (68,6 / 68,9 / 76,5) | +| catégorie ACTIVE, `stdout` → `/dev/null` | **61,9 µs** (61,7 / 62,3 / 61,7) | +| catégorie ÉTEINTE | **0,0045 µs** | + +**L'I/O n'est pas le coût : 8 µs sur 70.** Le reste est du formatage, dans le thread appelant. +Et l'extinction de catégorie court-circuite avant tout formatage — c'est gratuit, Qt fait ce +qu'il faut. + +**Rapporté au cycle** : la boucle d'arbitrage tourne à **60 s** exactement, pour ~30 lignes par +cycle (915 lignes sur 30 min relevées au journal). Soit **2,1 ms par cycle de 60 s — 0,0035 %.** +Pour atteindre 1 % du cycle, il faudrait ~8 600 lignes par cycle, soit 143 lignes par seconde +soutenues. + +> **Conclusion : la journalisation ne vole pas de temps à la boucle de décision sur cette cible.** +> Ce n'était pas un argument pour ce rapport, et l'y mettre sans mesurer l'aurait affaibli. + +### Le défaut qui reste, lui, est réel + +`nymeaLogMessageHandler` construit `messageString` — dont +`QDateTime::currentDateTime().toString("yyyy.MM.dd hh:mm:ss.zzz")` — **pour chaque message**, +alors que cette chaîne ne sert **que si un fichier journal est ouvert** : + +```cpp +QMutexLocker locker(&s_loggerMutex); +if (s_logFile.isOpen()) { // ← seul usage de messageString + QTextStream textStream(&s_logFile); + textStream << messageString << '\n'; +} +``` + +**Mesuré isolément sur la même cible : 28,0 µs par appel** (31,9 / 27,9 / 27,9), soit **40 % du +coût d'une ligne**. Et `nymead` tourne **sans fichier journal** dans le service livré +(`ExecStart=/usr/bin/nymead -n`, aucun descripteur `.log` ouvert) : ces 28 µs sont **jetés à +chaque message**, sur toutes les installations en configuration par défaut. + +Correctif : ne construire `messageString` que sous `if (s_logFile.isOpen())`. Le `switch` sert +déjà à deux fins — écrire sur `stdout` et fabriquer la chaîne ; seule la seconde est +conditionnelle. + +> Ce n'est pas une urgence : 28 µs × 30 lignes = 0,8 ms par cycle de 60 s. C'est signalé parce +> que c'est **gratuit à corriger** et que le coût est payé par tout le monde, tout le temps. + ## Ce qui est demandé 1. Confirmer le correctif contre la branche 1.15.x, et vérifier les deux tables jumelles (`m_stateLoggers`, `m_eventLoggers`). 2. Décider si la connexion doit prendre `thing` ou `info` pour contexte plutôt que `this` — ce qui fermerait la fenêtre au lieu de la rendre inoffensive. +3. **Indépendant du plantage** : conditionner la construction de `messageString` à + `s_logFile.isOpen()` dans `nymeaLogMessageHandler` — 28 µs par message rendus à toute + installation sans fichier journal, soit la configuration livrée.