diff --git a/.gitignore b/.gitignore index 85e7a105..922f95b5 100644 --- a/.gitignore +++ b/.gitignore @@ -3,3 +3,4 @@ .idea restore.list backup.tar.gz +logs.txt diff --git a/README.md b/README.md index ce209cf3..8c393b74 100644 --- a/README.md +++ b/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 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 ` + +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` diff --git a/utils/parse-replication-logs.js b/utils/parse-replication-logs.js new file mode 100644 index 00000000..9dcccab1 --- /dev/null +++ b/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); + }, + ); +}