Debug: Remove Excess System Calls (#4052)

* - Modify debug() to avoid making excess system calls to getpid() and localtime() for every debug event.
- Rename debug_getpid -> debug_child_getpid to clarify purpose for sole use in parrot.

* format

Author: dthain

dttools/src/debug.c

@@ -34,9 +34,11 @@ extern int debug_file_reopen(void);
 extern int debug_file_close(void);
 
 static void (*debug_write)(int64_t flags, const char *str) = debug_stderr_write;
-static pid_t (*debug_getpid)(void) = getpid;
+static pid_t (*debug_child_getpid)(void) = 0;
 static char debug_program_name[PATH_MAX];
 static int64_t debug_flags = D_NOTICE | D_ERROR | D_FATAL;
+static pid_t debug_cached_pid = 0;
+static int debug_time_zone_cached = 0;
 
 struct flag_info {
 	const char *name;
@@ -182,20 +184,37 @@ static void do_debug(int64_t flags, const char *fmt, va_list args)
 		gettimeofday(&tv, 0);
 		tm = localtime(&tv.tv_sec);
 
+		/*
+		If the TZ environment variable is not set, then every single call
+		to localtime() results in a stat("/etc/localtime") which impacts
+		the minimum latency of a debug event.
+		*/
+
+		if (!debug_time_zone_cached) {
+			if (!getenv("TZ")) {
+				setenv("TZ", tm->tm_zone, 0);
+			}
+			debug_time_zone_cached = 1;
+		}
+
+		/* Fetch the pid just once and use it multiple times. */
+		pid_t pid = getpid();
+
 		buffer_putfstring(&B,
-				"%04d/%02d/%02d %02d:%02d:%02d.%02ld ",
+				"%04d/%02d/%02d %02d:%02d:%02d.%02ld %s[%d]",
 				tm->tm_year + 1900,
 				tm->tm_mon + 1,
 				tm->tm_mday,
 				tm->tm_hour,
 				tm->tm_min,
 				tm->tm_sec,
-				(long)tv.tv_usec / 10000);
-		buffer_putfstring(&B, "%s[%d] ", debug_program_name, getpid());
+				(long)tv.tv_usec / 10000,
+				debug_program_name,
+				pid);
 	}
 	/* Parrot prints debug messages for children: */
-	if (getpid() != debug_getpid()) {
-		buffer_putfstring(&B, "<child:%d> ", (int)debug_getpid());
+	if (debug_child_getpid) {
+		buffer_putfstring(&B, "<child:%d> ", (int)debug_child_getpid());
 	}
 	buffer_putfstring(&B, "%s: ", debug_flags_to_name(flags));
 
@@ -309,16 +328,17 @@ void debug_config_file(const char *path)
 void debug_config(const char *name)
 {
 	strncpy(debug_program_name, path_basename(name), sizeof(debug_program_name) - 1);
+	debug_cached_pid = getpid();
 }
 
 void debug_config_file_size(off_t size)
 {
 	debug_file_size(size);
 }
 
-void debug_config_getpid(pid_t (*getpidf)(void))
+void debug_config_child_getpid(pid_t (*getpidf)(void))
 {
-	debug_getpid = getpidf;
+	debug_child_getpid = getpidf;
 }
 
 int64_t debug_flags_clear()

dttools/src/debug.h

@@ -124,7 +124,7 @@ modify the linker namespace we are using.
 #define debug_config_file      cctools_debug_config_file
 #define debug_config_file_size cctools_debug_config_file_size
 #define debug_config_fatal     cctools_debug_config_fatal
-#define debug_config_getpid    cctools_debug_config_getpid
+#define debug_config_child_getpid    cctools_debug_config_child_getpid
 #define debug_flags_set        cctools_debug_flags_set
 #define debug_flags_print      cctools_debug_flags_print
 #define debug_flags_clear      cctools_debug_flags_clear
@@ -206,7 +206,7 @@ void debug_config_file_size(off_t size);
 
 void debug_config_fatal(void (*callback) (void));
 
-void debug_config_getpid (pid_t (*getpidf)(void));
+void debug_config_child_getpid (pid_t (*getpidf)(void));
 
 /** Set debugging flags to enable output.
 Accepts a debug flag in ASCII form, and enables that subsystem.  For example: <tt>debug_flags_set("chirp");</tt>

parrot/src/pfs_main.cc

@@ -612,7 +612,7 @@ int main( int argc, char *argv[] )
 	debug_config(argv[0]);
 	debug_config_file_size(0); /* do not rotate debug file by default */
 	debug_config_fatal(pfs_process_killall);
-	debug_config_getpid(pfs_process_getpid);
+	debug_config_child_getpid(pfs_process_getpid);
 
 	/* Special file descriptors (currently the channel and the Parrot
 	 * directory) are allocated from the top of our file descriptor pool. After