search

grafana / xk6-client-tracing

A k6 extension for testing distributed tracing backends
GNU Affero General Public License v3.0
37 stars 5 forks source link

GoError: sending queue is full #30

Open bilsch-nice opened 6 days ago

bilsch-nice commented 6 days ago

I'm building a script based off of the param example and am getting an exception when I try to run:

{"dropped_items":19}
ERRO[0004] GoError: sending queue is full
        at reflect.methodValueCall (native)
        at file:///home/ubuntu/otel-tracing.js:71:16(76)  executor=ramping-vus scenario=write source=stacktrace
{"dropped_items":13}
ERRO[0004] GoError: sending queue is full
write   at reflect.methodValueCall (native)
        at file:///home/ubuntu/otel-tracing.js:71:16(76)  executor=ramping-vus scenario=write source=stacktrace
{"dropped_items":22}
ERRO[0004] GoError: sending queue is full
write   at reflect.methodValueCall (native)
        at file:///home/ubuntu/otel-tracing.js:71:16(76)  executor=ramping-vus scenario=write source=stacktrace
{"dropped_items":16}
ERRO[0004] GoError: sending queue is full
write   at reflect.methodValueCall (native)
        at file:///home/ubuntu/otel-tracing.js:71:16(76)  executor=ramping-vus scenario=write source=stacktrace
{"dropped_items":17}
ERRO[0004] GoError: sending queue is full
write   at reflect.methodValueCall (native)
        at file:///home/ubuntu/otel-tracing.js:71:16(76)  executor=ramping-vus scenario=write source=stacktrace
{}

I have modified a few parts from the original param example. The javascript for the script is as follows:

import { sleep } from 'k6';
import tracing from 'k6/x/tracing';
import { randomIntBetween } from 'https://jslib.k6.io/k6-utils/1.2.0/index.js';

/* 
export let options = {
    vus: 1,
    duration: "20m",
};
*/

/**
 * Minimum amount of virtual users (VUs)
 * @constant {number}
 */
const MIN_VUS = 1

/**
 * Maximum amount of virtual users (VUs)
 * @constant {number}
 */
const MAX_VUS = 25;

export const options = {
  scenarios: {
    write: {
      executor: 'ramping-vus',
      exec: 'default',
      startVUs: MIN_VUS,
      stages: [
        { duration: '5m', target: MAX_VUS },
        { duration: '30m', target: MAX_VUS },
      ],
      gracefulRampDown: '1m',
    },
  },
};

const endpoint = "out.load.balancer:4317";
const client = new tracing.Client({
    endpoint,
    exporter: tracing.EXPORTER_OTLP,
    tls: {
      insecure: true,
    }
});

export default function () {
    let pushSizeTraces = randomIntBetween(2,3);
    let pushSizeSpans = 0;
    let t = [];
    for (let i = 0; i < pushSizeTraces; i++) {
        let c = randomIntBetween(5,10)
        pushSizeSpans += c;

        t.push({
            random_service_name: false,
            spans: {
                count: c,
                size: randomIntBetween(300,1000),
                random_name: true,
                fixed_attrs: {
                    "test": "test",
                },
            }
        });
    }

    let gen = new tracing.ParameterizedGenerator(t)
    let traces = gen.traces()
    client.push(traces);

    // console.log(`Pushed ${pushSizeSpans} spans from ${pushSizeTraces} different traces. Here is a random traceID: ${t[Math.floor(Math.random() * t.length)].id}`);
    // sleep(15);
}

export function teardown() {
    client.shutdown();
}

Any ideas? What am I doing wrong here? I took the log and sleep out but otherwise the default function is unchanged.

This is running on ubuntu server compiled with go go version go1.21.9 linux/amd64.

zalegrala commented 6 days ago

I'm seeing this issue about changing the queue size, but perhaps we can make a change in the default config, which is 1000.

The client is constructed here, and could be modified to change from the default values.

bilsch-nice commented 6 days ago

So I moved the code to create and terminate the client to be within default and I get a different exception:

{"dropped_items":19}
ERRO[0001] GoError: sending queue is stopped                                                                                                      write   at reflect.methodValueCall (native)
        at file:///home/ubuntu/otel-tracing.js:71:16(92)  executor=ramping-vus scenario=write source=stacktrace

This was with just a single VU - when I hit enter to run it immediately starts emitting that exception

bilsch-nice commented 6 days ago

I'm seeing this issue about changing the queue size, but perhaps we can make a change in the default config, which is 1000.

The client is constructed here, and could be modified to change from the default values.

Is this related to my issue? The error I'm getting is from k6 itself not from the otel collector as far as I can tell.

bilsch-nice commented 6 days ago

What a difference a little sleep statement can make. I put a sleep(0.1) in to the bottom of the function and things started working. Until:

{}nning (03m18.7s), 16/25 VUs, 16602 complete and 0 interrupted iterations
{}ite   [==>-----------------------------------] 16/25 VUs  03m18.7s/35m00.0s
{}
ERRO[0199] panic: runtime error: index out of range [-1]
goroutine 467 [running]:
runtime/debug.Stack()
        runtime/debug/stack.go:24 +0x5e
go.k6.io/k6/js/common.RunWithPanicCatching.func1()
        go.k6.io/k6@v0.48.0/js/common/util.go:82 +0x1df
panic({0x19396c0?, 0xc00c66a918?})
        runtime/panic.go:914 +0x21f
github.com/dop251/goja.(*Runtime).runWrapped.func1()
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/runtime.go:2442 +0x171
panic({0x19396c0?, 0xc00c66a918?})
        runtime/panic.go:914 +0x21f
github.com/dop251/goja.(*vm).handleThrow(0xc002c1d0e0, {0x19396c0, 0xc00c66a918})
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/vm.go:788 +0x425
github.com/dop251/goja.(*vm).try.func1()
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/vm.go:807 +0x3f
panic({0x19396c0?, 0xc00c66a918?})
        runtime/panic.go:914 +0x21f
github.com/dop251/goja.(*vm).handleThrow(0xc002c1d0e0, {0x19396c0, 0xc00c66a918})
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/vm.go:788 +0x425
github.com/dop251/goja.(*vm).runTryInner.func1()
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/vm.go:830 +0x3f
panic({0x19396c0?, 0xc00c66a918?})
        runtime/panic.go:914 +0x21f
math/rand.(*rngSource).Uint64(...)
        math/rand/rng.go:249
math/rand.(*rngSource).Int63(0xc00c6698c0?)
        math/rand/rng.go:234 +0x85
math/rand.(*Rand).Int63(...)
        math/rand/rand.go:96
math/rand.(*Rand).Int31(...)
        math/rand/rand.go:110
math/rand.(*Rand).Int31n(0xc00047ce70, 0x3e)
        math/rand/rand.go:145 +0x53
math/rand.(*Rand).Intn(0x5583e9?, 0xc002b967c8?)
        math/rand/rand.go:183 +0x25
github.com/grafana/xk6-client-tracing/pkg/random.SelectElement[...](...)
        github.com/grafana/xk6-client-tracing@v0.0.0-00010101000000-000000000000/pkg/random/random.go:40
github.com/grafana/xk6-client-tracing/pkg/random.String(0xc)
        github.com/grafana/xk6-client-tracing@v0.0.0-00010101000000-000000000000/pkg/random/random.go:46 +0x7d
github.com/grafana/xk6-client-tracing/pkg/random.K6String(...)
        github.com/grafana/xk6-client-tracing@v0.0.0-00010101000000-000000000000/pkg/random/random.go:52
github.com/grafana/xk6-client-tracing/pkg/tracegen.(*ParameterizedGenerator).generateSpan(0xc00c626d38?, 0xc00cf3a5c0, {0xc00c651ba0?, 0xc00c08753c?})
        github.com/grafana/xk6-client-tracing@v0.0.0-00010101000000-000000000000/pkg/tracegen/parameterized.go:122 +0x7ca
github.com/grafana/xk6-client-tracing/pkg/tracegen.(*ParameterizedGenerator).Traces(0xc0088f4090)
        github.com/grafana/xk6-client-tracing@v0.0.0-00010101000000-000000000000/pkg/tracegen/parameterized.go:84 +0x756
reflect.Value.call({0x1803660?, 0xc0088f4090?, 0xc002b972b8?}, {0x1a47c1d, 0x4}, {0x2db14a0, 0x0, 0x1803660?})
        reflect/value.go:596 +0xce7
reflect.Value.Call({0x1803660?, 0xc0088f4090?, 0x0?}, {0x2db14a0?, 0x0?, 0x0?})
        reflect/value.go:380 +0xb9
github.com/dop251/goja.(*Runtime).newWrappedFunc.(*Runtime).wrapReflectFunc.func1({{0x1d9ba80, 0xc00c64d110}, {0xc00c648520, 0x0, 0x1a}})
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/runtime.go:1982 +0x3bd
github.com/dop251/goja.(*nativeFuncObject).vmCall(0xc00c9e0540, 0xc002c1d0e0, 0x0)
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/func.go:563 +0x186
github.com/dop251/goja.call.exec(0x6?, 0xc002c1d0e0)
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/vm.go:3366 +0x66
github.com/dop251/goja.(*vm).run(0xc002c1d0e0)
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/vm.go:582 +0x5b
github.com/dop251/goja.(*vm).runTryInner(0xc002c1d0e0?)
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/vm.go:834 +0x65
github.com/dop251/goja.(*baseJsFuncObject).__call(0xc002d2c480, {0xc00b84aec0?, 0x1, 0x0?}, {0x0?, 0x0}, {0x1d9bd78?, 0x2db14a0?})
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/func.go:426 +0x70f
github.com/dop251/goja.(*baseJsFuncObject)._call(...)
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/func.go:442
github.com/dop251/goja.(*baseJsFuncObject).call(0x0?, {{0x1d9bd78, 0x2db14a0}, {0xc00b84aec0, 0x1, 0x1}}, {0x0?, 0x0?})
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/func.go:450 +0x76
github.com/dop251/goja.(*baseJsFuncObject).Call(...)
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/func.go:382
github.com/dop251/goja.AssertFunction.func1.1()
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/runtime.go:2402 +0x71
github.com/dop251/goja.(*vm).try(0xc002c1d0e0, 0xc002b97990)
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/vm.go:811 +0x25b
github.com/dop251/goja.(*Runtime).runWrapped(0xc001e7a400, 0x7258665e2f18?)
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/runtime.go:2446 +0x71
github.com/dop251/goja.AssertFunction.func1({0x1d9bd78?, 0x2db14a0?}, {0xc00b84aec0?, 0x1?, 0x1?})
        github.com/dop251/goja@v0.0.0-20231027120936-b396bb4c349d/runtime.go:2401 +0x8c
go.k6.io/k6/js.(*VU).runFn.func2.1()
        go.k6.io/k6@v0.48.0/js/runner.go:867 +0x3e
go.k6.io/k6/js/eventloop.(*EventLoop).Start(0xc002c2e0a0, 0xc00c64cae0)
        go.k6.io/k6@v0.48.0/js/eventloop/eventloop.go:177 +0x19a
go.k6.io/k6/js.(*VU).runFn.func2()
        go.k6.io/k6@v0.48.0/js/runner.go:866 +0xdc
go.k6.io/k6/js/common.RunWithPanicCatching({0x1da3380?, 0xc000395c80?}, 0x17a7380?, 0xc00281f680?)
        go.k6.io/k6@v0.48.0/js/common/util.go:86 +0x7c
go.k6.io/k6/js.(*VU).runFn(0xc0011cfea0, {0x1d8af20, 0xc00c65ed70}, 0xa0?, 0xc006617f08, 0xc00b84aea0, {0xc00b84aec0, 0x1, 0x1})
        go.k6.io/k6@v0.48.0/js/runner.go:865 +0x287
go.k6.io/k6/js.(*ActiveVU).RunOnce(0xc0009edf80)
        go.k6.io/k6@v0.48.0/js/runner.go:798 +0x4b8
go.k6.io/k6/lib/executor.(*RampingVUs).Run.getIterationRunner.func3({0x1d8af20, 0xc0000d8cd0}, {0x1d77880?, 0xc0009edf80?})
        go.k6.io/k6@v0.48.0/lib/executor/helpers.go:81 +0x4a
go.k6.io/k6/lib/executor.(*vuHandle).runLoopsIfPossible(0xc000fc6480, 0xc0004a02b8)
        go.k6.io/k6@v0.48.0/lib/executor/vu_handle.go:205 +0xe3
created by go.k6.io/k6/lib/executor.(*rampingVUsRunState).runLoopsIfPossible in goroutine 460
        go.k6.io/k6@v0.48.0/lib/executor/ramping_vus.go:612 +0xec

Goja stack:
{}
{}
{}nning (03m18.7s), 16/25 VUs, 16602 complete and 0 interrupted iterations
{}ite   [==>-----------------------------------] 16/25 VUs  03m18.7s/35m00.0s
{}
{}
{}

     █ teardown

     data_received........: 0 B   0 B/s
     data_sent............: 0 B   0 B/s
     iteration_duration...: avg=101.1ms min=29.45µs med=101.06ms max=114.34ms p(90)=101.64ms p(95)=101.83ms
     iterations...........: 16603 83.558255/s
     vus..................: 16    min=1       max=16
     vus_max..............: 25    min=25      max=25

running (03m18.7s), 00/25 VUs, 16602 complete and 16 interrupted iterations
write ✗ [==>-----------------------------------] 15/25 VUs  03m18.7s/35m00.0s
ERRO[0199] a panic occurred during JS execution: runtime error: index out of range [-1]

Hopefully that exception is helpful to someone