From f232bb32c35880a716571dc12c4162e0b963b436 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Martin=20Ad=C3=A1mek?= Date: Wed, 12 Aug 2020 13:26:48 +0200 Subject: [PATCH] perf(core): do not generate sql when logging disabled Related: #732 --- packages/core/src/connections/Connection.ts | 2 +- packages/core/src/utils/Logger.ts | 10 +++---- packages/knex/src/AbstractSqlConnection.ts | 11 +++++--- tests/EntityManager.mysql.test.ts | 31 ++++++++++----------- tests/EntityManager.postgre.test.ts | 21 +++++++------- tests/EntityManager.sqlite.test.ts | 6 ++-- tests/EntityManager.sqlite2.test.ts | 6 ++-- tests/Migrator.test.ts | 6 ++-- tests/composite-keys.mysql.test.ts | 2 +- tests/embedded-entities.mysql.test.ts | 2 +- tests/issues/GH228.test.ts | 2 +- tests/issues/GH234.test.ts | 2 +- tests/issues/GH372.test.ts | 2 +- tests/issues/GH610.test.ts | 2 +- tests/joined-strategy.postgre.test.ts | 12 ++++---- 15 files changed, 59 insertions(+), 58 deletions(-) diff --git a/packages/core/src/connections/Connection.ts b/packages/core/src/connections/Connection.ts index 9c960d6afa37..776746050d5c 100644 --- a/packages/core/src/connections/Connection.ts +++ b/packages/core/src/connections/Connection.ts @@ -100,7 +100,7 @@ export abstract class Connection { // We only actually log something when debugMode is enabled. If it's not enabled, // we can jump out here as a performance optimization and save ourselves some cycles // preparing a message that won't get used. - if (!logger.debugMode || (Array.isArray(logger.debugMode) && !logger.debugMode.includes('query'))) { + if (!logger.isEnabled('query')) { return; } diff --git a/packages/core/src/utils/Logger.ts b/packages/core/src/utils/Logger.ts index 9d854379e446..967c20b2fb2f 100644 --- a/packages/core/src/utils/Logger.ts +++ b/packages/core/src/utils/Logger.ts @@ -9,11 +9,7 @@ export class Logger { * Logs a message inside given namespace. */ log(namespace: LoggerNamespace, message: string): void { - if (!this.debugMode) { - return; - } - - if (Array.isArray(this.debugMode) && !this.debugMode.includes(namespace)) { + if (!this.isEnabled(namespace)) { return; } @@ -29,6 +25,10 @@ export class Logger { this.debugMode = debugMode; } + isEnabled(namespace: LoggerNamespace): boolean { + return this.debugMode && (!Array.isArray(this.debugMode) || this.debugMode.includes(namespace)); + } + } export type LoggerNamespace = 'query' | 'query-params' | 'discovery' | 'info'; diff --git a/packages/knex/src/AbstractSqlConnection.ts b/packages/knex/src/AbstractSqlConnection.ts index 4c2fa3bec6fa..1d7ec6a4c8e8 100644 --- a/packages/knex/src/AbstractSqlConnection.ts +++ b/packages/knex/src/AbstractSqlConnection.ts @@ -1,7 +1,7 @@ import Knex, { Config, QueryBuilder, Raw, Transaction as KnexTransaction } from 'knex'; import { readFile } from 'fs-extra'; -import { Connection, EntityData, AnyEntity, QueryResult, Transaction, Utils } from '@mikro-orm/core'; +import { AnyEntity, Connection, EntityData, QueryResult, Transaction, Utils } from '@mikro-orm/core'; export abstract class AbstractSqlConnection extends Connection { @@ -100,10 +100,13 @@ export abstract class AbstractSqlConnection extends Connection { } private getSql(qb: QueryBuilder | Raw): string { - const debug = this.config.get('debug'); - const dumpParams = Array.isArray(debug) ? debug.includes('query-params') : debug; + const logger = this.config.getLogger(); - if (dumpParams) { + if (!logger.isEnabled('query')) { + return ''; + } + + if (logger.isEnabled('query-params')) { return qb.toString(); } diff --git a/tests/EntityManager.mysql.test.ts b/tests/EntityManager.mysql.test.ts index 35131d678cb7..5a2f35610f5c 100644 --- a/tests/EntityManager.mysql.test.ts +++ b/tests/EntityManager.mysql.test.ts @@ -322,7 +322,7 @@ describe('EntityManagerMySql', () => { test('nested transaction rollback with save-points will commit the outer one', async () => { const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); // start outer transaction @@ -646,7 +646,7 @@ describe('EntityManagerMySql', () => { await orm.em.persistAndFlush(author); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.transactional(async em => { @@ -664,7 +664,7 @@ describe('EntityManagerMySql', () => { await orm.em.persistAndFlush(author); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.transactional(async em => { @@ -831,7 +831,7 @@ describe('EntityManagerMySql', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const b0 = (await orm.em.findOne(FooBaz2, { id: baz.id }))!; @@ -1419,7 +1419,7 @@ describe('EntityManagerMySql', () => { await orm.em.persistAndFlush(author); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); orm.em.clear(); @@ -1466,7 +1466,6 @@ describe('EntityManagerMySql', () => { const mock = jest.fn(); const logger = new Logger(mock, true); Object.assign(orm.config, { logger }); - orm.config.set('debug', true); orm.em.clear(); const books1 = await orm.em.find(Book2, { title: '123' }, { @@ -1561,7 +1560,7 @@ describe('EntityManagerMySql', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const jon = await orm.em.findOneOrFail(Author2, author.id, ['friends'], { friends: { name: QueryOrder.ASC } }); @@ -1731,7 +1730,7 @@ describe('EntityManagerMySql', () => { test('self referencing (1 step)', async () => { const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const author = new Author2('name', 'email'); @@ -1853,7 +1852,7 @@ describe('EntityManagerMySql', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const res1 = await orm.em.find(Book2, { author: { name: 'Jon Snow' } }, ['perex']); expect(res1).toHaveLength(3); @@ -1965,7 +1964,7 @@ describe('EntityManagerMySql', () => { test('query highlighting', async () => { const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); orm.config.set('highlighter', new SqlHighlighter()); c.enabled = true; @@ -1985,7 +1984,7 @@ describe('EntityManagerMySql', () => { test('read replicas', async () => { const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); let author = new Author2('Jon Snow', 'snow@wall.st'); @@ -2080,7 +2079,7 @@ describe('EntityManagerMySql', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const res1 = await orm.em.find(Book2, { publisher: { $ne: null } }, { schema: 'mikro_orm_test_schema_2', populate: ['perex'] }); @@ -2116,7 +2115,7 @@ describe('EntityManagerMySql', () => { orm.em.remove(a.baz!); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.flush(); expect(mock.mock.calls[0][0]).toMatch('begin'); @@ -2245,7 +2244,7 @@ describe('EntityManagerMySql', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); // without paginate flag it fails to get 5 records @@ -2310,7 +2309,7 @@ describe('EntityManagerMySql', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const b = await orm.em.findOneOrFail(Book2, { author: { name: 'God' } }); @@ -2398,7 +2397,7 @@ describe('EntityManagerMySql', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const r1 = await orm.em.find(Author2, {}, { populate: { books: true } }); diff --git a/tests/EntityManager.postgre.test.ts b/tests/EntityManager.postgre.test.ts index c50180ab9c44..360d44779ef5 100644 --- a/tests/EntityManager.postgre.test.ts +++ b/tests/EntityManager.postgre.test.ts @@ -84,7 +84,7 @@ describe('EntityManagerPostgre', () => { await driver.nativeInsert(Test2.name, { id: 5, name: 't5' }); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const res = await driver.nativeInsertMany(Publisher2.name, [ @@ -205,7 +205,7 @@ describe('EntityManagerPostgre', () => { test('nested transaction rollback with save-points will commit the outer one', async () => { const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); // start outer transaction @@ -515,7 +515,7 @@ describe('EntityManagerPostgre', () => { await orm.em.persistAndFlush(author); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.transactional(async em => { @@ -533,7 +533,7 @@ describe('EntityManagerPostgre', () => { await orm.em.persistAndFlush(author); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.transactional(async em => { @@ -662,7 +662,7 @@ describe('EntityManagerPostgre', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); // autoJoinOneToOneOwner: false @@ -968,7 +968,7 @@ describe('EntityManagerPostgre', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const res = await orm.em.find(Author2, { books: { title: { $in: ['b1', 'b2'] } } }, ['books.perex']); expect(res).toHaveLength(1); @@ -1054,9 +1054,8 @@ describe('EntityManagerPostgre', () => { expect(b.createdAt).toBeInstanceOf(Date); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query', 'query-params']); Object.assign(orm.config, { logger }); - orm.config.set('debug', true); await orm.em.nativeInsert(Author2, { name: 'native name 1', email: 'native1@email.com' }); expect(mock.mock.calls[0][0]).toMatch('insert into "author2" ("email", "name") values (\'native1@email.com\', \'native name 1\') returning "id", "created_at", "updated_at"'); orm.config.set('debug', ['query']); @@ -1093,7 +1092,7 @@ describe('EntityManagerPostgre', () => { test('self referencing (1 step)', async () => { const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const author = new Author2('name', 'email'); @@ -1169,7 +1168,7 @@ describe('EntityManagerPostgre', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const res1 = await orm.em.find(Book2, { author: { name: 'Jon Snow' } }, ['perex']); expect(res1).toHaveLength(3); @@ -1281,7 +1280,7 @@ describe('EntityManagerPostgre', () => { expect(res1.map(a => a.name)).toEqual(['God 02', 'God 03']); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); // with paginate flag (and a bit of dark sql magic) we get what we want diff --git a/tests/EntityManager.sqlite.test.ts b/tests/EntityManager.sqlite.test.ts index 169c91bb5d00..436b0627d1d2 100644 --- a/tests/EntityManager.sqlite.test.ts +++ b/tests/EntityManager.sqlite.test.ts @@ -162,7 +162,7 @@ describe('EntityManagerSqlite', () => { test('nested transaction rollback with save-points will commit the outer one', async () => { const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); // start outer transaction @@ -447,7 +447,7 @@ describe('EntityManagerSqlite', () => { await orm.em.persistAndFlush(author); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.transactional(async em => { @@ -465,7 +465,7 @@ describe('EntityManagerSqlite', () => { await orm.em.persistAndFlush(author); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.transactional(async em => { diff --git a/tests/EntityManager.sqlite2.test.ts b/tests/EntityManager.sqlite2.test.ts index e3755a6696f1..f76c4d042ef3 100644 --- a/tests/EntityManager.sqlite2.test.ts +++ b/tests/EntityManager.sqlite2.test.ts @@ -96,7 +96,7 @@ describe('EntityManagerSqlite2', () => { test('nested transaction rollback with save-points will commit the outer one', async () => { const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); // start outer transaction @@ -385,7 +385,7 @@ describe('EntityManagerSqlite2', () => { await orm.em.persistAndFlush(author); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.transactional(async em => { @@ -403,7 +403,7 @@ describe('EntityManagerSqlite2', () => { await orm.em.persistAndFlush(author); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.transactional(async em => { diff --git a/tests/Migrator.test.ts b/tests/Migrator.test.ts index dcd1232d2985..dede82a9e069 100644 --- a/tests/Migrator.test.ts +++ b/tests/Migrator.test.ts @@ -121,7 +121,7 @@ describe('Migrator', () => { const runner = migrator.runner; const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const migration1 = new MigrationTest1(orm.em.getDriver(), orm.config); @@ -164,7 +164,7 @@ describe('Migrator', () => { migratorMock.mockImplementation(async () => void 0); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await migrator.up(migration.fileName); @@ -200,7 +200,7 @@ describe('Migrator', () => { migratorMock.mockImplementation(async () => void 0); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await migrator.up(migration.fileName); diff --git a/tests/composite-keys.mysql.test.ts b/tests/composite-keys.mysql.test.ts index f5af30d6d497..b9b828b037ec 100644 --- a/tests/composite-keys.mysql.test.ts +++ b/tests/composite-keys.mysql.test.ts @@ -275,7 +275,7 @@ describe('composite keys in mysql', () => { expect(wrap(u1.cars[2], true).__em).not.toBeUndefined(); // PK only, so will be merged automatically const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.persistAndFlush(u1); expect(mock.mock.calls[0][0]).toMatch('begin'); diff --git a/tests/embedded-entities.mysql.test.ts b/tests/embedded-entities.mysql.test.ts index 4158a18a8f8a..ee16ee52bea9 100644 --- a/tests/embedded-entities.mysql.test.ts +++ b/tests/embedded-entities.mysql.test.ts @@ -140,7 +140,7 @@ describe('embedded entities in mysql', () => { user.address3 = new Address1('Downing street 12', '789', 'London 3', 'UK 3'); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); orm.config.reset('highlighter'); await orm.em.persistAndFlush(user); diff --git a/tests/issues/GH228.test.ts b/tests/issues/GH228.test.ts index ef03f3d1ba1d..69cc3032340f 100644 --- a/tests/issues/GH228.test.ts +++ b/tests/issues/GH228.test.ts @@ -51,7 +51,7 @@ describe('GH issue 228', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.findAndCount(A, {}, { orderBy: { type: 'asc' }, diff --git a/tests/issues/GH234.test.ts b/tests/issues/GH234.test.ts index 7242a76ce062..9457ebd1db66 100644 --- a/tests/issues/GH234.test.ts +++ b/tests/issues/GH234.test.ts @@ -60,7 +60,7 @@ describe('GH issue 234', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const res1 = await orm.em.find(B, { aCollection: [1, 2, 3] }, ['aCollection']); expect(mock.mock.calls[0][0]).toMatch('select `e0`.* from `b` as `e0` left join `b_a_collection` as `e1` on `e0`.`id` = `e1`.`b_id` where `e1`.`a_id` in (?, ?, ?)'); diff --git a/tests/issues/GH372.test.ts b/tests/issues/GH372.test.ts index 55f6595b7d58..08b6fc0d411b 100644 --- a/tests/issues/GH372.test.ts +++ b/tests/issues/GH372.test.ts @@ -60,7 +60,7 @@ describe('GH issue 372', () => { test(`schema updates respect default values`, async () => { const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const a1 = new A(); diff --git a/tests/issues/GH610.test.ts b/tests/issues/GH610.test.ts index 2701ba04a062..7ee2b7ad24c0 100644 --- a/tests/issues/GH610.test.ts +++ b/tests/issues/GH610.test.ts @@ -38,7 +38,7 @@ describe('GH issue 610', () => { orm.em.persist(test); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.flush(); expect(mock.mock.calls[0][0]).toMatch('begin'); diff --git a/tests/joined-strategy.postgre.test.ts b/tests/joined-strategy.postgre.test.ts index 72e24774d8ba..c9655109b67f 100644 --- a/tests/joined-strategy.postgre.test.ts +++ b/tests/joined-strategy.postgre.test.ts @@ -99,7 +99,7 @@ describe('Joined loading strategy', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.findOneOrFail(Author2, { id: author2.id }, { populate: { books2: { perex: true } } }); @@ -150,7 +150,7 @@ describe('Joined loading strategy', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); await orm.em.find(Author2, { id: author2.id }, { populate: { books2: { perex: true } } }); @@ -215,7 +215,7 @@ describe('Joined loading strategy', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); mock.mock.calls.length = 0; const books = await orm.em.find(Book2, {}, { populate: { tags: LoadStrategy.JOINED }, orderBy: { tags: { name: 'desc' } } }); @@ -300,7 +300,7 @@ describe('Joined loading strategy', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); // autoJoinOneToOneOwner: false @@ -360,7 +360,7 @@ describe('Joined loading strategy', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const tags = await repo.findAll({ @@ -439,7 +439,7 @@ describe('Joined loading strategy', () => { orm.em.clear(); const mock = jest.fn(); - const logger = new Logger(mock, true); + const logger = new Logger(mock, ['query']); Object.assign(orm.config, { logger }); const res1 = await orm.em.find(Book2, { author: { name: 'Jon Snow' } }, { populate: { perex: true, author: LoadStrategy.JOINED } }); expect(res1).toHaveLength(3);