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

[Winlogbeat] Add experimental event log reader with increased performance #16849

Merged

Commits on Mar 12, 2020

  1. Add experimental event log reader with increased performance

    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 committed Mar 12, 2020
    Configuration menu
    Copy the full SHA
    52092de View commit details
    Browse the repository at this point in the history
  2. Add winlog.api to the documentation + fixes

    This explain how and why to enable the experimental implementation.
    
    Bug fixes
    
    Wrap errors to add more details to the cause
    
    Account for sysmon not being installed in tests
    
    Increase event log size everywhere
    
    Use a unique test event log per package
    
    TIL Go will run tests for different packages in parallel.
    andrewkroh committed Mar 12, 2020
    Configuration menu
    Copy the full SHA
    02483ee View commit details
    Browse the repository at this point in the history
  3. Remove logger

    andrewkroh committed Mar 12, 2020
    Configuration menu
    Copy the full SHA
    39d6358 View commit details
    Browse the repository at this point in the history

Commits on Mar 13, 2020

  1. Fix winmeta typo

    andrewkroh committed Mar 13, 2020
    Configuration menu
    Copy the full SHA
    4eff8ba View commit details
    Browse the repository at this point in the history
  2. Configuration menu
    Copy the full SHA
    1a03fda View commit details
    Browse the repository at this point in the history
  3. Add CHANGELOG

    andrewkroh committed Mar 13, 2020
    Configuration menu
    Copy the full SHA
    600e11c View commit details
    Browse the repository at this point in the history