vtbd stuck i/o

[Andriy Gapon]

>From time to time I experience a problem where a FreeBSD guest which
runs in a bhyve VM and uses virtio-blk disks gets stuck waiting for a
disk I/O operation to complete.

I tried to analyze one instance of them problem and discovered the vtblk
in a state where there was one request (a flush) in vtblk_req_ready,
nothing in vtblk_bioq and one apparently completed but unprocessed
request in vtblk_vq (which I discoved by manually following the steps in
virtqueue_dequeue).  It seemed like perhaps an interrupt was not
generated or lost somehow.

I will appreciate any help with either analyzing this problem or adding
some diagnostic code for future analysis.
It's not super easy to reproduce the problem, but it occurs once in a while.

Some data from my debugging session:

(kgdb) p *(struct vtblk_softc *)$26->d_drv1
$27 = {
  vtblk_dev = 0xfffff800036a3000,
  vtblk_mtx = {
    lock_object = {
      lo_name = 0xfffff800031f9440 "vtblk2",
      lo_flags = 16973824,
      lo_data = 0,
      lo_witness = 0xfffffe0000b94d00
    },
    mtx_lock = 4
  },
  vtblk_features = 268437060,
  vtblk_flags = 1,
  vtblk_vq = 0xfffff80003899000,
  vtblk_sglist = 0xfffff8000386a800,
  vtblk_disk = 0xfffff800038ae400,
  vtblk_bioq = {
    queue = {
      tqh_first = 0x0,
      tqh_last = 0xfffff8000389d150
    },
    last_offset = 42949672960,
    insert_point = 0x0
  },
  vtblk_req_free = {
    tqh_first = 0xfffff8000387dac0,
    tqh_last = 0xfffff8000387ea20
  },
  vtblk_req_ready = {
    tqh_first = 0xfffff8000387db00,
    tqh_last = 0xfffff8000387db20
  },
  vtblk_req_ordered = 0x0,
  vtblk_max_nsegs = 35,
  vtblk_request_count = 64,
  vtblk_write_cache = VTBLK_CACHE_WRITEBACK,
  vtblk_dump_queue = {
    tqh_first = 0x0,
    tqh_last = 0xfffff8000389d1a8
  },
  vtblk_dump_request = {
    vbr_hdr = {
      type = 0,
      ioprio = 0,
      sector = 0
    },
    vbr_bp = 0x0,
    vbr_ack = 0 '\000',
    vbr_link = {
      tqe_next = 0x0,
      tqe_prev = 0x0
    }
  }
}

(kgdb) p *$27.vtblk_vq
$30 = {
  vq_dev = 0xfffff800036a3b00,
  vq_name = "vtblk2 request", '\000' <repeats 17 times>,
  vq_queue_index = 0,
  vq_nentries = 64,
  vq_flags = 1,
  vq_alignment = 4096,
  vq_ring_size = 8192,
  vq_ring_mem = 0xfffffe003c687000,
  vq_max_indirect_size = 35,
  vq_indirect_mem_size = 560,
  vq_intrhand = 0xffffffff80888d02 <vtblk_vq_intr>,
  vq_intrhand_arg = 0xfffff8000389d100,
  vq_ring = {
    num = 64,
    desc = 0xfffffe003c687000,
    avail = 0xfffffe003c687400,
    used = 0xfffffe003c688000
  },
  vq_free_cnt = 63,
  vq_queued_cnt = 0,
  vq_desc_head_idx = 2,
  vq_used_cons_idx = 55297,
  vq_descx = 0xfffff80003899080
}

(kgdb) p *$27.vtblk_req_ready.tqh_first
$34 = {
  vbr_hdr = {
    type = 2147483652,
    ioprio = 1,
    sector = 0
  },
  vbr_bp = 0xfffff800038d8d38,
  vbr_ack = 255 '\377',
  vbr_link = {
    tqe_next = 0x0,
    tqe_prev = 0xfffff8000389d180
  }
}
(kgdb) p/x 2147483652
$35 = 0x80000004
(kgdb) p *$34.vbr_bp
$36 = {
  bio_cmd = 5,
  bio_flags = 8,
  bio_cflags = 0,
  bio_pflags = 0,
  bio_dev = 0x0,
  bio_disk = 0xfffff800038ae400,
  bio_offset = 42949672960,
  bio_bcount = 0,
  bio_data = 0x0,
  bio_ma = 0x0,
  bio_ma_offset = 0,
  bio_ma_n = 0,
  bio_error = 0,
  bio_resid = 0,
  bio_done = 0xffffffff80949672 <g_disk_done>,
  bio_driver1 = 0x0,
  bio_driver2 = 0x0,
  bio_caller1 = 0x0,
  bio_caller2 = 0x0,
  bio_queue = {
    tqe_next = 0x0,
    tqe_prev = 0xfffff8000389d150
  },
...
  bio_from = 0x0,
  bio_to = 0x0,
  bio_length = 0,
  bio_completed = 0,
  bio_children = 0,
  bio_inbed = 0,
  bio_parent = 0xfffff800081de8d0,
  bio_t0 = {
    sec = 23228,
    frac = 3207008011652053160
  },
  bio_task = 0x0,
  bio_task_arg = 0x0,
  bio_classifier1 = 0x0,
  bio_classifier2 = 0x0,
  bio_pblkno = 0
}

(kgdb) p $50.vq_ring.used->idx
$51 = 55298
(kgdb) p *$50.vq_ring.used
$52 = {
  flags = 0,
  idx = 55298,
  ring = 0xfffffe003c688004
}
(kgdb) p (55297 + 1) & 63
$53 = 2
(kgdb) p $50.vq_ring.used->ring[2]
$54 = {
  id = 10,
  len = 1
}
(kgdb) p $50.vq_descx[10]
$55 = {
  cookie = 0xfffff8000387db80,
  indirect = 0xfffff80003895400,
  indirect_paddr = 59331584,
  ndescs = 1
}
(kgdb) p *(struct vtblk_request *)$55.cookie
$57 = {
  vbr_hdr = {
    type = 1,
    ioprio = 1,
    sector = 32562128
  },
  vbr_bp = 0xfffff800061492f0,
  vbr_ack = 0 '\000',
  vbr_link = {
    tqe_next = 0x0,
    tqe_prev = 0x0
  }
}
(kgdb) p *$57.vbr_bp
$58 = {
  bio_cmd = 2,
  bio_flags = 0,
  bio_cflags = 0,
  bio_pflags = 0,
  bio_dev = 0x0,
  bio_disk = 0xfffff800038ae400,
  bio_offset = 16671809536,
  bio_bcount = 90112,
  bio_data = 0xfffffe001c268000 "",
  bio_ma = 0x0,
  bio_ma_offset = 0,
  bio_ma_n = 0,
  bio_error = 0,
  bio_resid = 0,
  bio_done = 0xffffffff80949672 <g_disk_done>,
  bio_driver1 = 0x0,
  bio_driver2 = 0x0,
  bio_caller1 = 0x0,
  bio_caller2 = 0x0,
  bio_queue = {
    tqe_next = 0x0,
    tqe_prev = 0xfffff8000389d150
  },
  bio_attribute = 0x0,
  bio_zone = {
...
  },
  bio_from = 0x0,
  bio_to = 0x0,
  bio_length = 90112,
  bio_completed = 0,
  bio_children = 0,
  bio_inbed = 0,
  bio_parent = 0xfffff80003b8b8d0,
  bio_t0 = {
    sec = 23228,
    frac = 3190990625700496616
  },
  bio_task = 0x0,
  bio_task_arg = 0x0,
  bio_classifier1 = 0x0,
  bio_classifier2 = 0x0,
  bio_pblkno = 32562128
}
-- 
Andriy Gapon