Logging: add '--log-show-timestamp' option.

Part of D4214 by @sobakasu w/ edits.

intern/clog/CLG_log.h

@@ -140,6 +140,7 @@ void CLG_exit(void);
 
 void CLG_output_set(void *file_handle);
 void CLG_output_use_basename_set(int value);
+void CLG_output_use_timestamp_set(int value);
 void CLG_fatal_fn_set(void (*fatal_fn)(void *file_handle));
 void CLG_backtrace_fn_set(void (*fatal_fn)(void *file_handle));
 

intern/clog/clog.c

@@ -31,11 +31,19 @@
 /* For 'isatty' to check for color. */
 #if defined(__unix__) || defined(__APPLE__) || defined(__HAIKU__)
 #  include <unistd.h>
+#  include <sys/time.h>
 #endif
 
 #if defined(_MSC_VER)
 #  include <io.h>
+#  include <windows.h>
 #endif
+
+/* For printing timestamp. */
+#define __STDC_FORMAT_MACROS
+#include <inttypes.h>
+
+
 /* Only other dependency (could use regular malloc too). */
 #include "MEM_guardedalloc.h"
 
@@ -69,11 +77,15 @@ typedef struct CLogContext {
 	CLG_IDFilter *filters[2];
 	bool use_color;
 	bool use_basename;
+	bool use_timestamp;
 
 	/** Borrowed, not owned. */
 	int output;
 	FILE *output_file;
 
+	/** For timer (use_timestamp). */
+	uint64_t timestamp_tick_start;
+
 	/** For new types. */
 	struct {
 		int level;
@@ -346,12 +358,35 @@ static void clg_ctx_backtrace(CLogContext *ctx)
 	fflush(ctx->output_file);
 }
 
+static uint64_t clg_timestamp_ticks_get(void)
+{
+	uint64_t tick;
+#if defined(_MSC_VER)
+	tick = GetTickCount64();
+#else
+	struct timeval tv;
+	gettimeofday(&tv, NULL);
+	tick = tv.tv_sec * 1000 + tv.tv_usec / 1000;
+#endif
+	return tick;
+}
+
 /** \} */
 
 /* -------------------------------------------------------------------- */
 /** \name Logging API
  * \{ */
 
+static void write_timestamp(CLogStringBuf *cstr, const uint64_t timestamp_tick_start)
+{
+	char timestamp_str[64];
+	const uint64_t timestamp = clg_timestamp_ticks_get() - timestamp_tick_start;
+	const uint timestamp_len = snprintf(
+	        timestamp_str, sizeof(timestamp_str), "%" PRIu64 ".%03u ",
+	        timestamp / 1000, (uint)(timestamp % 1000));
+	clg_str_append_with_len(cstr, timestamp_str, timestamp_len);
+}
+
 static void write_severity(CLogStringBuf *cstr, enum CLG_Severity severity, bool use_color)
 {
 	assert((unsigned int)severity < CLG_SEVERITY_LEN);
@@ -403,6 +438,10 @@ void CLG_log_str(
 	char cstr_stack_buf[CLOG_BUF_LEN_INIT];
 	clg_str_init(&cstr, cstr_stack_buf, sizeof(cstr_stack_buf));
 
+	if (lg->ctx->use_timestamp) {
+		write_timestamp(&cstr, lg->ctx->timestamp_tick_start);
+	}
+
 	write_severity(&cstr, severity, lg->ctx->use_color);
 	write_type(&cstr, lg);
 
@@ -435,6 +474,10 @@ void CLG_logf(
 	char cstr_stack_buf[CLOG_BUF_LEN_INIT];
 	clg_str_init(&cstr, cstr_stack_buf, sizeof(cstr_stack_buf));
 
+	if (lg->ctx->use_timestamp) {
+		write_timestamp(&cstr, lg->ctx->timestamp_tick_start);
+	}
+
 	write_severity(&cstr, severity, lg->ctx->use_color);
 	write_type(&cstr, lg);
 
@@ -483,6 +526,14 @@ static void CLG_ctx_output_use_basename_set(CLogContext *ctx, int value)
 	ctx->use_basename = (bool)value;
 }
 
+static void CLG_ctx_output_use_timestamp_set(CLogContext *ctx, int value)
+{
+	ctx->use_timestamp = (bool)value;
+	if (ctx->use_timestamp) {
+		ctx->timestamp_tick_start = clg_timestamp_ticks_get();
+	}
+}
+
 /** Action on fatal severity. */
 static void CLG_ctx_fatal_fn_set(CLogContext *ctx, void (*fatal_fn)(void *file_handle))
 {
@@ -585,6 +636,10 @@ void CLG_output_use_basename_set(int value)
 	CLG_ctx_output_use_basename_set(g_ctx, value);
 }
 
+void CLG_output_use_timestamp_set(int value)
+{
+	CLG_ctx_output_use_timestamp_set(g_ctx, value);
+}
 
 void CLG_fatal_fn_set(void (*fatal_fn)(void *file_handle))
 {

source/creator/creator_args.c

@@ -527,6 +527,7 @@ static int arg_handle_print_help(int UNUSED(argc), const char **UNUSED(argv), vo
 	BLI_argsPrintArgDoc(ba, "--log-level");
 	BLI_argsPrintArgDoc(ba, "--log-show-basename");
 	BLI_argsPrintArgDoc(ba, "--log-show-backtrace");
+	BLI_argsPrintArgDoc(ba, "--log-show-timestamp");
 	BLI_argsPrintArgDoc(ba, "--log-file");
 
 	printf("\n");
@@ -749,6 +750,15 @@ static int arg_handle_log_show_backtrace_set(int UNUSED(argc), const char **UNUS
 	return 0;
 }
 
+static const char arg_handle_log_show_timestamp_set_doc[] =
+"\n\tShow a timestamp for each log message in seconds since start."
+;
+static int arg_handle_log_show_timestamp_set(int UNUSED(argc), const char **UNUSED(argv), void *UNUSED(data))
+{
+	CLG_output_use_timestamp_set(true);
+	return 0;
+}
+
 static const char arg_handle_log_file_set_doc[] =
 "<filename>\n"
 "\n"
@@ -1876,6 +1886,7 @@ void main_args_setup(bContext *C, bArgs *ba)
 	BLI_argsAdd(ba, 1, NULL, "--log-level", CB(arg_handle_log_level_set), ba);
 	BLI_argsAdd(ba, 1, NULL, "--log-show-basename", CB(arg_handle_log_show_basename_set), ba);
 	BLI_argsAdd(ba, 1, NULL, "--log-show-backtrace", CB(arg_handle_log_show_backtrace_set), ba);
+	BLI_argsAdd(ba, 1, NULL, "--log-show-timestamp", CB(arg_handle_log_show_timestamp_set), ba);
 	BLI_argsAdd(ba, 1, NULL, "--log-file", CB(arg_handle_log_file_set), ba);
 
 	BLI_argsAdd(ba, 1, "-d", "--debug", CB(arg_handle_debug_mode_set), ba);