Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[pkg/stanza] Introduce batching logs in File consumer #36663

Merged
merged 30 commits into from
Mar 3, 2025
Merged

[pkg/stanza] Introduce batching logs in File consumer #36663

merged 30 commits into from
Mar 3, 2025

Conversation

andrzej-stencel
Copy link
Member

@andrzej-stencel andrzej-stencel commented Dec 4, 2024 •
edited
Loading

Description

Modifies the File consumer to emit logs in batches as opposed to sending each log individually through the Stanza pipeline and on to the Log Emitter.

Here are the changes introduced:

  • 6b4c9fe Changed the Reader::ReadToEnd method in File consumer to collect the tokens scanned from the file into batches. At this point, the Reader still emits each token individually, as the emit.Callback function only accepts a single token.
  • c206995 Changed emit.Callback function signature to accept a slice of tokens as opposed to a single token, and changed the Reader to emit a batch of tokens in one request. At this point, the batches are still split into individual tokens inside the emit function, because the Stanza operators can only process one entry at a time.
  • aedda3a Added ProcessBatch method to Stanza operators and used it in the emit function. At this point, the batch of tokens is translated to a batch of entries and passed to Log Emitter as a whole batch. The batch is still split in the Log Emitter, which calls consumeFunc for each entry in a loop.
  • 13d6054 Changed the LogEmitter to add the whole batch to its buffer, as opposed to adding entries one by one.

Slice of entries []entry.Entry vs. slice of pointers []*entry.Entry

I considered whether the ProcessBatch method in the Operator interface should accept a slice of structs []entry.Entry or a slice of pointers []*entry.Entry. I ran some tests (similar to #35454) and they showed a 7-10% performance loss when using a slice of structs vs. a slice of pointers. That's why I decided to use the slice of pointers []*entry.Entry.

Link to tracking issue

Testing

No changes in tests. The goal is for the functionality to not change and for performance to not decrease.

I have added a new benchmark in a separate PR #38054 that should be helpful in assessing the performance impact of this change.

Documentation

These are internal changes, no user documentation needs changing.

@andrzej-stencel
refactor: introduce batching in File consumer's Reader
6b4c9fe 
But send each token of the batch individually via `emit`.
@andrzej-stencel
change emit.Callback signature to accept a slice of tokens
c206995 
But still emit each Entry individually into the Stanza pipeline
@andrzej-stencel
add WriterOperator::WriteBatch and Operator::ProcessBatch methods
aedda3a 
The File input's `emitBatch` function now calls `ProcessBatch` instead of `Process`.

The added `ProcessBatch` method will make each Stanza operator
capable of accepting a batch of entries.

At this stage, all the implementations of `ProcessBatch` just call `Process` in a loop.
@andrzej-stencel
change signature of ProcessBatch to accept []*entry.Entry instead o…
477f67b 
…f `[]entry.Entry`

According to testing, this results in 7-10% performance improvement.
@andrzej-stencel
change LogEmitter to process entries in batches
13d6054 
Instead of adding each entry in a batch separately to the LogEmitter's buffer, add the whole batch in one operation.
@andrzej-stencel
add changelog entry for ProcessBatch method
dda1a60
@andrzej-stencel andrzej-stencel mentioned this pull request Dec 4, 2024
Closed
@github-actions github-actions bot requested a review from dehaansa December 4, 2024 09:04
@andrzej-stencel andrzej-stencel mentioned this pull request Dec 4, 2024
Closed
djaglowski
djaglowski reviewed Dec 4, 2024
View reviewed changes
Copy link
Member

@djaglowski djaglowski left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What is the performance impact of these changes?

pkg/stanza/fileconsumer/internal/reader/reader.go Outdated
err = r.emitFunc(ctx, emit.NewToken(token, r.FileAttributes))
if err != nil {
r.set.Logger.Error("failed to process token", zap.Error(err))
tokens = append(tokens, emit.NewToken(copyBody(token), copyAttributes(r.FileAttributes)))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What specifically introduces a need to make copies of the body and attributes?

It seems like a lot of overhead - are we sure it's necessary?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Without copying, for each token in the tokens collection, its Body would point to the same place in memory, specifically the Decoder's decodeBuffer.

This isn't a problem when the Reader emits each token before creating a new token, as the token's Body is copied in the emit function (specifically in the toBody function - the conversion from []byte to string copies the underlying array).

Similar with the attributes, the reader::FileAttributes map would be reused by all tokens if not copied.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If I'm understanding correctly then, we're just making the copies in a different place, so this does not introduce new work into the hot path?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm afraid it does introduce new work.

How I believe this worked before this change:

  • Every time a new token is read from the file, it's placed in the same area in memory - the Decoder's decodeBuffer.
  • A pointer to that place in memory is passed to the emit function
  • The emit function reads the bytes and creates a new Entry, copying the bytes into a new area in memory.

How this works after this change:

  • Every time a new token is read from the file, it's placed in the same area in memory - the Decoder's decodeBuffer.
  • In the Reader's readContent function, a batch of tokens is accumulated before calling the emit function, so the bytes from decodeBuffer need to be copied into a new area in memory for every new token
  • the accumulated slice of tokens is passed to the emit function, which creates a new Entry for every Token, copying the bytes for the second time.

pkg/stanza/operator/input/file/input.go Outdated
func (i *Input) emit(ctx context.Context, token emit.Token) error {
if len(token.Body) == 0 {
return nil
func (i *Input) emitBatch(ctx context.Context, tokens []emit.Token) error {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Given that this is in the hot path, we might be better off flattening these functions. It seems like a lot of extra error checking and wrapping, where we really just need to put a loop around what was already there, switch from return to append err + continue.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have inlined the convertToken function in de66483. Should I inline the convertTokens function as well?

pkg/stanza/operator/parser/container/parser.go Outdated
Comment on lines 71 to 77
func (p *Parser) ProcessBatch(ctx context.Context, entries []*entry.Entry) error {
var errs []error
for i := range entries {
errs = append(errs, p.Process(ctx, entries[i]))
}
return errors.Join(errs...)
}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this exactly the same for all parsers and transformers? If so, can we move it to helper/transformer.go, where one implementation can be inherited by all?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Riiiiight, this probably makes a lot of sense 😅

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh but wait, the ProcessBatch method calls the Process method, and Go does not support method overriding, so it will always call the Process method of the helper.TransformerOperator struct, right? Is there a simple way around it?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good question. We might not be able to fully eliminate the need for a ProcessBatch implementation in each operator, but I think at least the implementation details can be consolidated. Same idea as ParseWith here.

// transformer.go
type ProcessFunc func(context.Context, []*entry.Entry) error

func ProcessBatchWith(ctx context.Context, entries []*entry.Entry, f ProcessFunc) error {
	var errs []error
	for i := range entries {
		errs = append(errs, f(ctx, entries[i]))
	}
	return errors.Join(errs...)
}

// each implemenation of Transformer
func (p *Parser) ProcessBatch(ctx context.Context, entries []*entry.Entry) error {
	return p.ProcessBatchWith(ctx, entries, p.Process)
}

Even though the implementation of ProcessBatch is pretty simple, I still think it's worth consolidating because any changes in the future could easily be made inconsistently.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Implemented in d8704ab.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh I just realized I only updated transformers and missed parsers in the above commit. Added parsers in 5734fcc.

@djaglowski
Copy link
Member

What is the performance impact of these changes?

Do we have a benchmark or benchmarks that we can use to evaluate the net effect of these changes? A lot of the changes appear to have subtle implications so it's difficult to decide if they are worth it or not without some measurements.

@andrzej-stencel
Copy link
Member Author

andrzej-stencel commented Dec 16, 2024 •
edited
Loading

What is the performance impact of these changes?

I ran the EndToEnd benchmark (not sure how relevant it is) and the "end to end" test collecting 1 GB of logs from a single file with the collector binary. See below.

BenchmarkEndToEnd

pkg/stanza/adapter/BenchmarkEndToEnd 
$ go test -run=xxx -bench=EndToEnd
goos: linux
goarch: amd64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/adapter
cpu: 13th Gen Intel(R) Core(TM) i7-13700H
BenchmarkEndToEnd/workerCount=1,maxBatchSize=1,flushInterval=10ms-20                   2         733116691 ns/op        460448128 B/op   8800782 allocs/op
BenchmarkEndToEnd/workerCount=1,maxBatchSize=1,flushInterval=100ms-20                  2         647384276 ns/op        460445164 B/op   8800702 allocs/op
BenchmarkEndToEnd/workerCount=1,maxBatchSize=10,flushInterval=10ms-20                  2         600991822 ns/op        382361976 B/op   7020680 allocs/op
BenchmarkEndToEnd/workerCount=1,maxBatchSize=10,flushInterval=100ms-20                 2         604421607 ns/op        382354476 B/op   7020603 allocs/op
BenchmarkEndToEnd/workerCount=1,maxBatchSize=100,flushInterval=10ms-20                 2         551094092 ns/op        347132024 B/op   6206621 allocs/op
BenchmarkEndToEnd/workerCount=1,maxBatchSize=100,flushInterval=100ms-20                2         558686398 ns/op        347128024 B/op   6206598 allocs/op
BenchmarkEndToEnd/workerCount=1,maxBatchSize=1000,flushInterval=10ms-20                2         541430882 ns/op        343303492 B/op   6112393 allocs/op
BenchmarkEndToEnd/workerCount=1,maxBatchSize=1000,flushInterval=100ms-20               2         522679270 ns/op        343306200 B/op   6112372 allocs/op
BenchmarkEndToEnd/workerCount=1,maxBatchSize=10000,flushInterval=10ms-20               2         543155004 ns/op        344406224 B/op   6101974 allocs/op
BenchmarkEndToEnd/workerCount=1,maxBatchSize=10000,flushInterval=100ms-20              2         557043344 ns/op        344405516 B/op   6101967 allocs/op
BenchmarkEndToEnd/workerCount=2,maxBatchSize=1,flushInterval=10ms-20                   2         695154474 ns/op        460446040 B/op   8800736 allocs/op
BenchmarkEndToEnd/workerCount=2,maxBatchSize=1,flushInterval=100ms-20                  2         654490082 ns/op        460444880 B/op   8800742 allocs/op
BenchmarkEndToEnd/workerCount=2,maxBatchSize=10,flushInterval=10ms-20                  2         700169062 ns/op        382358900 B/op   7020720 allocs/op
BenchmarkEndToEnd/workerCount=2,maxBatchSize=10,flushInterval=100ms-20                 2         568586705 ns/op        382354560 B/op   7020616 allocs/op
BenchmarkEndToEnd/workerCount=2,maxBatchSize=100,flushInterval=10ms-20                 2         585962324 ns/op        347131136 B/op   6206675 allocs/op
BenchmarkEndToEnd/workerCount=2,maxBatchSize=100,flushInterval=100ms-20                2         537941018 ns/op        347125700 B/op   6206561 allocs/op
BenchmarkEndToEnd/workerCount=2,maxBatchSize=1000,flushInterval=10ms-20                2         529003978 ns/op        343313384 B/op   6112433 allocs/op
BenchmarkEndToEnd/workerCount=2,maxBatchSize=1000,flushInterval=100ms-20               2         533420602 ns/op        343308764 B/op   6112397 allocs/op
BenchmarkEndToEnd/workerCount=2,maxBatchSize=10000,flushInterval=10ms-20               2         520374890 ns/op        344423928 B/op   6102022 allocs/op
BenchmarkEndToEnd/workerCount=2,maxBatchSize=10000,flushInterval=100ms-20              2         524670569 ns/op        344409080 B/op   6101958 allocs/op
BenchmarkEndToEnd/workerCount=4,maxBatchSize=1,flushInterval=10ms-20                   2         729801709 ns/op        460443916 B/op   8800771 allocs/op
BenchmarkEndToEnd/workerCount=4,maxBatchSize=1,flushInterval=100ms-20                  2         695331941 ns/op        460445152 B/op   8800753 allocs/op
BenchmarkEndToEnd/workerCount=4,maxBatchSize=10,flushInterval=10ms-20                  2         609127970 ns/op        382356496 B/op   7020632 allocs/op
BenchmarkEndToEnd/workerCount=4,maxBatchSize=10,flushInterval=100ms-20                 2         561177946 ns/op        382353248 B/op   7020594 allocs/op
BenchmarkEndToEnd/workerCount=4,maxBatchSize=100,flushInterval=10ms-20                 2         580258299 ns/op        347130192 B/op   6206621 allocs/op
BenchmarkEndToEnd/workerCount=4,maxBatchSize=100,flushInterval=100ms-20                2         540122238 ns/op        347130740 B/op   6206614 allocs/op
BenchmarkEndToEnd/workerCount=4,maxBatchSize=1000,flushInterval=10ms-20                3         490890373 ns/op        343297152 B/op   6112335 allocs/op
BenchmarkEndToEnd/workerCount=4,maxBatchSize=1000,flushInterval=100ms-20               2         516348068 ns/op        343304052 B/op   6112370 allocs/op
BenchmarkEndToEnd/workerCount=4,maxBatchSize=10000,flushInterval=10ms-20               2         521940200 ns/op        344406800 B/op   6101944 allocs/op
BenchmarkEndToEnd/workerCount=4,maxBatchSize=10000,flushInterval=100ms-20              2         540817798 ns/op        344405140 B/op   6101957 allocs/op
BenchmarkEndToEnd/workerCount=8,maxBatchSize=1,flushInterval=10ms-20                   2         684520518 ns/op        460444084 B/op   8800734 allocs/op
BenchmarkEndToEnd/workerCount=8,maxBatchSize=1,flushInterval=100ms-20                  2         657656100 ns/op        460443584 B/op   8800704 allocs/op
BenchmarkEndToEnd/workerCount=8,maxBatchSize=10,flushInterval=10ms-20                  2         589294887 ns/op        382353692 B/op   7020618 allocs/op
BenchmarkEndToEnd/workerCount=8,maxBatchSize=10,flushInterval=100ms-20                 2         590353082 ns/op        382354828 B/op   7020627 allocs/op
BenchmarkEndToEnd/workerCount=8,maxBatchSize=100,flushInterval=10ms-20                 2         520960143 ns/op        347128612 B/op   6206573 allocs/op
BenchmarkEndToEnd/workerCount=8,maxBatchSize=100,flushInterval=100ms-20                2         519195290 ns/op        347129496 B/op   6206587 allocs/op
BenchmarkEndToEnd/workerCount=8,maxBatchSize=1000,flushInterval=10ms-20                2         557338458 ns/op        343316852 B/op   6112457 allocs/op
BenchmarkEndToEnd/workerCount=8,maxBatchSize=1000,flushInterval=100ms-20               2         526733440 ns/op        343303436 B/op   6112382 allocs/op
BenchmarkEndToEnd/workerCount=8,maxBatchSize=10000,flushInterval=10ms-20               2         553058060 ns/op        344406392 B/op   6101964 allocs/op
BenchmarkEndToEnd/workerCount=8,maxBatchSize=10000,flushInterval=100ms-20              2         544634770 ns/op        344406668 B/op   6101979 allocs/op
BenchmarkEndToEnd/workerCount=16,maxBatchSize=1,flushInterval=10ms-20                  2         692173162 ns/op        460445540 B/op   8800773 allocs/op
BenchmarkEndToEnd/workerCount=16,maxBatchSize=1,flushInterval=100ms-20                 2         691081284 ns/op        460443676 B/op   8800737 allocs/op
BenchmarkEndToEnd/workerCount=16,maxBatchSize=10,flushInterval=10ms-20                 2         613109702 ns/op        382355700 B/op   7020641 allocs/op
BenchmarkEndToEnd/workerCount=16,maxBatchSize=10,flushInterval=100ms-20                2         590538412 ns/op        382359592 B/op   7020622 allocs/op
BenchmarkEndToEnd/workerCount=16,maxBatchSize=100,flushInterval=10ms-20                2         567399749 ns/op        347130360 B/op   6206644 allocs/op
BenchmarkEndToEnd/workerCount=16,maxBatchSize=100,flushInterval=100ms-20               2         530738212 ns/op        347125680 B/op   6206576 allocs/op
BenchmarkEndToEnd/workerCount=16,maxBatchSize=1000,flushInterval=10ms-20               2         537735602 ns/op        343303236 B/op   6112361 allocs/op
BenchmarkEndToEnd/workerCount=16,maxBatchSize=1000,flushInterval=100ms-20              2         513183656 ns/op        343302976 B/op   6112356 allocs/op
BenchmarkEndToEnd/workerCount=16,maxBatchSize=10000,flushInterval=10ms-20              2         520426649 ns/op        344404100 B/op   6101938 allocs/op
BenchmarkEndToEnd/workerCount=16,maxBatchSize=10000,flushInterval=100ms-20             2         501402028 ns/op        344402404 B/op   6101928 allocs/op

Read 1 GB log file

I ran the "end-to-end" test collecting 1 GB of logs from a single file, as described in #35454 (comment). This (somewhat surprisingly to me) seems to result in a significant performance improvement of about 15%. I ran the tests on my laptop interchangeably, and consistently the main branch collector took 18 seconds to collect all logs, while the batching one took 15 seconds.

main-1 
=== Step 0: 2024-12-16T15:46:55,431446156+01:00
=== Step 1: 2024-12-16T15:46:57,776110136+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 580086
=== Step 2: 2024-12-16T15:46:58,795399607+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.51749e+06
=== Step 3: 2024-12-16T15:46:59,811430467+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 2.525834e+06
=== Step 4: 2024-12-16T15:47:00,826117615+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 3.51771e+06
=== Step 5: 2024-12-16T15:47:01,837294131+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 4.494632e+06
=== Step 6: 2024-12-16T15:47:02,851706243+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 5.503646e+06
=== Step 7: 2024-12-16T15:47:03,867007622+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 6.465843e+06
=== Step 8: 2024-12-16T15:47:04,880762477+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 7.484097e+06
=== Step 9: 2024-12-16T15:47:05,896817941+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 8.34754e+06
=== Step 10: 2024-12-16T15:47:06,918197128+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 9.190601e+06
=== Step 11: 2024-12-16T15:47:07,947497979+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.0064757e+07
=== Step 12: 2024-12-16T15:47:08,970509380+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.093098e+07
=== Step 13: 2024-12-16T15:47:10,006788214+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.1763265e+07
=== Step 14: 2024-12-16T15:47:11,031971467+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.2743549e+07
=== Step 15: 2024-12-16T15:47:12,048653620+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.3799651e+07
=== Step 16: 2024-12-16T15:47:13,061609270+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.4748804e+07
=== Step 17: 2024-12-16T15:47:14,078500681+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.5801047e+07
=== Step 18: 2024-12-16T15:47:15,101722837+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="19ae092a-e6ce-4e2e-8e41-b429a8baa599",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.6519105e+07
main-2 
=== Step 0: 2024-12-16T15:49:59,937734237+01:00
=== Step 1: 2024-12-16T15:50:00,960695129+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 675923
=== Step 2: 2024-12-16T15:50:01,974959315+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.613065e+06
=== Step 3: 2024-12-16T15:50:02,988684935+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 2.594632e+06
=== Step 4: 2024-12-16T15:50:04,002396877+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 3.626522e+06
=== Step 5: 2024-12-16T15:50:05,015851940+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 4.649102e+06
=== Step 6: 2024-12-16T15:50:06,031987112+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 5.65826e+06
=== Step 7: 2024-12-16T15:50:07,050476545+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 6.652504e+06
=== Step 8: 2024-12-16T15:50:08,069014012+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 7.601671e+06
=== Step 9: 2024-12-16T15:50:09,084814115+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 8.559654e+06
=== Step 10: 2024-12-16T15:50:10,098834674+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 9.47875e+06
=== Step 11: 2024-12-16T15:50:11,115570101+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.0519824e+07
=== Step 12: 2024-12-16T15:50:12,128264343+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.1482479e+07
=== Step 13: 2024-12-16T15:50:13,146768132+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.2395424e+07
=== Step 14: 2024-12-16T15:50:14,163070435+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.341538e+07
=== Step 15: 2024-12-16T15:50:15,179260462+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.4367245e+07
=== Step 16: 2024-12-16T15:50:16,194354312+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.5339147e+07
=== Step 17: 2024-12-16T15:50:17,219358900+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.6343188e+07
=== Step 18: 2024-12-16T15:50:18,236216987+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="60b56197-0e4c-4db9-b9ed-7243520643c1",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.6519105e+07
main-3 
=== Step 0: 2024-12-16T15:51:47,004466315+01:00
=== Step 1: 2024-12-16T15:51:48,028078945+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 718363
=== Step 2: 2024-12-16T15:51:49,049324584+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.566481e+06
=== Step 3: 2024-12-16T15:51:50,065647473+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 2.723456e+06
=== Step 4: 2024-12-16T15:51:51,089223968+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 3.659562e+06
=== Step 5: 2024-12-16T15:51:52,109708158+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 4.67665e+06
=== Step 6: 2024-12-16T15:51:53,127121621+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 5.788852e+06
=== Step 7: 2024-12-16T15:51:54,140868674+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 6.818451e+06
=== Step 8: 2024-12-16T15:51:55,157193263+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 7.739786e+06
=== Step 9: 2024-12-16T15:51:56,170706945+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 8.769256e+06
=== Step 10: 2024-12-16T15:51:57,190322380+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 9.753002e+06
=== Step 11: 2024-12-16T15:51:58,206357895+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.068764e+07
=== Step 12: 2024-12-16T15:51:59,234101493+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.167782e+07
=== Step 13: 2024-12-16T15:52:00,250850487+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.2714644e+07
=== Step 14: 2024-12-16T15:52:01,265582713+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.3643248e+07
=== Step 15: 2024-12-16T15:52:02,276497572+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.4622953e+07
=== Step 16: 2024-12-16T15:52:03,295299153+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.5473991e+07
=== Step 17: 2024-12-16T15:52:04,308069522+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.6489661e+07
=== Step 18: 2024-12-16T15:52:05,325366799+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="ccfbbd7f-23d8-4ed3-8e67-10121297c203",service_name="otelcontribcol",service_version="0.115.0-dev",transport=""} 1.6519105e+07
batching-1 
=== Step 0: 2024-12-16T15:49:25,451767918+01:00
=== Step 1: 2024-12-16T15:49:26,473595098+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 757945
=== Step 2: 2024-12-16T15:49:27,489701267+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.744846e+06
=== Step 3: 2024-12-16T15:49:28,502907791+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 2.938626e+06
=== Step 4: 2024-12-16T15:49:29,518975110+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 4.047107e+06
=== Step 5: 2024-12-16T15:49:30,541134228+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 5.224338e+06
=== Step 6: 2024-12-16T15:49:31,563921043+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 6.338091e+06
=== Step 7: 2024-12-16T15:49:32,576716675+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 7.521036e+06
=== Step 8: 2024-12-16T15:49:33,596550216+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 8.649884e+06
=== Step 9: 2024-12-16T15:49:34,620456460+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 9.814609e+06
=== Step 10: 2024-12-16T15:49:35,633902307+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.0996732e+07
=== Step 11: 2024-12-16T15:49:36,647248179+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.2160201e+07
=== Step 12: 2024-12-16T15:49:37,663024249+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.3322686e+07
=== Step 13: 2024-12-16T15:49:38,682719257+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.447508e+07
=== Step 14: 2024-12-16T15:49:39,696938377+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.5622622e+07
=== Step 15: 2024-12-16T15:49:40,712562869+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="1018bef3-4b44-4f54-aa68-45fc159ee265",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.6519105e+07
batching-2 
=== Step 0: 2024-12-16T15:50:48,180828422+01:00
=== Step 1: 2024-12-16T15:50:49,202082470+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 766985
=== Step 2: 2024-12-16T15:50:50,218864887+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.712576e+06
=== Step 3: 2024-12-16T15:50:51,238460470+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 2.846777e+06
=== Step 4: 2024-12-16T15:50:52,253083715+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 4.052889e+06
=== Step 5: 2024-12-16T15:50:53,267904710+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 5.220396e+06
=== Step 6: 2024-12-16T15:50:54,283451381+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 6.378984e+06
=== Step 7: 2024-12-16T15:50:55,304076543+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 7.475826e+06
=== Step 8: 2024-12-16T15:50:56,318229950+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 8.644039e+06
=== Step 9: 2024-12-16T15:50:57,332883110+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 9.767176e+06
=== Step 10: 2024-12-16T15:50:58,345458786+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.0924412e+07
=== Step 11: 2024-12-16T15:50:59,359149580+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.2103512e+07
=== Step 12: 2024-12-16T15:51:00,373009015+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.3215526e+07
=== Step 13: 2024-12-16T15:51:01,383947577+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.4357692e+07
=== Step 14: 2024-12-16T15:51:02,397871874+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.5498857e+07
=== Step 15: 2024-12-16T15:51:03,419258504+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="8714502b-68f4-495d-ac04-43daaac29e69",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.6519105e+07
batching-3 
=== Step 0: 2024-12-16T15:52:21,557555315+01:00
=== Step 1: 2024-12-16T15:52:22,588161825+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 733360
=== Step 2: 2024-12-16T15:52:23,598105509+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.707804e+06
=== Step 3: 2024-12-16T15:52:24,609804063+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 2.809491e+06
=== Step 4: 2024-12-16T15:52:25,625337319+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 3.927862e+06
=== Step 5: 2024-12-16T15:52:26,636396041+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 5.110002e+06
=== Step 6: 2024-12-16T15:52:27,652329616+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 6.302457e+06
=== Step 7: 2024-12-16T15:52:28,662959666+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 7.43236e+06
=== Step 8: 2024-12-16T15:52:29,675925365+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 8.598355e+06
=== Step 9: 2024-12-16T15:52:30,689062153+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 9.797821e+06
=== Step 10: 2024-12-16T15:52:31,704479779+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.0911129e+07
=== Step 11: 2024-12-16T15:52:32,718040442+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.206504e+07
=== Step 12: 2024-12-16T15:52:33,728085856+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.3183748e+07
=== Step 13: 2024-12-16T15:52:34,740337198+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.4287112e+07
=== Step 14: 2024-12-16T15:52:35,754972220+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.5495808e+07
=== Step 15: 2024-12-16T15:52:36,772794534+01:00
otelcol_receiver_accepted_log_records{receiver="filelog",service_instance_id="f4546346-b6dd-4d45-a3a7-40ddf4698e75",service_name="otelcontribcol",service_version="0.114.0-dev",transport=""} 1.6519105e+07

@andrzej-stencel
Copy link
Member Author

What is the performance impact of these changes?

Do we have a benchmark or benchmarks that we can use to evaluate the net effect of these changes? A lot of the changes appear to have subtle implications so it's difficult to decide if they are worth it or not without some measurements.

Great question. I'd love to have a synthetic benchmark that can mirror "real-world" performance. For now, I've been relying on the manual labor of building the binary and running it on an actual file.

@djaglowski
Copy link
Member

I ran the fileconsumer benchmarks on main and this branch and it does appear that there are some substantial memory & allocation impacts from the changes.

# on batch-logs-in-file-consumer
> (cd pkg/stanza/fileconsumer && go test -benchmem -run=^$ -bench ^BenchmarkFileInput$ github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer -race -v -count=10 | tee /tmp/batch.txt)
...
# on main
> (cd pkg/stanza/fileconsumer && go test -benchmem -run=^$ -bench ^BenchmarkFileInput$ github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer -race -v -count=10 | tee /tmp/main.txt) 

> benchstat /tmp/main.txt /tmp/batch.txt
                           │ /tmp/main.txt │            /tmp/batch.txt             │
                           │    sec/op     │    sec/op      vs base                │
FileInput/Single-10           97.81µ ±  1%   108.12µ ±  1%  +10.54% (p=0.000 n=10)
FileInput/Glob-10             106.2µ ±  1%    126.8µ ±  1%  +19.44% (p=0.000 n=10)
FileInput/MultiGlob-10        107.4µ ±  1%    128.5µ ±  3%  +19.67% (p=0.000 n=10)
FileInput/MaxConcurrent-10    423.0µ ± 26%    433.3µ ±  1%        ~ (p=0.739 n=10)
FileInput/FngrPrntLarge-10    98.09µ ±  6%   106.24µ ±  0%   +8.31% (p=0.002 n=10)
FileInput/FngrPrntSmall-10    98.01µ ±  2%   106.82µ ±  5%   +8.99% (p=0.000 n=10)
FileInput/NoFlush-10          99.09µ ±  4%   104.83µ ±  1%   +5.79% (p=0.001 n=10)
FileInput/Many-10             3.964m ± 24%    6.326m ± 45%  +59.58% (p=0.001 n=10)
geomean                       191.1µ          221.3µ        +15.76%

                           │ /tmp/main.txt  │               /tmp/batch.txt                │
                           │      B/op      │      B/op        vs base                    │
FileInput/Single-10            11.00 ±  36%    13610.00 ±  0%  +123627.27% (p=0.000 n=10)
FileInput/Glob-10              25.00 ± 116%    54451.00 ±  0%  +217704.00% (p=0.000 n=10)
FileInput/MultiGlob-10         24.50 ±  71%    54447.50 ±  0%  +222134.69% (p=0.000 n=10)
FileInput/MaxConcurrent-10     181.0 ±  90%     54526.0 ±  0%   +30024.86% (p=0.000 n=10)
FileInput/FngrPrntLarge-10     25.00 ±  56%    13635.00 ±  0%   +54440.00% (p=0.000 n=10)
FileInput/FngrPrntSmall-10     8.000 ±  88%   13611.000 ±  0%  +170037.50% (p=0.000 n=10)
FileInput/NoFlush-10           9.500 ±  58%   13612.500 ±  0%  +143189.47% (p=0.000 n=10)
FileInput/Many-10            43.20Ki ± 237%   1466.05Ki ± 13%    +3293.42% (p=0.000 n=10)
geomean                        56.41            40.26Ki         +72985.20%

                           │ /tmp/main.txt  │             /tmp/batch.txt             │
                           │   allocs/op    │  allocs/op    vs base                  │
FileInput/Single-10           0.00 ±   0%       30.00 ± 0%          ? (p=0.000 n=10)
FileInput/Glob-10              0.0 ±   0%       120.0 ± 0%          ? (p=0.000 n=10)
FileInput/MultiGlob-10         0.0 ±   0%       120.0 ± 0%          ? (p=0.000 n=10)
FileInput/MaxConcurrent-10     0.0 ±   0%       120.0 ± 0%          ? (p=0.000 n=10)
FileInput/FngrPrntLarge-10    0.00 ±   0%       30.00 ± 0%          ? (p=0.000 n=10)
FileInput/FngrPrntSmall-10    0.00 ±   0%       30.00 ± 0%          ? (p=0.000 n=10)
FileInput/NoFlush-10          0.00 ±   0%       30.00 ± 0%          ? (p=0.000 n=10)
FileInput/Many-10            43.50 ± 213%     3116.50 ± 6%  +7064.37% (p=0.000 n=10)
geomean                                   ¹     90.15       ?
¹ summaries must be >0 to compute geomean

This benchmark doesn't actually perform any work in the emitFunc but I think the work that is normally performed would be equivalent in either case. (For each token, copy the []byte into a string and create an entry.Entry.) Unless I'm misunderstanding something, I think these are the best benchmarks we have for these changes. Maybe we can find some more improvements that lessen the impact?

@andrzej-stencel
Copy link
Member Author

andrzej-stencel commented Jan 22, 2025 •
edited
Loading

EDIT: The original benchstat results I posted in this comment were flawed, I have now updated them with correct results, which are not as bad.

I tried to improve the allocations stats by pre-allocating memory for the batched entries in the following commits:

Here are the stats comparing main and current state. I'll look into using a pool of buffers to further enhance performance.

$ benchstat /tmp/main.txt /tmp/batch.txt
goos: linux
goarch: amd64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer
cpu: 13th Gen Intel(R) Core(TM) i7-13700H
                           │ /tmp/main.txt │            /tmp/batch.txt            │
                           │    sec/op     │    sec/op     vs base                │
FileInput/Single-20           146.7µ ±  2%   152.0µ ± 55%   +3.59% (p=0.004 n=10)
FileInput/Glob-20             161.2µ ±  3%   170.9µ ±  5%   +6.01% (p=0.002 n=10)
FileInput/MultiGlob-20        163.4µ ±  5%   181.5µ ± 10%  +11.09% (p=0.000 n=10)
FileInput/MaxConcurrent-20    589.5µ ±  7%   652.1µ ± 11%  +10.61% (p=0.000 n=10)
FileInput/FngrPrntLarge-20    147.0µ ±  5%   155.4µ ±  5%   +5.75% (p=0.005 n=10)
FileInput/FngrPrntSmall-20    146.6µ ±  1%   154.0µ ±  9%   +5.06% (p=0.000 n=10)
FileInput/NoFlush-20          148.2µ ±  2%   152.3µ ±  6%   +2.77% (p=0.029 n=10)
FileInput/Many-20             2.207m ± 11%   2.594m ± 62%  +17.56% (p=0.000 n=10)
geomean                       251.6µ         271.0µ         +7.71%

                           │ /tmp/main.txt  │              /tmp/batch.txt               │
                           │      B/op      │      B/op        vs base                  │
FileInput/Single-20            15.00 ±  33%     100.50 ±  50%   +570.00% (p=0.000 n=10)
FileInput/Glob-20              79.50 ±  64%     345.00 ± 238%   +333.96% (p=0.000 n=10)
FileInput/MultiGlob-20         69.00 ± 101%     383.50 ±  67%   +455.80% (p=0.000 n=10)
FileInput/MaxConcurrent-20     151.0 ± 160%     4758.0 ±  54%  +3050.99% (p=0.000 n=10)
FileInput/FngrPrntLarge-20     43.50 ±  45%     167.50 ±  78%   +285.06% (p=0.000 n=10)
FileInput/FngrPrntSmall-20     12.00 ± 100%      70.50 ± 191%   +487.50% (p=0.000 n=10)
FileInput/NoFlush-20           13.00 ±  46%     133.50 ±  35%   +926.92% (p=0.000 n=10)
FileInput/Many-20            28.93Ki ±  65%   370.52Ki ± 340%  +1180.93% (p=0.000 n=10)
geomean                        84.08             664.1          +689.88%

                           │ /tmp/main.txt │              /tmp/batch.txt              │
                           │   allocs/op   │   allocs/op    vs base                   │
FileInput/Single-20          0.000 ±  0%      0.000 ±   0%         ~ (p=1.000 n=10) ¹
FileInput/Glob-20            0.000 ±  0%      0.000 ±   0%         ~ (p=1.000 n=10)
FileInput/MultiGlob-20       0.000 ±  0%      0.000 ±   0%         ~ (p=1.000 n=10) ¹
FileInput/MaxConcurrent-20   0.000 ±  0%      3.000 ±  67%         ? (p=0.000 n=10)
FileInput/FngrPrntLarge-20   0.000 ±  0%      0.000 ±   0%         ~ (p=1.000 n=10) ¹
FileInput/FngrPrntSmall-20   0.000 ±  0%      0.000 ±   0%         ~ (p=1.000 n=10) ¹
FileInput/NoFlush-20         0.000 ±  0%      0.000 ±   0%         ~ (p=1.000 n=10) ¹
FileInput/Many-20            28.50 ± 58%     264.50 ± 336%  +828.07% (p=0.000 n=10)
geomean                                  ²                  ?                       ²
¹ all samples are equal
² summaries must be >0 to compute geomean

@andrzej-stencel
Copy link
Member Author

andrzej-stencel commented Jan 23, 2025 •
edited
Loading

I took a stab at implementing pooling of the buffers, as opposed to pre-allocating them. Comparing the benchmarks, it doesn't seem to give any performance gains though. Let me know if I missed something.

benchstat /tmp/batch.txt /tmp/pool.txt 
goos: linux
goarch: amd64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer
cpu: 13th Gen Intel(R) Core(TM) i7-13700H
                           │ /tmp/batch.txt │              /tmp/pool.txt              │
                           │   sec/op    │    sec/op      vs base                │
FileInput/Single-20          84.73µ ± 1%   100.77µ ±  2%  +18.92% (p=0.000 n=10)
FileInput/Glob-20            93.76µ ± 2%   125.43µ ±  3%  +33.78% (p=0.000 n=10)
FileInput/MultiGlob-20       94.60µ ± 4%   126.93µ ±  2%  +34.17% (p=0.000 n=10)
FileInput/MaxConcurrent-20   341.7µ ± 1%    406.9µ ±  3%  +19.10% (p=0.000 n=10)
FileInput/FngrPrntLarge-20   85.16µ ± 1%   101.72µ ±  2%  +19.45% (p=0.000 n=10)
FileInput/FngrPrntSmall-20   85.09µ ± 1%   101.94µ ±  1%  +19.81% (p=0.000 n=10)
FileInput/NoFlush-20         84.26µ ± 1%   100.80µ ±  1%  +19.63% (p=0.000 n=10)
FileInput/Many-20            1.297m ± 8%    1.585m ± 18%  +22.24% (p=0.000 n=10)
geomean                      145.7µ         179.6µ        +23.24%

                           │  /tmp/batch.txt   │               /tmp/pool.txt                │
                           │      B/op      │     B/op       vs base                   │
FileInput/Single-20            73.50 ±  48%   10406.50 ± 1%  +14058.50% (p=0.000 n=10)
FileInput/Glob-20              317.0 ±  47%    41682.0 ± 0%  +13048.90% (p=0.000 n=10)
FileInput/MultiGlob-20         466.5 ±  66%    41686.0 ± 0%   +8835.91% (p=0.000 n=10)
FileInput/MaxConcurrent-20   1.494Ki ±  60%   40.941Ki ± 1%   +2640.10% (p=0.000 n=10)
FileInput/FngrPrntLarge-20     86.50 ± 108%   10393.50 ± 1%  +11915.61% (p=0.000 n=10)
FileInput/FngrPrntSmall-20     72.00 ±  47%   10359.50 ± 0%  +14288.19% (p=0.000 n=10)
FileInput/NoFlush-20           72.00 ±  47%   10366.00 ± 0%  +14297.22% (p=0.000 n=10)
FileInput/Many-20            143.7Ki ± 136%   1046.1Ki ± 8%    +627.93% (p=0.000 n=10)
geomean                        426.6           30.50Ki        +7221.78%

                           │   /tmp/batch.txt   │               /tmp/pool.txt                │
                           │    allocs/op    │   allocs/op     vs base                  │
FileInput/Single-20           0.000 ±   0%        5.000 ±  0%          ? (p=0.000 n=10)
FileInput/Glob-20              0.00 ±   0%        20.00 ±  5%          ? (p=0.000 n=10)
FileInput/MultiGlob-20         0.00 ±   0%        20.00 ±  5%          ? (p=0.000 n=10)
FileInput/MaxConcurrent-20   500.0m ±    ?     21000.0m ±  5%  +4100.00% (p=0.000 n=10)
FileInput/FngrPrntLarge-20    0.000 ±   0%        5.000 ±  0%          ? (p=0.000 n=10)
FileInput/FngrPrntSmall-20    0.000 ±   0%        5.000 ±  0%          ? (p=0.000 n=10)
FileInput/NoFlush-20          0.000 ±   0%        5.000 ±  0%          ? (p=0.000 n=10)
FileInput/Many-20             103.0 ± 133%        574.5 ± 61%   +457.77% (p=0.000 n=10)
geomean                                    ¹      15.31        ?
¹ summaries must be >0 to compute geomean

@djaglowski
Copy link
Member

djaglowski commented Jan 28, 2025 •
edited
Loading

One thing I notice is that we're now making a copy of the attributes map for every token. This might not be necessary. Generally, the attributes describe the file, so should be the same for every token emitted by a given reader. However,
we somewhat recently added a record number attribute which breaks this assumption.

What if instead of func(ctx context.Context, tokens []Token) error, we had func(ctx context.Context, tokens [][]byte, attributes map[string]string, lastRecord int64) error. Then when converting to entries, we can check the "include record number" flag and if necessary use lastRecord and len(tokens) to assign a record number to each entry.

Some nuances to this:

  • Since the attribute map would be shared, the emit func shouldn't modify it. I don't think this is a problem immediately but something probably worth noting in comments at least.
  • If you follow how the attribute map gets converted into an entry.Entry's attributes, it recreates its own model for keys, but assigns the value directly. For this reason, I think we can't just use any for the map's values, since this is a reference type. Since all the file attributes are string values, it seems like using map[string]string should take care of this. (Ultimately, we're still copying the attribute values, but we aren't copying the map and keys every time.)

This might be a lot of work to test but if it makes sense to you it might be worth it.

Otherwise, I'm not seeing a lot of room for optimization. I know you've put a lot into this but if we really think this change introduces memory usage by orders of magnitude, then I think we may need to look at other designs such as using callbacks to update offsets.

@andrzej-stencel
Copy link
Member Author

One thing I notice is that we're now making a copy of the attributes map for every token. This might not be necessary. Generally, the attributes describe the file, so should be the same for every token emitted by a given reader. However,

This is true, some of the attributes are the same for all tokens and (currently) only the record number attribute changes for each token. A similar suggestion was offered from @swiatekm, in a different fashion: have one (a single instance of) attribute map for the common attributes (those describing the source file) and a second attribute map that would be allocated for every record - it would currently only hold the record number attribute. The solution with a single int for the record number surely uses less memory, but the approach with separate attribute maps is probably easier to potentially extend if a new attribute needs to be added in the future?

@andrzej-stencel
Copy link
Member Author

andrzej-stencel commented Feb 4, 2025 •
edited
Loading

I have removed memory allocations for attributes in branch prevent-allocations-for-attributes by following the approach described by Dan. Here's the diff with current branch.

Here's the benchmark comparison between the two branches:

benchstat /tmp/batch.txt /tmp/noattr.txt
goos: linux
goarch: amd64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/fileconsumer
cpu: 13th Gen Intel(R) Core(TM) i7-13700H
                           │ /tmp/batch.txt │           /tmp/noattr.txt           │
                           │     sec/op     │    sec/op     vs base               │
FileInput/Single-20            151.9µ ±  4%   160.3µ ±  5%  +5.52% (p=0.001 n=10)
FileInput/Glob-20              166.3µ ±  6%   172.0µ ±  7%  +3.41% (p=0.043 n=10)
FileInput/MultiGlob-20         168.5µ ±  2%   173.2µ ±  1%  +2.78% (p=0.001 n=10)
FileInput/MaxConcurrent-20     649.3µ ±  4%   669.8µ ±  6%       ~ (p=0.063 n=10)
FileInput/FngrPrntLarge-20     152.9µ ±  6%   163.8µ ±  6%  +7.08% (p=0.019 n=10)
FileInput/FngrPrntSmall-20     152.6µ ±  6%   159.0µ ±  7%       ~ (p=0.063 n=10)
FileInput/NoFlush-20           151.8µ ±  4%   152.7µ ±  5%       ~ (p=0.579 n=10)
FileInput/Many-20              2.571m ± 29%   2.330m ± 25%       ~ (p=0.190 n=10)
geomean                        266.2µ         271.6µ        +2.05%

                           │ /tmp/batch.txt │            /tmp/noattr.txt            │
                           │      B/op      │      B/op       vs base               │
FileInput/Single-20           107.00 ±  83%     76.00 ± 145%       ~ (p=0.305 n=10)
FileInput/Glob-20              603.0 ±  50%     324.5 ±  96%       ~ (p=0.724 n=10)
FileInput/MultiGlob-20         628.0 ± 127%     459.5 ±  36%       ~ (p=0.289 n=10)
FileInput/MaxConcurrent-20   3.015Ki ± 153%   5.775Ki ±  94%       ~ (p=0.247 n=10)
FileInput/FngrPrntLarge-20     110.5 ± 151%     109.5 ±  79%       ~ (p=0.382 n=10)
FileInput/FngrPrntSmall-20     71.50 ± 169%    107.50 ±  77%       ~ (p=0.515 n=10)
FileInput/NoFlush-20           72.00 ±  79%    132.00 ±  57%       ~ (p=0.118 n=10)
FileInput/Many-20            380.9Ki ± 118%   290.3Ki ± 135%       ~ (p=0.247 n=10)
geomean                        638.9            647.7         +1.37%

                           │ /tmp/batch.txt  │            /tmp/noattr.txt             │
                           │    allocs/op    │  allocs/op    vs base                  │
FileInput/Single-20           0.000 ±   0%     0.000 ±   0%        ~ (p=1.000 n=10) ¹
FileInput/Glob-20             0.000 ±   0%     0.000 ±   0%        ~ (p=1.000 n=10) ¹
FileInput/MultiGlob-20        0.000 ±    ?     0.000 ±   0%        ~ (p=1.000 n=10)
FileInput/MaxConcurrent-20    1.500 ± 233%     1.500 ±    ?        ~ (p=0.477 n=10)
FileInput/FngrPrntLarge-20    0.000 ±   0%     0.000 ±   0%        ~ (p=1.000 n=10) ¹
FileInput/FngrPrntSmall-20    0.000 ±   0%     0.000 ±   0%        ~ (p=1.000 n=10) ¹
FileInput/NoFlush-20          0.000 ±   0%     0.000 ±   0%        ~ (p=1.000 n=10) ¹
FileInput/Many-20            272.50 ± 117%     92.00 ± 126%  -66.24% (p=0.001 n=10)
geomean                                    ²                 -12.69%                ²
¹ all samples are equal
² summaries must be >0 to compute geomean

The allocation counts are down, as visible in the Many benchmark. The memory allocation bytes are down too, but it's hard to see this due to the very high variance in the benchmark results for memory allocations. I'm frankly a bit worried by this high variance.

@andrzej-stencel
Copy link
Member Author

I've incorporated latest changes from main, which includes the change #37734.

I'm looking forward to incorporating #38054 as well, as I believe that benchmark will give us a clearer picture of the performance impact.

@andrzej-stencel
Merge remote-tracking branch 'upstream/main' into batch-logs-in-file-…
a6d8fb8 
…consumer
@andrzej-stencel
test: fix File input benchmark
5e58a9b
@andrzej-stencel
Merge remote-tracking branch 'upstream/main' into batch-logs-in-file-…
006ae63 
…consumer
@andrzej-stencel
perf: prevent memory allocations for token attributes
dfab829 
Removes the need to allocate memory for each token's attributes.
The file-related attributes that are common to all tokens
only exist in a single instance now in Reader.
The row number attributes are only created later,
when Entry is created from a token.
@andrzej-stencel
Copy link
Member Author

andrzej-stencel commented Feb 21, 2025 •
edited
Loading

After incorporating the benchmark added in #38054, I can now compare main and this branch:

main 
$ (cd pkg/stanza/operator/input/file/ && go test -benchmem -run=^$ -bench Benchmark . -v -count=6 | tee /tmp/fileinput-main-$(git rev-parse --short HEAD).txt)
goos: linux
goarch: amd64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/file
cpu: 13th Gen Intel(R) Core(TM) i7-13700H
BenchmarkReadExistingLogs
BenchmarkReadExistingLogs/0-lines
BenchmarkReadExistingLogs/0-lines-20               70484             23031 ns/op           26841 B/op         45 allocs/op
BenchmarkReadExistingLogs/0-lines-20               47827             22781 ns/op           26872 B/op         45 allocs/op
BenchmarkReadExistingLogs/0-lines-20               46557             24626 ns/op           26976 B/op         46 allocs/op
BenchmarkReadExistingLogs/0-lines-20               49556             20808 ns/op           26881 B/op         46 allocs/op
BenchmarkReadExistingLogs/0-lines-20               48490             21711 ns/op           26926 B/op         46 allocs/op
BenchmarkReadExistingLogs/0-lines-20               54570             23494 ns/op           26957 B/op         46 allocs/op
BenchmarkReadExistingLogs/1-lines
BenchmarkReadExistingLogs/1-lines-20                4201            281598 ns/op           99820 B/op        192 allocs/op
BenchmarkReadExistingLogs/1-lines-20                3597            278643 ns/op          101172 B/op        195 allocs/op
BenchmarkReadExistingLogs/1-lines-20                4202            274729 ns/op          100037 B/op        193 allocs/op
BenchmarkReadExistingLogs/1-lines-20                4074            275832 ns/op          102114 B/op        197 allocs/op
BenchmarkReadExistingLogs/1-lines-20                4161            276897 ns/op          101796 B/op        196 allocs/op
BenchmarkReadExistingLogs/1-lines-20                5718            286110 ns/op          102193 B/op        197 allocs/op
BenchmarkReadExistingLogs/2-lines
BenchmarkReadExistingLogs/2-lines-20                3891            286790 ns/op          101980 B/op        200 allocs/op
BenchmarkReadExistingLogs/2-lines-20                6790            299994 ns/op          103685 B/op        204 allocs/op
BenchmarkReadExistingLogs/2-lines-20                4230            280316 ns/op          103476 B/op        203 allocs/op
BenchmarkReadExistingLogs/2-lines-20                3735            281811 ns/op          101645 B/op        200 allocs/op
BenchmarkReadExistingLogs/2-lines-20                4182            295597 ns/op          102921 B/op        202 allocs/op
BenchmarkReadExistingLogs/2-lines-20                3922            305502 ns/op          103116 B/op        203 allocs/op
BenchmarkReadExistingLogs/10-lines
BenchmarkReadExistingLogs/10-lines-20               3388            340723 ns/op          115932 B/op        258 allocs/op
BenchmarkReadExistingLogs/10-lines-20               5371            330354 ns/op          114449 B/op        256 allocs/op
BenchmarkReadExistingLogs/10-lines-20               3734            327431 ns/op          115598 B/op        258 allocs/op
BenchmarkReadExistingLogs/10-lines-20               4615            332575 ns/op          115508 B/op        258 allocs/op
BenchmarkReadExistingLogs/10-lines-20               3736            318994 ns/op          116489 B/op        259 allocs/op
BenchmarkReadExistingLogs/10-lines-20               3508            317881 ns/op          115664 B/op        258 allocs/op
BenchmarkReadExistingLogs/20-lines
BenchmarkReadExistingLogs/20-lines-20               3043            370798 ns/op          132970 B/op        330 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3166            399654 ns/op          132085 B/op        328 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3770            361589 ns/op          131562 B/op        328 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3362            344698 ns/op          133441 B/op        331 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3822            358177 ns/op          132667 B/op        330 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3208            365742 ns/op          132315 B/op        329 allocs/op
BenchmarkReadExistingLogs/100-lines
BenchmarkReadExistingLogs/100-lines-20              1645            691607 ns/op          265208 B/op        896 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1035           1078240 ns/op          271741 B/op        909 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1249            935385 ns/op          279790 B/op        924 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1726            911764 ns/op          276851 B/op        918 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1402            914500 ns/op          278960 B/op        922 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1326            925553 ns/op          281257 B/op        927 allocs/op
BenchmarkReadExistingLogs/1000-lines
BenchmarkReadExistingLogs/1000-lines-20              276           4381826 ns/op         1741158 B/op       7247 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              302           4746414 ns/op         1746959 B/op       7258 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              333           4715565 ns/op         1748366 B/op       7261 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              309           4407227 ns/op         1743468 B/op       7252 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              283           4436628 ns/op         1747759 B/op       7260 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              322           4404681 ns/op         1745806 B/op       7256 allocs/op
PASS
ok      github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/file        70.270s
batch 
$ (cd pkg/stanza/operator/input/file/ && go test -benchmem -run=^$ -bench Benchmark . -v -count=6 | tee /tmp/fileinput-batch-$(git rev-parse --short HEAD).txt)      
goos: linux
goarch: amd64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/file
cpu: 13th Gen Intel(R) Core(TM) i7-13700H
BenchmarkReadExistingLogs
BenchmarkReadExistingLogs/0-lines
BenchmarkReadExistingLogs/0-lines-20               60921             18329 ns/op           26757 B/op         45 allocs/op
BenchmarkReadExistingLogs/0-lines-20               71128             19956 ns/op           26823 B/op         45 allocs/op
BenchmarkReadExistingLogs/0-lines-20               58737             20652 ns/op           26839 B/op         45 allocs/op
BenchmarkReadExistingLogs/0-lines-20               53828             19314 ns/op           26818 B/op         45 allocs/op
BenchmarkReadExistingLogs/0-lines-20               54476             20152 ns/op           26840 B/op         45 allocs/op
BenchmarkReadExistingLogs/0-lines-20               55768             19443 ns/op           26803 B/op         45 allocs/op
BenchmarkReadExistingLogs/1-lines
BenchmarkReadExistingLogs/1-lines-20                3412            395931 ns/op          176782 B/op        602 allocs/op
BenchmarkReadExistingLogs/1-lines-20                2818            391429 ns/op          178631 B/op        609 allocs/op
BenchmarkReadExistingLogs/1-lines-20                3433            350361 ns/op          180602 B/op        616 allocs/op
BenchmarkReadExistingLogs/1-lines-20                3492            363100 ns/op          180283 B/op        615 allocs/op
BenchmarkReadExistingLogs/1-lines-20                2982            360208 ns/op          182287 B/op        622 allocs/op
BenchmarkReadExistingLogs/1-lines-20                4012            389339 ns/op          177750 B/op        606 allocs/op
BenchmarkReadExistingLogs/2-lines
BenchmarkReadExistingLogs/2-lines-20                2760            370782 ns/op          182384 B/op        624 allocs/op
BenchmarkReadExistingLogs/2-lines-20                2751            373535 ns/op          180724 B/op        617 allocs/op
BenchmarkReadExistingLogs/2-lines-20                2713            409702 ns/op          183695 B/op        629 allocs/op
BenchmarkReadExistingLogs/2-lines-20                2908            353704 ns/op          182225 B/op        623 allocs/op
BenchmarkReadExistingLogs/2-lines-20                2598            402355 ns/op          185016 B/op        634 allocs/op
BenchmarkReadExistingLogs/2-lines-20                3564            355158 ns/op          183739 B/op        628 allocs/op
BenchmarkReadExistingLogs/10-lines
BenchmarkReadExistingLogs/10-lines-20               2720            398449 ns/op          197345 B/op        687 allocs/op
BenchmarkReadExistingLogs/10-lines-20               3638            403747 ns/op          198275 B/op        690 allocs/op
BenchmarkReadExistingLogs/10-lines-20               3129            412386 ns/op          195996 B/op        682 allocs/op
BenchmarkReadExistingLogs/10-lines-20               2606            437088 ns/op          194788 B/op        678 allocs/op
BenchmarkReadExistingLogs/10-lines-20               2876            403799 ns/op          197543 B/op        688 allocs/op
BenchmarkReadExistingLogs/10-lines-20               2418            430050 ns/op          194630 B/op        677 allocs/op
BenchmarkReadExistingLogs/20-lines
BenchmarkReadExistingLogs/20-lines-20               2566            455933 ns/op          214970 B/op        762 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3277            448540 ns/op          218362 B/op        775 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3136            442772 ns/op          214775 B/op        762 allocs/op
BenchmarkReadExistingLogs/20-lines-20               2856            459318 ns/op          211965 B/op        751 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3038            358299 ns/op          211544 B/op        749 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3648            474670 ns/op          213288 B/op        756 allocs/op
BenchmarkReadExistingLogs/100-lines
BenchmarkReadExistingLogs/100-lines-20              1639            829174 ns/op          355692 B/op       1363 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1296            787417 ns/op          366267 B/op       1402 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1647            767658 ns/op          357199 B/op       1368 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1429            773337 ns/op          360601 B/op       1381 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1454            748198 ns/op          358960 B/op       1375 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1904            795617 ns/op          359363 B/op       1377 allocs/op
BenchmarkReadExistingLogs/1000-lines
BenchmarkReadExistingLogs/1000-lines-20              301           3755205 ns/op         1831472 B/op       7739 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              393           3470412 ns/op         1850409 B/op       7809 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              348           3560141 ns/op         1841913 B/op       7776 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              406           3821434 ns/op         1858603 B/op       7838 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              386           3808140 ns/op         1846718 B/op       7795 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              381           3715700 ns/op         1849136 B/op       7804 allocs/op
PASS
ok      github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/file        59.819s
$ benchstat /tmp/fileinput-main-187259e7d7.txt /tmp/fileinput-batch-006ae63233.txt 
goos: linux
goarch: amd64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/file
cpu: 13th Gen Intel(R) Core(TM) i7-13700H
                               │ /tmp/fileinput-main-187259e7d7.txt │ /tmp/fileinput-batch-006ae63233.txt │
                               │               sec/op               │    sec/op     vs base               │
ReadExistingLogs/0-lines-20                            22.91µ ±  9%   19.70µ ±  7%  -14.00% (p=0.002 n=6)
ReadExistingLogs/1-lines-20                            277.8µ ±  3%   376.2µ ±  7%  +35.44% (p=0.002 n=6)
ReadExistingLogs/2-lines-20                            291.2µ ±  5%   372.2µ ± 10%  +27.80% (p=0.002 n=6)
ReadExistingLogs/10-lines-20                           328.9µ ±  4%   408.1µ ±  7%  +24.08% (p=0.002 n=6)
ReadExistingLogs/20-lines-20                           363.7µ ± 10%   452.2µ ± 21%  +24.36% (p=0.026 n=6)
ReadExistingLogs/100-lines-20                          920.0µ ± 25%   780.4µ ±  6%        ~ (p=0.065 n=6)
ReadExistingLogs/1000-lines-20                         4.422m ±  7%   3.735m ±  7%  -15.52% (p=0.002 n=6)
geomean                                                367.3µ         394.4µ         +7.38%

                               │ /tmp/fileinput-main-187259e7d7.txt │ /tmp/fileinput-batch-006ae63233.txt  │
                               │                B/op                │     B/op       vs base               │
ReadExistingLogs/0-lines-20                            26.27Ki ± 0%    26.19Ki ± 0%   -0.31% (p=0.002 n=6)
ReadExistingLogs/1-lines-20                            99.11Ki ± 2%   175.25Ki ± 2%  +76.83% (p=0.002 n=6)
ReadExistingLogs/2-lines-20                            100.6Ki ± 1%    178.7Ki ± 1%  +77.68% (p=0.002 n=6)
ReadExistingLogs/10-lines-20                           112.9Ki ± 1%    192.1Ki ± 1%  +70.08% (p=0.002 n=6)
ReadExistingLogs/20-lines-20                           129.4Ki ± 1%    209.0Ki ± 2%  +61.54% (p=0.002 n=6)
ReadExistingLogs/100-lines-20                          271.4Ki ± 5%    350.7Ki ± 2%  +29.24% (p=0.002 n=6)
ReadExistingLogs/1000-lines-20                         1.665Mi ± 0%    1.762Mi ± 1%   +5.81% (p=0.002 n=6)
geomean                                                150.8Ki         214.4Ki       +42.22%

                               │ /tmp/fileinput-main-187259e7d7.txt │ /tmp/fileinput-batch-006ae63233.txt │
                               │             allocs/op              │  allocs/op   vs base                │
ReadExistingLogs/0-lines-20                              46.00 ± 2%    45.00 ± 0%         ~ (p=0.061 n=6)
ReadExistingLogs/1-lines-20                              195.5 ± 2%    612.0 ± 2%  +213.04% (p=0.002 n=6)
ReadExistingLogs/2-lines-20                              202.5 ± 1%    626.0 ± 1%  +209.14% (p=0.002 n=6)
ReadExistingLogs/10-lines-20                             258.0 ± 1%    684.5 ± 1%  +165.31% (p=0.002 n=6)
ReadExistingLogs/20-lines-20                             329.5 ± 0%    759.0 ± 2%  +130.35% (p=0.002 n=6)
ReadExistingLogs/100-lines-20                            920.0 ± 3%   1376.0 ± 2%   +49.57% (p=0.002 n=6)
ReadExistingLogs/1000-lines-20                          7.257k ± 0%   7.800k ± 1%    +7.48% (p=0.002 n=6)
geomean                                                  374.5         715.6        +91.08%

This result still shows a performance penalty. Next, I want to check how changes in prevent-allocations-for-attributes affect it.

@andrzej-stencel
Copy link
Member Author

andrzej-stencel commented Feb 21, 2025 •
edited
Loading

Here's the comparison between main and prevent-allocations-for-attributes:

main 
$ (cd pkg/stanza/operator/input/file/ && go test -benchmem -run=^$ -bench Benchmark . -v -count=6 | tee /tmp/fileinput-main-$(git rev-parse --short HEAD).txt)
goos: linux
goarch: amd64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/file
cpu: 13th Gen Intel(R) Core(TM) i7-13700H
BenchmarkReadExistingLogs
BenchmarkReadExistingLogs/0-lines
BenchmarkReadExistingLogs/0-lines-20               70484             23031 ns/op           26841 B/op         45 allocs/op
BenchmarkReadExistingLogs/0-lines-20               47827             22781 ns/op           26872 B/op         45 allocs/op
BenchmarkReadExistingLogs/0-lines-20               46557             24626 ns/op           26976 B/op         46 allocs/op
BenchmarkReadExistingLogs/0-lines-20               49556             20808 ns/op           26881 B/op         46 allocs/op
BenchmarkReadExistingLogs/0-lines-20               48490             21711 ns/op           26926 B/op         46 allocs/op
BenchmarkReadExistingLogs/0-lines-20               54570             23494 ns/op           26957 B/op         46 allocs/op
BenchmarkReadExistingLogs/1-lines
BenchmarkReadExistingLogs/1-lines-20                4201            281598 ns/op           99820 B/op        192 allocs/op
BenchmarkReadExistingLogs/1-lines-20                3597            278643 ns/op          101172 B/op        195 allocs/op
BenchmarkReadExistingLogs/1-lines-20                4202            274729 ns/op          100037 B/op        193 allocs/op
BenchmarkReadExistingLogs/1-lines-20                4074            275832 ns/op          102114 B/op        197 allocs/op
BenchmarkReadExistingLogs/1-lines-20                4161            276897 ns/op          101796 B/op        196 allocs/op
BenchmarkReadExistingLogs/1-lines-20                5718            286110 ns/op          102193 B/op        197 allocs/op
BenchmarkReadExistingLogs/2-lines
BenchmarkReadExistingLogs/2-lines-20                3891            286790 ns/op          101980 B/op        200 allocs/op
BenchmarkReadExistingLogs/2-lines-20                6790            299994 ns/op          103685 B/op        204 allocs/op
BenchmarkReadExistingLogs/2-lines-20                4230            280316 ns/op          103476 B/op        203 allocs/op
BenchmarkReadExistingLogs/2-lines-20                3735            281811 ns/op          101645 B/op        200 allocs/op
BenchmarkReadExistingLogs/2-lines-20                4182            295597 ns/op          102921 B/op        202 allocs/op
BenchmarkReadExistingLogs/2-lines-20                3922            305502 ns/op          103116 B/op        203 allocs/op
BenchmarkReadExistingLogs/10-lines
BenchmarkReadExistingLogs/10-lines-20               3388            340723 ns/op          115932 B/op        258 allocs/op
BenchmarkReadExistingLogs/10-lines-20               5371            330354 ns/op          114449 B/op        256 allocs/op
BenchmarkReadExistingLogs/10-lines-20               3734            327431 ns/op          115598 B/op        258 allocs/op
BenchmarkReadExistingLogs/10-lines-20               4615            332575 ns/op          115508 B/op        258 allocs/op
BenchmarkReadExistingLogs/10-lines-20               3736            318994 ns/op          116489 B/op        259 allocs/op
BenchmarkReadExistingLogs/10-lines-20               3508            317881 ns/op          115664 B/op        258 allocs/op
BenchmarkReadExistingLogs/20-lines
BenchmarkReadExistingLogs/20-lines-20               3043            370798 ns/op          132970 B/op        330 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3166            399654 ns/op          132085 B/op        328 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3770            361589 ns/op          131562 B/op        328 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3362            344698 ns/op          133441 B/op        331 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3822            358177 ns/op          132667 B/op        330 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3208            365742 ns/op          132315 B/op        329 allocs/op
BenchmarkReadExistingLogs/100-lines
BenchmarkReadExistingLogs/100-lines-20              1645            691607 ns/op          265208 B/op        896 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1035           1078240 ns/op          271741 B/op        909 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1249            935385 ns/op          279790 B/op        924 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1726            911764 ns/op          276851 B/op        918 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1402            914500 ns/op          278960 B/op        922 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1326            925553 ns/op          281257 B/op        927 allocs/op
BenchmarkReadExistingLogs/1000-lines
BenchmarkReadExistingLogs/1000-lines-20              276           4381826 ns/op         1741158 B/op       7247 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              302           4746414 ns/op         1746959 B/op       7258 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              333           4715565 ns/op         1748366 B/op       7261 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              309           4407227 ns/op         1743468 B/op       7252 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              283           4436628 ns/op         1747759 B/op       7260 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              322           4404681 ns/op         1745806 B/op       7256 allocs/op
PASS
ok      github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/file        70.270s
prevent-allocations-for-attributes 
$  (cd pkg/stanza/operator/input/file/ && go test -benchmem -run=^$ -bench Benchmark . -v -count=6 | tee /tmp/fileinput-noattr-$(git rev-parse --short HEAD).txt)
goos: linux
goarch: amd64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/file
cpu: 13th Gen Intel(R) Core(TM) i7-13700H
BenchmarkReadExistingLogs
BenchmarkReadExistingLogs/0-lines
BenchmarkReadExistingLogs/0-lines-20               65566             22851 ns/op           26846 B/op         45 allocs/op
BenchmarkReadExistingLogs/0-lines-20               51938             22194 ns/op           26851 B/op         45 allocs/op
BenchmarkReadExistingLogs/0-lines-20               43855             23682 ns/op           26927 B/op         46 allocs/op
BenchmarkReadExistingLogs/0-lines-20               52132             23865 ns/op           26926 B/op         46 allocs/op
BenchmarkReadExistingLogs/0-lines-20               52185             24350 ns/op           26928 B/op         46 allocs/op
BenchmarkReadExistingLogs/0-lines-20               53761             22944 ns/op           26952 B/op         46 allocs/op
BenchmarkReadExistingLogs/1-lines
BenchmarkReadExistingLogs/1-lines-20                4078            288720 ns/op          106755 B/op        198 allocs/op
BenchmarkReadExistingLogs/1-lines-20                4292            289172 ns/op          107036 B/op        198 allocs/op
BenchmarkReadExistingLogs/1-lines-20                4126            289504 ns/op          106870 B/op        198 allocs/op
BenchmarkReadExistingLogs/1-lines-20                5118            291535 ns/op          107268 B/op        199 allocs/op
BenchmarkReadExistingLogs/1-lines-20                3829            269770 ns/op          107881 B/op        200 allocs/op
BenchmarkReadExistingLogs/1-lines-20                6006            234947 ns/op          105643 B/op        196 allocs/op
BenchmarkReadExistingLogs/2-lines
BenchmarkReadExistingLogs/2-lines-20                5472            310275 ns/op          107026 B/op        203 allocs/op
BenchmarkReadExistingLogs/2-lines-20                3956            302870 ns/op          108422 B/op        205 allocs/op
BenchmarkReadExistingLogs/2-lines-20                3848            299569 ns/op          109148 B/op        206 allocs/op
BenchmarkReadExistingLogs/2-lines-20                4045            288719 ns/op          108325 B/op        205 allocs/op
BenchmarkReadExistingLogs/2-lines-20                3379            304325 ns/op          108676 B/op        206 allocs/op
BenchmarkReadExistingLogs/2-lines-20                3439            316499 ns/op          108564 B/op        205 allocs/op
BenchmarkReadExistingLogs/10-lines
BenchmarkReadExistingLogs/10-lines-20               3501            339380 ns/op          120970 B/op        260 allocs/op
BenchmarkReadExistingLogs/10-lines-20               3459            335376 ns/op          122676 B/op        263 allocs/op
BenchmarkReadExistingLogs/10-lines-20               3519            336288 ns/op          122348 B/op        263 allocs/op
BenchmarkReadExistingLogs/10-lines-20               3559            333274 ns/op          121029 B/op        260 allocs/op
BenchmarkReadExistingLogs/10-lines-20               3469            328585 ns/op          122990 B/op        264 allocs/op
BenchmarkReadExistingLogs/10-lines-20               3159            336813 ns/op          121245 B/op        261 allocs/op
BenchmarkReadExistingLogs/20-lines
BenchmarkReadExistingLogs/20-lines-20               3208            381970 ns/op          140645 B/op        336 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3084            378508 ns/op          139418 B/op        334 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3061            388351 ns/op          139785 B/op        335 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3114            371635 ns/op          138348 B/op        332 allocs/op
BenchmarkReadExistingLogs/20-lines-20               2811            380827 ns/op          138303 B/op        332 allocs/op
BenchmarkReadExistingLogs/20-lines-20               3537            356651 ns/op          139123 B/op        334 allocs/op
BenchmarkReadExistingLogs/100-lines
BenchmarkReadExistingLogs/100-lines-20              1651            687588 ns/op          282687 B/op        919 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1670            695154 ns/op          288499 B/op        929 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1923            668218 ns/op          286785 B/op        926 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1627            707902 ns/op          288726 B/op        929 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1495            700683 ns/op          291439 B/op        934 allocs/op
BenchmarkReadExistingLogs/100-lines-20              1671            717894 ns/op          291303 B/op        934 allocs/op
BenchmarkReadExistingLogs/1000-lines
BenchmarkReadExistingLogs/1000-lines-20              351           3649849 ns/op         1756591 B/op       7257 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              421           3562851 ns/op         1759938 B/op       7263 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              370           3502160 ns/op         1766711 B/op       7275 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              379           3516728 ns/op         1766709 B/op       7276 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              368           3337492 ns/op         1770093 B/op       7281 allocs/op
BenchmarkReadExistingLogs/1000-lines-20              354           3179941 ns/op         1770700 B/op       7282 allocs/op
PASS
ok      github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/file        76.871s
$ benchstat /tmp/fileinput-main-187259e7d7.txt /tmp/fileinput-noattr-dfab829acd.txt
goos: linux
goarch: amd64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/file
cpu: 13th Gen Intel(R) Core(TM) i7-13700H
                               │ /tmp/fileinput-main-187259e7d7.txt │ /tmp/fileinput-noattr-dfab829acd.txt │
                               │               sec/op               │    sec/op      vs base               │
ReadExistingLogs/0-lines-20                            22.91µ ±  9%    23.31µ ±  5%        ~ (p=0.485 n=6)
ReadExistingLogs/1-lines-20                            277.8µ ±  3%    288.9µ ± 19%        ~ (p=0.394 n=6)
ReadExistingLogs/2-lines-20                            291.2µ ±  5%    303.6µ ±  5%        ~ (p=0.093 n=6)
ReadExistingLogs/10-lines-20                           328.9µ ±  4%    335.8µ ±  2%        ~ (p=0.132 n=6)
ReadExistingLogs/20-lines-20                           363.7µ ± 10%    379.7µ ±  6%        ~ (p=0.240 n=6)
ReadExistingLogs/100-lines-20                          920.0µ ± 25%    697.9µ ±  4%  -24.14% (p=0.026 n=6)
ReadExistingLogs/1000-lines-20                         4.422m ±  7%    3.509m ±  9%  -20.64% (p=0.002 n=6)
geomean                                                367.3µ          349.6µ         -4.81%

                               │ /tmp/fileinput-main-187259e7d7.txt │ /tmp/fileinput-noattr-dfab829acd.txt │
                               │                B/op                │      B/op       vs base              │
ReadExistingLogs/0-lines-20                            26.27Ki ± 0%     26.30Ki ± 0%       ~ (p=0.965 n=6)
ReadExistingLogs/1-lines-20                            99.11Ki ± 2%    104.45Ki ± 1%  +5.39% (p=0.002 n=6)
ReadExistingLogs/2-lines-20                            100.6Ki ± 1%     106.0Ki ± 1%  +5.31% (p=0.002 n=6)
ReadExistingLogs/10-lines-20                           112.9Ki ± 1%     118.9Ki ± 1%  +5.33% (p=0.002 n=6)
ReadExistingLogs/20-lines-20                           129.4Ki ± 1%     136.0Ki ± 1%  +5.12% (p=0.002 n=6)
ReadExistingLogs/100-lines-20                          271.4Ki ± 5%     281.8Ki ± 2%  +3.85% (p=0.002 n=6)
ReadExistingLogs/1000-lines-20                         1.665Mi ± 0%     1.685Mi ± 1%  +1.16% (p=0.002 n=6)
geomean                                                150.8Ki          156.4Ki       +3.73%

                               │ /tmp/fileinput-main-187259e7d7.txt │ /tmp/fileinput-noattr-dfab829acd.txt │
                               │             allocs/op              │   allocs/op     vs base              │
ReadExistingLogs/0-lines-20                              46.00 ± 2%       46.00 ± 2%       ~ (p=1.000 n=6)
ReadExistingLogs/1-lines-20                              195.5 ± 2%       198.0 ± 1%  +1.28% (p=0.009 n=6)
ReadExistingLogs/2-lines-20                              202.5 ± 1%       205.0 ± 1%  +1.23% (p=0.009 n=6)
ReadExistingLogs/10-lines-20                             258.0 ± 1%       262.0 ± 1%  +1.55% (p=0.002 n=6)
ReadExistingLogs/20-lines-20                             329.5 ± 0%       334.0 ± 1%  +1.37% (p=0.002 n=6)
ReadExistingLogs/100-lines-20                            920.0 ± 3%       929.0 ± 1%  +0.98% (p=0.024 n=6)
ReadExistingLogs/1000-lines-20                          7.257k ± 0%      7.276k ± 0%  +0.25% (p=0.015 n=6)
geomean                                                  374.5            378.1       +0.95%

@djaglowski looks like your suggestion for attributes has actually worked. I'm going to add this commit andrzej-stencel@1095dee to this branch. Please let me know your thoughts on this.

@djaglowski
Copy link
Member

djaglowski commented Feb 24, 2025 •
edited
Loading

I modified the test cases to scale up to 100,000 lines per file and increased run count to 20 and see similar results. I think we should pull in the change.

benchstat /tmp/fileinput-main-07a745d1e3.txt /tmp/fileinput-noattrs-dfab829acd.txt 
goos: darwin
goarch: arm64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/pkg/stanza/operator/input/file
cpu: Apple M4 Pro
                                 │ /tmp/fileinput-main-07a745d1e3.txt │ /tmp/fileinput-noattrs-dfab829acd.txt │
                                 │               sec/op               │     sec/op      vs base               │
ReadExistingLogs/1-lines-14                               77.97µ ± 4%      78.70µ ± 1%       ~ (p=0.277 n=20)
ReadExistingLogs/10-lines-14                              90.46µ ± 1%      93.55µ ± 1%  +3.41% (p=0.000 n=20)
ReadExistingLogs/100-lines-14                             182.8µ ± 0%      184.7µ ± 0%  +1.05% (p=0.001 n=20)
ReadExistingLogs/1000-lines-14                            1.034m ± 0%      1.042m ± 1%  +0.72% (p=0.020 n=20)
ReadExistingLogs/10000-lines-14                           9.409m ± 1%      9.473m ± 1%       ~ (p=0.211 n=20)
ReadExistingLogs/100000-lines-14                          95.11m ± 1%      95.39m ± 0%       ~ (p=0.102 n=20)
geomean                                                   1.030m           1.042m       +1.18%

                                 │ /tmp/fileinput-main-07a745d1e3.txt │ /tmp/fileinput-noattrs-dfab829acd.txt │
                                 │                B/op                │      B/op       vs base               │
ReadExistingLogs/1-lines-14                              98.53Ki ± 0%    104.30Ki ± 0%  +5.86% (p=0.000 n=20)
ReadExistingLogs/10-lines-14                             113.7Ki ± 0%     121.0Ki ± 0%  +6.38% (p=0.000 n=20)
ReadExistingLogs/100-lines-14                            258.8Ki ± 0%     265.0Ki ± 0%  +2.38% (p=0.000 n=20)
ReadExistingLogs/1000-lines-14                           1.637Mi ± 0%     1.651Mi ± 0%  +0.87% (p=0.000 n=20)
ReadExistingLogs/10000-lines-14                          15.44Mi ± 0%     15.53Mi ± 0%  +0.57% (p=0.000 n=20)
ReadExistingLogs/100000-lines-14                         153.5Mi ± 0%     154.3Mi ± 0%  +0.56% (p=0.000 n=20)
geomean                                                  1.479Mi          1.520Mi       +2.74%

                                 │ /tmp/fileinput-main-07a745d1e3.txt │ /tmp/fileinput-noattrs-dfab829acd.txt │
                                 │             allocs/op              │   allocs/op     vs base               │
ReadExistingLogs/1-lines-14                                193.0 ± 1%       196.5 ± 0%  +1.81% (p=0.000 n=20)
ReadExistingLogs/10-lines-14                               258.0 ± 0%       264.0 ± 0%  +2.33% (p=0.000 n=20)
ReadExistingLogs/100-lines-14                              894.5 ± 0%       897.0 ± 0%  +0.28% (p=0.000 n=20)
ReadExistingLogs/1000-lines-14                            7.201k ± 0%      7.213k ± 0%  +0.17% (p=0.000 n=20)
ReadExistingLogs/10000-lines-14                           70.20k ± 0%      70.30k ± 0%  +0.14% (p=0.000 n=20)
ReadExistingLogs/100000-lines-14                          700.2k ± 0%      701.2k ± 0%  +0.14% (p=0.000 n=20)
geomean                                                   5.008k           5.048k       +0.81%

djaglowski
djaglowski approved these changes Mar 3, 2025
View reviewed changes
Copy link
Member

@djaglowski djaglowski left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Overall looks good to me. The one thing I'd call out is that we've removed tests for the attributes. It would be good to add equivalent ones somewhere so we know we're not regressing on the actual behavior.

@andrzej-stencel andrzej-stencel merged commit 2760116 into open-telemetry:main Mar 3, 2025
156 checks passed
@github-actions github-actions bot added this to the next release milestone Mar 3, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@bogdandrutu bogdandrutu bogdandrutu left review comments

@fatsheep9146 fatsheep9146 fatsheep9146 left review comments

@djaglowski djaglowski djaglowski approved these changes

@atoulme atoulme Awaiting requested review from atoulme atoulme is a code owner

@dehaansa dehaansa Awaiting requested review from dehaansa dehaansa is a code owner

Assignees

@fatsheep9146 fatsheep9146

Labels
pkg/stanza processor/logstransform Logs Transform processor receiver/otlpjsonfile
Projects
None yet
Milestone
v0.121.0
Development

Successfully merging this pull request may close these issues.

[pkg/stanza/fileconsumer] Emit logs in batches
4 participants
@andrzej-stencel @djaglowski @bogdandrutu @fatsheep9146