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.

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

encoding/xml: very low performance in xml parser #21823

Open
243083df opened this issue Sep 9, 2017 · 27 comments
Open

encoding/xml: very low performance in xml parser #21823

243083df opened this issue Sep 9, 2017 · 27 comments

Comments

@243083df
Copy link

@243083df 243083df commented Sep 9, 2017

What version of Go are you using (go version)?

1.9

Does this issue reproduce with the latest release?

True

What operating system and processor architecture are you using (go env)?

Windows

What did you do?

I trying to parse large files with SAX with go, and get decadent performance.
I rewrite code in C#, and get maximum performance.

file, err := os.Open(filename)
handle(err)
defer file.Close()
buffer := bufio.NewReaderSize(file, 1024*1024*256) // 33554432
decoder := xml.NewDecoder(buffer)
for {
        t, _ := decoder.Token()
        if t == nil {
            break
        }
        switch se := t.(type) {
        case xml.StartElement:
            if se.Name.Local == "House" {
                house := House{}
                err := decoder.DecodeElement(&house, &se)
                handle(err)
            }
        }
    }
using (XmlReader reader = XmlReader.Create(filename)
            {
                while (reader.Read())
                {
                    switch (reader.NodeType)
                    {
                        case XmlNodeType.Element:
                            if (reader.Name == "House")
                            {
                                //Code
                            }
                            break;
                    }
                }
            }

What did you expect to see?

Mature and fast xml parser in golang.

What did you see instead?

The bottleneck in SAX xml parsing with go is CPU, instead of low HDD io performance.

@ianlancetaylor
Copy link
Contributor

@ianlancetaylor ianlancetaylor commented Sep 9, 2017

Can you show us a complete, standalone example program? And provide your input file, or at least tell us about it?

What are the actual performance numbers?

Thanks.

@ianlancetaylor ianlancetaylor changed the title Very low performance in xml parser encoding/xml: very low performance in xml parser Sep 9, 2017
@ianlancetaylor ianlancetaylor added this to the Unplanned milestone Sep 9, 2017
@243083df
Copy link
Author

@243083df 243083df commented Sep 9, 2017

File is very big, around 10-50 millions records.
The xml file looks like this:

<?xml version="1.0" encoding="utf-8"?>
<LIST>
<ELEMENT ATTRIBUTE1="" ATTRIBUTE2="" /><ELEMENT ATTRIBUTE1="" ATTRIBUTE2="" />
</LIST>
@a-h
Copy link
Contributor

@a-h a-h commented Sep 10, 2017

I was curious, since I use .NET and Go regularly, so I turned this into a reproduction at https://github.com/a-h/sax

On my MacOS machine, I found that the Go version was much slower (around 20 seconds) than the .NET Core 2.0 one (around 3 seconds) for a file with 10 million elements in it laid out as per the example above.

I put the timing output in the README.md. I noted that the CPU was at 100% during Go execution.

I added an SVG of the Go CPU profile output to the repo.

screen shot 2017-09-10 at 22 55 33

@243083df
Copy link
Author

@243083df 243083df commented Sep 11, 2017

I think, @a-h's benchmark enough to investigate. I used same code.

@gopherbot
Copy link

@gopherbot gopherbot commented Sep 12, 2017

Change https://golang.org/cl/63390 mentions this issue: unicode: speed-up is16/is32

gopherbot pushed a commit that referenced this issue Sep 12, 2017
Avoid division in common case. There are 5438 ranges in unicode/tables.go
4110 of them have stride 1.
Stride 1 case got significantly faster. Other stride is a bit slower.
Measured by

import (
	"testing"
	"unicode"
)

func BenchmarkDiv1(b *testing.B) {
	rtb := &unicode.RangeTable{
		R16: []unicode.Range16{
			{0xa800, 0xdfff, 1}, // or 3
		},
	}
	for i := 0; i < b.N; i++ {
		unicode.Is(rtb, rune(0xc700))
	}
}

Div1-6  15.6ns ± 1%   9.9ns ± 1%  -36.54%  (p=0.000 n=10+10)
Div3-6  15.5ns ± 1%  16.1ns ± 1%   +3.67%  (p=0.000 n=10+10)

Helps a bit with xml parsing from issue #21823

XMLsax-6   30.9s ± 0%   29.6s ± 0%  -4.15%  (p=0.000 n=10+9)

Change-Id: Ibac1a91d7b9474d0c134b0add83e56caa62daa20
Reviewed-on: https://go-review.googlesource.com/63390
Run-TryBot: Ilya Tocar <ilya.tocar@intel.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
@243083df
Copy link
Author

@243083df 243083df commented Sep 13, 2017

By the way. Is call len(p) in https://github.com/golang/go/blob/master/src/bufio/bufio.go#L196 necessarily?

@mattn
Copy link
Member

@mattn mattn commented Sep 13, 2017

xml.NewDecoder already create bufio.Reader.

@243083df
Copy link
Author

@243083df 243083df commented Sep 14, 2017

@mattn Yes, but its create bufio.Reader without minimum read value.
bufio.Reader with minimum read value around 64Mb, speed up parsing 2Gb xml from 2m40s to 2m5s(around 20%, but its not stable) on HDD.

@robfordww
Copy link

@robfordww robfordww commented Nov 4, 2017

A lot of speed could be gained if the parser was referring to the xml byte slice instead of copying everything. I am working on such an parser for go, based on the rapidxml library in c++

@saleem-mirza
Copy link

@saleem-mirza saleem-mirza commented Dec 2, 2017

I am experiencing same issue. Parsing 1 GB XML takes minutes which C# version completes in few seconds ( < 10)

@suntong
Copy link

@suntong suntong commented Dec 31, 2017

So the go sax parser is about 6~7 times slower than the C#, i.e., much room to improve. Watching the development on this...

Anyone can confirm, whether unmarshaling into defined data structures, if possible, can speed things up? I always use the sax parser way, maybe it is time to go with the DOM parser way, as my files are not terribly big. I went with the sax parser way only because intuitively thinking, it should be faster than the DOM parser way.

@a-h
Copy link
Contributor

@a-h a-h commented Jan 3, 2018

Just checked the performance of various versions using Docker containers to see if 1.10beta1 is likely to improve performance (I thought I saw a few perf improvements to Unicode handling in the changelog).

docker run -it --rm -v `pwd`:/go/src/github.com/a-h/sax golang:1.10beta1 /bin/bash
docker run -it --rm -v `pwd`:/go/src/github.com/a-h/sax golang:1.9.2 /bin/bash
docker run -it --rm -v `pwd`:/go/src/github.com/a-h/sax golang:1.8 /bin/bash

Results

1.10: 0m21.383s
1.9.2: 0m21.281s
1.8: 0m27.370s

So, looks like no improvement this version.

@suntong
Copy link

@suntong suntong commented Jan 3, 2018

Well done!

Has anyone done a profile to see exactly where the pain-point is?
Maybe that might help pushing things a bit?

@a-h
Copy link
Contributor

@a-h a-h commented Jan 4, 2018

@a-h
Copy link
Contributor

@a-h a-h commented Mar 25, 2018

It's possible to reduce the amount of calls to the UTF8 DecodeRune etc. by keeping a cache of the names the decoder has already seen, on the basis that it's very likely those names will be seen again. This could be limited to a reasonable level, e.g. 10,000 XML names to stop it using too much RAM.

Over 1,000,000 XML elements, I saw an improvement from 1.632s to 1.431s.

$ go test -bench=Decoder -cpuprofile profile_cpu.out
processed authors:  1000000
goos: darwin
goarch: amd64
pkg: encoding/xml
BenchmarkDecoder-4             1        1437269859 ns/op        518663400 B/op   8000059 allocs/op
PASS
ok      encoding/xml    1.632s
$ go test -bench=Decoder -cpuprofile profile_cpu.out
processed authors:  1000000
goos: darwin
goarch: amd64
pkg: encoding/xml
BenchmarkDecoder-4             1        1211802156 ns/op        518656056 B/op   8000053 allocs/op
PASS
ok      encoding/xml    1.431s
func (d *Decoder) isName(s []byte) bool {
	// Check the cache first.
	if _, ok := d.names[string(s)]; ok {
		return true
	}
	// If it's not in the cache, add it if it's valid.
	v := isName(s)
	if v {
		d.names[string(s)] = true
	}
	return v
}

// Get name: /first(first|second)*/
// Do not set d.err if the name is missing (unless unexpected EOF is received):
// let the caller provide better context.
func (d *Decoder) name() (s string, ok bool) {
	d.buf.Reset()
	if !d.readName() {
		return "", false
	}

	// Now we check the characters.
	b := d.buf.Bytes()
	if !d.isName(b) {
		d.err = d.syntaxError("invalid XML name: " + string(b))
		return "", false
	}
	return string(b), true
}

@ianlancetaylor - is it worth me pursuing that as a change?

@a-h
Copy link
Contributor

@a-h a-h commented Mar 25, 2018

My benchmark is:

func BenchmarkDecoder(b *testing.B) {
	b.ReportAllocs()
	count := 1000000
	buffer := strings.NewReader(`<authors>` + authors(count) + `</authors`)
	for i := 0; i < b.N; i++ {
		buffer.Seek(0, io.SeekStart)
		decoder := NewDecoder(buffer)
		var authors = 0
		for {
			tok, _ := decoder.Token()
			if tok == nil {
				break
			}
			switch se := tok.(type) {
			case StartElement:
				if se.Name.Local == "author" {
					authors++
				}
			}
		}
		if authors != count {
			panic("failed to report correct number of authors")
		}
		fmt.Println("processed authors: ", authors)
	}
}

func authors(count int) string {
	buf := bytes.NewBufferString("")
	for i := 0; i < count; i++ {
		buf.WriteString(`<author name="Alan Watt" />`)
	}
	return buf.String()
}
@243083df
Copy link
Author

@243083df 243083df commented Mar 28, 2018

@a-h I think it would be better to use slice cache isead of Read|Unread byte

@a-h
Copy link
Contributor

@a-h a-h commented Mar 29, 2018

Do you mean something that reads into a buffer like this? https://github.com/a-h/lexical/blob/master/input/stream.go

@nussjustin
Copy link
Contributor

@nussjustin nussjustin commented Apr 12, 2018

@a-h The code could be further optimized like this:

// Get name: /first(first|second)*/
// Do not set d.err if the name is missing (unless unexpected EOF is received):
// let the caller provide better context.
func (d *Decoder) name() (s string, ok bool) {
	d.buf.Reset()
	if !d.readName() {
		return "", false
	}

	// Now we check the characters.
	b := d.buf.Bytes()
    if s, ok = d.names[string(b)]; ok {
		return s, ok
	}
	if !isName(b) {
		d.err = d.syntaxError("invalid XML name: " + string(b))
		return "", false
	}
    s = string(b)
    d.names[s] = s
	return s, true
}

This way we can avoid the isName check and reuse the string from the d.names map without allocation.

For the existing unmarshal benchmark this gives me

name         old time/op    new time/op    delta
Unmarshal-8    11.6µs ± 1%    11.7µs ± 3%     ~     (p=0.990 n=12+14)

name         old alloc/op   new alloc/op   delta
Unmarshal-8    8.27kB ± 0%    9.13kB ± 0%  +10.40%  (p=0.000 n=15+15)

name         old allocs/op  new allocs/op  delta
Unmarshal-8       190 ± 0%       166 ± 0%  -12.63%  (p=0.000 n=15+15)

No change on the time, but at work we have a tool that parses multiple XML files, each around 250MB+, and reusing the allocated names saves about 2 seconds per file (14s -> 12s).

In my case I shaved off another second by making copyValue accept both []byte and string, avoiding an allocation for each attribute value.

But again, this doesn't reflect in the existing benchmark:

name         old time/op    new time/op    delta
Unmarshal-8    11.6µs ± 1%    11.4µs ± 1%  -1.72%  (p=0.000 n=12+12)

name         old alloc/op   new alloc/op   delta
Unmarshal-8    8.27kB ± 0%    8.11kB ± 0%  -1.93%  (p=0.000 n=15+15)

name         old allocs/op  new allocs/op  delta
Unmarshal-8       190 ± 0%       186 ± 0%  -2.11%  (p=0.000 n=15+15)
@tamerh
Copy link

@tamerh tamerh commented Nov 15, 2018

Hi, any update on this or workaround solution? i also observed that it is slower than java.

@webern
Copy link

@webern webern commented Dec 23, 2018

I have also found my way here after seeing a very large box in my profile for encoding/xml (*Decoder) unmarshal. Golang XML 'feels' a lot slower than C++ rapidxml, pugixml and expat, though I have not benchmarked.

@tamerh
Copy link

@tamerh tamerh commented Jan 23, 2019

Hi all and @243083df, @l-we, @webern, @ajruckman, @qwantix, @evt

Regarding this issue you can try my library

https://github.com/tamerh/xml-stream-parser

@ilyabreev
Copy link

@ilyabreev ilyabreev commented Apr 27, 2019

Any progress on this issue?

@saleem-mirza
Copy link

@saleem-mirza saleem-mirza commented Apr 27, 2019

Actually, programmer who coded this library is long gone so we are clueless.

Disclaimer: this is not official excuse, I made it up since community is mysteriously silent on this issue

@webern
Copy link

@webern webern commented Apr 27, 2019

@saleem-mirza this begs the question, what are the plans for Golang to continue supporting XML natively as part of the standard library?

Currently the XML implementation suffers from several issues that make it substandard (when compared with Xerces, Java or libxml2, for example)

  1. It is very slow.
  2. It is non-validating (we need xsd validation)
  3. There is no support for loading XML when the schema is not known. i.e. we can load any json and we get a map[string]interface. But we cannot do this with xml.

I would love to work on something like this, but it would definitely be a full-time job, i.e. someone would have to be paid to build this.

@tamerh
Copy link

@tamerh tamerh commented Jun 11, 2019

Hi all and @243083df, @l-we, @webern, @ajruckman, @qwantix, @evt

Regarding this issue you can try my library

https://github.com/tamerh/xml-stream-parser

For people who are interested in streaming parsing i have refactored the library
to improve code quality, error handling and now it is more than 30% faster compare to previous version.Let me know if you have suggestions/feedbacks.

@gopherbot
Copy link

@gopherbot gopherbot commented Feb 8, 2020

Change https://golang.org/cl/218658 mentions this issue: encoding/xml: decoder to use buffered start attr

andrewkroh added a commit to andrewkroh/beats that referenced this issue Mar 5, 2020
This PR adds a new event log reader implementation that's behind a
feature flag for now. It achieves higher event throughput than the current
reader by not using XML and by heavily caching static metadata about events.
To enable it add `api` to each event log reader.

```
winlogbeat.event_logs:
- name: Security
  api: wineventlog-experimental
```

The existing reader requests each event as XML and then must unmarshal the XML
document. EvtFormatMessage is used to get the XML document from Windows. Then the
Go stdlib encoder/xml package is used to parse it. Both of these operations are
relatively slow (see golang/go#21823 about encoding/xml).

This new reader utilizes the publisher metadata APIs to fetch and cache metadata
about all event IDs associated with a provider. It does this the first time it
encounters a provider ID while reading events. __Risk: Caching this info could
lead to having stale information in memory if metadata changes via software
update (see Edge Cases).__ It caches the names of the event data parameters
and a templatized version of the message string.

To get the data for an event this reader receives EVT_VARIANT structs containing
the parameters rather than receiving and parsing XML. This is more efficent because
there are fewer and smaller memory allocations and no XML encoding or decoding.

To get the message for an event it utilizes the cached text/template it has
for the event ID and passes it the list of parameter values.

Edge Cases

There is no provider metadata installed on the host. Could happen for forwarded
events or reading from .evtx files.
- Migigate by falling back to getting parameter names by the event XML and rendering
  the message with EvtFormatMessage for each event.

Software is updated and an event ID changes it's event data parameters. Saw this
between Sysmon versions 9 and 10 with event ID 5.
- Mitigate by fingerprinting the number of event data parameters and their types.
- If the fingerprint changes, fetch the XML for the event and store the parameter
  names.

Benchmark Comparison

Comparing batch_size 500, that's a 2252% increase in events/sec, a -90% reduction in bytes allocated per event, and -65% reduction in number of allocations.

Current Reader

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBench -benchtest -benchtime 10s -v -cpuprofile .\cpu-orig.pprof -memprofile mem-orig.pprof .
=== RUN   TestBenchmarkBatchReadSize
--- PASS: TestBenchmarkBatchReadSize (121.51s)
    bench_test.go:99: batch_size=10, total_events=24720, batch_time=4.953727ms, events_per_sec=2018.6820953193426, bytes_alloced_per_event=18 kB, total_allocs=6220231
    bench_test.go:99: batch_size=100, total_events=25000, batch_time=47.59166ms, events_per_sec=2101.2084890503925, bytes_alloced_per_event=18 kB, total_allocs=6255322
    bench_test.go:99: batch_size=500, total_events=25500, batch_time=233.858192ms, events_per_sec=2138.0478302851157, bytes_alloced_per_event=18 kB, total_allocs=6375986
    bench_test.go:99: batch_size=1000, total_events=24000, batch_time=485.101262ms, events_per_sec=2061.425270008883, bytes_alloced_per_event=18 kB, total_allocs=6000314
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 121.907s

Experimental Reader

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBench -benchtest -benchtime 10s -v -cpuprofile .\cpu-final-exp.pprof -memprofile mem-final-exp.pprof .
=== RUN   TestBenchmarkBatchReadSize
--- PASS: TestBenchmarkBatchReadSize (180.91s)
    bench_test.go:99: batch_size=10, total_events=333820, batch_time=327.867µs, events_per_sec=30500.17232597364, bytes_alloced_per_event=2.0 kB, total_allocs=6119389
    bench_test.go:99: batch_size=100, total_events=600000, batch_time=1.922684ms, events_per_sec=52010.62681127008, bytes_alloced_per_event=1.8 kB, total_allocs=10621014
    bench_test.go:99: batch_size=500, total_events=594000, batch_time=9.940681ms, events_per_sec=50298.364870575766, bytes_alloced_per_event=1.7 kB, total_allocs=10499254
    bench_test.go:99: batch_size=1000, total_events=513000, batch_time=21.261628ms, events_per_sec=47033.08702419212, bytes_alloced_per_event=1.7 kB, total_allocs=9124868
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 181.307s
andrewkroh added a commit to andrewkroh/beats that referenced this issue Mar 5, 2020
This PR adds a new event log reader implementation that's behind a
feature flag for now. It achieves higher event throughput than the current
reader by not using XML and by heavily caching static metadata about events.
To enable it add `api` to each event log reader.

```
winlogbeat.event_logs:
- name: Security
  api: wineventlog-experimental
```

The existing reader requests each event as XML and then must unmarshal the XML
document. EvtFormatMessage is used to get the XML document from Windows. Then the
Go stdlib encoder/xml package is used to parse it. Both of these operations are
relatively slow (see golang/go#21823 about encoding/xml).

This new reader utilizes the publisher metadata APIs to fetch and cache metadata
about all event IDs associated with a provider. It does this the first time it
encounters a provider ID while reading events. __Risk: Caching this info could
lead to having stale information in memory if metadata changes via software
update (see Edge Cases).__ It caches the names of the event data parameters
and a templatized version of the message string.

To get the data for an event this reader receives EVT_VARIANT structs containing
the parameters rather than receiving and parsing XML. This is more efficient because
there are fewer and smaller memory allocations and no XML encoding or decoding.

To get the message for an event it utilizes the cached text/template it has
for the event ID and passes it the list of parameter values.

Edge Cases

There is no provider metadata installed on the host. Could happen for forwarded
events or reading from .evtx files.
- Migigate by falling back to getting parameter names by the event XML and rendering
  the message with EvtFormatMessage for each event.

Software is updated and an event ID changes it's event data parameters. Saw this
between Sysmon versions 9 and 10 with event ID 5.
- Mitigate by fingerprinting the number of event data parameters and their types.
- If the fingerprint changes, fetch the XML for the event and store the parameter
  names.

Benchmark Comparison

Comparing batch_size 500, that's a 2252% increase in events/sec, a -90% reduction in bytes allocated per event, and -65% reduction in number of allocations.

Current Reader

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBench -benchtest -benchtime 10s -v -cpuprofile .\cpu-orig.pprof -memprofile mem-orig.pprof .
=== RUN   TestBenchmarkBatchReadSize
--- PASS: TestBenchmarkBatchReadSize (121.51s)
    bench_test.go:99: batch_size=10, total_events=24720, batch_time=4.953727ms, events_per_sec=2018.6820953193426, bytes_alloced_per_event=18 kB, total_allocs=6220231
    bench_test.go:99: batch_size=100, total_events=25000, batch_time=47.59166ms, events_per_sec=2101.2084890503925, bytes_alloced_per_event=18 kB, total_allocs=6255322
    bench_test.go:99: batch_size=500, total_events=25500, batch_time=233.858192ms, events_per_sec=2138.0478302851157, bytes_alloced_per_event=18 kB, total_allocs=6375986
    bench_test.go:99: batch_size=1000, total_events=24000, batch_time=485.101262ms, events_per_sec=2061.425270008883, bytes_alloced_per_event=18 kB, total_allocs=6000314
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 121.907s

Experimental Reader

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBench -benchtest -benchtime 10s -v -cpuprofile .\cpu-final-exp.pprof -memprofile mem-final-exp.pprof .
=== RUN   TestBenchmarkBatchReadSize
--- PASS: TestBenchmarkBatchReadSize (180.91s)
    bench_test.go:99: batch_size=10, total_events=333820, batch_time=327.867µs, events_per_sec=30500.17232597364, bytes_alloced_per_event=2.0 kB, total_allocs=6119389
    bench_test.go:99: batch_size=100, total_events=600000, batch_time=1.922684ms, events_per_sec=52010.62681127008, bytes_alloced_per_event=1.8 kB, total_allocs=10621014
    bench_test.go:99: batch_size=500, total_events=594000, batch_time=9.940681ms, events_per_sec=50298.364870575766, bytes_alloced_per_event=1.7 kB, total_allocs=10499254
    bench_test.go:99: batch_size=1000, total_events=513000, batch_time=21.261628ms, events_per_sec=47033.08702419212, bytes_alloced_per_event=1.7 kB, total_allocs=9124868
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 181.307s
andrewkroh added a commit to andrewkroh/beats that referenced this issue Mar 5, 2020
This PR adds a new event log reader implementation that's behind a
feature flag for now. It achieves higher event throughput than the current
reader by not using XML and by heavily caching static metadata about events.
To enable it add `api` to each event log reader.

```
winlogbeat.event_logs:
- name: Security
  api: wineventlog-experimental
```

The existing reader requests each event as XML and then must unmarshal the XML
document. EvtFormatMessage is used to get the XML document from Windows. Then the
Go stdlib encoder/xml package is used to parse it. Both of these operations are
relatively slow (see golang/go#21823 about encoding/xml).

This new reader utilizes the publisher metadata APIs to fetch and cache metadata
about all event IDs associated with a provider. It does this the first time it
encounters a provider ID while reading events. __Risk: Caching this info could
lead to having stale information in memory if metadata changes via software
update (see Edge Cases).__ It caches the names of the event data parameters
and a templatized version of the message string.

To get the data for an event this reader receives EVT_VARIANT structs containing
the parameters rather than receiving and parsing XML. This is more efficient because
there are fewer and smaller memory allocations and no XML encoding or decoding.

To get the message for an event it utilizes the cached text/template it has
for the event ID and passes it the list of parameter values.

Edge Cases

There is no provider metadata installed on the host. Could happen for forwarded
events or reading from .evtx files.
- Mitigate by falling back to getting parameter names by the event XML and rendering
  the message with EvtFormatMessage for each event.

Software is updated and an event ID changes it's event data parameters. Saw this
between Sysmon versions 9 and 10 with event ID 5.
- Mitigate by fingerprinting the number of event data parameters and their types.
- If the fingerprint changes, fetch the XML for the event and store the parameter
  names.

Benchmark Comparison

Comparing batch_size 500, that's a 2252% increase in events/sec, a -90% reduction in bytes allocated per event, and -65% reduction in number of allocations.

Current Reader

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBench -benchtest -benchtime 10s -v -cpuprofile .\cpu-orig.pprof -memprofile mem-orig.pprof .
=== RUN   TestBenchmarkBatchReadSize
--- PASS: TestBenchmarkBatchReadSize (121.51s)
    bench_test.go:99: batch_size=10, total_events=24720, batch_time=4.953727ms, events_per_sec=2018.6820953193426, bytes_alloced_per_event=18 kB, total_allocs=6220231
    bench_test.go:99: batch_size=100, total_events=25000, batch_time=47.59166ms, events_per_sec=2101.2084890503925, bytes_alloced_per_event=18 kB, total_allocs=6255322
    bench_test.go:99: batch_size=500, total_events=25500, batch_time=233.858192ms, events_per_sec=2138.0478302851157, bytes_alloced_per_event=18 kB, total_allocs=6375986
    bench_test.go:99: batch_size=1000, total_events=24000, batch_time=485.101262ms, events_per_sec=2061.425270008883, bytes_alloced_per_event=18 kB, total_allocs=6000314
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 121.907s

Experimental Reader

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBench -benchtest -benchtime 10s -v -cpuprofile .\cpu-final-exp.pprof -memprofile mem-final-exp.pprof .
=== RUN   TestBenchmarkBatchReadSize
--- PASS: TestBenchmarkBatchReadSize (180.91s)
    bench_test.go:99: batch_size=10, total_events=333820, batch_time=327.867µs, events_per_sec=30500.17232597364, bytes_alloced_per_event=2.0 kB, total_allocs=6119389
    bench_test.go:99: batch_size=100, total_events=600000, batch_time=1.922684ms, events_per_sec=52010.62681127008, bytes_alloced_per_event=1.8 kB, total_allocs=10621014
    bench_test.go:99: batch_size=500, total_events=594000, batch_time=9.940681ms, events_per_sec=50298.364870575766, bytes_alloced_per_event=1.7 kB, total_allocs=10499254
    bench_test.go:99: batch_size=1000, total_events=513000, batch_time=21.261628ms, events_per_sec=47033.08702419212, bytes_alloced_per_event=1.7 kB, total_allocs=9124868
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 181.307s
andrewkroh added a commit to andrewkroh/beats that referenced this issue Mar 9, 2020
This PR adds a new event log reader implementation that's behind a
feature flag for now. It achieves higher event throughput than the current
reader by not using XML and by heavily caching static metadata about events.
To enable it add `api` to each event log reader.

```
winlogbeat.event_logs:
- name: Security
  api: wineventlog-experimental
```

The existing reader requests each event as XML and then must unmarshal the XML
document. EvtFormatMessage is used to get the XML document from Windows. Then the
Go stdlib encoder/xml package is used to parse it. Both of these operations are
relatively slow (see golang/go#21823 about encoding/xml).

This new reader utilizes the publisher metadata APIs to fetch and cache metadata
about all event IDs associated with a provider. It does this the first time it
encounters a provider ID while reading events. __Risk: Caching this info could
lead to having stale information in memory if metadata changes via software
update (see Edge Cases).__ It caches the names of the event data parameters
and a templatized version of the message string.

To get the data for an event this reader receives EVT_VARIANT structs containing
the parameters rather than receiving and parsing XML. This is more efficient because
there are fewer and smaller memory allocations and no XML encoding or decoding.

To get the message for an event it utilizes the cached text/template it has
for the event ID and passes it the list of parameter values.

Edge Cases

There is no provider metadata installed on the host. Could happen for forwarded
events or reading from .evtx files.
- Mitigate by falling back to getting parameter names by the event XML and rendering
  the message with EvtFormatMessage for each event.

Software is updated and an event ID changes it's event data parameters. Saw this
between Sysmon versions 9 and 10 with event ID 5.
- Mitigate by fingerprinting the number of event data parameters and their types.
- If the fingerprint changes, fetch the XML for the event and store the parameter
  names.

Benchmark Comparison

Comparing batch_size 500, that's a 1319% increase in events/sec, a -88% reduction in bytes allocated per event, but an overall increase in the number of allocations.

Current Reader

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBench -benchtest -benchtime 10s -benchmem -v .
=== RUN   TestBenchmarkBatchReadSize
--- PASS: TestBenchmarkBatchReadSize (119.34s)
    bench_test.go:99: batch_size=10, total_events=23800, batch_time=5.023152ms, events_per_sec=1990.7818835663343, bytes_alloced_per_event=17 kB, total_allocs=6012178
    bench_test.go:99: batch_size=100, total_events=24200, batch_time=47.488485ms, events_per_sec=2105.7736417575757, bytes_alloced_per_event=17 kB, total_allocs=6079096
    bench_test.go:99: batch_size=500, total_events=24500, batch_time=234.694467ms, events_per_sec=2130.4294318962366, bytes_alloced_per_event=17 kB, total_allocs=6150456
    bench_test.go:99: batch_size=1000, total_events=24000, batch_time=481.58722ms, events_per_sec=2076.4670623942225, bytes_alloced_per_event=17 kB, total_allocs=6024332
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 119.543s

Experimental Reader

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBench -benchtest -benchtime 10s -benchmem -v .
=== RUN   TestBenchmarkBatchReadSize
--- PASS: TestBenchmarkBatchReadSize (165.31s)
    bench_test.go:99: batch_size=10, total_events=171760, batch_time=591.871µs, events_per_sec=16895.573528691217, bytes_alloced_per_event=2.1 kB, total_allocs=5925315
    bench_test.go:99: batch_size=100, total_events=345700, batch_time=3.316411ms, events_per_sec=30153.078131751463, bytes_alloced_per_event=2.0 kB, total_allocs=11467585
    bench_test.go:99: batch_size=500, total_events=352500, batch_time=16.53926ms, events_per_sec=30231.098610215933, bytes_alloced_per_event=2.0 kB, total_allocs=11662811
    bench_test.go:99: batch_size=1000, total_events=339000, batch_time=34.02696ms, events_per_sec=29388.46138473728, bytes_alloced_per_event=2.0 kB, total_allocs=11224490
PASS
andrewkroh added a commit to andrewkroh/beats that referenced this issue Mar 10, 2020
This PR adds a new event log reader implementation that's behind a
feature flag for now. It achieves higher event throughput than the current
reader by not using XML and by heavily caching static metadata about events.
To enable it add `api` to each event log reader.

```
winlogbeat.event_logs:
- name: Security
  api: wineventlog-experimental
```

The existing reader requests each event as XML and then must unmarshal the XML
document. EvtFormatMessage is used to get the XML document from Windows. Then the
Go stdlib encoder/xml package is used to parse it. Both of these operations are
relatively slow (see golang/go#21823 about encoding/xml).

This new reader utilizes the publisher metadata APIs to fetch and cache metadata
about all event IDs associated with a provider. It does this the first time it
encounters a provider ID while reading events. __Risk: Caching this info could
lead to having stale information in memory if metadata changes via software
update (see Edge Cases).__ It caches the names of the event data parameters
and a templatized version of the message string.

To get the data for an event this reader receives EVT_VARIANT structs containing
the parameters rather than receiving and parsing XML. This is more efficient because
there are fewer and smaller memory allocations and no XML encoding or decoding.

To get the message for an event it utilizes the cached text/template it has
for the event ID and passes it the list of parameter values.

Edge Cases

There is no provider metadata installed on the host. Could happen for forwarded
events or reading from .evtx files.
- Mitigate by falling back to getting parameter names by the event XML and rendering
  the message with EvtFormatMessage for each event.

Software is updated and an event ID changes it's event data parameters. Saw this
between Sysmon versions 9 and 10 with event ID 5.
- Mitigate by fingerprinting the number of event data parameters and their types.
- If the fingerprint changes, fetch the XML for the event and store the parameter
  names.

Benchmark Comparison

Comparing batch_size 500, that's a 1396% increase in events/sec, a -81% reduction in bytes allocated per event, and -86% decrease in the number of allocations.

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBenchmarkRead -benchmem -benchtime 10s -benchtest -v .
--- PASS: TestBenchmarkRead (231.68s)
    --- PASS: TestBenchmarkRead/api=wineventlog (53.57s)
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=10 (12.19s)
            bench_test.go:128: 2067.28 events/sec        18283 B/event   182836 B/batch  251 allocs/event        2516 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=100 (16.73s)
            bench_test.go:128: 2144.50 events/sec        17959 B/event   1795989 B/batch         250 allocs/event        25020 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=500 (13.48s)
            bench_test.go:128: 1888.40 events/sec        17648 B/event   8824455 B/batch         250 allocs/event        125018 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=1000 (11.18s)
            bench_test.go:128: 2064.14 events/sec        17650 B/event   17650459 B/batch        250 allocs/event        250012 allocs/batch
    --- PASS: TestBenchmarkRead/api=wineventlog-experimental (98.28s)
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=10 (18.72s)
            bench_test.go:128: 16813.52 events/sec       3974 B/event    39744 B/batch   34 allocs/event         344 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=100 (25.39s)
            bench_test.go:128: 28300.30 events/sec       3634 B/event    363498 B/batch  33 allocs/event         3324 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=500 (26.40s)
            bench_test.go:128: 28266.73 events/sec       3332 B/event    1666041 B/batch         33 allocs/event         16597 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=1000 (27.77s)
            bench_test.go:128: 28387.74 events/sec       3330 B/event    3330690 B/batch         33 allocs/event         33127 allocs/batch
    --- PASS: TestBenchmarkRead/api=eventlogging (13.29s)
        bench_test.go:128: 56243.80 events/sec   8043 B/event    6513053 B/batch         31 allocs/event         25151 allocs/batch
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 231.932s
andrewkroh added a commit to andrewkroh/beats that referenced this issue Mar 12, 2020
This PR adds a new event log reader implementation that's behind a
feature flag for now. It achieves higher event throughput than the current
reader by not using XML and by heavily caching static metadata about events.
To enable it add `api` to each event log reader.

```
winlogbeat.event_logs:
- name: Security
  api: wineventlog-experimental
```

The existing reader requests each event as XML and then must unmarshal the XML
document. EvtFormatMessage is used to get the XML document from Windows. Then the
Go stdlib encoder/xml package is used to parse it. Both of these operations are
relatively slow (see golang/go#21823 about encoding/xml).

This new reader utilizes the publisher metadata APIs to fetch and cache metadata
about all event IDs associated with a provider. It does this the first time it
encounters a provider ID while reading events. __Risk: Caching this info could
lead to having stale information in memory if metadata changes via software
update (see Edge Cases).__ It caches the names of the event data parameters
and a templatized version of the message string.

To get the data for an event this reader receives EVT_VARIANT structs containing
the parameters rather than receiving and parsing XML. This is more efficient because
there are fewer and smaller memory allocations and no XML encoding or decoding.

To get the message for an event it utilizes the cached text/template it has
for the event ID and passes it the list of parameter values.

Edge Cases

There is no provider metadata installed on the host. Could happen for forwarded
events or reading from .evtx files.
- Mitigate by falling back to getting parameter names by the event XML and rendering
  the message with EvtFormatMessage for each event.

Software is updated and an event ID changes it's event data parameters. Saw this
between Sysmon versions 9 and 10 with event ID 5.
- Mitigate by fingerprinting the number of event data parameters and their types.
- If the fingerprint changes, fetch the XML for the event and store the parameter
  names.

Benchmark Comparison

Comparing batch_size 500, that's a 1396% increase in events/sec, a -81% reduction in bytes allocated per event, and -86% decrease in the number of allocations.

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBenchmarkRead -benchmem -benchtime 10s -benchtest -v .
--- PASS: TestBenchmarkRead (231.68s)
    --- PASS: TestBenchmarkRead/api=wineventlog (53.57s)
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=10 (12.19s)
            bench_test.go:128: 2067.28 events/sec        18283 B/event   182836 B/batch  251 allocs/event        2516 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=100 (16.73s)
            bench_test.go:128: 2144.50 events/sec        17959 B/event   1795989 B/batch         250 allocs/event        25020 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=500 (13.48s)
            bench_test.go:128: 1888.40 events/sec        17648 B/event   8824455 B/batch         250 allocs/event        125018 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=1000 (11.18s)
            bench_test.go:128: 2064.14 events/sec        17650 B/event   17650459 B/batch        250 allocs/event        250012 allocs/batch
    --- PASS: TestBenchmarkRead/api=wineventlog-experimental (98.28s)
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=10 (18.72s)
            bench_test.go:128: 16813.52 events/sec       3974 B/event    39744 B/batch   34 allocs/event         344 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=100 (25.39s)
            bench_test.go:128: 28300.30 events/sec       3634 B/event    363498 B/batch  33 allocs/event         3324 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=500 (26.40s)
            bench_test.go:128: 28266.73 events/sec       3332 B/event    1666041 B/batch         33 allocs/event         16597 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=1000 (27.77s)
            bench_test.go:128: 28387.74 events/sec       3330 B/event    3330690 B/batch         33 allocs/event         33127 allocs/batch
    --- PASS: TestBenchmarkRead/api=eventlogging (13.29s)
        bench_test.go:128: 56243.80 events/sec   8043 B/event    6513053 B/batch         31 allocs/event         25151 allocs/batch
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 231.932s
andrewkroh added a commit to andrewkroh/beats that referenced this issue Mar 12, 2020
This PR adds a new event log reader implementation that's behind a
feature flag for now. It achieves higher event throughput than the current
reader by not using XML and by heavily caching static metadata about events.
To enable it add `api` to each event log reader.

```
winlogbeat.event_logs:
- name: Security
  api: wineventlog-experimental
```

The existing reader requests each event as XML and then must unmarshal the XML
document. EvtFormatMessage is used to get the XML document from Windows. Then the
Go stdlib encoder/xml package is used to parse it. Both of these operations are
relatively slow (see golang/go#21823 about encoding/xml).

This new reader utilizes the publisher metadata APIs to fetch and cache metadata
about all event IDs associated with a provider. It does this the first time it
encounters a provider ID while reading events. __Risk: Caching this info could
lead to having stale information in memory if metadata changes via software
update (see Edge Cases).__ It caches the names of the event data parameters
and a templatized version of the message string.

To get the data for an event this reader receives EVT_VARIANT structs containing
the parameters rather than receiving and parsing XML. This is more efficient because
there are fewer and smaller memory allocations and no XML encoding or decoding.

To get the message for an event it utilizes the cached text/template it has
for the event ID and passes it the list of parameter values.

Edge Cases

There is no provider metadata installed on the host. Could happen for forwarded
events or reading from .evtx files.
- Mitigate by falling back to getting parameter names by the event XML and rendering
  the message with EvtFormatMessage for each event.

Software is updated and an event ID changes it's event data parameters. Saw this
between Sysmon versions 9 and 10 with event ID 5.
- Mitigate by fingerprinting the number of event data parameters and their types.
- If the fingerprint changes, fetch the XML for the event and store the parameter
  names.

Benchmark Comparison

Comparing batch_size 500, that's a 1396% increase in events/sec, a -81% reduction in bytes allocated per event, and -86% decrease in the number of allocations.

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBenchmarkRead -benchmem -benchtime 10s -benchtest -v .
--- PASS: TestBenchmarkRead (231.68s)
    --- PASS: TestBenchmarkRead/api=wineventlog (53.57s)
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=10 (12.19s)
            bench_test.go:128: 2067.28 events/sec        18283 B/event   182836 B/batch  251 allocs/event        2516 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=100 (16.73s)
            bench_test.go:128: 2144.50 events/sec        17959 B/event   1795989 B/batch         250 allocs/event        25020 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=500 (13.48s)
            bench_test.go:128: 1888.40 events/sec        17648 B/event   8824455 B/batch         250 allocs/event        125018 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=1000 (11.18s)
            bench_test.go:128: 2064.14 events/sec        17650 B/event   17650459 B/batch        250 allocs/event        250012 allocs/batch
    --- PASS: TestBenchmarkRead/api=wineventlog-experimental (98.28s)
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=10 (18.72s)
            bench_test.go:128: 16813.52 events/sec       3974 B/event    39744 B/batch   34 allocs/event         344 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=100 (25.39s)
            bench_test.go:128: 28300.30 events/sec       3634 B/event    363498 B/batch  33 allocs/event         3324 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=500 (26.40s)
            bench_test.go:128: 28266.73 events/sec       3332 B/event    1666041 B/batch         33 allocs/event         16597 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=1000 (27.77s)
            bench_test.go:128: 28387.74 events/sec       3330 B/event    3330690 B/batch         33 allocs/event         33127 allocs/batch
    --- PASS: TestBenchmarkRead/api=eventlogging (13.29s)
        bench_test.go:128: 56243.80 events/sec   8043 B/event    6513053 B/batch         31 allocs/event         25151 allocs/batch
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 231.932s
andrewkroh added a commit to elastic/beats that referenced this issue Mar 16, 2020
This PR adds a new event log reader implementation that's behind a
feature flag for now. It achieves higher event throughput than the current
reader by not using XML and by heavily caching static metadata about events.
To enable it add `api` to each event log reader.

```
winlogbeat.event_logs:
- name: Security
  api: wineventlog-experimental
```

The existing reader requests each event as XML and then must unmarshal the XML
document. EvtFormatMessage is used to get the XML document from Windows. Then the
Go stdlib encoder/xml package is used to parse it. Both of these operations are
relatively slow (see golang/go#21823 about encoding/xml).

This new reader utilizes the publisher metadata APIs to fetch and cache metadata
about all event IDs associated with a provider. It does this the first time it
encounters a provider ID while reading events. __Risk: Caching this info could
lead to having stale information in memory if metadata changes via software
update (see Edge Cases).__ It caches the names of the event data parameters
and a templatized version of the message string.

To get the data for an event this reader receives EVT_VARIANT structs containing
the parameters rather than receiving and parsing XML. This is more efficient because
there are fewer and smaller memory allocations and no XML encoding or decoding.

To get the message for an event it utilizes the cached text/template it has
for the event ID and passes it the list of parameter values.

Edge Cases

There is no provider metadata installed on the host. Could happen for forwarded
events or reading from .evtx files.
- Mitigate by falling back to getting parameter names by the event XML and rendering
  the message with EvtFormatMessage for each event.

Software is updated and an event ID changes it's event data parameters. Saw this
between Sysmon versions 9 and 10 with event ID 5.
- Mitigate by fingerprinting the number of event data parameters and their types.
- If the fingerprint changes, fetch the XML for the event and store the parameter
  names.

Benchmark Comparison

Comparing batch_size 500, that's a 1396% increase in events/sec, a -81% reduction in bytes allocated per event, and -86% decrease in the number of allocations.

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBenchmarkRead -benchmem -benchtime 10s -benchtest -v .
--- PASS: TestBenchmarkRead (231.68s)
    --- PASS: TestBenchmarkRead/api=wineventlog (53.57s)
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=10 (12.19s)
            bench_test.go:128: 2067.28 events/sec        18283 B/event   182836 B/batch  251 allocs/event        2516 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=100 (16.73s)
            bench_test.go:128: 2144.50 events/sec        17959 B/event   1795989 B/batch         250 allocs/event        25020 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=500 (13.48s)
            bench_test.go:128: 1888.40 events/sec        17648 B/event   8824455 B/batch         250 allocs/event        125018 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=1000 (11.18s)
            bench_test.go:128: 2064.14 events/sec        17650 B/event   17650459 B/batch        250 allocs/event        250012 allocs/batch
    --- PASS: TestBenchmarkRead/api=wineventlog-experimental (98.28s)
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=10 (18.72s)
            bench_test.go:128: 16813.52 events/sec       3974 B/event    39744 B/batch   34 allocs/event         344 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=100 (25.39s)
            bench_test.go:128: 28300.30 events/sec       3634 B/event    363498 B/batch  33 allocs/event         3324 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=500 (26.40s)
            bench_test.go:128: 28266.73 events/sec       3332 B/event    1666041 B/batch         33 allocs/event         16597 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=1000 (27.77s)
            bench_test.go:128: 28387.74 events/sec       3330 B/event    3330690 B/batch         33 allocs/event         33127 allocs/batch
    --- PASS: TestBenchmarkRead/api=eventlogging (13.29s)
        bench_test.go:128: 56243.80 events/sec   8043 B/event    6513053 B/batch         31 allocs/event         25151 allocs/batch
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 231.932s
andrewkroh added a commit to andrewkroh/beats that referenced this issue Mar 16, 2020
…#16849)

This PR adds a new event log reader implementation that's behind a
feature flag for now. It achieves higher event throughput than the current
reader by not using XML and by heavily caching static metadata about events.
To enable it add `api` to each event log reader.

```
winlogbeat.event_logs:
- name: Security
  api: wineventlog-experimental
```

The existing reader requests each event as XML and then must unmarshal the XML
document. EvtFormatMessage is used to get the XML document from Windows. Then the
Go stdlib encoder/xml package is used to parse it. Both of these operations are
relatively slow (see golang/go#21823 about encoding/xml).

This new reader utilizes the publisher metadata APIs to fetch and cache metadata
about all event IDs associated with a provider. It does this the first time it
encounters a provider ID while reading events. __Risk: Caching this info could
lead to having stale information in memory if metadata changes via software
update (see Edge Cases).__ It caches the names of the event data parameters
and a templatized version of the message string.

To get the data for an event this reader receives EVT_VARIANT structs containing
the parameters rather than receiving and parsing XML. This is more efficient because
there are fewer and smaller memory allocations and no XML encoding or decoding.

To get the message for an event it utilizes the cached text/template it has
for the event ID and passes it the list of parameter values.

Edge Cases

There is no provider metadata installed on the host. Could happen for forwarded
events or reading from .evtx files.
- Mitigate by falling back to getting parameter names by the event XML and rendering
  the message with EvtFormatMessage for each event.

Software is updated and an event ID changes it's event data parameters. Saw this
between Sysmon versions 9 and 10 with event ID 5.
- Mitigate by fingerprinting the number of event data parameters and their types.
- If the fingerprint changes, fetch the XML for the event and store the parameter
  names.

Benchmark Comparison

Comparing batch_size 500, that's a 1396% increase in events/sec, a -81% reduction in bytes allocated per event, and -86% decrease in the number of allocations.

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBenchmarkRead -benchmem -benchtime 10s -benchtest -v .
--- PASS: TestBenchmarkRead (231.68s)
    --- PASS: TestBenchmarkRead/api=wineventlog (53.57s)
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=10 (12.19s)
            bench_test.go:128: 2067.28 events/sec        18283 B/event   182836 B/batch  251 allocs/event        2516 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=100 (16.73s)
            bench_test.go:128: 2144.50 events/sec        17959 B/event   1795989 B/batch         250 allocs/event        25020 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=500 (13.48s)
            bench_test.go:128: 1888.40 events/sec        17648 B/event   8824455 B/batch         250 allocs/event        125018 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=1000 (11.18s)
            bench_test.go:128: 2064.14 events/sec        17650 B/event   17650459 B/batch        250 allocs/event        250012 allocs/batch
    --- PASS: TestBenchmarkRead/api=wineventlog-experimental (98.28s)
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=10 (18.72s)
            bench_test.go:128: 16813.52 events/sec       3974 B/event    39744 B/batch   34 allocs/event         344 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=100 (25.39s)
            bench_test.go:128: 28300.30 events/sec       3634 B/event    363498 B/batch  33 allocs/event         3324 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=500 (26.40s)
            bench_test.go:128: 28266.73 events/sec       3332 B/event    1666041 B/batch         33 allocs/event         16597 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=1000 (27.77s)
            bench_test.go:128: 28387.74 events/sec       3330 B/event    3330690 B/batch         33 allocs/event         33127 allocs/batch
    --- PASS: TestBenchmarkRead/api=eventlogging (13.29s)
        bench_test.go:128: 56243.80 events/sec   8043 B/event    6513053 B/batch         31 allocs/event         25151 allocs/batch
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 231.932s

(cherry picked from commit d81ef73)
andrewkroh added a commit to andrewkroh/beats that referenced this issue Mar 18, 2020
…#16849)

This PR adds a new event log reader implementation that's behind a
feature flag for now. It achieves higher event throughput than the current
reader by not using XML and by heavily caching static metadata about events.
To enable it add `api` to each event log reader.

```
winlogbeat.event_logs:
- name: Security
  api: wineventlog-experimental
```

The existing reader requests each event as XML and then must unmarshal the XML
document. EvtFormatMessage is used to get the XML document from Windows. Then the
Go stdlib encoder/xml package is used to parse it. Both of these operations are
relatively slow (see golang/go#21823 about encoding/xml).

This new reader utilizes the publisher metadata APIs to fetch and cache metadata
about all event IDs associated with a provider. It does this the first time it
encounters a provider ID while reading events. __Risk: Caching this info could
lead to having stale information in memory if metadata changes via software
update (see Edge Cases).__ It caches the names of the event data parameters
and a templatized version of the message string.

To get the data for an event this reader receives EVT_VARIANT structs containing
the parameters rather than receiving and parsing XML. This is more efficient because
there are fewer and smaller memory allocations and no XML encoding or decoding.

To get the message for an event it utilizes the cached text/template it has
for the event ID and passes it the list of parameter values.

Edge Cases

There is no provider metadata installed on the host. Could happen for forwarded
events or reading from .evtx files.
- Mitigate by falling back to getting parameter names by the event XML and rendering
  the message with EvtFormatMessage for each event.

Software is updated and an event ID changes it's event data parameters. Saw this
between Sysmon versions 9 and 10 with event ID 5.
- Mitigate by fingerprinting the number of event data parameters and their types.
- If the fingerprint changes, fetch the XML for the event and store the parameter
  names.

Benchmark Comparison

Comparing batch_size 500, that's a 1396% increase in events/sec, a -81% reduction in bytes allocated per event, and -86% decrease in the number of allocations.

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBenchmarkRead -benchmem -benchtime 10s -benchtest -v .
--- PASS: TestBenchmarkRead (231.68s)
    --- PASS: TestBenchmarkRead/api=wineventlog (53.57s)
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=10 (12.19s)
            bench_test.go:128: 2067.28 events/sec        18283 B/event   182836 B/batch  251 allocs/event        2516 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=100 (16.73s)
            bench_test.go:128: 2144.50 events/sec        17959 B/event   1795989 B/batch         250 allocs/event        25020 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=500 (13.48s)
            bench_test.go:128: 1888.40 events/sec        17648 B/event   8824455 B/batch         250 allocs/event        125018 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=1000 (11.18s)
            bench_test.go:128: 2064.14 events/sec        17650 B/event   17650459 B/batch        250 allocs/event        250012 allocs/batch
    --- PASS: TestBenchmarkRead/api=wineventlog-experimental (98.28s)
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=10 (18.72s)
            bench_test.go:128: 16813.52 events/sec       3974 B/event    39744 B/batch   34 allocs/event         344 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=100 (25.39s)
            bench_test.go:128: 28300.30 events/sec       3634 B/event    363498 B/batch  33 allocs/event         3324 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=500 (26.40s)
            bench_test.go:128: 28266.73 events/sec       3332 B/event    1666041 B/batch         33 allocs/event         16597 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=1000 (27.77s)
            bench_test.go:128: 28387.74 events/sec       3330 B/event    3330690 B/batch         33 allocs/event         33127 allocs/batch
    --- PASS: TestBenchmarkRead/api=eventlogging (13.29s)
        bench_test.go:128: 56243.80 events/sec   8043 B/event    6513053 B/batch         31 allocs/event         25151 allocs/batch
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 231.932s

(cherry picked from commit d81ef73)
andrewkroh added a commit to elastic/beats that referenced this issue Mar 20, 2020
…#17022)

This PR adds a new event log reader implementation that's behind a
feature flag for now. It achieves higher event throughput than the current
reader by not using XML and by heavily caching static metadata about events.
To enable it add `api` to each event log reader.

```
winlogbeat.event_logs:
- name: Security
  api: wineventlog-experimental
```

The existing reader requests each event as XML and then must unmarshal the XML
document. EvtFormatMessage is used to get the XML document from Windows. Then the
Go stdlib encoder/xml package is used to parse it. Both of these operations are
relatively slow (see golang/go#21823 about encoding/xml).

This new reader utilizes the publisher metadata APIs to fetch and cache metadata
about all event IDs associated with a provider. It does this the first time it
encounters a provider ID while reading events. __Risk: Caching this info could
lead to having stale information in memory if metadata changes via software
update (see Edge Cases).__ It caches the names of the event data parameters
and a templatized version of the message string.

To get the data for an event this reader receives EVT_VARIANT structs containing
the parameters rather than receiving and parsing XML. This is more efficient because
there are fewer and smaller memory allocations and no XML encoding or decoding.

To get the message for an event it utilizes the cached text/template it has
for the event ID and passes it the list of parameter values.

Edge Cases

There is no provider metadata installed on the host. Could happen for forwarded
events or reading from .evtx files.
- Mitigate by falling back to getting parameter names by the event XML and rendering
  the message with EvtFormatMessage for each event.

Software is updated and an event ID changes it's event data parameters. Saw this
between Sysmon versions 9 and 10 with event ID 5.
- Mitigate by fingerprinting the number of event data parameters and their types.
- If the fingerprint changes, fetch the XML for the event and store the parameter
  names.

Benchmark Comparison

Comparing batch_size 500, that's a 1396% increase in events/sec, a -81% reduction in bytes allocated per event, and -86% decrease in the number of allocations.

PS C:\Gopath\src\github.com\elastic\beats\winlogbeat\eventlog> go test -run TestBenchmarkRead -benchmem -benchtime 10s -benchtest -v .
--- PASS: TestBenchmarkRead (231.68s)
    --- PASS: TestBenchmarkRead/api=wineventlog (53.57s)
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=10 (12.19s)
            bench_test.go:128: 2067.28 events/sec        18283 B/event   182836 B/batch  251 allocs/event        2516 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=100 (16.73s)
            bench_test.go:128: 2144.50 events/sec        17959 B/event   1795989 B/batch         250 allocs/event        25020 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=500 (13.48s)
            bench_test.go:128: 1888.40 events/sec        17648 B/event   8824455 B/batch         250 allocs/event        125018 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog/batch_size=1000 (11.18s)
            bench_test.go:128: 2064.14 events/sec        17650 B/event   17650459 B/batch        250 allocs/event        250012 allocs/batch
    --- PASS: TestBenchmarkRead/api=wineventlog-experimental (98.28s)
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=10 (18.72s)
            bench_test.go:128: 16813.52 events/sec       3974 B/event    39744 B/batch   34 allocs/event         344 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=100 (25.39s)
            bench_test.go:128: 28300.30 events/sec       3634 B/event    363498 B/batch  33 allocs/event         3324 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=500 (26.40s)
            bench_test.go:128: 28266.73 events/sec       3332 B/event    1666041 B/batch         33 allocs/event         16597 allocs/batch
        --- PASS: TestBenchmarkRead/api=wineventlog-experimental/batch_size=1000 (27.77s)
            bench_test.go:128: 28387.74 events/sec       3330 B/event    3330690 B/batch         33 allocs/event         33127 allocs/batch
    --- PASS: TestBenchmarkRead/api=eventlogging (13.29s)
        bench_test.go:128: 56243.80 events/sec   8043 B/event    6513053 B/batch         31 allocs/event         25151 allocs/batch
PASS
ok      github.com/elastic/beats/v7/winlogbeat/eventlog 231.932s

(cherry picked from commit d81ef73)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet