Browse Source

feat: better logging for jobs

Signed-off-by: mertmit <mertmit99@gmail.com>
pull/5621/head
mertmit 1 year ago
parent
commit
e68d2d376c
  1. 73
      packages/nocodb/src/modules/jobs/export-import/duplicate.processor.ts
  2. 27
      packages/nocodb/src/modules/jobs/export-import/export.service.ts
  3. 81
      packages/nocodb/src/modules/jobs/export-import/import.service.ts
  4. 23
      packages/nocodb/src/modules/jobs/helpers.ts

73
packages/nocodb/src/modules/jobs/export-import/duplicate.processor.ts

@ -3,41 +3,22 @@ import { Process, Processor } from '@nestjs/bull';
import { Job } from 'bull';
import papaparse from 'papaparse';
import { UITypes } from 'nocodb-sdk';
import { Logger } from '@nestjs/common';
import { Base, Column, Model, Project } from '../../../models';
import { ProjectsService } from '../../../services/projects.service';
import { findWithIdentifier } from '../../../helpers/exportImportHelpers';
import { BulkDataAliasService } from '../../../services/bulk-data-alias.service';
import { JOBS_QUEUE, JobTypes } from '../../../interface/Jobs';
import { elapsedTime, initTime } from '../helpers';
import { ExportService } from './export.service';
import { ImportService } from './import.service';
import type { LinkToAnotherRecordColumn } from '../../../models';
const DEBUG = false;
const debugLog = function (...args: any[]) {
if (DEBUG) {
console.log(...args);
}
};
const initTime = function () {
return {
hrTime: process.hrtime(),
};
};
const elapsedTime = function (
time: { hrTime: [number, number] },
label?: string,
) {
const elapsedS = process.hrtime(time.hrTime)[0].toFixed(3);
const elapsedMs = process.hrtime(time.hrTime)[1] / 1000000;
if (label) debugLog(`${label}: ${elapsedS}s ${elapsedMs}ms`);
time.hrTime = process.hrtime();
};
@Processor(JOBS_QUEUE)
export class DuplicateProcessor {
private readonly logger = new Logger(
`${JOBS_QUEUE}:${DuplicateProcessor.name}`,
);
constructor(
private readonly exportService: ExportService,
private readonly importService: ImportService,
@ -77,7 +58,11 @@ export class DuplicateProcessor {
excludeHooks,
});
elapsedTime(hrTime, 'serializeModels');
elapsedTime(
hrTime,
`serialize models schema for ${base.project_id}::${base.id}`,
'duplicateBase',
);
if (!exportedModels) {
throw new Error(`Export failed for base '${base.id}'`);
@ -95,7 +80,7 @@ export class DuplicateProcessor {
req: req,
});
elapsedTime(hrTime, 'importModels');
elapsedTime(hrTime, `import models schema`, 'duplicateBase');
if (!idMap) {
throw new Error(`Import failed for base '${base.id}'`);
@ -166,7 +151,11 @@ export class DuplicateProcessor {
})
)[0];
elapsedTime(hrTime, 'serializeModel');
elapsedTime(
hrTime,
`serialize model schema for ${modelId}`,
'duplicateModel',
);
if (!exportedModel) {
throw new Error(`Export failed for base '${base.id}'`);
@ -184,7 +173,7 @@ export class DuplicateProcessor {
externalModels: relatedModels,
});
elapsedTime(hrTime, 'reimportModelSchema');
elapsedTime(hrTime, 'import model schema', 'duplicateModel');
if (!idMap) {
throw new Error(`Import failed for model '${modelId}'`);
@ -220,7 +209,7 @@ export class DuplicateProcessor {
externalModels: relatedModels,
});
elapsedTime(hrTime, 'reimportModelData');
elapsedTime(hrTime, 'import model data', 'duplicateModel');
}
return await Model.get(findWithIdentifier(idMap, sourceModel.id));
@ -274,7 +263,6 @@ export class DuplicateProcessor {
destProject,
destBase,
destModel: model,
debugLog,
});
handledLinks = await this.importService.importLinkFromCsvStream({
@ -283,10 +271,13 @@ export class DuplicateProcessor {
destProject,
destBase,
handledLinks,
debugLog,
});
elapsedTime(hrTime, model.title);
elapsedTime(
hrTime,
`import data and links for ${model.title}`,
'importModelsData',
);
}
// update external models (has bt to this model)
@ -341,18 +332,18 @@ export class DuplicateProcessor {
headers.push(childCol.column_name);
} else {
headers.push(null);
debugLog('child column not found', id);
this.logger.error(`child column not found (${id})`);
}
} else {
headers.push(col.column_name);
}
} else {
headers.push(null);
debugLog('column not found', id);
this.logger.error(`column not found (${id})`);
}
} else {
headers.push(null);
debugLog('header not found', header);
this.logger.error(`id not found (${header})`);
}
}
parser.resume();
@ -378,7 +369,7 @@ export class DuplicateProcessor {
raw: true,
});
} catch (e) {
console.log(e);
this.logger.error(e);
}
chunk = [];
parser.resume();
@ -397,7 +388,7 @@ export class DuplicateProcessor {
raw: true,
});
} catch (e) {
console.log(e);
this.logger.error(e);
}
chunk = [];
}
@ -406,7 +397,11 @@ export class DuplicateProcessor {
});
});
elapsedTime(hrTime, `external bt ${model.title}`);
elapsedTime(
hrTime,
`map existing links to ${model.title}`,
'importModelsData',
);
}
}
}

27
packages/nocodb/src/modules/jobs/export-import/export.service.ts

@ -1,7 +1,7 @@
import { Readable } from 'stream';
import { UITypes, ViewTypes } from 'nocodb-sdk';
import { unparse } from 'papaparse';
import { Injectable } from '@nestjs/common';
import { Injectable, Logger } from '@nestjs/common';
import NcConnectionMgrv2 from '../../../utils/common/NcConnectionMgrv2';
import { getViewAndModelByAliasOrId } from '../../../modules/datas/helpers';
import {
@ -12,11 +12,14 @@ import NcPluginMgrv2 from '../../../helpers/NcPluginMgrv2';
import { NcError } from '../../../helpers/catchError';
import { Base, Hook, Model, Project } from '../../../models';
import { DatasService } from '../../../services/datas.service';
import { elapsedTime, initTime } from '../helpers';
import type { BaseModelSqlv2 } from '../../../db/BaseModelSqlv2';
import type { LinkToAnotherRecordColumn, View } from '../../../models';
import type { View } from '../../../models';
@Injectable()
export class ExportService {
private readonly logger = new Logger(ExportService.name);
constructor(private datasService: DatasService) {}
async serializeModels(param: {
@ -422,7 +425,7 @@ export class ExportService {
true,
);
} catch (e) {
console.error(e);
this.logger.error(e);
throw e;
}
@ -488,7 +491,7 @@ export class ExportService {
true,
);
} catch (e) {
console.error(e);
this.logger.error(e);
throw e;
}
@ -597,6 +600,8 @@ export class ExportService {
}
async exportBase(param: { path: string; baseId: string }) {
const hrTime = initTime();
const base = await Base.get(param.baseId);
if (!base)
@ -613,6 +618,12 @@ export class ExportService {
modelIds: models.map((m) => m.id),
});
elapsedTime(
hrTime,
`serialize models for ${base.project_id}::${base.id}`,
'exportBase',
);
const exportData = {
id: `${project.id}::${base.id}`,
models: exportedModels,
@ -669,7 +680,7 @@ export class ExportService {
});
linkStream.on('error', (e) => {
console.error(e);
this.logger.error(e);
resolve(null);
});
});
@ -693,6 +704,12 @@ export class ExportService {
combinedLinkStream.push(null);
await uploadLinkPromise;
elapsedTime(
hrTime,
`export base ${base.project_id}::${base.id}`,
'exportBase',
);
} catch (e) {
throw NcError.badRequest(e);
}

81
packages/nocodb/src/modules/jobs/export-import/import.service.ts

@ -1,5 +1,5 @@
import { UITypes, ViewTypes } from 'nocodb-sdk';
import { Injectable } from '@nestjs/common';
import { Injectable, Logger } from '@nestjs/common';
import papaparse from 'papaparse';
import {
findWithIdentifier,
@ -27,12 +27,15 @@ import { HooksService } from '../../../services/hooks.service';
import { ViewsService } from '../../../services/views.service';
import NcPluginMgrv2 from '../../../helpers/NcPluginMgrv2';
import { BulkDataAliasService } from '../../../services/bulk-data-alias.service';
import { elapsedTime, initTime } from '../helpers';
import type { Readable } from 'stream';
import type { ViewCreateReqType } from 'nocodb-sdk';
import type { LinkToAnotherRecordColumn, User, View } from '../../../models';
@Injectable()
export class ImportService {
private readonly logger = new Logger(ImportService.name);
constructor(
private tablesService: TablesService,
private columnsService: ColumnsService,
@ -60,6 +63,8 @@ export class ImportService {
req: any;
externalModels?: Model[];
}) {
const hrTime = initTime();
// structured id to db id
const idMap = new Map<string, string>();
const externalIdMap = new Map<string, string>();
@ -112,6 +117,8 @@ export class ImportService {
}
}
elapsedTime(hrTime, 'generate id map for external models', 'importModels');
// create tables with static columns
for (const data of param.data) {
const modelData = data.model;
@ -149,9 +156,11 @@ export class ImportService {
tableReferences.set(modelData.id, table);
}
elapsedTime(hrTime, 'create tables with static columns', 'importModels');
const referencedColumnSet = [];
// create columns with reference to other columns
// create LTAR columns
for (const data of param.data) {
const modelData = data.model;
const table = tableReferences.get(modelData.id);
@ -160,7 +169,6 @@ export class ImportService {
(a) => a.uidt === UITypes.LinkToAnotherRecord,
);
// create columns with reference to other columns
for (const col of linkedColumnSet) {
if (col.colOptions) {
const colOptions = col.colOptions;
@ -702,6 +710,8 @@ export class ImportService {
);
}
elapsedTime(hrTime, 'create LTAR columns', 'importModels');
const sortedReferencedColumnSet = [];
// sort referenced columns to avoid referencing before creation
@ -815,6 +825,8 @@ export class ImportService {
}
}
elapsedTime(hrTime, 'create referenced columns', 'importModels');
// create views
for (const data of param.data) {
const modelData = data.model;
@ -931,6 +943,8 @@ export class ImportService {
}
}
elapsedTime(hrTime, 'create views', 'importModels');
// create hooks
for (const data of param.data) {
if (!data?.hooks) break;
@ -973,6 +987,8 @@ export class ImportService {
}
}
elapsedTime(hrTime, 'create hooks', 'importModels');
return idMap;
}
@ -1115,16 +1131,10 @@ export class ImportService {
file?: any;
};
req: any;
debug?: boolean;
}) {
const { user, projectId, baseId, src, req } = param;
const debug = param?.debug === true;
const hrTime = initTime();
const debugLog = (...args: any[]) => {
if (!debug) return;
console.log(...args);
};
const { user, projectId, baseId, src, req } = param;
const destProject = await Project.get(projectId);
const destBase = await Base.get(baseId);
@ -1133,15 +1143,6 @@ export class ImportService {
throw NcError.badRequest('Project or Base not found');
}
let start = process.hrtime();
const elapsedTime = function (label?: string) {
const elapsedS = process.hrtime(start)[0].toFixed(3);
const elapsedMs = process.hrtime(start)[1] / 1000000;
if (label) debugLog(`${label}: ${elapsedS}s ${elapsedMs}ms`);
start = process.hrtime();
};
switch (src.type) {
case 'local': {
const path = src.path.replace(/\/$/, '');
@ -1153,7 +1154,7 @@ export class ImportService {
await storageAdapter.fileRead(`${path}/schema.json`),
);
elapsedTime('read schema');
elapsedTime(hrTime, 'read schema from file', 'importBase');
// store fk_mm_model_id (mm) to link once
let handledLinks = [];
@ -1166,7 +1167,7 @@ export class ImportService {
req,
});
elapsedTime('import models');
elapsedTime(hrTime, 'import models schema', 'importBase');
if (idMap) {
const files = await (storageAdapter as any).getDirectoryList(
@ -1189,7 +1190,7 @@ export class ImportService {
const model = await Model.get(modelId);
debugLog(`Importing ${model.title}...`);
this.logger.debug(`Importing ${model.title}...`);
await this.importDataFromCsvStream({
idMap,
@ -1197,14 +1198,17 @@ export class ImportService {
destProject,
destBase,
destModel: model,
debugLog,
});
elapsedTime(`import ${model.title}`);
elapsedTime(
hrTime,
`import data for ${model.title}`,
'importBase',
);
}
// reset timer
elapsedTime();
elapsedTime(hrTime);
const linkReadStream = await (
storageAdapter as any
@ -1216,8 +1220,9 @@ export class ImportService {
destProject,
destBase,
handledLinks,
debugLog,
});
elapsedTime(hrTime, `import links`, 'importBase');
}
} catch (e) {
throw new Error(e);
@ -1237,12 +1242,9 @@ export class ImportService {
destProject: Project;
destBase: Base;
destModel: Model;
debugLog?: (...args: any[]) => void;
}): Promise<void> {
const { idMap, dataStream, destBase, destProject, destModel } = param;
const debugLog = param.debugLog || (() => {});
const headers: string[] = [];
let chunk = [];
@ -1269,18 +1271,20 @@ export class ImportService {
headers.push(childCol.column_name);
} else {
headers.push(null);
debugLog('child column not found', header);
this.logger.error(
`child column not found (${col.colOptions.fk_child_column_id})`,
);
}
} else {
headers.push(col.column_name);
}
} else {
headers.push(null);
debugLog('column not found', header);
this.logger.error(`column not found (${id})`);
}
} else {
headers.push(null);
debugLog('header not found', header);
this.logger.error(`id not found (${header})`);
}
}
parser.resume();
@ -1308,7 +1312,7 @@ export class ImportService {
raw: true,
});
} catch (e) {
console.log(e);
this.logger.error(e);
}
chunk = [];
parser.resume();
@ -1329,7 +1333,7 @@ export class ImportService {
raw: true,
});
} catch (e) {
console.log(e);
this.logger.error(e);
}
chunk = [];
}
@ -1346,12 +1350,9 @@ export class ImportService {
destProject: Project;
destBase: Base;
handledLinks: string[];
debugLog?: (...args: any[]) => void;
}): Promise<string[]> {
const { idMap, linkStream, destBase, destProject, handledLinks } = param;
const debugLog = param.debugLog || (() => {});
const lChunks: Record<string, any[]> = {}; // fk_mm_model_id: { rowId, childId }[]
const insertChunks = async () => {
@ -1369,7 +1370,7 @@ export class ImportService {
});
lChunks[k] = [];
} catch (e) {
console.log(e);
this.logger.error(e);
}
}
};
@ -1452,7 +1453,7 @@ export class ImportService {
[mm.child]: child,
});
} else {
debugLog('column not found', columnId);
this.logger.error(`column not found (${columnId})`);
}
parser.resume();

23
packages/nocodb/src/modules/jobs/helpers.ts

@ -0,0 +1,23 @@
import { Logger } from '@nestjs/common';
import { JOBS_QUEUE } from '../../interface/Jobs';
export const initTime = function () {
return {
hrTime: process.hrtime(),
};
};
export const elapsedTime = function (
time: { hrTime: [number, number] },
label?: string,
context?: string,
) {
const elapsedS = process.hrtime(time.hrTime)[0].toFixed(3);
const elapsedMs = process.hrtime(time.hrTime)[1] / 1000000;
if (label)
Logger.debug(
`${label}: ${elapsedS}s ${elapsedMs}ms`,
`${JOBS_QUEUE}${context ? `:${context}` : ''}`,
);
time.hrTime = process.hrtime();
};
Loading…
Cancel
Save