merge: Add configuration option for the "query is slow" warning (!1061)

View MR for information: https://activitypub.software/TransFem-org/Sharkey/-/merge_requests/1061

Approved-by: Marie <github@yuugi.dev>
Approved-by: Julia <julia@insertdomain.name>

.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.

.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.

.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.

.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

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'],

packages/backend/src/postgres.ts

@@ -98,9 +98,12 @@ 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;
+	enableQueryLogging?: boolean;
 	enableQueryParamLogging?: boolean;
 	printReplicationMode?: boolean,
 };
@@ -112,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) {
@@ -136,7 +139,7 @@ class MyCustomLogger implements Logger {
 			modded = truncateSql(modded);
 		}
 
-		return highlightSql(modded);
+		return this.props.enableQueryLogging ? highlightSql(modded) : modded;
 	}
 
 	@bindThis
@@ -150,6 +153,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;
@@ -161,7 +166,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
@@ -169,22 +175,32 @@ 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
 	public logSchemaBuild(message: string) {
-		sqlLogger.info(message);
+		sqlSchemaLogger.debug(message);
 	}
 
 	@bindThis
-	public log(message: string) {
+	public log(level: 'log' | 'info' | 'warn', message: string) {
-		sqlLogger.info(message);
+		switch (level) {
+			case 'log':
+			case 'info': {
+				sqlLogger.info(message);
+				break;
+			}
+			case 'warn': {
+				sqlLogger.warn(message);
+			}
+		}
 	}
 
 	@bindThis
 	public logMigration(message: string) {
-		sqlLogger.info(message);
+		sqlMigrateLogger.debug(message);
 	}
 }
 
@@ -314,14 +330,13 @@ export function createPostgresDataSource(config: Config) {
 			},
 		} : false,
 		logging: log,
-		logger: log
+		logger: new MyCustomLogger({
-			? new MyCustomLogger({
+			disableQueryTruncation: config.logging?.sql?.disableQueryTruncation,
-				disableQueryTruncation: config.logging?.sql?.disableQueryTruncation,
+			enableQueryLogging: log,
-				enableQueryParamLogging: config.logging?.sql?.enableQueryParamLogging,
+			enableQueryParamLogging: config.logging?.sql?.enableQueryParamLogging,
-				printReplicationMode: !!config.dbReplications,
+			printReplicationMode: !!config.dbReplications,
-			})
+		}),
-			: undefined,
+		maxQueryExecutionTime: config.db.slowQueryThreshold,
-		maxQueryExecutionTime: 300,
 		entities: entities,
 		migrations: ['../../migration/*.js'],
 	});