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.