Zero-allocation optimization for sendLine and readLine

[duhminick]

Description of the issue

For each line read by the tailer, there are two extra objects that get allocated: a Line and string. Both of these are quite small and they pile up quickly depending on how many log lines there are in a file. Having a lot of small objects adds pressure to the garbage collector.

(do note that this is using a diff between two heaps, the count is much greater)

(pprof) top10 -cum
Showing nodes accounting for 4676488, 3.18% of 146846076 total
Dropped 214 nodes (cum <= 734230)
Showing top 10 nodes out of 129
      flat  flat%   sum%        cum   cum%
         0     0%     0%    4545457  3.10%  github.com/aws/amazon-cloudwatch-agent/plugins/inputs/logfile/tail.(*Tail).tailFileSync
   2408595  1.64%  1.64%    2408595  1.64%  github.com/aws/amazon-cloudwatch-agent/plugins/inputs/logfile/tail.(*Tail).sendLine
   2136820  1.46%  3.10%    2136820  1.46%  github.com/aws/amazon-cloudwatch-agent/plugins/inputs/logfile/tail.(*Tail).readLine
         0     0%  3.10%    1133050  0.77%  github.com/aws/amazon-cloudwatch-agent/logs.(*LogAgent).Run
         0     0%  3.10%    1133050  0.77%  github.com/aws/amazon-cloudwatch-agent/plugins/inputs/logfile.(*LogFile).FindLogSrc
     32768 0.022%  3.12%    1133005  0.77%  github.com/aws/amazon-cloudwatch-agent/plugins/inputs/logfile.(*LogFile).getTargetFiles
     98305 0.067%  3.18%     813662  0.55%  github.com/aws/amazon-cloudwatch-agent/plugins/outputs/cloudwatchlogs/internal/pusher.(*sender).Send
         0     0%  3.18%     813662  0.55%  github.com/aws/amazon-cloudwatch-agent/plugins/outputs/cloudwatchlogs/internal/pusher.(*senderPool).Send.func1
         0     0%  3.18%     813662  0.55%  github.com/aws/amazon-cloudwatch-agent/plugins/outputs/cloudwatchlogs/internal/pusher.(*workerPool).worker
         0     0%  3.18%     715357  0.49%  github.com/aws/amazon-cloudwatch-agent/sdk/service/cloudwatchlogs.(*CloudWatchLogs).PutLogEvents

Description of changes

Update 1:

Removing the unsafe.String usage. It looks like there's a possible race condition when using it. I can't re-create it on my own machine even when running the test 50 times. However, the GH actions unit tests seem to get it pretty often (I retried a few times). My theory after digging is that since we're getting a slice of the bytes using the buffer reader, it may have mutated which makes unsafe.String unreliable to use.

Line object pooling

A sync.Pool is used which will allow for us to re-use Line objects. We get a Line object and update the fields, then send it over to the Lines channel. The consumer of the Lines channel (tailersrc.go) must put the object back into the sync.Pool once done.

Zero-copy for string in readLine

BenchmarkUnsafeStringVsRegularString/unsafe.String
BenchmarkUnsafeStringVsRegularString/unsafe.String-10           1000000000               0.3661 ns/op
BenchmarkUnsafeStringVsRegularString/string([]byte)
BenchmarkUnsafeStringVsRegularString/string([]byte)-10          56644741                20.38 ns/op

func BenchmarkUnsafeStringVsRegularString(b *testing.B) {
	data := []byte("benchmark test string with reasonable length for performance testing")

	b.Run("unsafe.String", func(b *testing.B) {
		for i := 0; i < b.N; i++ {
			_ = unsafe.String(unsafe.SliceData(data), len(data))
		}
	})

	b.Run("string([]byte)", func(b *testing.B) {
		for i := 0; i < b.N; i++ {
			_ = string(data)
		}
	})
}

Instead of creating a new string object, we instead use unsafe.String (https://pkg.go.dev/unsafe#String) which returns the underlying bytes as a string. This is considered unsafe as strings are immutable, however we are not modifying the data -- there should be no concern.

After

Showing nodes accounting for 334238, 1.64% of 20326820 total
Dropped 544 nodes (cum <= 101634)
Showing top 10 nodes out of 189
      flat  flat%   sum%        cum   cum%
         0     0%     0%    6014194 29.59%  github.com/aws/amazon-cloudwatch-agent/logs.(*LogAgent).Run
         0     0%     0%    6005831 29.55%  github.com/aws/amazon-cloudwatch-agent/plugins/inputs/logfile.(*LogFile).FindLogSrc
    294916  1.45%  1.45%    6003766 29.54%  github.com/aws/amazon-cloudwatch-agent/plugins/inputs/logfile.(*LogFile).getTargetFiles
         0     0%  1.45%    4197164 20.65%  github.com/aws/amazon-cloudwatch-agent/plugins/outputs/cloudwatchlogs/internal/pusher.(*queue).start
     39322  0.19%  1.64%    3905002 19.21%  github.com/aws/amazon-cloudwatch-agent/plugins/outputs/cloudwatchlogs/internal/pusher.(*sender).Send
         0     0%  1.64%    3905002 19.21%  github.com/aws/amazon-cloudwatch-agent/plugins/outputs/cloudwatchlogs/internal/pusher.(*senderPool).Send.func1
         0     0%  1.64%    3905002 19.21%  github.com/aws/amazon-cloudwatch-agent/plugins/outputs/cloudwatchlogs/internal/pusher.(*workerPool).worker
         0     0%  1.64%    3706908 18.24%  github.com/aws/amazon-cloudwatch-agent/sdk/service/cloudwatchlogs.(*CloudWatchLogs).PutLogEvents
         0     0%  1.64%    3464530 17.04%  github.com/aws/aws-sdk-go/aws/request.(*HandlerList).Run
         0     0%  1.64%    3464530 17.04%  github.com/aws/aws-sdk-go/aws/request.(*Request).Send

Notice that sendLine and readLine are no longer at the top. This also means that the lines are being properly released. If they weren't, it would pile up.

License

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

Tests

1. Unit tests
2. Integration tests

Requirements

Before commiting your code, please do the following steps.

1. Run make fmt and make fmt-sh
2. Run make lint

---

Integration Tests

To run integration tests against this PR, add the ready for testing label.

[duhminick]

TIL: this won't go to the heap because the compiler is smart enough to not "escape" it