Use secondary ring buffer for service log metadata.

[hpidcock]

When developing the service log, we tried to be memory conscious to ensure that
buffering of logs would have an upper bound on memory consumption while also
being kind to the garbage collector by reusing memory.

Following this strategy, the implementation arrived at using a ring buffer per
service with metadata about each log line being stored as text. This made the
buffering and consumption of a single service very natural.

But in recent work highlighted in #673, performance issues with service log
parsing was brought to the surface. Since the blending of logs from multiple
ring buffers requires the parsing of log line metadata, it incurs unnecessary
cost to deserialise log lines to enable this blending.

Here it is proposed that the metadata from the service log is removed from the
ring buffer. The metadata is instead placed in either a structured double buffer
or a structured ring buffer.

// Entry is a parsed log entry.
type Entry struct {
    // Time of the log entry.
    Time    time.Time
    // Message is the start position in the [RingBuffer] for the log line.
    Message RingPos
}

// ServiceLog is a collection of 
type ServiceLog struct {
    // buffers is a double buffer of log entries.
    buffers [2][]Entry

    // Service is the name of the service emitted for this log.
    Service string

    // RingBuffer contains the message bytes for each log entry.
    RingBuffer RingBuffer
}

Currently the memory burden per service is at least 100KiB due to the size of
the RingBuffer created for that service. This change will increase the memory
burden by at least unsafe.Sizeof([1 or 2][N]Entry); for 10k log lines this
is an additional 32kB/64kB. This burden can be offset by reducing the size of
the RingBuffer to have a net change in cost of 0b.

The most obvious deficiency of this change is the dual limit on the length of
log history. Previously a limit of 100KiB, with some of the limit attributed to
metadata of the log lines. This proposal would limit on buffered message length
and limit on number of log lines. Worst case is either one very long line or N
small log lines. Desired average case may require analysis of real workloads or
the introduction of dynamic balancing of the ring buffer and log entry buffer to
minimise the number of buffered bytes or lines that are already detached from
each other (either the buffered bytes or the log entry are beyond the buffer).

This proposal offers an opportunity to simplify the RingBuffer implementation
by moving the iterator implementation over to the new service log buffer. It can
instead facilitate a per-log-entry iteration and the waiting for new entries.
The iterator can also be reduced in complexity, as the emitting of truncation
messages can be simplified.

[benhoyt]

@dimaqq Had an interesting observation: could we just compare the timestamps as strings (they're in format "2021-05-20T15:39:12.345Z" so comparable as strings) when we order the merged logs for output. Worth further thought.

Additionally, it's worth spending half a day or so doing some performance testing to see whether this is worth it.

Assigning to @IronCore864 to determine 1) do performance testing, 2) see whether we can just compare timestamps as strings.

[IronCore864]

Here is a solution to improve the performance by not using bytes.SplitN. I did some testing with it: Before the fix in the solution, the benchmark test here takes 120 ns/op on average, and with the fix, it's reduced to 39 ns/op.

I did not fully understand the proposed solution, but the benchmark result interested me, so I did some testing on a Mac with an M4 chip. While it is a great improvement at almost 70% reduction, the unit is in nanoseconds, which makes me guess it's probably not worth it.

To validate my guess, I created a test for the streamLogs function where the parser is used:

// createTestIterators creates real servicelog.Iterator instances for benchmarking
func createTestIterators(entries []servicelog.Entry, serviceName string) servicelog.Iterator {
	// Create a smaller RingBuffer to reduce memory overhead
	rb := servicelog.NewRingBuffer(64 * 1024) // 64KB buffer
	lw := servicelog.NewFormatWriter(rb, serviceName)

	// Write all entries to the ring buffer using the proper format
	for _, entry := range entries {
		fmt.Fprintf(lw, "%s\n", entry.Message)
	}

	// Get a tail iterator from the ring buffer
	return rb.TailIterator()
}

// BenchmarkStreamLogs_SingleService benchmarks streamLogs with one service and 1000 entries
func BenchmarkStreamLogs_SingleService(b *testing.B) {
	// Create test data with 100 entries
	entries := make([]servicelog.Entry, 100)
	baseTime := time.Now()
	for i := 0; i < 100; i++ {
		entries[i] = servicelog.Entry{
			Time:    baseTime.Add(time.Duration(i) * time.Millisecond),
			Service: "test-service",
			Message: fmt.Sprintf("log message %d", i),
		}
	}

	b.ResetTimer()
	for i := 0; i < b.N; i++ {
		// Create fresh iterators for each benchmark iteration
		its := map[string]servicelog.Iterator{
			"test-service": createTestIterators(entries, "test-service"),
		}

		logs := make(chan servicelog.Entry, 100)
		done := make(chan struct{})

		// Start streaming in a goroutine
		go func() {
			defer close(logs)
			streamLogs(its, logs, done)
		}()

		// Consume all logs
		count := 0
		for log := range logs {
			if !log.Time.IsZero() {
				count++
				// Close done channel after receiving all 100 logs
				if count == 100 {
					close(done)
				}
			}
		}

		// Verify we got all logs
		if count != 100 {
			b.Fatalf("Expected 100 logs, got %d", count)
		}
	}
}

For a single service with merely 100 entries of logs (which probably is less than a realistic scenario), BenchmarkStreamLogs_SingleService (mostly creating an iterator then calling streamLogs, which also does sorting) takes c.a. 42,000 ns/op.

So, even if Parser.Next (which calls Parse, which returns an Entry with a timestamp) takes 0 nanoseconds, comparatively speaking, the optimization cuts approximately 120 nanoseconds off the 42,000-nanosecond baseline, which is less than 0.3% improvement. If we talk about absolute numbers, 120 nanoseconds is 0.00000012 seconds, parsing 1000 logs would be 0.00012 seconds, which isn't much.

FYI, if we change Entry.Time to a string, BenchmarkParser test takes 59 ns/op, the improvement is less than what's in the PR mentioned at the beginning.

As a summary, I think maybe it's not worth it, especially considering Entry is used in multiple places, and servicelog.Parse is also used in the main test/root test.

[benhoyt]

@IronCore864 I think we should probably table Harry's suggestion for now -- I think it's a good one, but would be a fair bit of work. For now, perhaps we can stick with a more targeted optimisation, like the one I proposed here: #673 (review)

And instead of string interning, which is a bit messy, do a single string() call on both the service name and the log message (to get a single allocation), and then use subslicing on that to set Entry.Service and Entry.Message.

Let me know if you want to discuss further.