Merge pull request #37838 from Jordie0608/ithoughtaboutmakingthissendanemailbutidontwanttodrownmyinbox

Query debug logging

code/__HELPERS/_logging.dm

@@ -128,6 +128,9 @@
 /proc/log_qdel(text)
 	WRITE_LOG(GLOB.world_qdel_log, "QDEL: [text]")
 
+/proc/log_query_debug(text)
+	WRITE_LOG(GLOB.query_debug_log, "SQL: [text]")
+
 /* Log to both DD and the logfile. */
 /proc/log_world(text)
 	WRITE_LOG(GLOB.world_runtime_log, text)

code/_globalvars/logging.dm

@@ -20,6 +20,8 @@ GLOBAL_VAR(world_pda_log)
 GLOBAL_PROTECT(world_pda_log)
 GLOBAL_VAR(world_manifest_log)
 GLOBAL_PROTECT(world_manifest_log)
+GLOBAL_VAR(query_debug_log)
+GLOBAL_PROTECT(query_debug_log)
 
 GLOBAL_LIST_EMPTY(bombers)
 GLOBAL_PROTECT(bombers)

code/controllers/configuration/entries/dbconfig.dm

@@ -4,7 +4,7 @@
 /datum/config_entry/string/address
 	config_entry_value = "localhost"
 	protection = CONFIG_ENTRY_LOCKED | CONFIG_ENTRY_HIDDEN
-	
+
 /datum/config_entry/number/port
 	config_entry_value = 3306
 	min_val = 0
@@ -24,3 +24,8 @@
 
 /datum/config_entry/string/feedback_tableprefix
 	protection = CONFIG_ENTRY_LOCKED | CONFIG_ENTRY_HIDDEN
+
+/datum/config_entry/number/query_debug_log_timeout
+	config_entry_value = 70
+	min_val = 1
+	protection = CONFIG_ENTRY_LOCKED | CONFIG_ENTRY_HIDDEN

code/controllers/subsystem/dbcore.dm

@@ -231,10 +231,24 @@ Delayed insert mode was removed in mysql 7 and only works with MyISAM type table
 		to_chat(usr, "<span class='danger'>A SQL error occurred during this operation, check the server logs.</span>")
 
 /datum/DBQuery/proc/Execute(sql_query = sql, cursor_handler = default_cursor, log_error = TRUE)
+	var/start_time
+	var/timeout = CONFIG_GET(number/query_debug_log_timeout)
+	if(timeout)
+		start_time = REALTIMEOFDAY
 	Close()
 	. = _dm_db_execute(_db_query, sql_query, db_connection._db_con, cursor_handler, null)
 	if(!. && log_error)
 		log_sql("[ErrorMsg()] | Query used: [sql]")
+	if(timeout)
+		if((REALTIMEOFDAY - start_time) > timeout)
+			log_query_debug("Query execution started at [start_time]")
+			log_query_debug("Query execution ended at [REALTIMEOFDAY]")
+			log_query_debug("Possible slow query timeout detected.")
+			log_query_debug("Query used: [sql]")
+			slow_query_check()
+
+/datum/DBQuery/proc/slow_query_check()
+	message_admins("HEY! A database query may have timed out. Did the server just hang? <a href='?_src_=holder;[HrefToken()];slowquery=yes'>\[YES\]</a>|<a href='?_src_=holder;[HrefToken()];slowquery=no'>\[NO\]</a>")
 
 /datum/DBQuery/proc/NextRow()
 	return _dm_db_next_row(_db_query,item,conversions)

code/game/world.dm

@@ -20,7 +20,7 @@ GLOBAL_PROTECT(security_mode)
 	TgsNew()
 
 	GLOB.revdata = new
-	
+
 	config.Load()
 
 	//SetupLogs depends on the RoundID, so lets check
@@ -95,6 +95,7 @@ GLOBAL_PROTECT(security_mode)
 	GLOB.sql_error_log = "[GLOB.log_directory]/sql.log"
 	GLOB.world_qdel_log = "[GLOB.log_directory]/qdel.log"
 	GLOB.world_runtime_log = "[GLOB.log_directory]/runtime.log"
+	GLOB.query_debug_log = "[GLOB.log_directory]/query_debug.log"
 
 #ifdef UNIT_TESTS
 	GLOB.test_log = file("[GLOB.log_directory]/tests.log")

code/modules/admin/topic.dm

@@ -2461,6 +2461,19 @@
 		usr.client.cmd_admin_mod_antag_rep(C, href_list["modantagrep"])
 		show_player_panel(M)
 
+	else if(href_list["slowquery"])
+		if(!check_rights(R_ADMIN))
+			return
+		var/answer = href_list["slowquery"]
+		if(answer == "yes")
+			log_query_debug("[usr.key] | Reported a server hang")
+			if(alert(usr, "Had you just press any admin buttons?", "Query server hang report", "Yes", "No") == "Yes")
+				var/response = input(usr,"What were you just doing?","Query server hang report") as null|text
+				if(response)
+					log_query_debug("[usr.key] | [response]")
+		else if(answer == "no")
+			log_query_debug("[usr.key] | Reported no server hang")
+
 /datum/admins/proc/HandleCMode()
 	if(!check_rights(R_ADMIN))
 		return

config/dbconfig.txt

@@ -18,7 +18,7 @@ FEEDBACK_DATABASE feedback
 ## Prefix to be added to the name of every table, older databases will require this be set to erro_
 ## Note, this does not change the table names in the database, you will have to do that yourself.
 ##IE:
-##	FEEDBACK_TABLEPREFIX 
+##	FEEDBACK_TABLEPREFIX
 ##	FEEDBACK_TABLEPREFIX SS13_
 ## Remove "SS13_" if you are using the standard schema file.
 FEEDBACK_TABLEPREFIX SS13_
@@ -28,3 +28,7 @@ FEEDBACK_LOGIN username
 
 ## Password used to access the database.
 FEEDBACK_PASSWORD password
+
+## Time in deciseconds for a query to execute before alerting a for possible slow query timeout.
+## While enabled queries and their execution times are logged if they exceed this value.
+#QUERY_DEBUG_LOG_TIMEOUT 70