Inquiétude sur la charge CPU

[domotruc]

Message initial de meute sur le forum:

Par contre maintenant le Daemon JMQTT est devenu le plus gros consommateur de CPU de ma VM, il apparaît toutes les 2 à 3 secondes en tête du TOP avec 7 à 14% et quelques fois des pointes à plus de 90%, mon graphique de charge sous ESXI oscille maintenant entre 5 et 15 %, avant ça dépassait pas les 7%. C'est le "21537" :

PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
21537 www-data  20   0  377840  42644  33116 S  12,0  0,5   2:33.97 php
919 mysql     20   0  797096 225768  17320 S   3,7  2,8  84:05.24 mysqld
31235 www-data  20   0  381928  45852  33852 S   2,0  0,6   3:33.17 php
24703 www-data  39  19       0      0      0 Z   1,3  0,0   0:00.04 php
1662 www-data  20   0  293820  32132   8616 S   0,7  0,4  17:07.56 python
1712 www-data  20   0  520172  33232   8516 S   0,7  0,4  30:22.32 python
26542 www-data  20   0  438984  27124  17988 S   0,7  0,3   0:07.96 apache2
27102 www-data  20   0  439040  28392  19244 S   0,7  0,3   0:18.98 apache2
15266 root      20   0   44940   3824   3140 R   0,3  0,0   0:00.56 top
24227 root      20   0  416672   7036   5336 S   0,3  0,1   3:00.05 ebusd
28406 www-data  20   0  512796  29264  20048 S   0,3  0,4   0:12.75 apache2
31632 www-data  20   0  513508  28424  18180 S   0,3  0,3   0:05.85 apache2

J'ai désactivé la détection auto des topics pour voir car je me dis que ça doit consommer pas mal et en plus une fois qu'on a fini sa config on en a plus besoin tout le temps mais ça change rien. Je sais pas si c'est une impression mais je me demande si ça n'a pas un impact aussi sur le process mysqld, je ne me souviens pas l'avoir vu précédemment aussi souvent dans le haut ... il y a beaucoup de requêtes faites vers la DB ?

Tu penses qu'il y aurait des pistes exploitables pour alléger le process ? En plus je pool que toutes les minutes et il n'y a pas beaucoup de broadcast et sa charge CPU varie plus vite que la fréquence des échanges donc je me dis qu'il doit fair des trucs en boucle non ?

[domotruc]

Quelques premiers éléments:

• Requêtes BD:
  • A chaque message: recherche des équipements jMQTT ayant souscrits à ce message, puis recherche de la commande associée et sauvegarde de la nouvelle valeur (plusieurs commandes dans le cas d'une payload JSON).
  • Je ne sais pas dire si c'est beaucoup, je n'ai pas vraiment de point de comparaisons.
• Côté plugin, je ne vois pas vraiment de pistes sauf dans le cas de payload JSON où je pourrais décoder directement jusqu'au niveau le plus bas et ne plus traiter les niveaux intermédiaires. Je ne sais pas dire si le gain est suffisant v.s. l'inconvénient que peut générer un changement de comportement du plugin.
• Je vois que tes messages arrivent en rafale (par exemple entre 03:26:01.930 et 03:26:02.746). Tu ne pourrais pas introduire un délai entre chaque message pour lisser la charge CPU?

[domotruc]

Réponse de meute sur le forum:

Les raffales sont des commandes donc logiquement elles font appel a une quantité de requêtes très limitée sur la BD car pas de parsing json à faire, il faut juste transmettre un topic et sa valeur et dans le cas de mon pooling c'est une valeur vide.

Il doit vraiment y avoir un truc qui pompe anormalement car chaque minute et synchro avec mon pooling que je dois faire vers ma chaudière, la charge cpu gonfle.

Sans le MQTT ma charge VM c'est une légère ondulation de moins d'1% d’amplitude autour de 5% et pourtant y en a des trucs qui tournent pendant ce temps, scenarios, des dizaines de virtuels qui regroupent des multitudes d’équipements avec des calculs et qui sont constamment rafraîchis, des dizaines d'équipements,plusieurs plugins pour divers protocoles qui communiquent constamment (Z-Wave, Hue, RFxcom, jeedouino, harmony, MiHome, Modbus ...) Et là avec le MQTT chaque minute ça tape entre 15 et 20% en même temps que mon pooling. J'ai vérifié et ebusd passe inaperçu niveau charge et Mosquito également donc c'est bien le plugin MQTT qui provoque ça.

Comme tu peux le voir sur le graph vers la moitié les pics on baissés un peu car j'ai désactivé quelques équipements MQTT que j'avais utilisé pour des tests et qui souscrivaient de toute façon à des topic déjà souscrits par ceux de prod. Donc ça a allégé un peu la charge.

Mais bon ,ca me parait beaucoup pour simplement envoyer 5 ou 6 topics sans valeur pour faire mon pooling et recevoir donc aussi 5 ou 6 topics à parser sur maxi 3 niveaux et ce 1 fois toutes les minutes.

Je ne m'y connais pas encore assez dans l'ecosystème entre Jeedom et ses plugins pour analyser vraiment ce qu'il peut se passer, mais je vais chercher un peu quand-même dans le code, ça me permettra d'en apprendre un peu plus.

PS : Ma machine virtuelle tourne dans une VM ESXI sur un NUC I5, la machine virtuelle a 4 vcores et 8Go alloués ce qui fait qu'elle en a largement sous le pied. J'ai un benchmark jeedom à 0.70 donc cette augmentation de charge ponctuelle n'est pas anodine pour finalement si peu, c'est des pointes qui prennent 2 fois plus de charge que tout le reste pour en faire 100 fois moins.

[domotruc]

Bonjour meute, Je viens de faire un test avec un traffic continu de 10 messages par seconde: le démon jMQTT prend 7 à 8% de CPU. Et bien le double avec 20 msg/s. Tes chiffres paraissent effectivement haut, je vais essayer de reproduire ton traffic pool/broadcast en le modélisant sur le simulateur MQTT que j'utilise pour valider le plugin. Stéphane

[domotruc]

Réponse de meute sur le forum

Hello,

Ne pourrais-tu pas mettre en cache mémoire dans un array la liste des topics avec leur Id jeedom et le param de parsing pour éviter de devoir scruter à chaque fois tous les eqLogic JMQTT pour retrouver a qui s'adresse chaque Topic reçu ?

Car le problème c'est qu'on a beau recevoir un seul message concernant 1 seul Topic il y a malgré tout une lecture "foreach" sur toutes les commandes de tous les équipements JMQTT qui existent pour retrouver toutes celles qui le concernent à chaque fois. Donc si on reçoit un message et qu'on a 5 équipements comprenant chacun 20 commandes ça fait mini 100 accès à la base sans compter les suivants pour le parsing et si on reçoit 5 messages à la suite l'un de l'autre c'est mini 500 accès pour juste 5 message reçus.

Je pense que le problème est là, il faudrait mettre en cache et rafraichir ce cache au démarrage du daemon et lors de l'ajout ou la suppression de commandes ou d’équipements JMQTT, le reste du temps pas besoin d'interroger la DB pour savoir quoi faire avec un Topic à la réception, l'interrogation du cache suffira à traiter le topic, le seul accès qu'il y aura c'est la ou les les écritures de la valeur reçue dans les eqLogic qui lui correspondent.

Donc la charge est surtout due au nombre de commandes qui existent, car même en ne recevant qu'un message si il existe 500 commandes JMQTT c'est là que la charge apparaît. Pour simuler il faut que tu crées un ou plusieurs équipements avec beaucoup de commandes infos dans chaque et là tu verras apparaître la charge même avec un seul message Mosquito reçu. Le problème de charge n'est pas vraiment du à la quantité et la fréquence de message reçus, évidement au plus on en reçoit au plus la charge est impactée car ca ne fait que multiplier le problème qui existe déjà sur une seul message.

Si tu avais la possibilité de faire une requête sur la DB avec le topic comme critère ça serait différent, l'utilisation d'un cache serait utile quand même mais dans une moindre mesure.

[domotruc]

Je fais bien une requête BD avec le topic comme critère, c'est pour cette raison que je mémorise le topic dans le champ LogicalId de la classe cmd, pour utiliser la méthode byEqLogicIdAndLogicalId qui permet en une requête BD de récupérer la commande de l'équipement associée au topic reçu.

Donc pour chaque message il y a 1 requête BD pour récupérer les eqLogic jMQTT et conserver ceux qui écoute le message, 1 seul la grande majorité des cas; puis une requête BD pour récupérer la cmd de cette eqLogic qui est associée au topic reçu. Dans ton exemple, pour 5 messages on a 10 requêtes BD et pas 500.

Je me pose une question: pourquoi pool tu avec une telle fréquence? Si tu insérais ne serait-ce que 500ms de délai entre chaque commande, tu lisserais grandement ta charge CPU. Peux-tu essayer?

[meute]

Autant pour moi, je n'avais pas remarqué que tu stockais le "topic" dans le LogicalId et que donc il faisait parti de la requête, je pensais que tous les logicalId de JMQTT étaient balayés

En attendant j'ai testé avec un sleep de 0.5 entre chaque topic que je dois pooler toutes les minutes pour recevoir en retour un update du topic depuis l'autre client MQTTT et le résultat est strictement le même.

Sur le graph le sleep de 0.5 a été implémenté à partir de 23H40, à +-23H46 j'ai désactivé complètement le scenario qui s'occupe du pooling et ma charge est redevenu ce qu'elle était avant, donc 4.5% avec ondulations de 1% et plus de pics.

J'ai également ensuite fais un test qui n'est pas sur le graph, j'ai stoppé l'autre client (ebusd ) donc JMQTT a continué à pooler vers le broker mais de l'autre côté personne n'était la pour recevoir et donc renvoyer les topics updatés et là les pics ont diminués presque de moitiés car aucun topic reçu en retour ensuite du coup et donc c'est cohérent. Donc l'envoi des 5 topics depuis une commande semble consommer autant que la réception des 5 topics updatés. Et éviter le burst ne change quasi rien. Par contre, je ne sais pas si la charge se produit entre Jeedom et le plugin ou entre le plugin et Mosquito , c'est peut-être l'implémentation du client MQTT utilisé par le plugin qui n'est pas optimale. Et comme dis précédemment, j'ai revérifié et Mosquito et ebusd passent inaperçus dans la charge, le seul process qui monte toutes les minutes c'est celui de JMQTT.

Sur le graphique on peut remarquer des variations car je pool toutes les minutes 5 topics, toutes les 5 minutes ce ne sont plus 5 mais 11 topics et toutes les heures ce sont 16 topics, d'où la légère différence toutes les 5 minutes et le pic à 23H00, celui là est particulièrement grand et pas proportionnel au nombre de topics poolés sur ce coup là, en général c'est pas autant je pense.

[domotruc]

Ça n'est pas normal. En testant, je suis tombé sur un autre problème... Pour que le délai soit effectif, il faut cocher certaines cases 'parallèle'.

Exemple qui marche:

2018-01-31 06:21:51.779 hw/temp/set 60
2018-01-31 06:21:52.797 hw/temp/set 60
2018-01-31 06:21:53.706 hw/temp/set 60

Exemple qui ne marche pas: Les 3 commandes sont envoyées en rafale à la fin du scénario.

2018-01-31 06:19:00.805 hw/temp/set 60
2018-01-31 06:19:00.807 hw/temp/set 60
2018-01-31 06:19:00.809 hw/temp/set 60

Ce comportement est propre au plugin jMQTT, j'ouvre une anomalie dédiée.

Stéphane

[meute]

Effectivement l'activation parallèle sur les commandes règle le "problème" de burst en fin de scenario mais fondamentalement sur la charge ça n'a rien changé, c'est strictement identique.

Au log maintenant je vois chaque commande de pool qui part vers ebusd avec "Topic/get" et le retour par update du "Topic" se fait avant que la commande de pool du topic suivant ne soit transmise donc pendant le sleep du scenario. Avant cela les 5 commandes de pool partaient en burst et le retour des 5 updates se faisait après en burst aussi forcément, mais en terme de charge ça ne change rien. Je prend toujours 5% mini à chaque fois. Alors évidement 5% de charge supplémentaire peut sembler faible mais c'est autant que la charge consommée par tout le reste, en terme de "proportion" c'est étrange. De plus c'est une charge lissée donc le pic réel est bien plus élevé, mais plus court, que sur le graphique ESXI. .

Un "top -d 1 -p 5927" sur le process du daemon JMQTT le confirme en montrant une charge à 90% qui dure 3 secondes toutes les minutes exactement au moment du début du pool des 5 topics espacés maintenant de 0.5s et pendant toute la durée donc (4x0.5s). Il ne me semble pas logique qu'autant de charge soit nécessaire pour une opération aussi "légère". Derrière ça mosquitto et ebusd doivent bosser aussi et faire probablement tout autant d'opérations voir plus pour ebusd car il doit ensuite interroger le ebus, lire le retour et updater les topics et eux restent quasi invisibles, un "Top -d 1" sur le process ebusd pendant le pool ne dépasse pas 1%.

Il doit y avoir une ou plusieurs operations consommatrices quelque part, la question c'est de savoir si elles sont justifiées ou pas.

[meute]

Dans la fonction "publishMosquitto" ne serait-il pas possible de déléguer la publication vers le daemon afin qu'elle soit faite dans son thread et de pouvoir ainsi utiliser le client Mosquitto existant pour ne pas devoir en recréé un et le connecter pour chaque publication ? Car là dans le cas d'une publication de plusieurs topics ça fait autant de création de client, de connexion et de déconnexion que de publication.

Aussi du coup pour chaque publication pendant la connexion avec le client créé pour l'occasion il y a appel de la fonction "loopforever" de Mosquitto-PHP jusqu'à la reception du callback onConnect ce qui ne doit pas être top pour la charge, non ? j'ai pas retracé 100% du code mais rien que le nom de la fonction me laisse penser qu'elle ne devrait être utilisée qu'en cas de réelle nécessité, donc à la connexion du client ... et en tout cas pas pour chaque publication, ce qui pourrait donc être évité en délégant le job d'une façon ou d'une autre au daemon.

[domotruc]

Tout à fait, c'est un des premiers points que j'ai essayé d'optimiser en reprenant le plugin. En vain. La difficulté est que le démon ne partage pas le même thread que les appels à publishMosquitto depuis l'interface desktop ou les scénarios. Ils ne peuvent donc pas partager le même client mosquitto-PHP. J'ai essayé d'obtenir de l'aide sur le forum ici, sans succès.

[domotruc]

Bonjour meute, J'ai modélisé le même traffic MQTT que le tiens. Au moment du traitement de la rafale des 5 commandes get, la charge du démon monte à ~50% (top -d 1). Par contre, le process qui envoie les 5 commandes (i.e. le scénario qui appelle publishMosquitto) n'est pas visible, sa charge semble négligeable. Si j'insère un délai d'une seconde entre chaque commande de pool, la charge tombe à 10% ce qui est logique (tes résultats sont bizarres sur ce point). Ce qui améliorerait un peu les choses, serait de ne conserver que les valeurs JSON de plus bas niveau (supprimer les niveaux intermédiaires). Dans ton cas, ça diviserait la charge par 2 en gros. Et surtout ça supprimerait des commandes qui ne servent à rien non? Qu'en penses-tu? Stéphane

[meute]

Probablement oui mais les niveaux intermédiaires ne sont pas requis pour le parsing jusqu'au niveau le plus bas ? On peut supprimer les infos des niveaux supérieurs sans risque de perturber le parsing ? J'ai pas analysé cette partie de code.

De plus si on peut le faire maintenant c'est grace à la l'issue #26 que tu as implémenté , sans ça les infos se seraient recréées automatiquement non ?

[domotruc]

Bonjour,

Dans le code, c'est faisable, tout est faisable :smiley: Je te posais la question pour être sûr que tu n'utilises pas les niveaux intermédiaires (je vais également la poser sur le forum pour être certain que ça ne perturbe personne).

Ça peut être fait indépendamment de #26. Mais #26 a introduit un fonctionnement qui est perturbant (voir nouveau commentaire dans #26) et qui disparaîtrait en effectuant systématiquement le parsing jusqu'au niveau le plus bas.

[domotruc]

Je vais abandonner #35 suite aux discussions sur le forum. Je laisse ouvert ce sujet, j'essaierai d'instrumenter le code pour comprendre où il passe du temps.

[domotruc]

Bonjour @meute, la version publiée ce jour devrait améliorer la charge CPU, si tu peux re-tester?