Skip to content

Commit

Permalink
[TECH] Mise à jour du script de parsing des logs.
Browse files Browse the repository at this point in the history 
 #285
  • Loading branch information
@pix-service-auto-merge
pix-service-auto-merge authored Jan 27, 2025
2 parents 107cd26 + 7626bcc commit d4fb5bc
Show file tree
Hide file tree
Showing 2 changed files with 71 additions and 212 deletions.
53 changes: 21 additions & 32 deletions README.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 <NOM_APPLICATION> 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 <DATE_EXECUTION>
```

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`)

Expand Down
230 changes: 50 additions & 180 deletions utils/parse-replication-logs.js
View file
Original file line number Diff line number Diff line change
@@ -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
Expand All @@ -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) {
Expand All @@ -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) {
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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);
},
);

0 comments on commit d4fb5bc

Please sign in to comment.