Tuto - Analyse de la fréquence de lancement et durée de traitement des scenarios

ngrataloup · Août 28, 2023, 7:08

Bonjour à tous,

Update : grosse mise à jour du scenario qui intègre des détections sur les temps de traitements totaux (sur la journée et unitaire des scenarios

Je vous partage un tutoriel que j’utilise de temps en temps pour analyser mes scenarios et notamment détectés les scenarios qui se lancent trop fréquemment ou sceux qui durent trop longtemps :

Rien de bien extraordinaire, mais ca permet de détecter quelques optimisations ou quelques declencheurs non optimaux ! en tout cas d’avoir une visibilité sur le nb de déclenchement et detecter des choses bizarres

Il est donc capable d’alerter sur :

Les scenarios qui se lancent trop fréquemment (alerte si dépassement d’un seuil de lancement / jour) - par défaut 300 lancements / jour, soit un peu plus d’1 toutes les 5min)
Les scenarios dont le temps de fonctionnement global sur 1 journée est supérieur à une durée en s - par défaut, un temps global de fonctionnement de plus de 30min sur la journée
Les scenarios dont de temps de fonctionnement unitaire est supérieur à une durée en s - par defaut, un temps unitaire de fonctionnement de plus de 60s

Les différents paramètres d’alerte sont les seuls éléments à paramétrer :

// critères de selection
$NbLancementJour = 300 ;  // 300 lancements par jours 
$DureeTotaleJour = 1800;  // Plus de 30min par jour --> 1800s - 30min
$DureeMoyenne = 60 ; // + de 60s par lancement unitaire

Le résultats :
Une liste des scenarios en erreur avec le groupe, le groupe, le mode, les triggers du scenario et les données d’alerte

[2024-04-25 22:28:17][SCENARIO] ┌──────────── Logs bloc code - version du 25/04/2024 22:00
[2024-04-25 22:28:20][SCENARIO] | Calcul vitesse via geoloc (67)
[2024-04-25 22:28:20][SCENARIO] |     - Groupe             : Famille
[2024-04-25 22:28:20][SCENARIO] |     - Mode               : schedule
[2024-04-25 22:28:20][SCENARIO] |     - Triggers
[2024-04-25 22:28:20][SCENARIO] |         - Planifiés      : * * * * *
[2024-04-25 22:28:20][SCENARIO] | /!\ - Occurences         : 1349 (Estimation / 24h : 1441
[2024-04-25 22:28:20][SCENARIO] |     - Durée total / jour : 1236s (Estimation / 24h : 1320s)
[2024-04-25 22:28:20][SCENARIO] |     - Durée moyenne      : 1s par lancement
[2024-04-25 22:28:20][SCENARIO] | mySQL - Analyse des process (268)
[2024-04-25 22:28:20][SCENARIO] |     - Groupe             : _Maintenance
[2024-04-25 22:28:20][SCENARIO] |     - Mode               : schedule
[2024-04-25 22:28:20][SCENARIO] |     - Triggers
[2024-04-25 22:28:20][SCENARIO] |         - Planifiés      : * * * * *
[2024-04-25 22:28:20][SCENARIO] | /!\ - Occurences         : 1349 (Estimation / 24h : 1441
[2024-04-25 22:28:20][SCENARIO] |     - Durée total / jour : 364s (Estimation / 24h : 389s)
[2024-04-25 22:28:20][SCENARIO] |     - Durée moyenne      : 0s par lancement
[2024-04-25 22:28:20][SCENARIO] | Tunnel SSH - Audit (209)
[2024-04-25 22:28:20][SCENARIO] |     - Groupe             : Gestion infra domotique
[2024-04-25 22:28:20][SCENARIO] |     - Mode               : all
[2024-04-25 22:28:20][SCENARIO] |     - Triggers
[2024-04-25 22:28:20][SCENARIO] |         - Planifiés      : * * * * *
[2024-04-25 22:28:20][SCENARIO] | /!\ - Occurences         : 1349 (Estimation / 24h : 1441
[2024-04-25 22:28:20][SCENARIO] | /!\ - Durée total        : 6789s (Estimation / 24h : 7251s)
[2024-04-25 22:28:20][SCENARIO] |     - Durée moyenne      : 5s par lancement
[2024-04-25 22:28:20][SCENARIO] | Calcul Humidité max (145)
[2024-04-25 22:28:20][SCENARIO] |     - Groupe             : VMC
[2024-04-25 22:28:20][SCENARIO] |     - Mode               : provoke
[2024-04-25 22:28:20][SCENARIO] |     - Triggers
[2024-04-25 22:28:20][SCENARIO] |         - Provoqués      : [SdB Filles][0x00158d000ad615dd][Humidité] | [SdB Parents][0x00124b0029115d84][Humidité]
[2024-04-25 22:28:20][SCENARIO] | /!\ - Occurences         : 417 (Estimation / 24h : 445
[2024-04-25 22:28:20][SCENARIO] |     - Durée total / jour : 86s (Estimation / 24h : 92s)
[2024-04-25 22:28:20][SCENARIO] |     - Durée moyenne      : 0s par lancement

Voilà …
le scenario à simplement collé dans un bloc code :

Scenario

$version = '25/04/2024 22:00';
$scenario->setLog('┌──────────── Logs bloc code - version du '.$version);

// critères de selection
$NbLancementJour = 300 ;  // 300 lancements par jours 
$DureeTotaleJour = 1800;  // Plus de 30min par jour --> 1800s - 30min
$DureeMoyenne = 60 ; // + de 60s par lancement unitaire

// constantes diverses - ne pas toucher
$directory = '/var/www/html/log/scenarioLog';
$today = date('Y-m-d');
$command = 'grep -c -E "^.('.$today.').*Début" * | sort -rn -k2 -t":"';
$estimationFactor = 1 / ((strtotime('now') - strtotime('today 00:00')) / 86400); 

chdir($directory);

function cmdName($id) {
    if (empty($id)) return "";
    try {
        $cmdHumaneName = cmd::byString($id)->getHumanName();
        return $cmdHumaneName;
    } catch (Exception $e) {
        return $id . " - Commande inconnue";
    }
}

function CalcDelai($id) {
    $today = date('Y-m-d');
    $command = "grep -E '^\[".$today.".*(-- Début :|Fin correcte du scénario)' scenario" . $id . ".log | sed -e 's/[][]//g' -e 's/-//g' -e 's/  / /g' -e 's/SCENARIO//g' | awk '{ print $1, $2, $3 }'";
    exec($command, $outputArray, $returnValue);
    
    $startTimestamp = null;
    $stopTimestamp = null;
    $durations = [];
    
    foreach ($outputArray as $line) {
        list($date, $heure, $state) = explode(' ', $line, 3);
        $timestamp = strtotime($date . ' ' . $heure);
        if ($state == 'Début') {
            $startTimestamp = $timestamp;
        } elseif ($state == 'Fin') {
            $stopTimestamp = $timestamp;
            if ($startTimestamp !== null && $stopTimestamp !== null) {
                $durations[] = $stopTimestamp - $startTimestamp;
                $startTimestamp = null;
                $stopTimestamp = null;
            }
        }
    }
    $totalDuration = array_sum($durations);
    $averageDuration = count($durations) > 0 ? $totalDuration / count($durations) : 0;
    return ['totalDuration' => $totalDuration, 'averageDuration' => $averageDuration];
}

function estimDelai( $_delais, $_count){
  $estimationFactor = 1 / ((strtotime('now') - strtotime('today 00:00')) / 86400);
  
  if ( $_count > 5 ) {
    $totalDurationEstimee = round($_delais['totalDuration'] * $estimationFactor) ;
    $countEstime = round($_count * $estimationFactor);
  } else {
    $totalDurationEstimee = $_delais['totalDuration']  ;
    $countEstime = $_count  ;
  }
  return [ 'totalDurationEstimee' => $totalDurationEstimee , 'countEstime' => $countEstime ] ;
}
  
exec($command, $outputArray, $returnValue);

$scenarioResults = [];  // Array to store results

if ($returnValue === 0) {

    foreach ($outputArray as $line) {

        list($filename, $count) = explode(':', $line, 2);
        $scenId = str_replace(["scenario", ".log"], "", $filename);
        $scen = $scenario::byId($scenId);

        $scenName = $scen->getName();
        $scenGroup = $scen->getGroup() ?: 'Aucun';
        $scenMode = $scen->getMode();
        $scenSchedule = $scen->getSchedule();
        $scenScheduleString = is_array($scenarioSchedule) ? implode(" | ", $scenSchedule) : $scenSchedule;
        $scenProvoke = array_map('cmdName', $scen->getTrigger());
        $scenProvokeString = implode(" | ", $scenProvoke);

        $delais = CalcDelai($scenId);
        $delaisEstimes = estimDelai($delais, $count);

        $scenResults[] = [
            'scenId' => $scenId,
            'scenName' => $scenName,
            'scenGroup' => $scenGroup,
            'scenMode' => $scenMode,
            'count' => $count,
            'countEstimeJour' => $delaisEstimes['countEstime'],
            'scenScheduleString' => $scenScheduleString,
            'scenProvokeString' => $scenProvokeString,
            'totalDuration' => $delais['totalDuration'],
            'totalDurationEstimeeJour' => $delaisEstimes['totalDurationEstimee'] ,
            'averageDuration' => round($delais['averageDuration'],1)
        ];
    }
} else {
    $scenResults[] = 'Erreur lors de l\'exécution de la commande.';
}

// Now, we'll use $scenarioResults to log information
foreach ($scenResults as $result) {
    if (is_array($result)) {
      if ( $result['count'] >= $NbLancementJour || $result['totalDuration'] >= $DureeTotaleJour || $result['averageDuration'] >= $DureeMoyenne ) {
        $scenario->setLog('| ' . $result['scenName'] .' ('.$result['scenId'].')');
        $scenario->setLog('|     - Groupe             : ' . $result['scenGroup']);
        $scenario->setLog('|     - Mode               : ' . $result['scenMode']);
        if ( empty($result['scenScheduleString']) && empty($result['scenProvokeString']) )  $scenario->setLog('|     - Triggers           : Aucun') ;
        else $scenario->setLog('|     - Triggers ') ;
        if ( !empty($result['scenScheduleString'])) $scenario->setLog('|         - Planifiés      : ' . $result['scenScheduleString']);
        if ( !empty($result['scenProvokeString'])) $scenario->setLog('|         - Provoqués      : ' . $result['scenProvokeString']);
        if ( $result['countEstimeJour'] >= $NbLancementJour ) $scenario->setLog('| /!\ - Occurences         : ' . $result['count'].' (Estimation / 24h : '.$result['countEstimeJour'].')');
        else $scenario->setLog('|     - Occurences         : ' . $result['count'].' (Estimation / 24h : '.$result['countEstimeJour'].')');
        if ( $result['totalDurationEstimeeJour'] >= $DureeTotaleJour ) $scenario->setLog('| /!\ - Durée total        : ' . $result['totalDuration'].'s (Estimation / 24h : '.$result['totalDurationEstimeeJour'].'s)');
        else $scenario->setLog('|     - Durée total / jour : ' . $result['totalDuration'].'s (Estimation / 24h : '.$result['totalDurationEstimeeJour'].'s)');
        if ( $result['averageDuration'] >= $DureeMoyenne ) $scenario->setLog('| /!\ - Durée moyenne      : ' . $result['averageDuration'].'s par lancement');
        else $scenario->setLog('|     - Durée moyenne      : ' . $result['averageDuration'].'s par lancement');
      }
    } else {
        $scenario->setLog($result);  // Logging the error message
    }
}

$scenario->setLog('└───────────────────────────');

Et pour terminer et pour rappel, quelques sujets en lien avec la supervision de son Jeedom :
Tuto - analyser les archives pour détecter des pbs (lenteurs / espaces disques)
Tuto - vérifier l’externalisation des backups et leur cohérence
Tuto : Monitorer son infra domotique (serveur / batterie / last communication) sur JeedomConnect
Tuto : Gestion du renouvellement d’un certificat Let’s Encrypt via scenario Jeedom

skaman85 · Août 29, 2023, 12:32

Tout d’abord, merci pour ce partage !

Si jamais tu as une idée, j’ai ce message d’erreur dans les logs :

0000|------------------------------------
0001|[2023-08-29 14:29:22][SCENARIO] -- Start : Scenario lance manuellement.
0002|[2023-08-29 14:29:22][SCENARIO] - Exécution du sous-élément de type [action] : code
0003|[2023-08-29 14:29:22][SCENARIO] Exécution d'un bloc code 
0004|[2023-08-29 14:29:22][SCENARIO] syntax error, unexpected '`'
0005|[2023-08-29 14:29:22][SCENARIO] Fin correcte du scénario

ngrataloup · Août 29, 2023, 12:49

est-ce que tu n’as pas en fin de bloc code des ``` issus d’un mauvais copier coller du bloc code ici ?
(les ``` etaient sur la même ligne que la dernière ligne et pas juste en dessous !! c’est corrigé)

Norbert

pctetra · Août 29, 2023, 12:49

bonjour

il faut vérifier la fin du bloc code enlever : ‹ ` ›
Moi c’était le problème

pctetra · Août 29, 2023, 12:55

les réponses se sont croisées, je confirme que j’avais le même problème en fin du bloc code, ça fonctionne maintenant
Et merci pour ces outils bien utiles, j’utilise déjà celui pour analyser les archives

rom.jou · Août 29, 2023, 1:00

Au top ce scénario, testé et approuvé !
J’ai 3 scénarios gourmands, mais c’est volontaire (des watchdogs qui vérifient que tout est normal).
Remarque vraiment tout mineure : serait-il possible d’afficher la durée moyenne de fonctionnement avec des décimales ? Mes scénarios « gourmands » sont tous à 0s de durée moyenne

ngrataloup · Août 29, 2023, 1:09

tu peux modifier la ligne suivante :

$scenario->setLog('|   - Durée Moyenne de fonctionnement : ' . round($averageDuration, 0) . ' s');

en remplacant le 0, par 1 ou 2
(j’ai mis à jour le bloc code en mettant 1)

Attention, si durée = 0s … je pense que la precision n’ets pas significative car je me base sur le timestamp qui est en seconde. donc un scenario qui se lance à 15:10:02,9 et qui se termine à 15:10:03,1 (soit 0,2s) … sera afficher comme 1s

Norbert

rom.jou · Août 29, 2023, 1:29

Rapide et efficace comme toujours .
Je m’énerve tout seul, j’étais focus sur la ligne juste au-dessus où tu fais le count(), mais c’est logique que ce soit à l’affichage que tu gères l’arrondi !

Et en passant à 2 décimales j’ai bien une durée plus précise.

skaman85 · Août 29, 2023, 3:30

Merci ! c’était effectivement ça !