log,time: improve performance for writing a line to a log, add Time.format_rfc3339_micro/0 (#22662)

vlib/log/log.v

@@ -8,12 +8,13 @@ import time
 
 // TimeFormat define the log time string format, come from time/format.v
 pub enum TimeFormat {
-	tf_ss_micro      // YYYY-MM-DD HH:mm:ss.123456 (24h) default
+	tf_ss_micro      // YYYY-MM-DD HH:mm:ss.123456 (24h)
 	tf_default       // YYYY-MM-DD HH:mm (24h)
 	tf_ss            // YYYY-MM-DD HH:mm:ss (24h)
 	tf_ss_milli      // YYYY-MM-DD HH:mm:ss.123 (24h)
 	tf_ss_nano       // YYYY-MM-DD HH:mm:ss.123456789 (24h)
 	tf_rfc3339       // YYYY-MM-DDTHH:mm:ss.123Z (24 hours, see https://www.rfc-editor.org/rfc/rfc3339.html)
+	tf_rfc3339_micro // default, YYYY-MM-DDTHH:mm:ss.123456Z (24 hours, see https://www.rfc-editor.org/rfc/rfc3339.html)
 	tf_rfc3339_nano  // YYYY-MM-DDTHH:mm:ss.123456789Z (24 hours, see https://www.rfc-editor.org/rfc/rfc3339.html)
 	tf_hhmm          // HH:mm (24h)
 	tf_hhmmss        // HH:mm:ss (24h)
@@ -31,8 +32,8 @@ mut:
 	output_label       string
 	ofile              os.File
 	output_target      LogTarget // output to console (stdout/stderr) or file or both.
-	time_format        TimeFormat
+	time_format        TimeFormat = .tf_rfc3339_micro
-	custom_time_format string = 'MMMM Do YY N kk:mm:ss A' // timestamp with custom format
+	custom_time_format string     = 'MMMM Do YY N kk:mm:ss A' // timestamp with custom format
 	short_tag          bool
 	always_flush       bool // flush after every single .fatal(), .error(), .warn(), .info(), .debug() call
 pub mut:
@@ -116,9 +117,22 @@ pub fn (mut l Log) reopen() ! {
 
 // log_file writes log line `s` with `level` to the log file.
 fn (mut l Log) log_file(s string, level Level) {
-	timestamp := l.time_format(time.now())
+	timestamp := l.time_format(time.utc())
 	e := tag_to_file(level, l.short_tag)
-	l.ofile.writeln('${timestamp} [${e}] ${s}') or { panic(err) }
+
+	unsafe {
+		l.ofile.write_ptr(timestamp.str, timestamp.len)
+		l.ofile.write_ptr(' '.str, 1)
+
+		l.ofile.write_ptr('['.str, 1)
+		l.ofile.write_ptr(e.str, e.len)
+		l.ofile.write_ptr(']'.str, 1)
+
+		l.ofile.write_ptr(' '.str, 1)
+		l.ofile.write_ptr(s.str, s.len)
+
+		l.ofile.write_ptr('\n'.str, 1)
+	}
 	if l.always_flush {
 		l.flush()
 	}
@@ -126,7 +140,7 @@ fn (mut l Log) log_file(s string, level Level) {
 
 // log_cli writes log line `s` with `level` to stdout.
 fn (l &Log) log_cli(s string, level Level) {
-	timestamp := l.time_format(time.now())
+	timestamp := l.time_format(time.utc())
 	e := tag_to_cli(level, l.short_tag)
 	println('${timestamp} [${e}] ${s}')
 	if l.always_flush {
@@ -201,6 +215,9 @@ pub fn (mut f Log) free() {
 // time_format return a timestamp string in the pre-defined format
 fn (l Log) time_format(t time.Time) string {
 	match l.time_format {
+		.tf_rfc3339_micro { // YYYY-MM-DDTHH:mm:ss.123456Z (24 hours, see https://www.rfc-editor.org/rfc/rfc3339.html)
+			return t.format_rfc3339_micro()
+		}
 		.tf_ss_micro { // YYYY-MM-DD HH:mm:ss.123456 (24h) default
 			return t.format_ss_micro()
 		}

vlib/time/format.v

@@ -174,6 +174,39 @@ pub fn (t Time) format_rfc3339() string {
 	return buf.bytestr()
 }
 
+// format_rfc3339_micro returns a date string in "YYYY-MM-DDTHH:mm:ss.123456Z" format (24 hours, see https://www.rfc-editor.org/rfc/rfc3339.html)
+@[manualfree]
+pub fn (t Time) format_rfc3339_micro() string {
+	mut buf := [u8(`0`), `0`, `0`, `0`, `-`, `0`, `0`, `-`, `0`, `0`, `T`, `0`, `0`, `:`, `0`,
+		`0`, `:`, `0`, `0`, `.`, `0`, `0`, `0`, `0`, `0`, `0`, `Z`]
+
+	defer {
+		unsafe { buf.free() }
+	}
+
+	t_ := time_with_unix(t)
+	if t_.is_local {
+		utc_time := t_.local_to_utc()
+		int_to_byte_array_no_pad(utc_time.year, mut buf, 4)
+		int_to_byte_array_no_pad(utc_time.month, mut buf, 7)
+		int_to_byte_array_no_pad(utc_time.day, mut buf, 10)
+		int_to_byte_array_no_pad(utc_time.hour, mut buf, 13)
+		int_to_byte_array_no_pad(utc_time.minute, mut buf, 16)
+		int_to_byte_array_no_pad(utc_time.second, mut buf, 19)
+		int_to_byte_array_no_pad(utc_time.nanosecond / 1000, mut buf, 26)
+	} else {
+		int_to_byte_array_no_pad(t_.year, mut buf, 4)
+		int_to_byte_array_no_pad(t_.month, mut buf, 7)
+		int_to_byte_array_no_pad(t_.day, mut buf, 10)
+		int_to_byte_array_no_pad(t_.hour, mut buf, 13)
+		int_to_byte_array_no_pad(t_.minute, mut buf, 16)
+		int_to_byte_array_no_pad(t_.second, mut buf, 19)
+		int_to_byte_array_no_pad(t_.nanosecond / 1000, mut buf, 26)
+	}
+
+	return buf.bytestr()
+}
+
 // format_rfc3339_nano returns a date string in "YYYY-MM-DDTHH:mm:ss.123456789Z" format (24 hours, see https://www.rfc-editor.org/rfc/rfc3339.html)
 @[manualfree]
 pub fn (t Time) format_rfc3339_nano() string {

vlib/time/time_test.v

@@ -108,6 +108,18 @@ fn test_format_rfc3339() {
 	assert utc_res.contains('T')
 }
 
+fn test_format_rfc3339_micro() {
+	res := local_time_to_test.format_rfc3339_micro()
+	assert res.ends_with('23:42.123456Z')
+	assert res.starts_with('1980-07-1')
+	assert res.contains('T')
+
+	utc_res := utc_time_to_test.format_rfc3339_micro()
+	assert utc_res.ends_with('23:42.123456Z')
+	assert utc_res.starts_with('1980-07-1')
+	assert utc_res.contains('T')
+}
+
 fn test_format_rfc3339_nano() {
 	res := local_time_to_test.format_rfc3339_nano()
 	assert res.ends_with('23:42.123456789Z')

vlib/v/slow_tests/inout/dump_expression.out

@@ -10,7 +10,7 @@
             is_opened: false
         }
         output_target: console
-        time_format: tf_ss_micro
+        time_format: tf_rfc3339_micro
         custom_time_format: 'MMMM Do YY N kk:mm:ss A'
         short_tag: false
         always_flush: false