[FEATURE] Ajout d'un script pour parser des logs de réplication

Merge pull request #22 from 1024pix/tech-add-script-to-parse-replication-logs

.gitignore

@@ -3,3 +3,4 @@
 .idea
 restore.list
 backup.tar.gz
+logs.txt

README.md

@@ -106,3 +106,51 @@ Se connecter à la BDD de test
 
 Les tests d'intégration sortent en erreur sur CircleCI avec le message suivant 
 `Error: spawn psql ENOENT`
+
+## Parser les logs
+
+L'analyse de ce qui prend du temps est complexe sur les logs brutes s'il y a: 
+- plusieurs jobs de restauration (variable d'environnement`PG_RESTORE_JOBS`);
+- beaucoup de tables.
+
+Pour faciliter l'analyse, utilisez le script d'analyse de log. 
+
+Etapes:
+* récupérer les logs `scalingo --region osc-secnum-fr1 --app <NOM_APPLICATION> logs --lines 100000 > logs.txt`
+* déterminer la date d'exécutionau format YYYY-MM-DDDD, ex: 2020-10-13
+* exécuter `node utils/parse-replication-logs.js ./logs.txt <DATE_EXECUTION>`
+
+Exemples de résultat sur `pix-datawarehouse-production` le 22/10/2020 
+``` 
+$ node utils/parse-replication-logs.js ./logs.txt 2020-10-22                                                                                                                                                                                               1 ↵
+Durée de récupération du backup: 1h 27min 42s
+Durée de réplication: 8h 51min 17s
+Durée de l'enrichissement: 1h 39min 42s
+Durée totale: 11h 58min 41s
+FK CONSTRAINT total duration : 7h 57min 25s
+	FK CONSTRAINT schooling-registrations students_organizationid_foreign : 2h 11min 4s
+	FK CONSTRAINT competence-evaluations competence_evaluations_assessmentid_foreign : 2h 10min 41s
+	FK CONSTRAINT knowledge-elements knowledge_elements_answerid_foreign : 0h 58min 52s
+CONSTRAINT total duration : 2h 49min 60s
+	CONSTRAINT answers answers_pkey : 1h 26min 32s
+	CONSTRAINT knowledge-elements knowledge-elements_pkey : 1h 13min 36s
+	CONSTRAINT knowledge-element-snapshots knowledge-element-snapshots_pkey : 0h 2min 59s
+INDEX total duration : 10h 21min 34s
+	INDEX knowledge-elements_assessmentId_idx : 4h 16min 55s
+	INDEX knowledge_elements_userid_index : 3h 49min 46s
+	INDEX answers_assessmentid_index : 2h 7min 20s
+SEQUENCE total duration : 0h 0min 28s
+	SEQUENCE SET assessments_id_seq : 0h 0min 4s
+	SEQUENCE SET user-orga-settings_id_seq : 0h 0min 3s
+	SEQUENCE SET assessment-results_id_seq : 0h 0min 3s
+TABLE DATA total duration : 4h 8min 7s
+	TABLE DATA knowledge-element-snapshots : 1h 51min 60s
+	TABLE DATA knowledge-elements : 1h 11min 25s
+	TABLE DATA answers : 0h 46min 55s
+```
+
+S'il y a eu 
+- plusieurs exécutions le même jour
+- une exécution incomplète (pas de message `Start restore` ou `Restore done`)
+
+Alors vous obtiendrez le message suivant `TypeError: Cannot read property '0' of null`

utils/parse-replication-logs.js

@@ -0,0 +1,228 @@
+'use strict';
+const fs = require('fs');
+
+let DATE;
+const START_BACKUP = 'Backup ID:';
+const START_REPLICATION = 'Start restore';
+const START_ENRICHMENT = 'Restore done';
+
+function _printPrettyTimeElapsedBetweenTwoDates(olderDate, date) {
+  const secondsElapsed = _getSecondsElapsedBetweenTwoDates(olderDate, date);
+  return _printPrettyTimeElapsed(secondsElapsed);
+}
+
+function _printPrettyTimeElapsed(secondsElapsed) {
+  const hours = Math.trunc(secondsElapsed / 60 / 60);
+  const secondsMinusHours = secondsElapsed - (hours * 60 * 60);
+  const minutes = Math.trunc(secondsMinusHours / 60);
+  const seconds = Math.round(secondsMinusHours - (minutes * 60), 0);
+  return `${hours}h ${minutes}min ${seconds}s`;
+}
+
+function _getSecondsElapsedBetweenTwoDates(olderDate, date) {
+  return (date.getTime() - olderDate.getTime()) / 1000;
+}
+
+function _extractTimestampFromLogLine(logLine) {
+  const rx = /[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}\.[0-9]* \+[0-9]{4}/g;
+  const match = rx.exec(logLine);
+  return new Date(match[0]);
+}
+
+function _filterLinesInDate(logLines) {
+  return logLines.filter((line) => line.startsWith(DATE));
+}
+
+function _extractTimestampFromContent(logLines, content) {
+  const logLineWithTimestamp = logLines.find((line) => line.includes(content));
+  return _extractTimestampFromLogLine(logLineWithTimestamp);
+}
+
+function _editItemIfComplete(collection, key) {
+  if (collection[key].endTimestamp && collection[key].startTimestamp) {
+    collection[key] = {
+      operation: collection[key].operation,
+      elapsed: _getSecondsElapsedBetweenTwoDates(collection[key].startTimestamp, collection[key].endTimestamp),
+    };
+  }
+}
+
+function _findItemsInLogLines(logLines) {
+  const findingItems = {};
+  const rxLaunch = /.* launching item ([0-9]*) (.*)/g;
+  const rxFinished = /.* finished item ([0-9]*) .*/g;
+  for (const logLine of logLines) {
+    rxLaunch.lastIndex = 0;
+    rxFinished.lastIndex = 0;
+    const matchLaunch = rxLaunch.exec(logLine);
+    const matchFinished = rxFinished.exec(logLine);
+    if (matchLaunch) {
+      const line = matchLaunch[0];
+      const opId = matchLaunch[1].toString();
+      const op = matchLaunch[2];
+      if (!findingItems[opId]) {
+        findingItems[opId] = {};
+      }
+      findingItems[opId].startTimestamp = _extractTimestampFromLogLine(line);
+      findingItems[opId].operation = op;
+      _editItemIfComplete(findingItems, opId);
+    }
+    if (matchFinished) {
+      const line = matchFinished[0];
+      const opId = matchFinished[1].toString();
+      if (!findingItems[opId]) {
+        findingItems[opId] = {};
+      }
+      findingItems[opId].endTimestamp = _extractTimestampFromLogLine(line);
+      _editItemIfComplete(findingItems, opId);
+    }
+  }
+
+  return findingItems;
+}
+
+function _categorize(foundItems) {
+  const sequenceItems = {};
+  const tableDataItems = {};
+  const constraintItems = {};
+  const indexItems = {};
+  const fkConstraintItems = {};
+  sequenceItems.totalElapsed = 0;
+  sequenceItems.operations = [];
+  tableDataItems.totalElapsed = 0;
+  tableDataItems.operations = [];
+  constraintItems.totalElapsed = 0;
+  constraintItems.operations = [];
+  indexItems.totalElapsed = 0;
+  indexItems.operations = [];
+  fkConstraintItems.totalElapsed = 0;
+  fkConstraintItems.operations = [];
+  for (const operationInfo of Object.values(foundItems)) {
+    if (operationInfo.operation.startsWith('FK CONSTRAINT')) {
+      fkConstraintItems.totalElapsed += operationInfo.elapsed;
+      fkConstraintItems.operations.push(operationInfo);
+    }
+    if (operationInfo.operation.startsWith('CONSTRAINT')) {
+      constraintItems.totalElapsed += operationInfo.elapsed;
+      constraintItems.operations.push(operationInfo);
+    }
+    if (operationInfo.operation.startsWith('INDEX')) {
+      indexItems.totalElapsed += operationInfo.elapsed;
+      indexItems.operations.push(operationInfo);
+    }
+    if (operationInfo.operation.startsWith('SEQUENCE')) {
+      sequenceItems.totalElapsed += operationInfo.elapsed;
+      sequenceItems.operations.push(operationInfo);
+    }
+    if (operationInfo.operation.startsWith('TABLE DATA')) {
+      tableDataItems.totalElapsed += operationInfo.elapsed;
+      tableDataItems.operations.push(operationInfo);
+    }
+  }
+
+  return {
+    sequenceItems,
+    tableDataItems,
+    constraintItems,
+    indexItems,
+    fkConstraintItems,
+  };
+}
+
+function _sortByElapsed(categoryItems) {
+  categoryItems.operations = categoryItems.operations.sort(_compareOperation);
+  return categoryItems;
+}
+
+function _compareOperation(operationA, operationB) {
+  if (operationA.elapsed > operationB.elapsed) {
+    return -1;
+  } else if (operationA.elapsed < operationB.elapsed) {
+    return 1;
+  } else {
+    return 0;
+  }
+}
+
+function _categorizeAndSortByElapsed(foundItems) {
+  const {
+    sequenceItems,
+    tableDataItems,
+    constraintItems,
+    indexItems,
+    fkConstraintItems,
+  } = _categorize(foundItems);
+
+  return {
+    sequenceItems: _sortByElapsed(sequenceItems),
+    tableDataItems: _sortByElapsed(tableDataItems),
+    constraintItems: _sortByElapsed(constraintItems),
+    indexItems: _sortByElapsed(indexItems),
+    fkConstraintItems: _sortByElapsed(fkConstraintItems),
+  };
+}
+
+function _do(logLines) {
+  const foundItems = _findItemsInLogLines(logLines);
+  const {
+    sequenceItems,
+    tableDataItems,
+    constraintItems,
+    indexItems,
+    fkConstraintItems,
+  } = _categorizeAndSortByElapsed(foundItems);
+
+  console.log(`FK CONSTRAINT total duration : ${_printPrettyTimeElapsed(fkConstraintItems.totalElapsed)}`);
+  for (let i = 0; i < 3 && fkConstraintItems.operations.length > 0; ++i) {
+    console.log(`\t${fkConstraintItems.operations[i].operation} : ${_printPrettyTimeElapsed(fkConstraintItems.operations[i].elapsed)}`);
+  }
+  console.log(`CONSTRAINT total duration : ${_printPrettyTimeElapsed(constraintItems.totalElapsed)}`);
+  for (let i = 0; i < 3 && constraintItems.operations.length > 0; ++i) {
+    console.log(`\t${constraintItems.operations[i].operation} : ${_printPrettyTimeElapsed(constraintItems.operations[i].elapsed)}`);
+  }
+  console.log(`INDEX total duration : ${_printPrettyTimeElapsed(indexItems.totalElapsed)}`);
+  for (let i = 0; i < 3 && indexItems.operations.length > 0; ++i) {
+    console.log(`\t${indexItems.operations[i].operation} : ${_printPrettyTimeElapsed(indexItems.operations[i].elapsed)}`);
+  }
+  console.log(`SEQUENCE total duration : ${_printPrettyTimeElapsed(sequenceItems.totalElapsed)}`);
+  for (let i = 0; i < 3 && sequenceItems.operations.length > 0; ++i) {
+    console.log(`\t${sequenceItems.operations[i].operation} : ${_printPrettyTimeElapsed(sequenceItems.operations[i].elapsed)}`);
+  }
+  console.log(`TABLE DATA total duration : ${_printPrettyTimeElapsed(tableDataItems.totalElapsed)}`);
+  for (let i = 0; i < 3 && tableDataItems.operations.length > 0; ++i) {
+    console.log(`\t${tableDataItems.operations[i].operation} : ${_printPrettyTimeElapsed(tableDataItems.operations[i].elapsed)}`);
+  }
+}
+
+async function main() {
+  try {
+    const args = process.argv.slice(2);
+    const logfile = args[0];
+    DATE = args[1];
+    const logs = fs.readFileSync(logfile, 'utf8');
+    let logLines = logs.split('\n');
+    logLines = _filterLinesInDate(logLines);
+    const startBackupTimestamp = _extractTimestampFromContent(logLines, START_BACKUP);
+    const startReplicationTimestamp = _extractTimestampFromContent(logLines, START_REPLICATION);
+    const startEnrichmentTimestamp = _extractTimestampFromContent(logLines, START_ENRICHMENT);
+    const endTimestamp = _extractTimestampFromLogLine(logLines.slice(-1));
+    console.log(`Durée de récupération du backup: ${_printPrettyTimeElapsedBetweenTwoDates(startBackupTimestamp, startReplicationTimestamp)}`);
+    console.log(`Durée de réplication: ${_printPrettyTimeElapsedBetweenTwoDates(startReplicationTimestamp, startEnrichmentTimestamp)}`);
+    console.log(`Durée de l'enrichissement: ${_printPrettyTimeElapsedBetweenTwoDates(startEnrichmentTimestamp, endTimestamp)}`);
+    console.log(`Durée totale: ${_printPrettyTimeElapsedBetweenTwoDates(startBackupTimestamp, endTimestamp)}`);
+    _do(logLines);
+  } catch (error) {
+    console.error('\n', error);
+    process.exit(1);
+  }
+}
+
+if (require.main === module) {
+  main().then(
+    () => process.exit(0),
+    (err) => {
+      console.error(err);
+      process.exit(1);
+    },
+  );
+}