docs(upstream): la journalisation ne vole pas de temps au cycle — mesuré, pas déduit
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.
This commit is contained in:
parent
9eef60fc35
commit
85ba2a5d3f
@ -135,9 +135,77 @@ gdb -batch -q --core=<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.
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user