Seeing more "flush check fired" messages than expected

[leftwo]

I'm seeing more "flush check fired" messages than I expect to be seeing.

I'm running tests on a single system with:

./target/release/dsc start --create --cleanup --extent-count 200

And then:

./target/release/crutest yolo --dsc 127.0.0.1:9998 -g 9 --continuous -q

While the test is just running normally I see the messages:

R:707217 W:656072 F:13198 RE:0 WE:64865 VE:0 FE:1292
R:719139 W:668226 F:13459 RE:0 WE:64865 VE:0 FE:1292
R:731381 W:680649 F:13729 RE:0 WE:64865 VE:0 FE:1292
R:743711 W:693253 F:13972 RE:0 WE:64865 VE:0 FE:1292
Oct 07 16:41:28.551 WARN flush check fired despite having jobs; resetting it, session_id: 4ff07b0c-9d9d-4309-982d-403f57de8a35
R:753666 W:703442 F:14192 RE:0 WE:64865 VE:0 FE:1292
Oct 07 16:41:29.743 WARN flush check fired despite having jobs; resetting it, session_id: 4ff07b0c-9d9d-4309-982d-403f57de8a35
Oct 07 16:41:30.354 WARN flush check fired despite having jobs; resetting it, session_id: 4ff07b0c-9d9d-4309-982d-403f57de8a35
Oct 07 16:41:31.356 WARN flush check fired despite having jobs; resetting it, session_id: 4ff07b0c-9d9d-4309-982d-403f57de8a35
Oct 07 16:41:32.358 WARN flush check fired despite having jobs; resetting it, session_id: 4ff07b0c-9d9d-4309-982d-403f57de8a35
Oct 07 16:41:34.575 WARN flush check fired despite having jobs; resetting it, session_id: 4ff07b0c-9d9d-4309-982d-403f57de8a35
Oct 07 16:41:35.686 WARN flush check fired despite having jobs; resetting it, session_id: 4ff07b0c-9d9d-4309-982d-403f57de8a35
R:757535 W:707553 F:14270 RE:0 WE:64865 VE:0 FE:1292
R:769386 W:719761 F:14519 RE:0 WE:64865 VE:0 FE:1292

[mkeeter]

I tested this on my machine and believe it's working as intended: when running locally, you can stack up enough IO that a flush exceeds 500ms.

Here's perf-downstairs.d when running crutest yolo on my system:

96276  flush
           value  ------------- Distribution ------------- count
           16384 |                                         0
           32768 |@                                        1
           65536 |                                         0
          131072 |                                         0
          262144 |                                         0
          524288 |                                         0
         1048576 |                                         0
         2097152 |                                         0
         4194304 |                                         0
         8388608 |                                         0
        16777216 |@@@@                                     3
        33554432 |@                                        1
        67108864 |@@@@@@@@@@@@                             9
       134217728 |@@@@@@@@@@                               8
       268435456 |@@@@@@@@@                                7
       536870912 |@@@                                      2
      1073741824 |                                         0

There are several flushes in the >= 536870912 ns bucket, which is larger than the 500ms flush check window.

The upstairs prints that message because it's surprised to see no IO activity for > 500 ms (while jobs are in progress), but if a single flush takes that long, then I don't see any actual red flags.

[leftwo]

On an instance where I have FIO running in a loop, I see these messages on the propolis console:

23:43:16.029Z WARN propolis-server (vm_state_driver): flush check fired despite having jobs; resetting it
    session_id = 753fb635-715b-42d6-8f9d-62120463f381
23:43:21.034Z WARN propolis-server (vm_state_driver): flush check fired despite having jobs; resetting it
    session_id = 753fb635-715b-42d6-8f9d-62120463f381
23:43:22.493Z INFO propolis-server (vm_state_driver): request completed
    file = /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.4/src/server.rs:867
    latency_us = 3118
    local_addr = [fd00:1122:3344:101::1:63]:61488
    method = GET
    remote_addr = [fd00:1122:3344:101::2b]:64800
    req_id = eee27e6b-9cf2-4a5e-a41d-e60c2772210f
    response_code = 200
    uri = /3a386d35-03e9-4302-8f43-f25195624593
23:43:26.032Z WARN propolis-server (vm_state_driver): flush check fired despite having jobs; resetting it
    session_id = 753fb635-715b-42d6-8f9d-62120463f381
23:43:31.065Z WARN propolis-server (vm_state_driver): flush check fired despite having jobs; resetting it
    session_id = 753fb635-715b-42d6-8f9d-62120463f381
23:43:32.494Z INFO propolis-server (vm_state_driver): request completed
    file = /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.4/src/server.rs:867
    latency_us = 3124
    local_addr = [fd00:1122:3344:101::1:63]:61488
    method = GET
    remote_addr = [fd00:1122:3344:101::2b]:64800
    req_id = 0f3863f6-87bc-4ae6-83f2-2836ccb2139e
    response_code = 200
    uri = /3a386d35-03e9-4302-8f43-f25195624593
23:43:36.056Z WARN propolis-server (vm_state_driver): flush check fired despite having jobs; resetting it
    session_id = 753fb635-715b-42d6-8f9d-62120463f381
23:43:41.064Z WARN propolis-server (vm_state_driver): flush check fired despite having jobs; resetting it
    session_id = 753fb635-715b-42d6-8f9d-62120463f381
23:43:42.494Z INFO propolis-server (vm_state_driver): request completed
    file = /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.4/src/server.rs:867
    latency_us = 3127
    local_addr = [fd00:1122:3344:101::1:63]:61488
    method = GET
    remote_addr = [fd00:1122:3344:101::2b]:64800
    req_id = af614a0e-58c6-453d-9172-6f57c60a5e11
    response_code = 200
    uri = /3a386d35-03e9-4302-8f43-f25195624593

So, it's at least possible to see this on a real VM.