Skip to content

Commit

Permalink
Avoid rendering the whole event to get only the provider name (open-t…
Browse files Browse the repository at this point in the history
…elemetry#34914)

**Description:**
The code was always getting the event as a XML string that was
unmarshalled into a type only to obtain the provider name. That can be
done in a cheaper fashion by requesting the `System` properties of the
event and reading only the provider name.

**Link to tracking Issue:**
Fixes open-telemetry#34755

**Testing:**
The benchmark below is only good to compare memory usage, which shows
that this change is already beneficial. See the changes for the
benchmark code.

```terminal
goos: windows
goarch: amd64
pkg: github.com/open-telemetry/opentelemetry-collector-contrib/receiver/windowseventlogreceiver
cpu: Intel(R) Core(TM) i9-10885H CPU @ 2.40GHz
                                │ .\old.txt  │             .\pr.txt              │
                                │   sec/op   │   sec/op    vs base               │
ReadWindowsEventLogger/10-16      1.255 ± 0%   1.255 ± 0%       ~ (p=0.912 n=10)
ReadWindowsEventLogger/100-16     1.379 ± 9%   1.256 ± 0%       ~ (p=0.190 n=10)
ReadWindowsEventLogger/1_000-16   2.633 ± 5%   2.507 ± 0%       ~ (p=0.063 n=10)
geomean                           1.658        1.581       -4.62%

                                │   .\old.txt   │               .\pr.txt               │
                                │     B/op      │     B/op      vs base                │
ReadWindowsEventLogger/10-16      3.228Mi ±  6%   2.190Mi ± 8%  -32.17% (p=0.000 n=10)
ReadWindowsEventLogger/100-16     5.399Mi ± 42%   2.276Mi ± 4%  -57.85% (p=0.000 n=10)
ReadWindowsEventLogger/1_000-16   26.12Mi ±  8%   17.66Mi ± 4%  -32.38% (p=0.000 n=10)
geomean                           7.693Mi         4.448Mi       -42.18%

                                │   .\old.txt   │              .\pr.txt               │
                                │   allocs/op   │  allocs/op   vs base                │
ReadWindowsEventLogger/10-16       67.18k ±  7%   44.74k ± 9%  -33.40% (p=0.000 n=10)
ReadWindowsEventLogger/100-16     112.87k ± 42%   46.69k ± 4%  -58.64% (p=0.000 n=10)
ReadWindowsEventLogger/1_000-16    551.6k ±  8%   368.0k ± 4%  -33.28% (p=0.000 n=10)
geomean                            161.1k         91.61k       -43.14%
```

**Documentation:**
N/A
  • Loading branch information
pjanotti authored Sep 3, 2024
1 parent bfdee42 commit 640adad
Show file tree
Hide file tree
Showing 5 changed files with 185 additions and 33 deletions.
Original file line number Diff line number Diff line change
@@ -0,0 +1,27 @@
# Use this changelog template to create an entry for release notes.

# One of 'breaking', 'deprecation', 'new_component', 'enhancement', 'bug_fix'
change_type: 'enhancement'

# The name of the component, or a single word describing the area of concern, (e.g. filelogreceiver)
component: windowseventlogreceiver

# A brief description of the change. Surround your text with quotes ("") if it needs to start with a backtick (`).
note: Avoid rendering the whole event to obtain the provider name

# Mandatory: One or more tracking issues related to the change. You can use the PR number here if no issue exists.
issues: [34755]

# (Optional) One or more lines of additional information to render under the primary note.
# These lines will be padded with 2 spaces and then inserted directly into the document.
# Use pipe (|) for multiline entries.
subtext:

# If your change doesn't affect end users or the exported elements of any package,
# you should instead start your pull request title with [chore] or use the "Skip Changelog" label.
# Optional: The change log or logs in which this entry should be included.
# e.g. '[user]' or '[user, api]'
# Include 'user' if the change is relevant to end users.
# Include 'api' if there is a change to a library API.
# Default: '[user]'
change_logs: [user]
20 changes: 20 additions & 0 deletions pkg/stanza/operator/input/windows/api.go
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@ var (
renderProc SyscallProc = api.NewProc("EvtRender")
closeProc SyscallProc = api.NewProc("EvtClose")
createBookmarkProc SyscallProc = api.NewProc("EvtCreateBookmark")
createRenderContextProc SyscallProc = api.NewProc("EvtCreateRenderContext")
updateBookmarkProc SyscallProc = api.NewProc("EvtUpdateBookmark")
openPublisherMetadataProc SyscallProc = api.NewProc("EvtOpenPublisherMetadata")
formatMessageProc SyscallProc = api.NewProc("EvtFormatMessage")
Expand Down Expand Up @@ -70,12 +71,21 @@ const (
)

const (
// EvtRenderEventValues is a flag to render the event properties specified in the rendering context
EvtRenderEventValues uint32 = 0
// EvtRenderEventXML is a flag to render an event as an XML string
EvtRenderEventXML uint32 = 1
// EvtRenderBookmark is a flag to render a bookmark as an XML string
EvtRenderBookmark uint32 = 2
)

const (
// EvtRenderContextValues is a flag to render the system properties under the System element.
// The properties are returned in the order defined in the EVT_SYSTEM_PROPERTY_ID enumeration.
// https://learn.microsoft.com/en-us/windows/win32/api/winevt/ne-winevt-evt_render_context_flags
EvtRenderContextSystem uint32 = 1
)

var evtSubscribeFunc = evtSubscribe

// evtSubscribe is the direct syscall implementation of EvtSubscribe (https://docs.microsoft.com/en-us/windows/win32/api/winevt/nf-winevt-evtsubscribe)
Expand Down Expand Up @@ -130,6 +140,16 @@ func evtCreateBookmark(bookmarkXML *uint16) (uintptr, error) {
return handle, nil
}

// evtCreateRenderContext is the direct syscall implementation of EvtCreateRenderContext (https://docs.microsoft.com/en-us/windows/win32/api/winevt/nf-winevt-evtcreaterendercontext)
func evtCreateRenderContext(valuePathsCount uint32, valuePaths **uint16, flags uint32) (uintptr, error) {
handle, _, err := createRenderContextProc.Call(uintptr(valuePathsCount), uintptr(unsafe.Pointer(valuePaths)), uintptr(flags))
if !errors.Is(err, ErrorSuccess) {
return 0, err
}

return handle, nil
}

// evtUpdateBookmark is the direct syscall implementation of EvtUpdateBookmark (https://docs.microsoft.com/en-us/windows/win32/api/winevt/nf-winevt-evtcreatebookmark)
func evtUpdateBookmark(bookmark uintptr, event uintptr) error {
_, _, err := updateBookmarkProc.Call(bookmark, event)
Expand Down
54 changes: 54 additions & 0 deletions pkg/stanza/operator/input/windows/event.go
Original file line number Diff line number Diff line change
Expand Up @@ -8,16 +8,70 @@ package windows // import "github.com/open-telemetry/opentelemetry-collector-con
import (
"errors"
"fmt"
"unicode/utf16"
"unsafe"
)

// errUnknownNextFrame is an error returned when a systemcall indicates the next frame is 0 bytes.
var errUnknownNextFrame = errors.New("the buffer size needed by the next frame of a render syscall was 0, unable to determine size of next frame")

// systemPropertiesRenderContext stores a custom rendering context to get only the event properties.
var systemPropertiesRenderContext = uintptr(0)
var systemPropertiesRenderContextErr error

func init() {
// This is not expected to fail, however, collecting the error if a new failure mode appears.
systemPropertiesRenderContext, systemPropertiesRenderContextErr = evtCreateRenderContext(0, nil, EvtRenderContextSystem)
}

// Event is an event stored in windows event log.
type Event struct {
handle uintptr
}

// GetPublisherName will get the publisher name of the event.
func (e *Event) GetPublisherName(buffer Buffer) (string, error) {
if e.handle == 0 {
return "", fmt.Errorf("event handle does not exist")
}

if systemPropertiesRenderContextErr != nil {
return "", fmt.Errorf("failed to create render context: %w", systemPropertiesRenderContextErr)
}

bufferUsed, err := evtRender(systemPropertiesRenderContext, e.handle, EvtRenderEventValues, buffer.SizeBytes(), buffer.FirstByte())
if errors.Is(err, ErrorInsufficientBuffer) {
buffer.UpdateSizeBytes(*bufferUsed)
return e.GetPublisherName(buffer)
}

if err != nil {
return "", fmt.Errorf("failed to get provider name: %w", err)
}

utf16Ptr := (**uint16)(unsafe.Pointer(buffer.FirstByte()))
providerName := utf16PtrToString(*utf16Ptr)

return providerName, nil
}

// utf16PtrToString converts Windows API LPWSTR (pointer to string) to go string
func utf16PtrToString(s *uint16) string {
if s == nil {
return ""
}

utf16Len := 0
curPtr := unsafe.Pointer(s)
for *(*uint16)(curPtr) != 0 {
curPtr = unsafe.Pointer(uintptr(curPtr) + unsafe.Sizeof(*s))
utf16Len++
}

slice := unsafe.Slice(s, utf16Len)
return string(utf16.Decode(slice))
}

// RenderSimple will render the event as EventXML without formatted info.
func (e *Event) RenderSimple(buffer Buffer) (EventXML, error) {
if e.handle == 0 {
Expand Down
67 changes: 34 additions & 33 deletions pkg/stanza/operator/input/windows/input.go
Original file line number Diff line number Diff line change
Expand Up @@ -234,63 +234,64 @@ func (i *Input) read(ctx context.Context) int {
func (i *Input) processEvent(ctx context.Context, event Event) {
remoteServer := i.remote.Server

if i.raw {
if len(i.excludeProviders) > 0 {
simpleEvent, err := event.RenderSimple(i.buffer)
if err != nil {
i.Logger().Error("Failed to render simple event", zap.Error(err))
return
}
var providerName string // The provider name is only retrieved if needed.
if !i.raw || len(i.excludeProviders) > 0 {
var err error
providerName, err = event.GetPublisherName(i.buffer)
if err != nil {
i.Logger().Error("Failed to get provider name", zap.Error(err))
return
}
}

for _, excludeProvider := range i.excludeProviders {
if simpleEvent.Provider.Name == excludeProvider {
return
}
if len(i.excludeProviders) > 0 {
for _, excludeProvider := range i.excludeProviders {
if providerName == excludeProvider {
return
}
}
}

if i.raw {
rawEvent, err := event.RenderRaw(i.buffer)
if err != nil {
i.Logger().Error("Failed to render raw event", zap.Error(err))
return
}

rawEvent.RemoteServer = remoteServer
i.sendEventRaw(ctx, rawEvent)
return
}
simpleEvent, err := event.RenderSimple(i.buffer)
if err != nil {
i.Logger().Error("Failed to render simple event", zap.Error(err))
return
}
simpleEvent.RemoteServer = remoteServer

for _, excludeProvider := range i.excludeProviders {
if simpleEvent.Provider.Name == excludeProvider {
return
}
}

publisher, openPublisherErr := i.publisherCache.get(simpleEvent.Provider.Name)
publisher, openPublisherErr := i.publisherCache.get(providerName)
if openPublisherErr != nil {
// This happens only the first time the code fails to open the publisher.
i.Logger().Warn(
"Failed to open event source, respective log entries cannot be formatted",
zap.String("provider", simpleEvent.Provider.Name), zap.Error(openPublisherErr))
zap.String("provider", providerName), zap.Error(openPublisherErr))
}

if !publisher.Valid() {
i.sendEvent(ctx, simpleEvent)
return
if publisher.Valid() {
formattedEvent, err := event.RenderFormatted(i.buffer, publisher)
if err == nil {
formattedEvent.RemoteServer = remoteServer
i.sendEvent(ctx, formattedEvent)
return
}

i.Logger().Error("Failed to render formatted event", zap.Error(err))
}

formattedEvent, err := event.RenderFormatted(i.buffer, publisher)
// Falling back to simple event (non-formatted).
simpleEvent, err := event.RenderSimple(i.buffer)
if err != nil {
i.Logger().Error("Failed to render formatted event", zap.Error(err))
i.sendEvent(ctx, simpleEvent)
i.Logger().Error("Failed to render simple event", zap.Error(err))
return
}
formattedEvent.RemoteServer = remoteServer
i.sendEvent(ctx, formattedEvent)

simpleEvent.RemoteServer = remoteServer
i.sendEvent(ctx, simpleEvent)
}

// sendEvent will send EventXML as an entry to the operator's output.
Expand Down
50 changes: 50 additions & 0 deletions receiver/windowseventlogreceiver/receiver_windows_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -72,6 +72,56 @@ func TestCreateWithInvalidInputConfig(t *testing.T) {
require.Error(t, err, "receiver creation should fail if given invalid input config")
}

// BenchmarkReadWindowsEventLogger benchmarks the performance of reading Windows Event Log events.
// This benchmark is not good to measure time performance since it uses a "eventually" construct
// to wait for the logs to be read. However, it is good to evaluate memory usage.
func BenchmarkReadWindowsEventLogger(b *testing.B) {
b.StopTimer()

tests := []struct {
name string
count int
}{
{
name: "10",
count: 10,
},
{
name: "100",
count: 100,
},
{
name: "1_000",
count: 1_000,
},
}
for _, tt := range tests {
b.Run(tt.name, func(b *testing.B) {
for i := 0; i < b.N; i++ {
// Set up the receiver and sink.
ctx := context.Background()
factory := newFactoryAdapter()
createSettings := receivertest.NewNopSettings()
cfg := createTestConfig()
cfg.InputConfig.StartAt = "beginning"
cfg.InputConfig.MaxReads = tt.count
sink := new(consumertest.LogsSink)

receiver, err := factory.CreateLogsReceiver(ctx, createSettings, cfg, sink)
require.NoError(b, err)

_ = receiver.Start(ctx, componenttest.NewNopHost())
b.StartTimer()
assert.Eventually(b, func() bool {
return sink.LogRecordCount() >= tt.count
}, 20*time.Second, 250*time.Millisecond)
b.StopTimer()
_ = receiver.Shutdown(ctx)
}
})
}
}

func TestReadWindowsEventLogger(t *testing.T) {
logMessage := "Test log"
src := "otel-windowseventlogreceiver-test"
Expand Down

0 comments on commit 640adad

Please sign in to comment.