teardown makes the max value of iteration_duration not correct

[heww]

Environment

• k6 version: v0.30.0
• OS and version: Ubuntu 18.04
• Docker version and image, if applicable:

Expected Behavior

teardown should not affect the max value of the iteration_duration

Actual Behavior

the max value of the iteration_duration includes the running duration of the teardown

Steps to Reproduce the Problem

cat <<EOF | k6 run -u 100 -i 100 -
import { sleep } from 'k6'

export let options = {
    setupTimeout: '70s',
    teardownTimeout: '130s',
    noUsageReport: true,
}

export function setup() {
    sleep(60)
}

export default function () {
    sleep(10)
}

export function teardown() {
    sleep(120)
}
EOF

          /\      |‾‾| /‾‾/   /‾‾/   
     /\  /  \     |  |/  /   /  /    
    /  \/    \    |     (   /   ‾‾\  
   /          \   |  |\  \ |  (‾)  | 
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: -
     output: -

  scenarios: (100.00%) 1 scenario, 100 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 100 iterations shared among 100 VUs (maxDuration: 10m0s, gracefulStop: 30s)


running (03m10.1s), 000/100 VUs, 100 complete and 0 interrupted iterations
default ✓ [======================================] 100 VUs  00m10.0s/10m0s  100/100 shared iters

     █ setup

     █ teardown

     data_received........: 0 B 0 B/s
     data_sent............: 0 B 0 B/s
     iteration_duration...: avg=11.56s min=10s med=10s max=2m0s p(90)=10s p(95)=10s
     iterations...........: 100 0.526129/s
     vus..................: 0   min=0   max=100
     vus_max..............: 100 min=100 max=100

The max value of the iteration_duration should be 10s, not 2m.

[na--]

Thanks for reporting this, though it's an already known issue, see #891, #1508, and #1321. The linked forum posts in grafana/k6-docs#205 offer a workaround, until we get around to actually writing the docs and properly fixing the issue...

In short, setup() and teardown() emit metrics with a different root group tag. Some people need these metrics and set thresholds on them, to ensure that some thing was successfully set up or cleaned up, or something like that... Unfortunately, at the moment the end-of-test summary doesn't distinguish between them and aggregates everything by default, including iteration_duration, as you have noticed. One long-term solution to the problem is explored in #1321, essentially allowing users to silence some metrics or intentionally track some sub-metrics.

However, until we have explicit tracking of sub-metrics, the only way to force k6 to track them is to set a threshold on one. This is what the workaround in grafana/k6-docs#205 describe. In your case, if you have this script:

import { sleep } from 'k6'
import http from 'k6/http'

export let options = {
    vus: 5,
    duration: "10s",
    thresholds: {
        // We're using 'scenario:default' because that's the internal k6
        // scenario name when we haven't actually specified `options.scenarios`
        // explicitly and are just using the old execution shortcuts instead...
        'iteration_duration{scenario:default}': [
            // Some dummy threshold that's always going to pass. You don't even
            // need to have something here, I tried it and just this
            // `'http_req_duration{scenario:default}': []` is enough to trick
            // k6, but that's undefined behavior I can't promise we won't break
            // in the future...
            `max>=0`,
        ],
        // You can isolate setup and teardown metrics, if you are interested in them
        // for some reason. This looks nasty, but '::' is the group separator...
        'iteration_duration{group:::setup}': [`max>=0`],
        'iteration_duration{group:::teardown}': [`max>=0`],

        // And you can also isolate the HTTP metrics, in case of long-running requests
        'http_req_duration{scenario:default}': [`max>=0`],
    },
}

export function setup() {
    http.get('http://httpbin.test.k6.io/delay/5');
}
export default function () {
    http.get('http://test.k6.io/?where=default');
    sleep(0.5);
}

export function teardown() {
    http.get('http://httpbin.test.k6.io/delay/3');
    sleep(5);
}

You'd get a summary like this:

     data_received..............: 818 kB 34 kB/s
     data_sent..................: 6.8 kB 281 B/s
     http_req_blocked...........: avg=16.84ms  min=5.08µs   med=8.5µs    max=425.94ms p(90)=31.27µs  p(95)=144.7ms 
     http_req_connecting........: avg=16.52ms  min=0s       med=0s       max=422.32ms p(90)=0s       p(95)=140.52ms
     http_req_duration..........: avg=294.58ms min=136.76ms med=144.68ms max=5.14s    p(90)=370.37ms p(95)=426.15ms
     ✓ { scenario:default }.....: avg=190.61ms min=136.76ms med=144.57ms max=494.64ms p(90)=369.16ms p(95)=383.5ms 
     http_req_receiving.........: avg=5.47ms   min=92.18µs  med=2.97ms   max=176.21ms p(90)=5.46ms   p(95)=8.55ms  
     http_req_sending...........: avg=34.25µs  min=14.43µs  med=27.75µs  max=128.64µs p(90)=49.98µs  p(95)=93.97µs 
     http_req_tls_handshaking...: avg=0s       min=0s       med=0s       max=0s       p(90)=0s       p(95)=0s      
     http_req_waiting...........: avg=289.07ms min=134.96ms med=140.49ms max=5.14s    p(90)=368.41ms p(95)=423.14ms
     http_reqs..................: 76     3.122164/s
     iteration_duration.........: avg=864.44ms min=637.02ms med=645.3ms  max=8.27s    p(90)=870.96ms p(95)=994.84ms
     ✓ { group:::setup }........: avg=5.28s    min=5.28s    med=5.28s    max=5.28s    p(90)=5.28s    p(95)=5.28s   
     ✓ { group:::teardown }.....: avg=8.27s    min=8.27s    med=8.27s    max=8.27s    p(90)=8.27s    p(95)=8.27s   
     ✓ { scenario:default }.....: avg=704.6ms  min=637.02ms med=645.1ms  max=1.32s    p(90)=869.53ms p(95)=883.91ms
     iterations.................: 74     3.040002/s
     vus........................: 0      min=0 max=5
     vus_max....................: 5      min=5 max=5