From 8a618a29fa20a8f60db169551c03258a27463ae6 Mon Sep 17 00:00:00 2001
From: Kai Krakow <kai@kaishome.de>
Date: Wed, 3 Oct 2018 20:42:55 +0200
Subject: [PATCH] gamemode-scheduler: Improve logging

During finding the cause of an issue, we discovered bad interactions
with other resource management daemon that may be running at the same
time and may interfere with GameMode's ability to properly set
scheduling parameters of the process. Usually, this results in EPERM
(instead of EINVAL for lacking kernel support). It also means that the
other daemon is leaking wrong scheduling settings into the games with
negative performance impacts (quite the opposite of what the user wanted
to achieve). So we should give some valuable hints.

This commit improves logging by detecting the error situation and giving
context-based hints on what to do next. To keep logging verbosity low,
the hint is only logged once per error code.

Closes: https://github.com/FeralInteractive/gamemode/issues/68
Signed-off-by: Kai Krakow <kai@kaishome.de>
---
 daemon/gamemode.c | 54 +++++++++++++++++++++++++++++++++++++----------
 1 file changed, 43 insertions(+), 11 deletions(-)

diff --git a/daemon/gamemode.c b/daemon/gamemode.c
index dc0465a..a784bcb 100644
--- a/daemon/gamemode.c
+++ b/daemon/gamemode.c
@@ -184,15 +184,15 @@ void game_mode_context_destroy(GameModeContext *self)
  */
 static void game_mode_apply_scheduler(GameModeContext *self, pid_t client)
 {
-	LOG_MSG("Setting scheduling policies...\n");
-
 	/*
 	 * read configuration "renice" (1..20)
 	 */
 	long int renice = 0;
 	config_get_renice_value(self->config, &renice);
 	if ((renice < 1) || (renice > 20)) {
-		LOG_ERROR("Renice value [%ld] defaulted to [%d].\n", renice, -NICE_DEFAULT_PRIORITY);
+		LOG_ERROR("Invalid renice value '%ld' reset to default: %d.\n",
+		          renice,
+		          -NICE_DEFAULT_PRIORITY);
 		renice = NICE_DEFAULT_PRIORITY;
 	} else {
 		renice = -renice;
@@ -202,13 +202,14 @@ static void game_mode_apply_scheduler(GameModeContext *self, pid_t client)
 	 * don't adjust priority if it was already adjusted
 	 */
 	if (getpriority(PRIO_PROCESS, (id_t)client) != 0) {
-		LOG_ERROR("Client [%d] already reniced, ignoring.\n", client);
+		LOG_ERROR("Refused to renice client [%d]: already reniced\n", client);
 	} else if (setpriority(PRIO_PROCESS, (id_t)client, (int)renice)) {
 		LOG_ERROR(
-		    "Renicing client [%d] failed with error %d, ignoring (your user may not have "
-		    "permission to do this).\n",
+		    "Failed to renice client [%d], ignoring error condition: %s\n"
+		    "    -- Your user may not have permission to do this. Please read the docs\n"
+		    "    -- to learn how to adjust the pam limits.\n",
 		    client,
-		    errno);
+		    strerror(errno));
 	}
 
 	/*
@@ -231,14 +232,45 @@ static void game_mode_apply_scheduler(GameModeContext *self, pid_t client)
 	if (!(strcmp(softrealtime, "off") == 0) && (enable_softrealtime)) {
 		const struct sched_param p = { .sched_priority = 0 };
 		if (sched_setscheduler(client, SCHED_ISO | SCHED_RESET_ON_FORK, &p)) {
+			const char *additional_message = "";
+			switch (errno) {
+			case EPERM: {
+				static int once = 0;
+				if (once++)
+					break;
+				additional_message =
+				    "    -- The error indicates that you may be running a resource management\n"
+				    "    -- daemon managing your game launcher and it leaks lower scheduling\n"
+				    "    -- classes into the games. This is likely a bug in the management daemon\n"
+				    "    -- and not a bug in GameMode, it should be reported upstream.\n"
+				    "    -- If unsure, please also look here:\n"
+				    "    -- https://github.com/FeralInteractive/gamemode/issues/68\n";
+				break;
+			}
+			case EINVAL: {
+				static int once = 0;
+				if (once++)
+					break;
+				additional_message =
+				    "    -- The error indicates that your kernel may not support this. If you\n"
+				    "    -- don't know what SCHED_ISO means, you can safely ignore this. If you\n"
+				    "    -- expected it to work, ensure you're running a kernel with MuQSS or\n"
+				    "    -- PDS scheduler.\n"
+				    "    -- For further technical reading on the topic start here:\n"
+				    "    -- https://lwn.net/Articles/720227/\n";
+				break;
+			}
+			}
 			LOG_ERROR(
-			    "Setting client [%d] to SCHED_ISO failed with error %d, ignoring (your "
-			    "kernel may not support this).\n",
+			    "Failed setting client [%d] into SCHED_ISO mode, ignoring error condition: %s\n%s",
 			    client,
-			    errno);
+			    strerror(errno),
+			    additional_message);
 		}
 	} else {
-		LOG_ERROR("Not using softrealtime, setting is '%s'.\n", softrealtime);
+		LOG_ERROR("Skipped setting client [%d] into SCHED_ISO mode: softrealtime setting is '%s'\n",
+		          client,
+		          softrealtime);
 	}
 }