Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[TECH] Mise à jour du script de parsing des logs. #285

Merged
merged 2 commits into from
Jan 27, 2025
Merged

[TECH] Mise à jour du script de parsing des logs. #285

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
119d41a
tech: update parse-replication-logs script
HEYGUL Jan 26, 2025
7626bcc
update README
HEYGUL Jan 27, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
53 changes: 21 additions & 32 deletions README.md
View file
Open in desktop
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
Open in desktop
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);
},
);