diff --git a/packages/nocodb/src/modules/jobs/export-import/duplicate.processor.ts b/packages/nocodb/src/modules/jobs/export-import/duplicate.processor.ts index 83a20755ed..05742a13af 100644 --- a/packages/nocodb/src/modules/jobs/export-import/duplicate.processor.ts +++ b/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', + ); } } } diff --git a/packages/nocodb/src/modules/jobs/export-import/export.service.ts b/packages/nocodb/src/modules/jobs/export-import/export.service.ts index 44f5e843dc..4dfefb39e1 100644 --- a/packages/nocodb/src/modules/jobs/export-import/export.service.ts +++ b/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); } diff --git a/packages/nocodb/src/modules/jobs/export-import/import.service.ts b/packages/nocodb/src/modules/jobs/export-import/import.service.ts index 550a3e52a7..035044df32 100644 --- a/packages/nocodb/src/modules/jobs/export-import/import.service.ts +++ b/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(); const externalIdMap = new Map(); @@ -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 { 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 { const { idMap, linkStream, destBase, destProject, handledLinks } = param; - const debugLog = param.debugLog || (() => {}); - const lChunks: Record = {}; // 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(); diff --git a/packages/nocodb/src/modules/jobs/helpers.ts b/packages/nocodb/src/modules/jobs/helpers.ts new file mode 100644 index 0000000000..e4f2e33c1b --- /dev/null +++ b/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(); +};