Graceful stop is ignored when running SQL tests via xk6-sql plugin

alex-dubrouski commented 3 weeks ago

Brief summary

We are using K6 with xk6-sql plugin to load test our local TiDB cluster. On top of regular load tests we run basic chaos engineering like cluster failover and node restart during the test. We noticed that TiDB cluster disruptions cause K6 process to hang for a long time.

k6 version

v0.53.0

OS

Linux x86-64

Docker version and image (if applicable)

No response

Steps to reproduce the problem

When running simple select test and manually restarting one of the cluster nodes:

./k6 run -e executor="ramping-arrival-rate" -e preAllocatedVUs=10000 -e gracefulStop=30s -e stages="10s:5,30s:10000,4m:10000,10s:5" -e K6_DNS="ttl=0,select=roundRobin,policy=preferIPv6" simple-range.js

this test is expected to finish in 4mins 50sec, but it actually takes:

running (19m19.8s), 00000/10000 VUs, 2597641 complete and 2502 interrupted iterations
open_model ✓ [======================================] 02502/10000 VUs  4m50s  00114.01 iters/s

Please note running (19m19.8s), traffic correctly drops to 0 after 4mins 50sec, but process keeps sitting idle for over 15 more minutes I built K6 locally from the trunk with debug symbols and profiled the app when it hangs with perf and bcc-tools: Offcpu (idle descheduled threads) Offwake (re-scheduled threads and threads that woke them up combined in one stack) and perf:

# ........  .......  .................  ......................................
#
    13.89%  k6       k6                 [.] runtime.checkTimers
    13.69%  k6       k6                 [.] runtime.findRunnable
    13.65%  k6       [kernel.kallsyms]  [k] __perf_event_task_sched_in
    13.52%  k6       k6                 [.] runtime.checkdead
    10.98%  k6       k6                 [.] runtime/internal/syscall.EpollWait
    10.66%  k6       [kernel.kallsyms]  [k] __schedule
    10.60%  k6       [kernel.kallsyms]  [k] touch_atime
     3.35%  k6       k6                 [.] runtime.runtimer
     2.78%  k6       [kernel.kallsyms]  [k] fput_many
     1.82%  k6       k6                 [.] runtime.slicebytetostring
     1.50%  k6       [kernel.kallsyms]  [k] _raw_read_lock_irqsave
     1.23%  k6       k6                 [.] runtime.retake
     1.19%  k6       [kernel.kallsyms]  [k] perf_event_groups_first
     0.34%  k6       [kernel.kallsyms]  [k] syscall_return_via_sysret
     0.23%  k6       k6                 [.] runtime.runOneTimer
     0.22%  k6       k6                 [.] runtime.stealWork
     0.18%  k6       [kernel.kallsyms]  [k] htab_map_update_elem
     0.15%  k6       [kernel.kallsyms]  [k] finish_task_switch.isra.0
     0.03%  k6       [kernel.kallsyms]  [k] native_write_msr
     0.00%  k6       [kernel.kallsyms]  [k] native_apic_msr_write

Test script is very simple it just randomly selects data range from a set of configured tables:

import sql from 'k6/x/sql';
import { check } from 'k6';
import * as db_config from './db-config.js';
import * as common from './common.js';

export const options = common.options;

export default function() {
    const randomId = common.getRandomId();
    const randomTable = common.getRandomTable();

    const results = sql.query(db_config.db, 'SELECT c FROM ' + randomTable + ' WHERE id BETWEEN ? AND ?',
        randomId, randomId + common.rangeSize);

    check(results, {
        'is length >= 1': (r) => r.length >= 1,
    });
}

export function teardown() {
    db_config.db.close();
}

Expected behaviour

K6 process supposed to exit after configured graceful stop

Actual behaviour

K6 process keeps sitting idle for a prolonged amount of time

joanlopez commented 1 week ago

Hi @alex-dubrouski,

I'll allocate some time to try to reproduce this issue, but meanwhile, here's a couple of questions:

Do you think this is something specific to TiDB and how it manages connections? Or could be reproducible with MySQL as well?
Do you think this is something specific to TiDB cluster? Or would likely be the same with a single instance?

Also, could you please share a redacted example of how you set up db_config.db, please? Like, how do you call sql.open. I'm not interested about the connection details (host, port, etc) but if you use any specific configuration other than just the basic connection string.

Thanks!

alex-dubrouski commented 1 week ago

Hi @joanlopez,

Here is the config

import sql from 'k6/x/sql';

const connectionString = __ENV.db_user + ':'
        + __ENV.db_pwd + '@tcp('
        + __ENV.db_host + ':'
        + __ENV.db_port + ')/'
        + __ENV.db_name;

export let db = sql.open("mysql", connectionString);

I also asked TiDB team to provide details on their co fig and experiment.

ol-neostyle commented 1 week ago

Hi @joanlopez,

We currently don't know if this is specific to TiDB, but I think it could be reproducible with MySQL as well. It should not be specific to TiDB cluster.

In our experiment we started the load using K6 that supposed to complete in X mins and after some time we sent signal.SIGSTOP to one of the tidb-server process on the TiDB node. Other tidb nodes are working fine. This causes K6 to hang, we see it is seems to consider those connections alive and keep polling them.

In our test we used: 1 HAProxy (that round robins TiDB hosts) and a TiDB Cluster of (3 PD nodes, 4 TiDB nodes, and 4 TiKV nodes).

Bu I think it might be reproducible with 1-2 TiDB Hosts as well. Potentially even with MySql.

joanlopez commented 1 week ago

Great, thanks @alex-dubrouski and @ol-neostyle for the additional details. I'll try to reproduce it asap, hopefully along this week.

grafana / k6