From b057d3be0de1de61c4a83e3b1d8c247df6240475 Mon Sep 17 00:00:00 2001 From: Hazelnoot Date: Fri, 30 May 2025 08:10:46 -0400 Subject: [PATCH 1/7] add slowQueryThreshold setting to configure slow query warning --- .config/ci.yml | 4 ++++ .config/cypress-devcontainer.yml | 4 ++++ .config/docker_example.yml | 4 ++++ .config/example.yml | 6 ++++-- packages/backend/src/config.ts | 10 ++++++++-- packages/backend/src/postgres.ts | 2 +- 6 files changed, 25 insertions(+), 5 deletions(-) diff --git a/.config/ci.yml b/.config/ci.yml index 7d5261aacd..a1c8c23b44 100644 --- a/.config/ci.yml +++ b/.config/ci.yml @@ -115,6 +115,10 @@ db: user: postgres pass: ci + # Log a warning to the server console if any query takes longer than this to complete. + # Measured in milliseconds; set to 0 to disable. (default: 300) + slowQueryThreshold: 300 + # If false, then query results will be cached in redis. # If true (default), then queries will not be cached. # This will reduce database load at the cost of increased Redis traffic and risk of bugs and unpredictable behavior. diff --git a/.config/cypress-devcontainer.yml b/.config/cypress-devcontainer.yml index 51f408983c..97f78f3ccc 100644 --- a/.config/cypress-devcontainer.yml +++ b/.config/cypress-devcontainer.yml @@ -57,6 +57,10 @@ db: user: postgres pass: postgres + # Log a warning to the server console if any query takes longer than this to complete. + # Measured in milliseconds; set to 0 to disable. (default: 300) + slowQueryThreshold: 300 + # If false, then query results will be cached in redis. # If true (default), then queries will not be cached. # This will reduce database load at the cost of increased Redis traffic and risk of bugs and unpredictable behavior. diff --git a/.config/docker_example.yml b/.config/docker_example.yml index 1b55eee7f5..051526024e 100644 --- a/.config/docker_example.yml +++ b/.config/docker_example.yml @@ -118,6 +118,10 @@ db: user: example-misskey-user pass: example-misskey-pass + # Log a warning to the server console if any query takes longer than this to complete. + # Measured in milliseconds; set to 0 to disable. (default: 300) + slowQueryThreshold: 300 + # If false, then query results will be cached in redis. # If true (default), then queries will not be cached. # This will reduce database load at the cost of increased Redis traffic and risk of bugs and unpredictable behavior. diff --git a/.config/example.yml b/.config/example.yml index b7843da9ad..7d9b6ceda6 100644 --- a/.config/example.yml +++ b/.config/example.yml @@ -121,13 +121,15 @@ db: user: sharkey pass: example-misskey-pass + # Log a warning to the server console if any query takes longer than this to complete. + # Measured in milliseconds; set to 0 to disable. (default: 300) + slowQueryThreshold: 300 + # If false, then query results will be cached in redis. # If true (default), then queries will not be cached. # This will reduce database load at the cost of increased Redis traffic and risk of bugs and unpredictable behavior. #disableCache: false - # - # Extra Connection options #extra: # ssl: true diff --git a/packages/backend/src/config.ts b/packages/backend/src/config.ts index d61112ae40..c2e7efd456 100644 --- a/packages/backend/src/config.ts +++ b/packages/backend/src/config.ts @@ -41,6 +41,7 @@ type Source = { db?: string; user?: string; pass?: string; + slowQueryThreshold?: number; disableCache?: boolean; extra?: { [x: string]: string }; }; @@ -225,6 +226,7 @@ export type Config = { db: string; user: string; pass: string; + slowQueryThreshold?: number; disableCache?: boolean; extra?: { [x: string]: string }; }; @@ -411,6 +413,10 @@ export function loadConfig(): Config { const internalMediaProxy = `${scheme}://${host}/proxy`; const redis = convertRedisOptions(config.redis, host); + // nullish => 300 (default) + // 0 => undefined (disabled) + const slowQueryThreshold = (config.db.slowQueryThreshold ?? 300) || undefined; + return { version, publishTarballInsteadOfProvideRepositoryUrl: !!config.publishTarballInsteadOfProvideRepositoryUrl, @@ -429,7 +435,7 @@ export function loadConfig(): Config { apiUrl: `${scheme}://${host}/api`, authUrl: `${scheme}://${host}/auth`, driveUrl: `${scheme}://${host}/files`, - db: { ...config.db, db: dbDb, user: dbUser, pass: dbPass }, + db: { ...config.db, db: dbDb, user: dbUser, pass: dbPass, slowQueryThreshold }, dbReplications: config.dbReplications, dbSlaves: config.dbSlaves, fulltextSearch: config.fulltextSearch, @@ -637,7 +643,7 @@ function applyEnvOverrides(config: Source) { // these are all the settings that can be overridden _apply_top([['url', 'port', 'address', 'socket', 'chmodSocket', 'disableHsts', 'id', 'dbReplications', 'websocketCompression']]); - _apply_top(['db', ['host', 'port', 'db', 'user', 'pass', 'disableCache']]); + _apply_top(['db', ['host', 'port', 'db', 'user', 'pass', 'slowQueryThreshold', 'disableCache']]); _apply_top(['dbSlaves', Array.from((config.dbSlaves ?? []).keys()), ['host', 'port', 'db', 'user', 'pass']]); _apply_top([ ['redis', 'redisForPubsub', 'redisForJobQueue', 'redisForTimelines', 'redisForReactions', 'redisForRateLimit'], diff --git a/packages/backend/src/postgres.ts b/packages/backend/src/postgres.ts index 34fca6dd92..eed60dd499 100644 --- a/packages/backend/src/postgres.ts +++ b/packages/backend/src/postgres.ts @@ -321,7 +321,7 @@ export function createPostgresDataSource(config: Config) { printReplicationMode: !!config.dbReplications, }) : undefined, - maxQueryExecutionTime: 300, + maxQueryExecutionTime: config.db.slowQueryThreshold, entities: entities, migrations: ['../../migration/*.js'], }); From 04160af3ae807e37be65f361ad6e5012a5813820 Mon Sep 17 00:00:00 2001 From: Hazelnoot Date: Fri, 30 May 2025 08:17:28 -0400 Subject: [PATCH 2/7] fix TypeORM logging to native console instead of NestJS logger --- packages/backend/src/postgres.ts | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/packages/backend/src/postgres.ts b/packages/backend/src/postgres.ts index eed60dd499..eef11d1ed8 100644 --- a/packages/backend/src/postgres.ts +++ b/packages/backend/src/postgres.ts @@ -101,6 +101,7 @@ const sqlLogger = dbLogger.createSubLogger('sql', 'gray'); export type LoggerProps = { disableQueryTruncation?: boolean; + enableQueryLogging?: boolean; enableQueryParamLogging?: boolean; printReplicationMode?: boolean, }; @@ -150,6 +151,8 @@ class MyCustomLogger implements Logger { @bindThis public logQuery(query: string, parameters?: any[], queryRunner?: QueryRunner) { + if (!this.props.enableQueryLogging) return; + const prefix = (this.props.printReplicationMode && queryRunner) ? `[${queryRunner.getReplicationMode()}] ` : undefined; @@ -314,13 +317,12 @@ export function createPostgresDataSource(config: Config) { }, } : false, logging: log, - logger: log - ? new MyCustomLogger({ - disableQueryTruncation: config.logging?.sql?.disableQueryTruncation, - enableQueryParamLogging: config.logging?.sql?.enableQueryParamLogging, - printReplicationMode: !!config.dbReplications, - }) - : undefined, + logger: new MyCustomLogger({ + disableQueryTruncation: config.logging?.sql?.disableQueryTruncation, + enableQueryLogging: log, + enableQueryParamLogging: config.logging?.sql?.enableQueryParamLogging, + printReplicationMode: !!config.dbReplications, + }), maxQueryExecutionTime: config.db.slowQueryThreshold, entities: entities, migrations: ['../../migration/*.js'], From 8e660d2aaf75d30a16ef3bf185e930c4b0895ce0 Mon Sep 17 00:00:00 2001 From: Hazelnoot Date: Fri, 30 May 2025 10:19:32 -0400 Subject: [PATCH 3/7] don't highlight queries in production --- packages/backend/src/postgres.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/backend/src/postgres.ts b/packages/backend/src/postgres.ts index eef11d1ed8..6a3b60db95 100644 --- a/packages/backend/src/postgres.ts +++ b/packages/backend/src/postgres.ts @@ -137,7 +137,7 @@ class MyCustomLogger implements Logger { modded = truncateSql(modded); } - return highlightSql(modded); + return this.props.enableQueryLogging ? highlightSql(modded) : modded; } @bindThis From 3fecde29b5d8c8c38ea740ec27586f598b36fbe2 Mon Sep 17 00:00:00 2001 From: Hazelnoot Date: Fri, 30 May 2025 10:25:01 -0400 Subject: [PATCH 4/7] fix TypeORM logger implementation --- packages/backend/src/postgres.ts | 19 +++++++++++++++---- 1 file changed, 15 insertions(+), 4 deletions(-) diff --git a/packages/backend/src/postgres.ts b/packages/backend/src/postgres.ts index 6a3b60db95..cc7dd75b56 100644 --- a/packages/backend/src/postgres.ts +++ b/packages/backend/src/postgres.ts @@ -164,7 +164,8 @@ class MyCustomLogger implements Logger { const prefix = (this.props.printReplicationMode && queryRunner) ? `[${queryRunner.getReplicationMode()}] ` : undefined; - sqlLogger.error(this.transformQueryLog(query, { prefix }), this.transformParameters(parameters)); + const transformed = this.transformQueryLog(query, { prefix }); + sqlLogger.error(`Query error (${error}): ${transformed}`, this.transformParameters(parameters)); } @bindThis @@ -172,7 +173,8 @@ class MyCustomLogger implements Logger { const prefix = (this.props.printReplicationMode && queryRunner) ? `[${queryRunner.getReplicationMode()}] ` : undefined; - sqlLogger.warn(this.transformQueryLog(query, { prefix }), this.transformParameters(parameters)); + const transformed = this.transformQueryLog(query, { prefix }); + sqlLogger.warn(`Query is slow (${time}ms): ${transformed}`, this.transformParameters(parameters)); } @bindThis @@ -181,8 +183,17 @@ class MyCustomLogger implements Logger { } @bindThis - public log(message: string) { - sqlLogger.info(message); + public log(level: 'log' | 'info' | 'warn', message: string) { + switch (level) { + case 'log': + case 'info': { + sqlLogger.info(message); + break; + } + case 'warn': { + sqlLogger.warn(message); + } + } } @bindThis From dd1969c800dbe9b7e0af13c36a3bab252d4f460b Mon Sep 17 00:00:00 2001 From: Hazelnoot Date: Fri, 30 May 2025 10:29:36 -0400 Subject: [PATCH 5/7] suppress messages from TypeORM migration and schema loading in production --- packages/backend/src/postgres.ts | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/packages/backend/src/postgres.ts b/packages/backend/src/postgres.ts index cc7dd75b56..851cc6c87c 100644 --- a/packages/backend/src/postgres.ts +++ b/packages/backend/src/postgres.ts @@ -98,6 +98,8 @@ pg.types.setTypeParser(20, Number); export const dbLogger = new MisskeyLogger('db'); const sqlLogger = dbLogger.createSubLogger('sql', 'gray'); +const sqlMigrateLogger = sqlLogger.createSubLogger('migrate'); +const sqlSchemaLogger = sqlLogger.createSubLogger('schema'); export type LoggerProps = { disableQueryTruncation?: boolean; @@ -179,7 +181,7 @@ class MyCustomLogger implements Logger { @bindThis public logSchemaBuild(message: string) { - sqlLogger.info(message); + sqlSchemaLogger.debug(message); } @bindThis @@ -198,7 +200,7 @@ class MyCustomLogger implements Logger { @bindThis public logMigration(message: string) { - sqlLogger.info(message); + sqlMigrateLogger.debug(message); } } From 4637d4eb3fdae145395f29cbb97a90e161377ecd Mon Sep 17 00:00:00 2001 From: Hazelnoot Date: Fri, 30 May 2025 10:31:33 -0400 Subject: [PATCH 6/7] clarify query truncation message --- packages/backend/src/postgres.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/backend/src/postgres.ts b/packages/backend/src/postgres.ts index 851cc6c87c..b4bd934972 100644 --- a/packages/backend/src/postgres.ts +++ b/packages/backend/src/postgres.ts @@ -115,7 +115,7 @@ function highlightSql(sql: string) { } function truncateSql(sql: string) { - return sql.length > 100 ? `${sql.substring(0, 100)}...` : sql; + return sql.length > 100 ? `${sql.substring(0, 100)} [truncated]` : sql; } function stringifyParameter(param: any) { From b219ca29c5038e7391612ddebdd667b940f03e95 Mon Sep 17 00:00:00 2001 From: Hazelnoot Date: Fri, 30 May 2025 12:22:33 -0400 Subject: [PATCH 7/7] comment new property --- .config/ci.yml | 6 +++--- .config/cypress-devcontainer.yml | 6 +++--- .config/docker_example.yml | 6 +++--- .config/example.yml | 6 +++--- 4 files changed, 12 insertions(+), 12 deletions(-) diff --git a/.config/ci.yml b/.config/ci.yml index a1c8c23b44..5fcf78b737 100644 --- a/.config/ci.yml +++ b/.config/ci.yml @@ -115,9 +115,9 @@ db: user: postgres pass: ci - # Log a warning to the server console if any query takes longer than this to complete. - # Measured in milliseconds; set to 0 to disable. (default: 300) - slowQueryThreshold: 300 + ## Log a warning to the server console if any query takes longer than this to complete. + ## Measured in milliseconds; set to 0 to disable. (default: 300) + #slowQueryThreshold: 300 # If false, then query results will be cached in redis. # If true (default), then queries will not be cached. diff --git a/.config/cypress-devcontainer.yml b/.config/cypress-devcontainer.yml index 97f78f3ccc..97263da68f 100644 --- a/.config/cypress-devcontainer.yml +++ b/.config/cypress-devcontainer.yml @@ -57,9 +57,9 @@ db: user: postgres pass: postgres - # Log a warning to the server console if any query takes longer than this to complete. - # Measured in milliseconds; set to 0 to disable. (default: 300) - slowQueryThreshold: 300 + ## Log a warning to the server console if any query takes longer than this to complete. + ## Measured in milliseconds; set to 0 to disable. (default: 300) + #slowQueryThreshold: 300 # If false, then query results will be cached in redis. # If true (default), then queries will not be cached. diff --git a/.config/docker_example.yml b/.config/docker_example.yml index 051526024e..3aaa56e333 100644 --- a/.config/docker_example.yml +++ b/.config/docker_example.yml @@ -118,9 +118,9 @@ db: user: example-misskey-user pass: example-misskey-pass - # Log a warning to the server console if any query takes longer than this to complete. - # Measured in milliseconds; set to 0 to disable. (default: 300) - slowQueryThreshold: 300 + ## Log a warning to the server console if any query takes longer than this to complete. + ## Measured in milliseconds; set to 0 to disable. (default: 300) + #slowQueryThreshold: 300 # If false, then query results will be cached in redis. # If true (default), then queries will not be cached. diff --git a/.config/example.yml b/.config/example.yml index 7d9b6ceda6..8cac42c050 100644 --- a/.config/example.yml +++ b/.config/example.yml @@ -121,9 +121,9 @@ db: user: sharkey pass: example-misskey-pass - # Log a warning to the server console if any query takes longer than this to complete. - # Measured in milliseconds; set to 0 to disable. (default: 300) - slowQueryThreshold: 300 + ## Log a warning to the server console if any query takes longer than this to complete. + ## Measured in milliseconds; set to 0 to disable. (default: 300) + #slowQueryThreshold: 300 # If false, then query results will be cached in redis. # If true (default), then queries will not be cached.