Use a rust DLL for logging (tgstation#36858)

By moving our logging to a DLL we see a drop in CPU/real time of 2-3 orders of magnitude. This is due to BYOND opening and closing file handles on every write, causing incredible amounts of unneeded overhead. The logging library also handles timestamps for us, further increasing performance gains.

This library will also allow for further offloading in the future, such as completely replacing file2text() and friends.

A pre-compiled DLL is bundled, but Linux users will have to compile manually. Directions can be found at the rust-g repo.

Log output is enhanced with millisecond time stamps:

[2018-04-01 15:56:23.522] blah blah blah

This includes runtimes as well, which benefit from the same timestamp improvements and no longer have hacky splitting code to add their own timestamps.

Log shutdown is handled in a dedicated proc called as late as possible, as rust-g integration expands this will be factored out into a generic native code shutdown proc.

.travis.yml

@@ -8,6 +8,7 @@ env:
     - BYOND_MAJOR="512"
     - BYOND_MINOR="1418"
     - NODE_VERSION="4"
+    - RUST_G_VERSION="0.2.0"
     - BUILD_TOOLS=false
     - BUILD_TESTING=false
     - DM_MAPFILE="loadallmaps"
@@ -18,8 +19,10 @@ env:
 
 cache:
   directories:
-    - tgui/node_modules
     - $HOME/BYOND-${BYOND_MAJOR}.${BYOND_MINOR}
+    - tgui/node_modules
+    - $HOME/.rustup
+    - $HOME/.cargo
 
 
 addons:
@@ -28,6 +31,7 @@ addons:
       - libc6-i386
       - libgcc1:i386
       - libstdc++6:i386
+      - gcc-multilib
       - python3
       - python3-pip
 
@@ -41,5 +45,6 @@ before_script:
 script:
   - tools/travis/check_filedirs.sh tgstation.dme
   - tools/travis/build_tools.sh
+  - tools/travis/build_dependencies.sh
   - tools/travis/build_byond.sh
 

README.md

@@ -64,6 +64,11 @@ byondkey = Rank
 
 where the admin rank must be properly capitalised.
 
+This codebase also depends on a native library called rust-g. A precompiled
+Windows DLL is included in this repository, but Linux users will need to build
+and install it themselves. Directions can be found at the [rust-g
+repo](https://github.com/tgstation13/rust-g).
+
 Finally, to start the server, run Dream Daemon and enter the path to your
 compiled tgstation.dmb file. Make sure to set the port to the one you
 specified in the config.txt, and set the Security box to 'Safe'. Then press GO

TGS3.json

@@ -17,6 +17,7 @@
       "data"
     ],
     "dlls": [
-      "libmariadb.dll"
+      "libmariadb.dll",
+      "rust_g.dll"
     ]
-  }
+  }

code/__HELPERS/_logging.dm

@@ -1,9 +1,13 @@
+//location of the rust-g library
+#define RUST_G "rust_g"
+
 //wrapper macros for easier grepping
 #define DIRECT_OUTPUT(A, B) A << B
 #define SEND_IMAGE(target, image) DIRECT_OUTPUT(target, image)
 #define SEND_SOUND(target, sound) DIRECT_OUTPUT(target, sound)
 #define SEND_TEXT(target, text) DIRECT_OUTPUT(target, text)
 #define WRITE_FILE(file, text) DIRECT_OUTPUT(file, text)
+#define WRITE_LOG(log, text) call(RUST_G, "log_write")(log, text)
 
 //print a warning message to world.log
 #define WARNING(MSG) warning("[MSG] in [__FILE__] at line [__LINE__] src: [src] usr: [usr].")
@@ -26,99 +30,129 @@
 
 #ifdef UNIT_TESTS
 /proc/log_test(text)
-	WRITE_FILE(GLOB.test_log, "\[[time_stamp()]]: [text]")
+	WRITE_LOG(GLOB.test_log, text)
 	SEND_TEXT(world.log, text)
 #endif
 
+
+/* Items with ADMINPRIVATE prefixed are stripped from public logs. */
 /proc/log_admin(text)
 	GLOB.admin_log.Add(text)
 	if (CONFIG_GET(flag/log_admin))
-		WRITE_FILE(GLOB.world_game_log, "\[[time_stamp()]]ADMIN: [text]")
+		WRITE_LOG(GLOB.world_game_log, "ADMIN: [text]")
 
-//Items using this proc are stripped from public logs - use with caution
 /proc/log_admin_private(text)
 	GLOB.admin_log.Add(text)
 	if (CONFIG_GET(flag/log_admin))
-		WRITE_FILE(GLOB.world_game_log, "\[[time_stamp()]]ADMINPRIVATE: [text]")
+		WRITE_LOG(GLOB.world_game_log, "ADMINPRIVATE: [text]")
 
 /proc/log_adminsay(text)
 	if (CONFIG_GET(flag/log_adminchat))
-		log_admin_private("ASAY: [text]")
+		WRITE_LOG(GLOB.world_game_log, "ADMINPRIVATE: ASAY: [text]")
 
 /proc/log_dsay(text)
 	if (CONFIG_GET(flag/log_adminchat))
-		log_admin("DSAY: [text]")
+		WRITE_LOG(GLOB.world_game_log, "ADMIN: DSAY: [text]")
+
 
+/* All other items are public. */
 /proc/log_game(text)
 	if (CONFIG_GET(flag/log_game))
-		WRITE_FILE(GLOB.world_game_log, "\[[time_stamp()]]GAME: [text]")
-
-/proc/log_vote(text)
-	if (CONFIG_GET(flag/log_vote))
-		WRITE_FILE(GLOB.world_game_log, "\[[time_stamp()]]VOTE: [text]")
+		WRITE_LOG(GLOB.world_game_log, "GAME: [text]")
 
 /proc/log_access(text)
 	if (CONFIG_GET(flag/log_access))
-		WRITE_FILE(GLOB.world_game_log, "\[[time_stamp()]]ACCESS: [text]")
-
-/proc/log_say(text)
-	if (CONFIG_GET(flag/log_say))
-		WRITE_FILE(GLOB.world_game_log, "\[[time_stamp()]]SAY: [text]")
-
-/proc/log_prayer(text)
-	if (CONFIG_GET(flag/log_prayer))
-		WRITE_FILE(GLOB.world_game_log, "\[[time_stamp()]]PRAY: [text]")
+		WRITE_LOG(GLOB.world_game_log, "ACCESS: [text]")
 
 /proc/log_law(text)
 	if (CONFIG_GET(flag/log_law))
-		WRITE_FILE(GLOB.world_game_log, "\[[time_stamp()]]LAW: [text]")
+		WRITE_LOG(GLOB.world_game_log, "LAW: [text]")
+
+/proc/log_attack(text)
+	if (CONFIG_GET(flag/log_attack))
+		WRITE_LOG(GLOB.world_attack_log, "ATTACK: [text]")
+
+/proc/log_manifest(ckey, datum/mind/mind,mob/body, latejoin = FALSE)
+	if (CONFIG_GET(flag/log_manifest))
+		WRITE_LOG(GLOB.world_manifest_log, "[ckey] \\ [body.real_name] \\ [mind.assigned_role] \\ [mind.special_role ? mind.special_role : "NONE"] \\ [latejoin ? "LATEJOIN":"ROUNDSTART"]")
+
+
+/proc/log_say(text)
+	if (CONFIG_GET(flag/log_say))
+		WRITE_LOG(GLOB.world_game_log, "SAY: [text]")
 
 /proc/log_ooc(text)
 	if (CONFIG_GET(flag/log_ooc))
-		WRITE_FILE(GLOB.world_game_log, "\[[time_stamp()]]OOC: [text]")
+		WRITE_LOG(GLOB.world_game_log, "OOC: [text]")
 
 /proc/log_whisper(text)
 	if (CONFIG_GET(flag/log_whisper))
-		WRITE_FILE(GLOB.world_game_log, "\[[time_stamp()]]WHISPER: [text]")
+		WRITE_LOG(GLOB.world_game_log, "WHISPER: [text]")
 
 /proc/log_emote(text)
 	if (CONFIG_GET(flag/log_emote))
-		WRITE_FILE(GLOB.world_game_log, "\[[time_stamp()]]EMOTE: [text]")
+		WRITE_LOG(GLOB.world_game_log, "EMOTE: [text]")
 
-/proc/log_attack(text)
-	if (CONFIG_GET(flag/log_attack))
-		WRITE_FILE(GLOB.world_attack_log, "\[[time_stamp()]]ATTACK: [text]")
+/proc/log_prayer(text)
+	if (CONFIG_GET(flag/log_prayer))
+		WRITE_LOG(GLOB.world_game_log, "PRAY: [text]")
 
 /proc/log_pda(text)
 	if (CONFIG_GET(flag/log_pda))
-		WRITE_FILE(GLOB.world_pda_log, "\[[time_stamp()]]PDA: [text]")
+		WRITE_LOG(GLOB.world_pda_log, "PDA: [text]")
 
 /proc/log_comment(text)
 	if (CONFIG_GET(flag/log_pda))
 		//reusing the PDA option because I really don't think news comments are worth a config option
-		WRITE_FILE(GLOB.world_game_log, "\[[time_stamp()]]COMMENT: [text]")
+		WRITE_LOG(GLOB.world_pda_log, "COMMENT: [text]")
 
 /proc/log_chat(text)
 	if (CONFIG_GET(flag/log_pda))
-		WRITE_FILE(GLOB.world_game_log, "\[[time_stamp()]]CHAT: [text]")
+		//same thing here
+		WRITE_LOG(GLOB.world_pda_log, "CHAT: [text]")
 
-/proc/log_qdel(text)
-	WRITE_FILE(GLOB.world_qdel_log, "\[[time_stamp()]]QDEL: [text]")
+/proc/log_vote(text)
+	if (CONFIG_GET(flag/log_vote))
+		WRITE_LOG(GLOB.world_game_log, "VOTE: [text]")
+
+
+/proc/log_topic(text)
+	WRITE_LOG(GLOB.world_game_log, "TOPIC: [text]")
+
+/proc/log_href(text)
+	WRITE_LOG(GLOB.world_href_log, "HREF: [text]")
 
 /proc/log_sql(text)
-	WRITE_FILE(GLOB.sql_error_log, "\[[time_stamp()]]SQL: [text]")
+	WRITE_LOG(GLOB.sql_error_log, "SQL: [text]")
 
-/proc/log_config(text)
-	WRITE_FILE(GLOB.config_error_log, text)
-	SEND_TEXT(world.log, text)
+/proc/log_qdel(text)
+	WRITE_LOG(GLOB.world_qdel_log, "QDEL: [text]")
 
-//This replaces world.log so it displays both in DD and the file
+/* Log to both DD and the logfile. */
 /proc/log_world(text)
-	WRITE_FILE(GLOB.world_runtime_log, text)
+	WRITE_LOG(GLOB.world_runtime_log, text)
+	SEND_TEXT(world.log, text)
+
+/* Log to the logfile only. */
+/proc/log_runtime(text)
+	WRITE_LOG(GLOB.world_runtime_log, text)
+
+/* Rarely gets called; just here in case the config breaks. */
+/proc/log_config(text)
+	WRITE_LOG(GLOB.config_error_log, text)
 	SEND_TEXT(world.log, text)
 
-// Helper procs for building detailed log lines
 
+/* For logging round startup. */
+/proc/start_log(log)
+	WRITE_LOG(log, "Starting up round ID [GLOB.round_id].\n-------------------------")
+
+/* Close open log handles. This should be called as late as possible, and no logging should hapen after. */
+/proc/shutdown_logging()
+	call(RUST_G, "log_close_all")()
+
+
+/* Helper procs for building detailed log lines */
 /proc/datum_info_line(datum/D)
 	if(!istype(D))
 		return
@@ -136,7 +170,5 @@
 	else if(A.loc)
 		return "[A.loc] (0, 0, 0) ([A.loc.type])"
 
-
-/proc/log_manifest(key,datum/mind/mind,mob/body,latejoin = FALSE)
-	if (CONFIG_GET(flag/log_manifest))
-		WRITE_FILE(GLOB.manifest_log, "[key] \\ [body.real_name] \\ [mind.assigned_role] \\ [mind.special_role ? mind.special_role : "NONE"] \\ [latejoin ? "LATEJOIN":"ROUNDSTART"]")
+//this is only used here (for now)
+#undef RUST_G

code/_globalvars/logging.dm

@@ -18,8 +18,8 @@ GLOBAL_VAR(sql_error_log)
 GLOBAL_PROTECT(sql_error_log)
 GLOBAL_VAR(world_pda_log)
 GLOBAL_PROTECT(world_pda_log)
-GLOBAL_VAR(manifest_log)
-GLOBAL_PROTECT(manifest_log)
+GLOBAL_VAR(world_manifest_log)
+GLOBAL_PROTECT(world_manifest_log)
 
 GLOBAL_LIST_EMPTY(bombers)
 GLOBAL_PROTECT(bombers)
@@ -41,4 +41,4 @@ GLOBAL_PROTECT(adminlog)
 
 GLOBAL_LIST_EMPTY(individual_log_list) // Logs each mob individual logs, a global so it doesn't get lost on cloning/changing mobs
 
-GLOBAL_LIST_EMPTY(active_turfs_startlist)
+GLOBAL_LIST_EMPTY(active_turfs_startlist)

code/controllers/configuration/configuration.dm

@@ -258,7 +258,7 @@
 			if ("disabled")
 				currentmap = null
 			else
-				WRITE_FILE(GLOB.config_error_log, "Unknown command in map vote config: '[command]'")
+				log_config("Unknown command in map vote config: '[command]'")
 
 
 /datum/controller/configuration/proc/pick_mode(mode_name)

code/game/objects/structures/morgue.dm

@@ -257,9 +257,9 @@ GLOBAL_LIST_EMPTY(crematoriums)
 				M.emote("scream")
 			if(user)
 				user.log_message("Cremated <b>[M]/[M.ckey]</b>", INDIVIDUAL_ATTACK_LOG)
-				log_attack("\[[time_stamp()]\] <b>[user]/[user.ckey]</b> cremated <b>[M]/[M.ckey]</b>")
+				log_attack("[user]/[user.ckey] cremated [M]/[M.ckey]")
 			else
-				log_attack("\[[time_stamp()]\] <b>UNKNOWN</b> cremated <b>[M]/[M.ckey]</b>")
+				log_attack("UNKNOWN cremated [M]/[M.ckey]")
 			M.death(1)
 			if(M) //some animals get automatically deleted on death.
 				M.ghostize()

code/game/world.dm

@@ -4,14 +4,14 @@ GLOBAL_VAR(security_mode)
 GLOBAL_VAR(restart_counter)
 GLOBAL_PROTECT(security_mode)
 
-//This happens after the Master subsystem news (it's a global datum)
+//This happens after the Master subsystem new(s) (it's a global datum)
 //So subsystems globals exist, but are not initialised
 /world/New()
-	log_world("World loaded at [time_stamp()]")
+	log_world("World loaded at [time_stamp()]!")
 
 	SetupExternalRSC()
 
-	GLOB.config_error_log = GLOB.manifest_log = GLOB.world_pda_log = GLOB.sql_error_log = GLOB.world_href_log = GLOB.world_runtime_log = GLOB.world_attack_log = GLOB.world_game_log = file("data/logs/config_error.log") //temporary file used to record errors with loading config, moved to log directory once logging is set bl
+	GLOB.config_error_log = GLOB.world_manifest_log = GLOB.world_pda_log = GLOB.sql_error_log = GLOB.world_href_log = GLOB.world_runtime_log = GLOB.world_attack_log = GLOB.world_game_log = "data/logs/config_error.log" //temporary file used to record errors with loading config, moved to log directory once logging is set bl
 
 	CheckSecurityMode()
 
@@ -81,24 +81,30 @@ GLOBAL_PROTECT(security_mode)
 			GLOB.log_directory += "[replacetext(time_stamp(), ":", ".")]"
 	else
 		GLOB.log_directory = "data/logs/[override_dir]"
-	GLOB.world_game_log = file("[GLOB.log_directory]/game.log")
-	GLOB.world_attack_log = file("[GLOB.log_directory]/attack.log")
-	GLOB.world_runtime_log = file("[GLOB.log_directory]/runtime.log")
-	GLOB.world_qdel_log = file("[GLOB.log_directory]/qdel.log")
-	GLOB.world_href_log = file("[GLOB.log_directory]/hrefs.html")
-	GLOB.world_pda_log = file("[GLOB.log_directory]/pda.log")
-	GLOB.sql_error_log = file("[GLOB.log_directory]/sql.log")
-	GLOB.manifest_log = file("[GLOB.log_directory]/manifest.log")
+
+	GLOB.world_game_log = "[GLOB.log_directory]/game.log"
+	GLOB.world_attack_log = "[GLOB.log_directory]/attack.log"
+	GLOB.world_pda_log = "[GLOB.log_directory]/pda.log"
+	GLOB.world_manifest_log = "[GLOB.log_directory]/manifest.log"
+	GLOB.world_href_log = "[GLOB.log_directory]/hrefs.log"
+	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"
+
 #ifdef UNIT_TESTS
 	GLOB.test_log = file("[GLOB.log_directory]/tests.log")
-	WRITE_FILE(GLOB.test_log, "\n\nStarting up round ID [GLOB.round_id]. [time_stamp()]\n---------------------")
+	start_log(GLOB.test_log)
 #endif
-	WRITE_FILE(GLOB.world_game_log, "\n\nStarting up round ID [GLOB.round_id]. [time_stamp()]\n---------------------")
-	WRITE_FILE(GLOB.world_attack_log, "\n\nStarting up round ID [GLOB.round_id]. [time_stamp()]\n---------------------")
-	WRITE_FILE(GLOB.world_runtime_log, "\n\nStarting up round ID [GLOB.round_id]. [time_stamp()]\n---------------------")
-	WRITE_FILE(GLOB.world_pda_log, "\n\nStarting up round ID [GLOB.round_id]. [time_stamp()]\n---------------------")
-	WRITE_FILE(GLOB.manifest_log, "\n\nStarting up round ID [GLOB.round_id]. [time_stamp()]\n---------------------")
-	GLOB.changelog_hash = md5('html/changelog.html')					//used for telling if the changelog has changed recently
+	start_log(GLOB.world_game_log)
+	start_log(GLOB.world_attack_log)
+	start_log(GLOB.world_pda_log)
+	start_log(GLOB.world_manifest_log)
+	start_log(GLOB.world_href_log)
+	start_log(GLOB.sql_error_log)
+	start_log(GLOB.world_qdel_log)
+	start_log(GLOB.world_runtime_log)
+
+	GLOB.changelog_hash = md5('html/changelog.html') //for telling if the changelog has changed recently
 	if(fexists(GLOB.config_error_log))
 		fcopy(GLOB.config_error_log, "[GLOB.log_directory]/config_error.log")
 		fdel(GLOB.config_error_log)
@@ -121,7 +127,6 @@ GLOBAL_PROTECT(security_mode)
 		warning("/tg/station 13 uses many file operations, a few shell()s, and some external call()s. Trusted mode is recommended. You can download our source code for your own browsing and compilation at https://github.com/tgstation/tgstation")
 
 /world/Topic(T, addr, master, key)
-
 	SERVER_TOOLS_ON_TOPIC	//redirect to server tools if necessary
 
 	var/static/list/topic_handlers = TopicHandlers()
@@ -134,7 +139,7 @@ GLOBAL_PROTECT(security_mode)
 			break
 
 	if((!handler || initial(handler.log)) && config && CONFIG_GET(flag/log_world_topic))
-		WRITE_FILE(GLOB.world_game_log, "TOPIC: \"[T]\", from:[addr], master:[master], key:[key]")
+		log_topic("\"[T]\", from:[addr], master:[master], key:[key]")
 
 	if(!handler)
 		return
@@ -210,9 +215,11 @@ GLOBAL_PROTECT(security_mode)
 
 		if(do_hard_reboot)
 			log_world("World hard rebooted at [time_stamp()]")
+			shutdown_logging() // See comment below.
 			SERVER_TOOLS_REBOOT_BYOND
 
 	log_world("World rebooted at [time_stamp()]")
+	shutdown_logging() // Past this point, no logging procs can be used, at risk of data loss.
 	..()
 
 /world/proc/update_status()