Race conditions with Go SDK

[G4Vi]

Running the stdout adapter on ../test/nested.instr.wasm can yield varying results. No triage has been done to determine if it occurs with the other adapters.

One run:

gavin@teleporter:~/dev/observe-sdk/go$ go run bin/stdout/main.go ../test/nested.c.instr.wasm
Hello from Wasm!
2023/11/17 14:59:47  Call to _start took 279.05µs
2023/11/17 14:59:47    Call to __main_void took 227.212µs
2023/11/17 14:59:47      Call to malloc took 20.93µs
2023/11/17 14:59:47      Call to main took 149.579µs
2023/11/17 14:59:47        Call to one took 144.082µs
2023/11/17 14:59:47          Call to two took 138.563µs
2023/11/17 14:59:47            Call to three took 132.061µs
2023/11/17 14:59:47              Call to printf took 125.978µs
2023/11/17 14:59:47                Call to vfprintf took 119.754µs
2023/11/17 14:59:47                  Call to printf_core took 94.882µs
2023/11/17 14:59:47                    Call to __fwritex took 87.077µs
2023/11/17 14:59:47                      Call to __stdio_write took 39.71µs
2023/11/17 14:59:47                        Call to writev took 33.156µs
2023/11/17 14:59:47                          Call to __wasi_fd_write took 21.692µs
2023/11/17 14:59:47    Call to __wasm_call_dtors took 21.599µs

Another run:

gavin@teleporter:~/dev/observe-sdk/go$ go run bin/stdout/main.go ../test/nested.c.instr.wasm
Hello from Wasm!
2023/11/17 14:59:50  Call to _start took 268.672µs
2023/11/17 14:59:50    Call to __main_void took 225.266µs
2023/11/17 14:59:50      Call to main took 158.609µs
2023/11/17 14:59:50        Call to one took 153.519µs
2023/11/17 14:59:50          Call to two took 146.536µs
2023/11/17 14:59:50            Call to three took 138.794µs
2023/11/17 14:59:50              Call to printf took 133.646µs
2023/11/17 14:59:50                Call to vfprintf took 127.749µs
2023/11/17 14:59:50                  Call to printf_core took 105.449µs
2023/11/17 14:59:50                    Call to __fwritex took 98.354µs
2023/11/17 14:59:50                      Call to __stdio_write took 48.64µs
2023/11/17 14:59:50                        Call to writev took 41.878µs
2023/11/17 14:59:50                          Call to __wasi_fd_write took 32.052µs
2023/11/17 14:59:50                            Call to __imported_wasi_snapshot_preview1_fd_write took 26.243µs`

In the second trace __imported_wasi_snapshot_preview1_fd_write shows up which wasn't in the first. However, then __wasm_call_dtors doesn't show up which was in the first trace.

[mhmd-azeez]

I think this is because of observe.Options.SpanFilter.MinDuration, by default it's 20µs, so if wazero executes the function in less than that, it will be skipped. I was able to get deterministic results by setting the limit to 1ns:

trace, err = adapterBase.NewTraceCtx(ctx, c.Wazero, data.Data, &observe.Options{
    SpanFilter:        &observe.SpanFilter{MinDuration: 1 * time.Nanosecond},
    ChannelBufferSize: 1024,

[nilslice]

I think it's most likely what @mhmd-azeez points out.

But worth some additional investigation. I'll look more closely at the results @G4Vi posted asap.