From 119d41a78e01b3ec949d701a108a34c25991be06 Mon Sep 17 00:00:00 2001 From: Guillaume Lagorce Date: Sun, 26 Jan 2025 11:11:23 +0100 Subject: [PATCH 1/2] tech: update parse-replication-logs script --- utils/parse-replication-logs.js | 230 +++++++------------------------- 1 file changed, 50 insertions(+), 180 deletions(-) diff --git a/utils/parse-replication-logs.js b/utils/parse-replication-logs.js index d339296a..63f152ce 100644 --- a/utils/parse-replication-logs.js +++ b/utils/parse-replication-logs.js @@ -1,10 +1,21 @@ 'use strict'; -const fs = require('fs'); +import fs from 'fs'; let DATE; const START_BACKUP = 'Start create Backup'; -const START_REPLICATION = 'Start restore'; -const START_ENRICHMENT = 'Restore done'; +const END_BACKUP = 'End create Backup'; +const START_DROP = 'Start drop Objects AndRestoreBackup'; +const END_DROP = 'End drop Objects AndRestoreBackup'; +const START_CREATE_VIEW = 'Start create view'; +const END_CREATE_VIEW = 'End create view'; +const START_RESTORE = 'Start restore'; +const END_RESTORE = 'Restore done'; +const START_INCREMENTAL = 'Start incremental replication'; +const END_INCREMENTAL = 'Incremental replication done'; +const START_LCMS = 'learningContent.run - Started'; +const END_LCMS = 'learningContent.run - Ended'; +const START_UPDATE_AUTH_METHODS = 'UPDATE \\"authentication-methods\\" - Started'; +const END_UPDATE_AUTH_METHODS = 'UPDATE \\"authentication-methods\\" - Ended'; function log(args) { // eslint-disable-next-line no-console @@ -13,7 +24,7 @@ function log(args) { function _printPrettyTimeElapsedBetweenTwoDates(olderDate, date) { const secondsElapsed = _getSecondsElapsedBetweenTwoDates(olderDate, date); - return _printPrettyTimeElapsed(secondsElapsed); + return `${_printPrettyTimeElapsed(secondsElapsed)} (de ${olderDate?.toLocaleTimeString()} à ${date?.toLocaleTimeString()})`; } function _printPrettyTimeElapsed(secondsElapsed) { @@ -25,7 +36,7 @@ function _printPrettyTimeElapsed(secondsElapsed) { } function _getSecondsElapsedBetweenTwoDates(olderDate, date) { - return (date.getTime() - olderDate.getTime()) / 1000; + return (date?.getTime() - olderDate?.getTime()) / 1000; } function _extractTimestampFromLogLine(logLine) { @@ -40,165 +51,10 @@ function _filterLinesInDate(logLines) { function _extractTimestampFromContent(logLines, content) { const logLineWithTimestamp = logLines.find((line) => line.includes(content)); + if (!logLineWithTimestamp) return undefined; 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); - - log(`FK CONSTRAINT total duration : ${_printPrettyTimeElapsed(fkConstraintItems.totalElapsed)}`); - for (let i = 0; i < 3 && fkConstraintItems.operations.length > 0; ++i) { - log(`\t${fkConstraintItems.operations[i].operation} : ${_printPrettyTimeElapsed(fkConstraintItems.operations[i].elapsed)}`); - } - log(`CONSTRAINT total duration : ${_printPrettyTimeElapsed(constraintItems.totalElapsed)}`); - for (let i = 0; i < 3 && constraintItems.operations.length > 0; ++i) { - log(`\t${constraintItems.operations[i].operation} : ${_printPrettyTimeElapsed(constraintItems.operations[i].elapsed)}`); - } - log(`INDEX total duration : ${_printPrettyTimeElapsed(indexItems.totalElapsed)}`); - for (let i = 0; i < 3 && indexItems.operations.length > 0; ++i) { - log(`\t${indexItems.operations[i].operation} : ${_printPrettyTimeElapsed(indexItems.operations[i].elapsed)}`); - } - log(`SEQUENCE total duration : ${_printPrettyTimeElapsed(sequenceItems.totalElapsed)}`); - for (let i = 0; i < 3 && sequenceItems.operations.length > 0; ++i) { - log(`\t${sequenceItems.operations[i].operation} : ${_printPrettyTimeElapsed(sequenceItems.operations[i].elapsed)}`); - } - log(`TABLE DATA total duration : ${_printPrettyTimeElapsed(tableDataItems.totalElapsed)}`); - for (let i = 0; i < 3 && tableDataItems.operations.length > 0; ++i) { - log(`\t${tableDataItems.operations[i].operation} : ${_printPrettyTimeElapsed(tableDataItems.operations[i].elapsed)}`); - } -} - async function main() { try { const args = process.argv.slice(2); @@ -207,15 +63,31 @@ async function main() { 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)); - log(`Durée de création du backup: ${_printPrettyTimeElapsedBetweenTwoDates(startBackupTimestamp, startReplicationTimestamp)}`); - log(`Durée de réplication: ${_printPrettyTimeElapsedBetweenTwoDates(startReplicationTimestamp, startEnrichmentTimestamp)}`); - log(`Durée de l'enrichissement: ${_printPrettyTimeElapsedBetweenTwoDates(startEnrichmentTimestamp, endTimestamp)}`); - log(`Durée totale: ${_printPrettyTimeElapsedBetweenTwoDates(startBackupTimestamp, endTimestamp)}`); - _do(logLines); + const endBackupTimestamp = _extractTimestampFromContent(logLines, END_BACKUP); + const startDropTimestamp = _extractTimestampFromContent(logLines, START_DROP); + const endDropTimestamp = _extractTimestampFromContent(logLines, END_DROP); + const startCreateViewTimestamp = _extractTimestampFromContent(logLines, START_CREATE_VIEW); + const endCreateViewTimestamp = _extractTimestampFromContent(logLines, END_CREATE_VIEW); + const startRestoreTimestamp = _extractTimestampFromContent(logLines, START_RESTORE); + const endRestoreTimestamp = _extractTimestampFromContent(logLines, END_RESTORE); + const startIncrementalTimestamp = _extractTimestampFromContent(logLines, START_INCREMENTAL); + const endIncrementalTimestamp = _extractTimestampFromContent(logLines, END_INCREMENTAL); + const startLearningContentTimestamp = _extractTimestampFromContent(logLines, START_LCMS); + const endLearningContentTimestamp = _extractTimestampFromContent(logLines, END_LCMS); + const startUpdateAuthMethods = _extractTimestampFromContent(logLines, START_UPDATE_AUTH_METHODS); + const endUpdateAuthMethods = _extractTimestampFromContent(logLines, END_UPDATE_AUTH_METHODS); + + log(`# Dans le fichier ${logfile}`); + log(`Durée de création du backup: ${_printPrettyTimeElapsedBetweenTwoDates(startBackupTimestamp, endBackupTimestamp)}`); + log(`Durée du drop des tables: ${_printPrettyTimeElapsedBetweenTwoDates(startDropTimestamp, endDropTimestamp)}`); + log(`Durée du restore: ${_printPrettyTimeElapsedBetweenTwoDates(startRestoreTimestamp, endRestoreTimestamp)}`); + log(`Durée de la création des vues: ${_printPrettyTimeElapsedBetweenTwoDates(startCreateViewTimestamp, endCreateViewTimestamp)}`); + log(`Durée de la mise à jour des authentication-methods: ${_printPrettyTimeElapsedBetweenTwoDates(startUpdateAuthMethods, endUpdateAuthMethods)}`); + log(`Durée de l'incrémentale: ${_printPrettyTimeElapsedBetweenTwoDates(startIncrementalTimestamp, endIncrementalTimestamp)}`); + log(`Durée du Learning Content: ${_printPrettyTimeElapsedBetweenTwoDates(startLearningContentTimestamp, endLearningContentTimestamp)}`); + log(`Durée totale: ${_printPrettyTimeElapsedBetweenTwoDates(startBackupTimestamp, endLearningContentTimestamp)}`); } catch (error) { // eslint-disable-next-line no-console console.error('\n', error); @@ -224,15 +96,13 @@ async function main() { } } -if (require.main === module) { - main().then( +main().then( + // eslint-disable-next-line n/no-process-exit + () => process.exit(0), + (err) => { + // eslint-disable-next-line no-console + console.error(err); // eslint-disable-next-line n/no-process-exit - () => process.exit(0), - (err) => { - // eslint-disable-next-line no-console - console.error(err); - // eslint-disable-next-line n/no-process-exit - process.exit(1); - }, - ); -} + process.exit(1); + }, +); From 7626bcc8f96dc5ff9a9dc3aabdb2255b0d0f1e5d Mon Sep 17 00:00:00 2001 From: Guillaume Lagorce Date: Mon, 27 Jan 2025 07:29:12 +0100 Subject: [PATCH 2/2] update README --- README.md | 53 +++++++++++++++++++++-------------------------------- 1 file changed, 21 insertions(+), 32 deletions(-) diff --git a/README.md b/README.md index 76cceb3e..0e7516d5 100644 --- a/README.md +++ b/README.md @@ -358,52 +358,41 @@ Pour faciliter l'analyse, utilisez le script d'analyse de log. Étapes : -* récupérer les logs +- récupérer les logs -``` bash +```bash scalingo --region osc-secnum-fr1 --app logs --lines 100000 > /tmp/logs.txt ``` -* déterminer la date d'exécution au format `YYYY-MM-DDDD`, par exemple : `2020-10-13` +- déterminer la date d'exécution au format `YYYY-MM-DDDD`, par exemple : `2020-10-13` -* exécuter -``` bash +- exécuter + +```bash node utils/parse-replication-logs.js ./logs.txt ``` -Exemples de résultat sur `pix-datawarehouse-production` le 22/10/2020 -``` bash +Exemples de résultat sur `pix-datawarehouse-production` le 26/01/2025 + +```bash 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 +```1 ↵ +# Dans le fichier /tmp/pix-datawarehouse-ex-production-logs.txt +Durée de création du backup: 0h 50min 20s +Durée du drop des tables: 0h 0min 2s +Durée de la création des vues: 0h 0min 0s +Durée de l'enrichissement: 0h 0min 19s +Durée de la mise à jour des authentication-methods: NaNh NaNmin NaNs +Durée du restore: 1h 44min 60s +Durée de l'incrémentale: 0h 2min 30s +Durée du Learning Content: 0h 1min 38s +Durée totale: 2h 39min 49s ``` 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`)