[pkg/stanza] make log emitter and entry conversion in adapter synchronous #35669

bacherfl · 2024-10-08T08:28:59Z

Description

This PR changes the LogEmitter to accept a synchronous consumer callback function for processing a batch of log entries as an alternative to sending log entry batches to a channel.
The components that use the LogEmitter (adapter and parser) have been adapted accordingly. Also, in the case of the adapter, the log entries are converted directly, rather than sending them over a channel to the converter and receiving the converted results over a different channel.

Link to tracking issue

Fixes #35453

Testing

I did some initial performance tests using the TestLogLargeFiles load test to see how this change affects the performance. Below are the results:

Before the change (i.e. with async log entry batch processing)

=== RUN   TestLogLargeFiles/filelog-largefiles-2Gb-lifetime
2024/10/08 09:02:53  | Sent:17,769,795 logs (179,507/sec) | Received:17,755,188 items (179,346/sec)

=== RUN   TestLogLargeFiles/filelog-largefiles-6GB-lifetime
2024/10/08 09:06:29  | Sent:42,857,755 logs (216,465/sec) | Received:42,851,987 items (216,424/sec)

Test                                         |Result|Duration|CPU Avg%|CPU Max%|RAM Avg MiB|RAM Max MiB|Sent Items|Received Items|
---------------------------------------------|------|-------:|-------:|-------:|----------:|----------:|---------:|-------------:|
LogLargeFiles/filelog-largefiles-2Gb-lifetime|PASS  |    100s|    73.1|    78.4|        106|        118|  18249451|      18249451|
LogLargeFiles/filelog-largefiles-6GB-lifetime|PASS  |    200s|    87.5|    98.1|        110|        116|  44358460|      44358460|

After the change (i.e. with sync log entry batch processing)

=== RUN   TestLogLargeFiles/filelog-largefiles-2Gb-lifetime
2024/10/08 10:09:51 Agent RAM (RES): 139 MiB, CPU:71.7% | Sent:17,802,561 logs (179,836/sec) | Received:17,788,273 items (179,680/sec)

=== RUN   TestLogLargeFiles/filelog-largefiles-6GB-lifetime
2024/10/08 10:05:15 Agent RAM (RES): 140 MiB, CPU:95.6% | Sent:42,912,030 logs (216,744/sec) | Received:42,904,306 items (216,689/sec)

Test                                         |Result|Duration|CPU Avg%|CPU Max%|RAM Avg MiB|RAM Max MiB|Sent Items|Received Items|
---------------------------------------------|------|-------:|-------:|-------:|----------:|----------:|---------:|-------------:|
LogLargeFiles/filelog-largefiles-2Gb-lifetime|PASS  |    100s|    74.8|    78.9|        127|        139|  17984687|      17984687|
LogLargeFiles/filelog-largefiles-6GB-lifetime|PASS  |    200s|    89.3|   100.9|        134|        140|  43376210|      43376210|

Those results seem to indicate comparable throughput, but with an increased resource consumption, especially in terms of memory.

I also did a test comparing the performance between the synchronous and asynchronous log emitter using the same methodology as in #35454.

The results were the following, and indicate an increase in the time it takes for reading the generated log file (see #35454 for details on how the file is generated and the test execution):

Async Log Emitter: ~8s
Sync Log Emitter: ~12s

output-async.log

=== Step 3: Thu Oct 10 08:54:23 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="3744d4cb-5080-427c-8c16-a96cb40a57d4",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 2.209674e+06 === Step 4: Thu Oct 10 08:54:25 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="3744d4cb-5080-427c-8c16-a96cb40a57d4",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 5.428103e+06 === Step 5: Thu Oct 10 08:54:26 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="3744d4cb-5080-427c-8c16-a96cb40a57d4",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 7.337017e+06 === Step 6: Thu Oct 10 08:54:27 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="3744d4cb-5080-427c-8c16-a96cb40a57d4",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 9.258843e+06 === Step 7: Thu Oct 10 08:54:29 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="3744d4cb-5080-427c-8c16-a96cb40a57d4",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.3082428e+07 === Step 8: Thu Oct 10 08:54:31 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="3744d4cb-5080-427c-8c16-a96cb40a57d4",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.6519068e+07

output-sync.log

=== Step 2: Thu Oct 10 08:51:27 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.580891e+06 === Step 3: Thu Oct 10 08:51:28 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 3.01034e+06 === Step 4: Thu Oct 10 08:51:29 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 4.434627e+06 === Step 5: Thu Oct 10 08:51:31 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 7.416612e+06 === Step 6: Thu Oct 10 08:51:34 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.0496072e+07 === Step 7: Thu Oct 10 08:51:36 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.3523882e+07 === Step 8: Thu Oct 10 08:51:37 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.4929707e+07 === Step 9: Thu Oct 10 08:51:39 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.6519105e+07

Signed-off-by: Florian Bacher <[email protected]>

… log emitter Signed-off-by: Florian Bacher <[email protected]>

Signed-off-by: Florian Bacher <[email protected]>

djaglowski

Thanks for working on this.

I am not very certain that the testbed benchmarks are a fair comparison for these changes, since they rely on so many external factors besides the adapter code itself. I left some suggestions about how we can update the adapter benchmarks to give us a better comparison.

pkg/stanza/operator/helper/emitter.go

testbed/tests/scenarios.go

testbed/tests/log_test.go

processor/logstransformprocessor/processor.go

pkg/stanza/operator/parser/container/parser.go

pkg/stanza/adapter/receiver.go

pkg/stanza/operator/helper/emitter.go

pkg/stanza/adapter/receiver_test.go

bacherfl · 2024-10-16T05:01:42Z

Thanks for the thorough review @djaglowski and sorry for the late reply - I will go through all comments today and address them

Signed-off-by: Florian Bacher <[email protected]>

pkg/stanza/adapter/converter.go

pkg/stanza/adapter/receiver_test.go

Signed-off-by: Florian Bacher <[email protected]>

#### Description This PR introduces a benchmark test for the receiver adapter which tests the performance of handling the log entries sent to the `LogEmitter`, which are then received and converted by the receiver adapter. The changes have been made based on the comment linked here: #35669 (comment)  #### Link to tracking issue Part of #35453  #### Testing Added additional benchmark tests --------- Signed-off-by: Florian Bacher <[email protected]>

bacherfl · 2024-10-29T07:32:59Z

@andrzej-stencel One question regarding the removal of the converter: I've found that this is currently used in two places other than pkg/stanza:

Filelog receiver tests:

opentelemetry-collector-contrib/receiver/filelogreceiver/filelog_test.go

Line 84 in e8256ae

converter := adapter.NewConverter(componenttest.NewNopTelemetrySettings())
Namedpipe receiver:

opentelemetry-collector-contrib/receiver/namedpipereceiver/namedpipe_test.go

Line 58 in e8256ae

converter := adapter.NewConverter(componenttest.NewNopTelemetrySettings())

In both cases it seems like the converter is used to generate test data, and can likely be replaced easily with the Convert function. Do you think we can include the adaptations for the tests of these two receivers in this PR, or would you prefer to have this done in a separate PR?
In the latter case we would need to keep the Converter type for now and then remove it as part of the follow up PR.

Signed-off-by: Florian Bacher <[email protected]>

djaglowski · 2024-10-29T16:01:17Z

I agree it should be possible to refactor those tests to remove the converter. Seems like a good followup PR.

Regarding the benchmarks, do you mind running them multiple times and using benchstat to compare?

go test -benchmem -run=^$ -bench . ./path/to/package -count=10 | tee before.txt
...
go test -benchmem -run=^$ -bench . ./path/to/package -count=10 | tee after.txt

benchstat before.txt after.txt

Based on the one run it looks promising but given the impact here I think we should have a more statistically significant comparison. If these are running quickly, it'd be interesting to see another order of magnitude too (not required though).

bacherfl · 2024-10-30T06:16:18Z

I agree it should be possible to refactor those tests to remove the converter. Seems like a good followup PR.

Regarding the benchmarks, do you mind running them multiple times and using benchstat to compare?
go test -benchmem -run=^$ -bench . ./path/to/package -count=10 | tee before.txt
...
go test -benchmem -run=^$ -bench . ./path/to/package -count=10 | tee after.txt

benchstat before.txt after.txt
Based on the one run it looks promising but given the impact here I think we should have a more statistically significant comparison. If these are running quickly, it'd be interesting to see another order of magnitude too (not required though).

Sure, will post the updated results soon

bacherfl · 2024-10-30T10:30:31Z

Alright, here is the result of the benchstat comparison:

goos: darwin
goarch: arm64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/adapter
                                                │ before.txt  │              after.txt               │
                                                │   sec/op    │    sec/op     vs base                │
Receiver/1_Log_entry_per_iteration-10             100.1m ± 0%   100.1m ±  0%        ~ (p=0.631 n=10)
Receiver/10_Log_entries_per_iteration-10          100.1m ± 0%   100.1m ±  0%        ~ (p=0.218 n=10)
Receiver/100_Log_entries_per_iteration-10         258.1µ ± 8%   253.4µ ±  1%   -1.82% (p=0.000 n=10)
Receiver/1_000_Log_entries_per_iteration-10       1.615m ± 8%   2.518m ±  1%  +55.94% (p=0.000 n=10)
Receiver/10_000_Log_entries_per_iteration-10      15.49m ± 2%   25.14m ±  6%  +62.30% (p=0.000 n=10)
Receiver/100_000_Log_entries_per_iteration-10     159.0m ± 5%   251.9m ± 44%  +58.45% (p=0.000 n=10)
Receiver/1_000_000_Log_entries_per_iteration-10    1.545 ± 4%    2.506 ±  0%  +62.19% (p=0.000 n=10)
geomean                                           28.66m        37.35m        +30.33%

                                                │  before.txt  │              after.txt              │
                                                │     B/op     │     B/op      vs base               │
Receiver/1_Log_entry_per_iteration-10             4.365Ki ± 2%   4.320Ki ± 1%       ~ (p=0.100 n=10)
Receiver/10_Log_entries_per_iteration-10          18.49Ki ± 1%   18.44Ki ± 0%  -0.28% (p=0.000 n=10)
Receiver/100_Log_entries_per_iteration-10         158.5Ki ± 0%   158.5Ki ± 0%  +0.01% (p=0.000 n=10)
Receiver/1_000_Log_entries_per_iteration-10       1.549Mi ± 0%   1.548Mi ± 0%  -0.08% (p=0.000 n=10)
Receiver/10_000_Log_entries_per_iteration-10      15.48Mi ± 0%   15.48Mi ± 0%  -0.06% (p=0.000 n=10)
Receiver/100_000_Log_entries_per_iteration-10     154.8Mi ± 0%   154.8Mi ± 0%  -0.05% (p=0.000 n=10)
Receiver/1_000_000_Log_entries_per_iteration-10   1.512Gi ± 0%   1.511Gi ± 0%  -0.05% (p=0.000 n=10)
geomean                                           1.829Mi        1.825Mi       -0.22%

                                                │ before.txt  │              after.txt               │
                                                │  allocs/op  │  allocs/op   vs base                 │
Receiver/1_Log_entry_per_iteration-10              83.00 ± 1%    82.00 ± 1%  -1.20% (p=0.010 n=10)
Receiver/10_Log_entries_per_iteration-10           510.0 ± 0%    509.0 ± 0%  -0.20% (p=0.001 n=10)
Receiver/100_Log_entries_per_iteration-10         4.734k ± 0%   4.734k ± 0%       ~ (p=1.000 n=10) ¹
Receiver/1_000_Log_entries_per_iteration-10       47.36k ± 0%   47.34k ± 0%  -0.04% (p=0.000 n=10)
Receiver/10_000_Log_entries_per_iteration-10      473.5k ± 0%   473.4k ± 0%  -0.03% (p=0.000 n=10)
Receiver/100_000_Log_entries_per_iteration-10     4.735M ± 0%   4.734M ± 0%  -0.03% (p=0.000 n=10)
Receiver/1_000_000_Log_entries_per_iteration-10   47.35M ± 0%   47.34M ± 0%  -0.03% (p=0.000 n=10)
geomean                                           51.85k        51.74k       -0.22%

bacherfl · 2024-10-30T10:32:43Z

@andrzej-stencel @djaglowski I think this is ready for review now, since the removal of the converter type will be done as a follow up

djaglowski · 2024-10-30T15:20:14Z

goos: darwin
goarch: arm64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/adapter
                                                │ before.txt  │              after.txt               │
                                                │   sec/op    │    sec/op     vs base                │
Receiver/1_Log_entry_per_iteration-10             100.1m ± 0%   100.1m ±  0%        ~ (p=0.631 n=10)
Receiver/10_Log_entries_per_iteration-10          100.1m ± 0%   100.1m ±  0%        ~ (p=0.218 n=10)
Receiver/100_Log_entries_per_iteration-10         258.1µ ± 8%   253.4µ ±  1%   -1.82% (p=0.000 n=10)
Receiver/1_000_Log_entries_per_iteration-10       1.615m ± 8%   2.518m ±  1%  +55.94% (p=0.000 n=10)
Receiver/10_000_Log_entries_per_iteration-10      15.49m ± 2%   25.14m ±  6%  +62.30% (p=0.000 n=10)
Receiver/100_000_Log_entries_per_iteration-10     159.0m ± 5%   251.9m ± 44%  +58.45% (p=0.000 n=10)
Receiver/1_000_000_Log_entries_per_iteration-10    1.545 ± 4%    2.506 ±  0%  +62.19% (p=0.000 n=10)
geomean                                           28.66m        37.35m        +30.33%

                                                │  before.txt  │              after.txt              │
                                                │     B/op     │     B/op      vs base               │
Receiver/1_Log_entry_per_iteration-10             4.365Ki ± 2%   4.320Ki ± 1%       ~ (p=0.100 n=10)
Receiver/10_Log_entries_per_iteration-10          18.49Ki ± 1%   18.44Ki ± 0%  -0.28% (p=0.000 n=10)
Receiver/100_Log_entries_per_iteration-10         158.5Ki ± 0%   158.5Ki ± 0%  +0.01% (p=0.000 n=10)
Receiver/1_000_Log_entries_per_iteration-10       1.549Mi ± 0%   1.548Mi ± 0%  -0.08% (p=0.000 n=10)
Receiver/10_000_Log_entries_per_iteration-10      15.48Mi ± 0%   15.48Mi ± 0%  -0.06% (p=0.000 n=10)
Receiver/100_000_Log_entries_per_iteration-10     154.8Mi ± 0%   154.8Mi ± 0%  -0.05% (p=0.000 n=10)
Receiver/1_000_000_Log_entries_per_iteration-10   1.512Gi ± 0%   1.511Gi ± 0%  -0.05% (p=0.000 n=10)
geomean                                           1.829Mi        1.825Mi       -0.22%

                                                │ before.txt  │              after.txt               │
                                                │  allocs/op  │  allocs/op   vs base                 │
Receiver/1_Log_entry_per_iteration-10              83.00 ± 1%    82.00 ± 1%  -1.20% (p=0.010 n=10)
Receiver/10_Log_entries_per_iteration-10           510.0 ± 0%    509.0 ± 0%  -0.20% (p=0.001 n=10)
Receiver/100_Log_entries_per_iteration-10         4.734k ± 0%   4.734k ± 0%       ~ (p=1.000 n=10) ¹
Receiver/1_000_Log_entries_per_iteration-10       47.36k ± 0%   47.34k ± 0%  -0.04% (p=0.000 n=10)
Receiver/10_000_Log_entries_per_iteration-10      473.5k ± 0%   473.4k ± 0%  -0.03% (p=0.000 n=10)
Receiver/100_000_Log_entries_per_iteration-10     4.735M ± 0%   4.734M ± 0%  -0.03% (p=0.000 n=10)
Receiver/1_000_000_Log_entries_per_iteration-10   47.35M ± 0%   47.34M ± 0%  -0.03% (p=0.000 n=10)
geomean                                           51.85k        51.74k       -0.22%

@bacherfl, this appears to show a ~60% increase in CPU consumption, but the earlier (single run) result showed just about the opposite. Just double checking, is it possible before/after were switched?

andrzej-stencel

I re-ran the manual test "Run the collector binary reading a 1 GiB file" described in detail in #35454 (comment), comparing v0.112.0 to this PR. Surprisingly, the results say pretty consistently that this change decreases the time for File Log receiver to read a 1 GB file from ~17 seconds to ~14-15 seconds. This is about 15% improvement in performance!

pkg/stanza/operator/helper/emitter.go

bacherfl · 2024-11-04T06:35:33Z

goos: darwin
goarch: arm64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/adapter
                                                │ before.txt  │              after.txt               │
                                                │   sec/op    │    sec/op     vs base                │
Receiver/1_Log_entry_per_iteration-10             100.1m ± 0%   100.1m ±  0%        ~ (p=0.631 n=10)
Receiver/10_Log_entries_per_iteration-10          100.1m ± 0%   100.1m ±  0%        ~ (p=0.218 n=10)
Receiver/100_Log_entries_per_iteration-10         258.1µ ± 8%   253.4µ ±  1%   -1.82% (p=0.000 n=10)
Receiver/1_000_Log_entries_per_iteration-10       1.615m ± 8%   2.518m ±  1%  +55.94% (p=0.000 n=10)
Receiver/10_000_Log_entries_per_iteration-10      15.49m ± 2%   25.14m ±  6%  +62.30% (p=0.000 n=10)
Receiver/100_000_Log_entries_per_iteration-10     159.0m ± 5%   251.9m ± 44%  +58.45% (p=0.000 n=10)
Receiver/1_000_000_Log_entries_per_iteration-10    1.545 ± 4%    2.506 ±  0%  +62.19% (p=0.000 n=10)
geomean                                           28.66m        37.35m        +30.33%

                                                │  before.txt  │              after.txt              │
                                                │     B/op     │     B/op      vs base               │
Receiver/1_Log_entry_per_iteration-10             4.365Ki ± 2%   4.320Ki ± 1%       ~ (p=0.100 n=10)
Receiver/10_Log_entries_per_iteration-10          18.49Ki ± 1%   18.44Ki ± 0%  -0.28% (p=0.000 n=10)
Receiver/100_Log_entries_per_iteration-10         158.5Ki ± 0%   158.5Ki ± 0%  +0.01% (p=0.000 n=10)
Receiver/1_000_Log_entries_per_iteration-10       1.549Mi ± 0%   1.548Mi ± 0%  -0.08% (p=0.000 n=10)
Receiver/10_000_Log_entries_per_iteration-10      15.48Mi ± 0%   15.48Mi ± 0%  -0.06% (p=0.000 n=10)
Receiver/100_000_Log_entries_per_iteration-10     154.8Mi ± 0%   154.8Mi ± 0%  -0.05% (p=0.000 n=10)
Receiver/1_000_000_Log_entries_per_iteration-10   1.512Gi ± 0%   1.511Gi ± 0%  -0.05% (p=0.000 n=10)
geomean                                           1.829Mi        1.825Mi       -0.22%

                                                │ before.txt  │              after.txt               │
                                                │  allocs/op  │  allocs/op   vs base                 │
Receiver/1_Log_entry_per_iteration-10              83.00 ± 1%    82.00 ± 1%  -1.20% (p=0.010 n=10)
Receiver/10_Log_entries_per_iteration-10           510.0 ± 0%    509.0 ± 0%  -0.20% (p=0.001 n=10)
Receiver/100_Log_entries_per_iteration-10         4.734k ± 0%   4.734k ± 0%       ~ (p=1.000 n=10) ¹
Receiver/1_000_Log_entries_per_iteration-10       47.36k ± 0%   47.34k ± 0%  -0.04% (p=0.000 n=10)
Receiver/10_000_Log_entries_per_iteration-10      473.5k ± 0%   473.4k ± 0%  -0.03% (p=0.000 n=10)
Receiver/100_000_Log_entries_per_iteration-10     4.735M ± 0%   4.734M ± 0%  -0.03% (p=0.000 n=10)
Receiver/1_000_000_Log_entries_per_iteration-10   47.35M ± 0%   47.34M ± 0%  -0.03% (p=0.000 n=10)
geomean                                           51.85k        51.74k       -0.22%

@bacherfl, this appears to show a ~60% increase in CPU consumption, but the earlier (single run) result showed just about the opposite. Just double checking, is it possible before/after were switched?

@djaglowski this does seem a bit odd, I will double check the results again

I just re-ran the tests and got the same results - However I noticed that I posted the sync results (i.e. after) before the async (before) results in the single run results, so that may have been misleading. Considering this, the results seem to be consistent also with the multiple-run results

Co-authored-by: Andrzej Stencel <[email protected]>

Signed-off-by: Florian Bacher <[email protected]>

djaglowski

Thanks for taking this on @bacherfl.

The performance hit is unfortunate but it appears necessary to increase reliability (and maintainability).

#### Description This PR removes the `Converter` type that was previously used mainly by the stanza receiver adapter (see #35669 (comment) for more details). Two other receivers were still using the converter to generate test data within the unit tests, so those have been adapted as well with this PR  #### Link to tracking issue Follow up to #35453  #### Testing Adapted unit tests that were still using the converter --------- Signed-off-by: Florian Bacher <[email protected]>

#### Description This PR removes the `Converter` type that was previously used mainly by the stanza receiver adapter (see open-telemetry#35669 (comment) for more details). Two other receivers were still using the converter to generate test data within the unit tests, so those have been adapted as well with this PR  #### Link to tracking issue Follow up to open-telemetry#35453  #### Testing Adapted unit tests that were still using the converter --------- Signed-off-by: Florian Bacher <[email protected]>

#### Description This PR introduces a benchmark test for the receiver adapter which tests the performance of handling the log entries sent to the `LogEmitter`, which are then received and converted by the receiver adapter. The changes have been made based on the comment linked here: open-telemetry#35669 (comment)  #### Link to tracking issue Part of open-telemetry#35453  #### Testing Added additional benchmark tests --------- Signed-off-by: Florian Bacher <[email protected]>

…nous (open-telemetry#35669)  #### Description This PR changes the `LogEmitter` to accept a synchronous consumer callback function for processing a batch of log entries as an alternative to sending log entry batches to a channel. The components that use the `LogEmitter` (adapter and parser) have been adapted accordingly. Also, in the case of the adapter, the log entries are converted directly, rather than sending them over a channel to the converter and receiving the converted results over a different channel.  #### Link to tracking issue Fixes open-telemetry#35453  #### Testing I did some initial performance tests using the `TestLogLargeFiles` load test to see how this change affects the performance. Below are the results: **Before the change (i.e. with async log entry batch processing)** ``` === RUN TestLogLargeFiles/filelog-largefiles-2Gb-lifetime 2024/10/08 09:02:53 | Sent:17,769,795 logs (179,507/sec) | Received:17,755,188 items (179,346/sec) === RUN TestLogLargeFiles/filelog-largefiles-6GB-lifetime 2024/10/08 09:06:29 | Sent:42,857,755 logs (216,465/sec) | Received:42,851,987 items (216,424/sec) Test |Result|Duration|CPU Avg%|CPU Max%|RAM Avg MiB|RAM Max MiB|Sent Items|Received Items| ---------------------------------------------|------|-------:|-------:|-------:|----------:|----------:|---------:|-------------:| LogLargeFiles/filelog-largefiles-2Gb-lifetime|PASS | 100s| 73.1| 78.4| 106| 118| 18249451| 18249451| LogLargeFiles/filelog-largefiles-6GB-lifetime|PASS | 200s| 87.5| 98.1| 110| 116| 44358460| 44358460| ``` **After the change (i.e. with sync log entry batch processing)** ``` === RUN TestLogLargeFiles/filelog-largefiles-2Gb-lifetime 2024/10/08 10:09:51 Agent RAM (RES): 139 MiB, CPU:71.7% | Sent:17,802,561 logs (179,836/sec) | Received:17,788,273 items (179,680/sec) === RUN TestLogLargeFiles/filelog-largefiles-6GB-lifetime 2024/10/08 10:05:15 Agent RAM (RES): 140 MiB, CPU:95.6% | Sent:42,912,030 logs (216,744/sec) | Received:42,904,306 items (216,689/sec) Test |Result|Duration|CPU Avg%|CPU Max%|RAM Avg MiB|RAM Max MiB|Sent Items|Received Items| ---------------------------------------------|------|-------:|-------:|-------:|----------:|----------:|---------:|-------------:| LogLargeFiles/filelog-largefiles-2Gb-lifetime|PASS | 100s| 74.8| 78.9| 127| 139| 17984687| 17984687| LogLargeFiles/filelog-largefiles-6GB-lifetime|PASS | 200s| 89.3| 100.9| 134| 140| 43376210| 43376210| ``` Those results seem to indicate comparable throughput, but with an increased resource consumption, especially in terms of memory. I also did a test comparing the performance between the synchronous and asynchronous log emitter using the same methodology as in open-telemetry#35454. The results were the following, and indicate an increase in the time it takes for reading the generated log file (see open-telemetry#35454 for details on how the file is generated and the test execution): - Async Log Emitter: ~8s - Sync Log Emitter: ~12s <details> <summary>output-async.log</summary> === Step 3: Thu Oct 10 08:54:23 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="3744d4cb-5080-427c-8c16-a96cb40a57d4",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 2.209674e+06 === Step 4: Thu Oct 10 08:54:25 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="3744d4cb-5080-427c-8c16-a96cb40a57d4",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 5.428103e+06 === Step 5: Thu Oct 10 08:54:26 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="3744d4cb-5080-427c-8c16-a96cb40a57d4",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 7.337017e+06 === Step 6: Thu Oct 10 08:54:27 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="3744d4cb-5080-427c-8c16-a96cb40a57d4",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 9.258843e+06 === Step 7: Thu Oct 10 08:54:29 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="3744d4cb-5080-427c-8c16-a96cb40a57d4",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.3082428e+07 === Step 8: Thu Oct 10 08:54:31 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="3744d4cb-5080-427c-8c16-a96cb40a57d4",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.6519068e+07 </details> <details> <summary>output-sync.log</summary> === Step 2: Thu Oct 10 08:51:27 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.580891e+06 === Step 3: Thu Oct 10 08:51:28 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 3.01034e+06 === Step 4: Thu Oct 10 08:51:29 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 4.434627e+06 === Step 5: Thu Oct 10 08:51:31 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 7.416612e+06 === Step 6: Thu Oct 10 08:51:34 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.0496072e+07 === Step 7: Thu Oct 10 08:51:36 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.3523882e+07 === Step 8: Thu Oct 10 08:51:37 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.4929707e+07 === Step 9: Thu Oct 10 08:51:39 CEST 2024 otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="dcf5371b-19eb-47b3-a820-756c1832b448",service_name="otelcontribcol",service_version="0.111.0-dev",transport=""} 1.6519105e+07 </details> --------- Signed-off-by: Florian Bacher <[email protected]> Co-authored-by: Andrzej Stencel <[email protected]>

#### Description This PR removes the `Converter` type that was previously used mainly by the stanza receiver adapter (see open-telemetry#35669 (comment) for more details). Two other receivers were still using the converter to generate test data within the unit tests, so those have been adapted as well with this PR  #### Link to tracking issue Follow up to open-telemetry#35453  #### Testing Adapted unit tests that were still using the converter --------- Signed-off-by: Florian Bacher <[email protected]>

[pkg/stanza] make log emitter and entry conversion synchronous

e39f7d6

Signed-off-by: Florian Bacher <[email protected]>

github-actions bot added pkg/stanza testbed labels Oct 8, 2024

github-actions bot requested a review from djaglowski October 8, 2024 08:29

bacherfl added 2 commits October 9, 2024 09:31

Merge branch 'main' into feat/35453/synchronous-log-emitter

0229024

adapt container parser and log transformer to work synchronously with…

9d7f616

… log emitter Signed-off-by: Florian Bacher <[email protected]>

github-actions bot added the processor/logstransform Logs Transform processor label Oct 9, 2024

adapt container parser and log transformer to work synchronously with…

f2a4063

… log emitter Signed-off-by: Florian Bacher <[email protected]>

github-actions bot requested a review from dehaansa October 9, 2024 11:47

bacherfl changed the title ~~[pkg/stanza] make log emitter and entry conversion in adapter synchronous~~ [chore] make log emitter and entry conversion in adapter synchronous Oct 9, 2024

bacherfl added 7 commits October 9, 2024 14:13

trigger CI checks

04709ed

Signed-off-by: Florian Bacher <[email protected]>

adapt tests

602a01d

Signed-off-by: Florian Bacher <[email protected]>

fix linting

827cc94

Signed-off-by: Florian Bacher <[email protected]>

remove unused fields and adapt integration tests

6e5fac5

Signed-off-by: Florian Bacher <[email protected]>

remove unused fields, fix linting

0dd265d

Signed-off-by: Florian Bacher <[email protected]>

fix data race in unit test

5d957f1

Signed-off-by: Florian Bacher <[email protected]>

Merge branch 'main' into feat/35453/synchronous-log-emitter

7430d6c

bacherfl changed the title ~~[chore] make log emitter and entry conversion in adapter synchronous~~ [pkg/stanza] make log emitter and entry conversion in adapter synchronous Oct 10, 2024

bacherfl added 2 commits October 10, 2024 09:40

add changelog entry

404cc31

Signed-off-by: Florian Bacher <[email protected]>

Merge branch 'main' into feat/35453/synchronous-log-emitter

9d69cb7

bacherfl marked this pull request as ready for review October 10, 2024 08:53

bacherfl requested a review from a team as a code owner October 10, 2024 08:53

github-actions bot assigned djaglowski Oct 10, 2024

djaglowski reviewed Oct 10, 2024

View reviewed changes

address comments from PR review

3c92b32

Signed-off-by: Florian Bacher <[email protected]>

bacherfl mentioned this pull request Oct 16, 2024

[chore] add receiver adapter benchmark tests #35833

Merged

djaglowski reviewed Oct 16, 2024

View reviewed changes

pkg/stanza/adapter/converter.go Outdated Show resolved Hide resolved

pkg/stanza/adapter/receiver_test.go Outdated Show resolved Hide resolved

send converted entries to flushChan directly

4f1624d

Signed-off-by: Florian Bacher <[email protected]>

fix linting

6907735

Signed-off-by: Florian Bacher <[email protected]>

bacherfl marked this pull request as ready for review October 30, 2024 10:32

github-actions bot assigned dashpole Oct 30, 2024

andrzej-stencel approved these changes Oct 31, 2024

View reviewed changes

andrzej-stencel reviewed Oct 31, 2024

View reviewed changes

pkg/stanza/operator/helper/emitter.go Outdated Show resolved Hide resolved

bacherfl and others added 7 commits November 4, 2024 07:50

Update pkg/stanza/operator/helper/emitter.go

38c34ef

Co-authored-by: Andrzej Stencel <[email protected]>

fix previous benchmark tests

58ec352

Signed-off-by: Florian Bacher <[email protected]>

fix linting

85bd70e

Signed-off-by: Florian Bacher <[email protected]>

fix linting

2eeacc3

Signed-off-by: Florian Bacher <[email protected]>

Merge branch 'main' into feat/35453/synchronous-log-emitter

2546832

Merge branch 'main' into feat/35453/synchronous-log-emitter

b5a211a

revert import of file input package

dd6adce

Signed-off-by: Florian Bacher <[email protected]>

djaglowski approved these changes Nov 7, 2024

View reviewed changes

djaglowski merged commit c840e69 into open-telemetry:main Nov 7, 2024
158 checks passed

github-actions bot added this to the next release milestone Nov 7, 2024

bacherfl mentioned this pull request Nov 11, 2024

[chore] remove converter type from stanza #36288

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[pkg/stanza] make log emitter and entry conversion in adapter synchronous #35669

[pkg/stanza] make log emitter and entry conversion in adapter synchronous #35669

bacherfl commented Oct 8, 2024 •

edited

Loading

djaglowski left a comment

bacherfl commented Oct 16, 2024

bacherfl commented Oct 29, 2024

djaglowski commented Oct 29, 2024

bacherfl commented Oct 30, 2024

bacherfl commented Oct 30, 2024

bacherfl commented Oct 30, 2024

djaglowski commented Oct 30, 2024

andrzej-stencel left a comment •

edited

Loading

bacherfl commented Nov 4, 2024 •

edited

Loading

djaglowski left a comment

[pkg/stanza] make log emitter and entry conversion in adapter synchronous #35669

[pkg/stanza] make log emitter and entry conversion in adapter synchronous #35669

Conversation

bacherfl commented Oct 8, 2024 • edited Loading

Description

Link to tracking issue

Testing

djaglowski left a comment

Choose a reason for hiding this comment

bacherfl commented Oct 16, 2024

bacherfl commented Oct 29, 2024

djaglowski commented Oct 29, 2024

bacherfl commented Oct 30, 2024

bacherfl commented Oct 30, 2024

bacherfl commented Oct 30, 2024

djaglowski commented Oct 30, 2024

andrzej-stencel left a comment • edited Loading

Choose a reason for hiding this comment

bacherfl commented Nov 4, 2024 • edited Loading

djaglowski left a comment

Choose a reason for hiding this comment

bacherfl commented Oct 8, 2024 •

edited

Loading

andrzej-stencel left a comment •

edited

Loading

bacherfl commented Nov 4, 2024 •

edited

Loading