LKML Archive on lore.kernel.org
help / color / mirror / Atom feed
* BUG REPORT: vfio_pci driver
@ 2021-08-13 18:34 Russ Weight
  2021-08-13 22:09 ` Alex Williamson
  0 siblings, 1 reply; 3+ messages in thread
From: Russ Weight @ 2021-08-13 18:34 UTC (permalink / raw)
  To: Alex Williamson
  Cc: Cornelia Huck, Adler, Michael, Whisonant, Tim, kvm, linux-kernel,
	Tom Rix

[-- Attachment #1: Type: text/plain, Size: 3102 bytes --]

Bug Description:

A bug in the vfio_pci driver was reported in junction with work on FPGA
cards. We were able to reproduce and root-cause the bug using system-tap.
The original bug description is below. An understanding of the referenced
dfl and opae tools is not required - it is the sequence of IOCTL calls and
IRQ vectors that matters:

> I’m trying to get an example AFU working that uses 2 IRQs, active at the same 
> time. I’m hitting what looks to be a dfl_pci driver bug.
>
> The code tries to allocate two IRQ vectors: 0 and 1. I see opaevfio.c doing the 
> right thing, picking the MSIX index. Allocating either IRQ 0 or IRQ 1 works fine 
> and I confirm that the VFIO_DEVICE_SET_IRQS looks reasonable, choosing MSIX and 
> either start of 0 or 1 and count 1.
>
> Note that opaevfio.c always passes count 1, so it will make separate calls for 
> each IRQ vector.
>
> When I try to allocate both, I see the following:
>
>   * If the VFIO_DEVICE_SET_IRQS ioctl is called first with start 0 and then
>     start 1 (always count 1), the start 1 (second) ioctl trap returns EINVAL.
>   * If I set up the vectors in decreasing order, so start 1 followed by start 0,
>     the program works!
>   * I ruled out OPAE SDK user space problems by setting up my program to
>     allocate in increasing order, which would normally fail. I changed only the
>     ioctl call in user space opaevfio.c, inverting bit 0 of start so that the
>     driver is called in decreasing index order. Of course this binds the wrong
>     vectors to the fds, but I don’t care about that for now. This works! From
>     this, I conclude that it can’t be a user space problem since the difference
>     between working and failing is solely the order in which IRQ vectors are
>     bound in ioctl calls.

The EINVAL is coming from vfio_msi_set_block() here:
https://github.com/torvalds/linux/blob/master/drivers/vfio/pci/vfio_pci_intrs.c#L373

vfio_msi_set_block() is being called from vfio_pci_set_msi_trigger() here on
the second IRQ request:
https://github.com/torvalds/linux/blob/master/drivers/vfio/pci/vfio_pci_intrs.c#L530

We believe the bug is in vfio_pci_set_msi_trigger(), in the 2nd parameter to the call
to vfio_msi_enable() here:
https://github.com/torvalds/linux/blob/master/drivers/vfio/pci/vfio_pci_intrs.c#L533

In both the passing and failing cases, the first IRQ request results in a call
to vfio_msi_enable() at line 533 and the second IRQ request results in the
call to vfio_msi_set_block() at line 530. It is during the first IRQ request
that vfio_msi_enable() sets vdev->num_ctx based on the 2nd parameter (nvec).
vdev->num_ctx is part of the conditional that results in the EINVAL for the
failing case.

In the passing case, vdev->num_ctx is 2. In the failing case, it is 1.

I am attaching two text files containing trace information from systemtap: one for
the failing case and one for the passing case. They contain a lot more information
than is needed, but if you search for vfio_pci_set_msi_trigger and vfio_msi_set_block,
you will see values for some of the call parameters.

- Russ


[-- Attachment #2: vfio_pci_pass.txt --]
[-- Type: text/plain, Size: 24082 bytes --]

     0 irqtest(103848): -> vfio_pci_match
     8 irqtest(103848):  -> get_pf_vdev
    12 irqtest(103848):  <- get_pf_vdev
    13 irqtest(103848): <- vfio_pci_match
     0 irqtest(103848): -> vfio_pci_open
     4 irqtest(103848):  -> vfio_pci_set_power_state
     7 irqtest(103848):  <- vfio_pci_set_power_state
108747 irqtest(103848):  -> pci_restore_msi_state
108756 irqtest(103848):  <- pci_restore_msi_state
108806 irqtest(103848):  -> vfio_config_init
108814 irqtest(103848):   -> vfio_fill_vconfig_bytes
108842 irqtest(103848):   <- vfio_fill_vconfig_bytes
108853 irqtest(103848):   -> vfio_fill_vconfig_bytes
108861 irqtest(103848):   <- vfio_fill_vconfig_bytes
108869 irqtest(103848):   -> vfio_fill_vconfig_bytes
108891 irqtest(103848):   <- vfio_fill_vconfig_bytes
108896 irqtest(103848):   -> vfio_fill_vconfig_bytes
108902 irqtest(103848):   <- vfio_fill_vconfig_bytes
108906 irqtest(103848):  <- vfio_config_init
108914 irqtest(103848):  -> vfio_pci_vf_token_user_add
108920 irqtest(103848):   -> get_pf_vdev
108925 irqtest(103848):   <- get_pf_vdev
108929 irqtest(103848):  <- vfio_pci_vf_token_user_add
108934 irqtest(103848): <- vfio_pci_open
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     7 irqtest(103848): <- vfio_pci_ioctl
     0 irqtest(103848): -> vfio_pci_read
     7 irqtest(103848):  -> vfio_pci_rw
    13 irqtest(103848):   -> vfio_pci_config_rw
    21 irqtest(103848):    -> vfio_basic_config_read
    27 irqtest(103848):     -> vfio_default_config_read
    34 irqtest(103848):      -> vfio_user_config_read
    42 irqtest(103848):      <- vfio_user_config_read
    46 irqtest(103848):     <- vfio_default_config_read
    51 irqtest(103848):    <- vfio_basic_config_read
    56 irqtest(103848):   <- vfio_pci_config_rw
    59 irqtest(103848):  <- vfio_pci_rw
    63 irqtest(103848): <- vfio_pci_read
     0 irqtest(103848): -> vfio_pci_write
    18 irqtest(103848):  -> vfio_pci_rw
    19 irqtest(103848):   -> vfio_pci_config_rw
    22 irqtest(103848):    -> vfio_basic_config_write
    27 irqtest(103848):     -> vfio_default_config_write
    29 irqtest(103848):      -> vfio_user_config_read
    31 irqtest(103848):      <- vfio_user_config_read
    33 irqtest(103848):      -> vfio_user_config_write
    36 irqtest(103848):      <- vfio_user_config_write
    37 irqtest(103848):     <- vfio_default_config_write
    39 irqtest(103848):    <- vfio_basic_config_write
    40 irqtest(103848):   <- vfio_pci_config_rw
    41 irqtest(103848):  <- vfio_pci_rw
    43 irqtest(103848): <- vfio_pci_write
vfio_pci_ioctl was called: 15211
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     2 irqtest(103848): <- vfio_pci_ioctl
     0 irqtest(103848): -> vfio_pci_mmap
    32 irqtest(103848): <- vfio_pci_mmap
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     2 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
     0 irqtest(103848): -> vfio_pci_mmap
     7 irqtest(103848): <- vfio_pci_mmap
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103848): -> vfio_pci_ioctl
     2 irqtest(103848):  -> vfio_pci_get_irq_count
     4 irqtest(103848):  <- vfio_pci_get_irq_count
     5 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848):  -> vfio_pci_get_irq_count
     2 irqtest(103848):  <- vfio_pci_get_irq_count
     3 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848):  -> vfio_pci_get_irq_count
     3 irqtest(103848):  <- vfio_pci_get_irq_count
     4 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848):  -> vfio_pci_get_irq_count
     2 irqtest(103848):  <- vfio_pci_get_irq_count
     3 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848):  -> vfio_pci_get_irq_count
     3 irqtest(103848):  <- vfio_pci_get_irq_count
     4 irqtest(103848): <- vfio_pci_ioctl
     0 irqtest(103848): -> vfio_pci_mmap_fault
     4 irqtest(103848):  -> __vfio_pci_memory_enabled
     6 irqtest(103848):  <- __vfio_pci_memory_enabled
     9 irqtest(103848): <- vfio_pci_mmap_fault
     0 irqtest(103848): -> vfio_pci_mmap_fault
     1 irqtest(103848):  -> __vfio_pci_memory_enabled
     2 irqtest(103848):  <- __vfio_pci_memory_enabled
     4 irqtest(103848): <- vfio_pci_mmap_fault
     0 irqtest(103848): -> vfio_pci_mmap_close
     2 irqtest(103848): <- vfio_pci_mmap_close
     0 irqtest(103848): -> vfio_pci_mmap_close
     1 irqtest(103848): <- vfio_pci_mmap_close
     0 irqtest(103848): -> vfio_pci_release
     2 irqtest(103848):  -> vfio_pci_vf_token_user_add
     3 irqtest(103848):   -> get_pf_vdev
     5 irqtest(103848):   <- get_pf_vdev
     6 irqtest(103848):  <- vfio_pci_vf_token_user_add
     9 irqtest(103848):  -> vfio_pci_set_irqs_ioctl
    12 irqtest(103848):  <- vfio_pci_set_irqs_ioctl
    14 irqtest(103848):  -> vfio_config_free
    16 irqtest(103848):  <- vfio_config_free
103469 irqtest(103848):  -> pci_restore_msi_state
103478 irqtest(103848):  <- pci_restore_msi_state
103490 irqtest(103848):  -> vfio_pci_walk_wrapper
103496 irqtest(103848):   -> vfio_pci_count_devs
103502 irqtest(103848):   <- vfio_pci_count_devs
103506 irqtest(103848):  <- vfio_pci_walk_wrapper
103510 irqtest(103848):  -> vfio_pci_walk_wrapper
103515 irqtest(103848):   -> vfio_pci_count_devs
103519 irqtest(103848):   <- vfio_pci_count_devs
103522 irqtest(103848):  <- vfio_pci_walk_wrapper
103526 irqtest(103848):  -> vfio_pci_walk_wrapper
103530 irqtest(103848):   -> vfio_pci_count_devs
103534 irqtest(103848):   <- vfio_pci_count_devs
103538 irqtest(103848):  <- vfio_pci_walk_wrapper
103541 irqtest(103848):  -> vfio_pci_walk_wrapper
103545 irqtest(103848):   -> vfio_pci_count_devs
103549 irqtest(103848):   <- vfio_pci_count_devs
103553 irqtest(103848):  <- vfio_pci_walk_wrapper
103558 irqtest(103848):  -> vfio_pci_walk_wrapper
103563 irqtest(103848):   -> vfio_pci_get_unused_devs
103570 irqtest(103848):   <- vfio_pci_get_unused_devs
103574 irqtest(103848):  <- vfio_pci_walk_wrapper
103579 irqtest(103848):  -> vfio_pci_set_power_state
103584 irqtest(103848):  <- vfio_pci_set_power_state
103588 irqtest(103848): <- vfio_pci_release
     0 irqtest(103848): -> vfio_pci_match
     2 irqtest(103848):  -> get_pf_vdev
     4 irqtest(103848):  <- get_pf_vdev
     5 irqtest(103848): <- vfio_pci_match
     0 irqtest(103848): -> vfio_pci_open
     1 irqtest(103848):  -> vfio_pci_set_power_state
     3 irqtest(103848):  <- vfio_pci_set_power_state
103601 irqtest(103848):  -> pci_restore_msi_state
103611 irqtest(103848):  <- pci_restore_msi_state
103658 irqtest(103848):  -> vfio_config_init
103665 irqtest(103848):   -> vfio_fill_vconfig_bytes
103693 irqtest(103848):   <- vfio_fill_vconfig_bytes
103703 irqtest(103848):   -> vfio_fill_vconfig_bytes
103711 irqtest(103848):   <- vfio_fill_vconfig_bytes
103719 irqtest(103848):   -> vfio_fill_vconfig_bytes
103741 irqtest(103848):   <- vfio_fill_vconfig_bytes
103746 irqtest(103848):   -> vfio_fill_vconfig_bytes
103752 irqtest(103848):   <- vfio_fill_vconfig_bytes
103756 irqtest(103848):  <- vfio_config_init
103764 irqtest(103848):  -> vfio_pci_vf_token_user_add
103769 irqtest(103848):   -> get_pf_vdev
103774 irqtest(103848):   <- get_pf_vdev
103778 irqtest(103848):  <- vfio_pci_vf_token_user_add
103782 irqtest(103848): <- vfio_pci_open
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     6 irqtest(103848): <- vfio_pci_ioctl
     0 irqtest(103848): -> vfio_pci_read
     5 irqtest(103848):  -> vfio_pci_rw
    10 irqtest(103848):   -> vfio_pci_config_rw
    16 irqtest(103848):    -> vfio_basic_config_read
    21 irqtest(103848):     -> vfio_default_config_read
    27 irqtest(103848):      -> vfio_user_config_read
    33 irqtest(103848):      <- vfio_user_config_read
    37 irqtest(103848):     <- vfio_default_config_read
    42 irqtest(103848):    <- vfio_basic_config_read
    47 irqtest(103848):   <- vfio_pci_config_rw
    50 irqtest(103848):  <- vfio_pci_rw
    54 irqtest(103848): <- vfio_pci_read
     0 irqtest(103848): -> vfio_pci_write
     4 irqtest(103848):  -> vfio_pci_rw
     8 irqtest(103848):   -> vfio_pci_config_rw
    13 irqtest(103848):    -> vfio_basic_config_write
    21 irqtest(103848):     -> vfio_default_config_write
    26 irqtest(103848):      -> vfio_user_config_read
    31 irqtest(103848):      <- vfio_user_config_read
    36 irqtest(103848):      -> vfio_user_config_write
    42 irqtest(103848):      <- vfio_user_config_write
    47 irqtest(103848):     <- vfio_default_config_write
    51 irqtest(103848):    <- vfio_basic_config_write
    55 irqtest(103848):   <- vfio_pci_config_rw
    59 irqtest(103848):  <- vfio_pci_rw
    62 irqtest(103848): <- vfio_pci_write
vfio_pci_ioctl was called: 15211
     0 irqtest(103848): -> vfio_pci_ioctl
     4 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     4 irqtest(103848): <- vfio_pci_ioctl
     0 irqtest(103848): -> vfio_pci_mmap
    45 irqtest(103848): <- vfio_pci_mmap
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
     0 irqtest(103848): -> vfio_pci_mmap
     6 irqtest(103848): <- vfio_pci_mmap
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848):  -> vfio_pci_get_irq_count
     3 irqtest(103848):  <- vfio_pci_get_irq_count
     4 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848):  -> vfio_pci_get_irq_count
     2 irqtest(103848):  <- vfio_pci_get_irq_count
     3 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848):  -> vfio_pci_get_irq_count
     3 irqtest(103848):  <- vfio_pci_get_irq_count
     4 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848):  -> vfio_pci_get_irq_count
     2 irqtest(103848):  <- vfio_pci_get_irq_count
     3 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848):  -> vfio_pci_get_irq_count
     3 irqtest(103848):  <- vfio_pci_get_irq_count
     3 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15214
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848):  -> vfio_pci_get_irq_count
     3 irqtest(103848):  <- vfio_pci_get_irq_count
     4 irqtest(103848):  -> vfio_pci_set_irqs_ioctl
vfio_pci_set_msi_trigger: irq_type: index: vector: flags: 0x5 0x2 0x1 0x24
vfio_pci_set_msi_trigger: vdev: 0xffff8ea6bc003200
    10 irqtest(103848):   -> vfio_pci_set_msi_trigger
    12 irqtest(103848):    -> vfio_pci_memory_lock_and_enable
    16 irqtest(103848):    <- vfio_pci_memory_lock_and_enable
    18 irqtest(103848):    -> pci_alloc_irq_vectors_affinity
    20 irqtest(103848):     -> __pci_enable_msix_range
    23 irqtest(103848):      -> pci_msi_supported
    25 irqtest(103848):      <- pci_msi_supported
    27 irqtest(103848):      -> pci_msix_vec_count
    30 irqtest(103848):      <- pci_msix_vec_count
    40 irqtest(103848):      -> pci_msix_vec_count
    42 irqtest(103848):      <- pci_msix_vec_count
    47 irqtest(103848):      -> pci_msi_setup_msi_irqs
    55 irqtest(103848):       -> pci_msi_domain_check_cap
    57 irqtest(103848):       <- pci_msi_domain_check_cap
    60 irqtest(103848):       -> pci_msi_domain_calc_hwirq
    62 irqtest(103848):       <- pci_msi_domain_calc_hwirq
   139 irqtest(103848):       -> pci_msi_domain_calc_hwirq
   140 irqtest(103848):       <- pci_msi_domain_calc_hwirq
   181 irqtest(103848):       -> pci_msi_domain_write_msg
   183 irqtest(103848):        -> __pci_write_msi_msg
   185 irqtest(103848):        <- __pci_write_msi_msg
   187 irqtest(103848):       <- pci_msi_domain_write_msg
   195 irqtest(103848):       -> pci_msi_domain_write_msg
   196 irqtest(103848):        -> __pci_write_msi_msg
   197 irqtest(103848):        <- __pci_write_msi_msg
   198 irqtest(103848):       <- pci_msi_domain_write_msg
   204 irqtest(103848):      <- pci_msi_setup_msi_irqs
   206 irqtest(103848):      -> msi_verify_entries
   208 irqtest(103848):      <- msi_verify_entries
   212 irqtest(103848):      -> __pci_msix_desc_mask_irq
   214 irqtest(103848):      <- __pci_msix_desc_mask_irq
   216 irqtest(103848):      -> __pci_msix_desc_mask_irq
   217 irqtest(103848):      <- __pci_msix_desc_mask_irq
   218 irqtest(103848):      -> populate_msi_sysfs
   223 irqtest(103848):      <- populate_msi_sysfs
   228 irqtest(103848):     <- __pci_enable_msix_range
   229 irqtest(103848):    <- pci_alloc_irq_vectors_affinity
   231 irqtest(103848):    -> vfio_pci_memory_unlock_and_restore
   234 irqtest(103848):    <- vfio_pci_memory_unlock_and_restore
vfio_msi_set_block: start: count: 0x1, 0x1
vfio_msi_set_block: vdev->num_ctx: 0x2
   237 irqtest(103848):    -> vfio_msi_set_block
vfio_msi_set_vector_signal was called: 1 / 7
   241 irqtest(103848):     -> vfio_msi_set_vector_signal
   244 irqtest(103848):      -> pci_irq_vector
   246 irqtest(103848):      <- pci_irq_vector
   248 irqtest(103848):      -> vfio_pci_memory_lock_and_enable
   251 irqtest(103848):      <- vfio_pci_memory_lock_and_enable
   256 irqtest(103848):      -> pci_write_msi_msg
   259 irqtest(103848):       -> __pci_write_msi_msg
   261 irqtest(103848):       <- __pci_write_msi_msg
   262 irqtest(103848):      <- pci_write_msi_msg
   280 irqtest(103848):      -> pci_msi_domain_write_msg
   281 irqtest(103848):       -> __pci_write_msi_msg
   282 irqtest(103848):       <- __pci_write_msi_msg
   283 irqtest(103848):      <- pci_msi_domain_write_msg
   289 irqtest(103848):      -> pci_msi_unmask_irq
   292 irqtest(103848):       -> msi_set_mask_bit
   293 irqtest(103848):        -> __pci_msix_desc_mask_irq
   295 irqtest(103848):        <- __pci_msix_desc_mask_irq
   297 irqtest(103848):       <- msi_set_mask_bit
   298 irqtest(103848):      <- pci_msi_unmask_irq
   323 irqtest(103848):      -> vfio_pci_memory_unlock_and_restore
   325 irqtest(103848):      <- vfio_pci_memory_unlock_and_restore
   327 irqtest(103848):     <- vfio_msi_set_vector_signal
vfio_msi_set_vector_signal returned with: 0
   330 irqtest(103848):    <- vfio_msi_set_block
   331 irqtest(103848):   <- vfio_pci_set_msi_trigger
   332 irqtest(103848):  <- vfio_pci_set_irqs_ioctl
   334 irqtest(103848): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15214
     0 irqtest(103848): -> vfio_pci_ioctl
     1 irqtest(103848):  -> vfio_pci_get_irq_count
     3 irqtest(103848):  <- vfio_pci_get_irq_count
     5 irqtest(103848):  -> vfio_pci_set_irqs_ioctl
vfio_pci_set_msi_trigger: irq_type: index: vector: flags: 0x2 0x2 0x0 0x24
vfio_pci_set_msi_trigger: vdev: 0xffff8ea6bc003200
     7 irqtest(103848):   -> vfio_pci_set_msi_trigger
vfio_msi_set_block: start: count: 0x0, 0x1
vfio_msi_set_block: vdev->num_ctx: 0x2
     9 irqtest(103848):    -> vfio_msi_set_block
vfio_msi_set_vector_signal was called: 0 / 8
    11 irqtest(103848):     -> vfio_msi_set_vector_signal
    13 irqtest(103848):      -> pci_irq_vector
    14 irqtest(103848):      <- pci_irq_vector
    15 irqtest(103848):      -> vfio_pci_memory_lock_and_enable
    18 irqtest(103848):      <- vfio_pci_memory_lock_and_enable
    21 irqtest(103848):      -> pci_write_msi_msg
    23 irqtest(103848):       -> __pci_write_msi_msg
    24 irqtest(103848):       <- __pci_write_msi_msg
    25 irqtest(103848):      <- pci_write_msi_msg
    34 irqtest(103848):      -> pci_msi_domain_write_msg
    35 irqtest(103848):       -> __pci_write_msi_msg
    36 irqtest(103848):       <- __pci_write_msi_msg
    37 irqtest(103848):      <- pci_msi_domain_write_msg
    40 irqtest(103848):      -> pci_msi_unmask_irq
    41 irqtest(103848):       -> msi_set_mask_bit
    42 irqtest(103848):        -> __pci_msix_desc_mask_irq
    43 irqtest(103848):        <- __pci_msix_desc_mask_irq
    45 irqtest(103848):       <- msi_set_mask_bit
    46 irqtest(103848):      <- pci_msi_unmask_irq
    62 irqtest(103848):      -> vfio_pci_memory_unlock_and_restore
    64 irqtest(103848):      <- vfio_pci_memory_unlock_and_restore
    66 irqtest(103848):     <- vfio_msi_set_vector_signal
vfio_msi_set_vector_signal returned with: 0
    67 irqtest(103848):    <- vfio_msi_set_block
    68 irqtest(103848):   <- vfio_pci_set_msi_trigger
    69 irqtest(103848):  <- vfio_pci_set_irqs_ioctl
    70 irqtest(103848): <- vfio_pci_ioctl
     0 irqtest(103848): -> vfio_pci_mmap_close
     1 irqtest(103848): <- vfio_pci_mmap_close
     0 irqtest(103848): -> vfio_pci_mmap_close
     1 irqtest(103848): <- vfio_pci_mmap_close
     0 irqtest(103848): -> vfio_pci_release
     1 irqtest(103848):  -> vfio_pci_vf_token_user_add
     3 irqtest(103848):   -> get_pf_vdev
     4 irqtest(103848):   <- get_pf_vdev
     5 irqtest(103848):  <- vfio_pci_vf_token_user_add
     8 irqtest(103848):  -> vfio_pci_set_irqs_ioctl
vfio_pci_set_msi_trigger: irq_type: index: vector: flags: 0x2 0x2 0x0 0x21
vfio_pci_set_msi_trigger: vdev: 0xffff8ea6bc003200
    11 irqtest(103848):   -> vfio_pci_set_msi_trigger
    14 irqtest(103848):    -> vfio_msi_disable
vfio_msi_set_block: start: count: 0x0, 0x2
vfio_msi_set_block: vdev->num_ctx: 0x2
    18 irqtest(103848):     -> vfio_msi_set_block
vfio_msi_set_vector_signal was called: 0 / -1
    20 irqtest(103848):      -> vfio_msi_set_vector_signal
    21 irqtest(103848):       -> pci_irq_vector
    22 irqtest(103848):       <- pci_irq_vector
    24 irqtest(103848):       -> vfio_pci_memory_lock_and_enable
    26 irqtest(103848):       <- vfio_pci_memory_lock_and_enable
    36 irqtest(103848):       -> pci_msi_mask_irq
    38 irqtest(103848):        -> msi_set_mask_bit
    39 irqtest(103848):         -> __pci_msix_desc_mask_irq
    41 irqtest(103848):         <- __pci_msix_desc_mask_irq
    43 irqtest(103848):        <- msi_set_mask_bit
    44 irqtest(103848):       <- pci_msi_mask_irq
    55 irqtest(103848):       -> pci_msi_domain_write_msg
    56 irqtest(103848):        -> __pci_write_msi_msg
    58 irqtest(103848):        <- __pci_write_msi_msg
    58 irqtest(103848):       <- pci_msi_domain_write_msg
    68 irqtest(103848):       -> vfio_pci_memory_unlock_and_restore
    70 irqtest(103848):       <- vfio_pci_memory_unlock_and_restore
    72 irqtest(103848):      <- vfio_msi_set_vector_signal
vfio_msi_set_vector_signal returned with: 0
vfio_msi_set_vector_signal was called: 1 / -1
    74 irqtest(103848):      -> vfio_msi_set_vector_signal
    75 irqtest(103848):       -> pci_irq_vector
    76 irqtest(103848):       <- pci_irq_vector
    77 irqtest(103848):       -> vfio_pci_memory_lock_and_enable
    80 irqtest(103848):       <- vfio_pci_memory_lock_and_enable
    84 irqtest(103848):       -> pci_msi_mask_irq
    85 irqtest(103848):        -> msi_set_mask_bit
    86 irqtest(103848):         -> __pci_msix_desc_mask_irq
    87 irqtest(103848):         <- __pci_msix_desc_mask_irq
    89 irqtest(103848):        <- msi_set_mask_bit
    90 irqtest(103848):       <- pci_msi_mask_irq
    94 irqtest(103848):       -> pci_msi_domain_write_msg
    95 irqtest(103848):        -> __pci_write_msi_msg
    96 irqtest(103848):        <- __pci_write_msi_msg
    97 irqtest(103848):       <- pci_msi_domain_write_msg
   102 irqtest(103848):       -> vfio_pci_memory_unlock_and_restore
   104 irqtest(103848):       <- vfio_pci_memory_unlock_and_restore
   105 irqtest(103848):      <- vfio_msi_set_vector_signal
vfio_msi_set_vector_signal returned with: 0
   106 irqtest(103848):     <- vfio_msi_set_block
   107 irqtest(103848):     -> vfio_pci_memory_lock_and_enable
   110 irqtest(103848):     <- vfio_pci_memory_lock_and_enable
   112 irqtest(103848):     -> pci_free_irq_vectors
   114 irqtest(103848):      -> pci_disable_msix
   119 irqtest(103848):       -> free_msi_irqs
   123 irqtest(103848):        -> default_teardown_msi_irqs
   210 irqtest(103848):        <- default_teardown_msi_irqs
   218 irqtest(103848):       <- free_msi_irqs
   219 irqtest(103848):      <- pci_disable_msix
   220 irqtest(103848):      -> pci_disable_msi
   222 irqtest(103848):      <- pci_disable_msi
   223 irqtest(103848):     <- pci_free_irq_vectors
   224 irqtest(103848):     -> vfio_pci_memory_unlock_and_restore
   226 irqtest(103848):     <- vfio_pci_memory_unlock_and_restore
   227 irqtest(103848):    <- vfio_msi_disable
   228 irqtest(103848):   <- vfio_pci_set_msi_trigger
   229 irqtest(103848):  <- vfio_pci_set_irqs_ioctl
   231 irqtest(103848):  -> vfio_config_free
   232 irqtest(103848):  <- vfio_config_free
103062 irqtest(103848):  -> pci_restore_msi_state
103071 irqtest(103848):  <- pci_restore_msi_state
103082 irqtest(103848):  -> vfio_pci_walk_wrapper
103087 irqtest(103848):   -> vfio_pci_count_devs
103092 irqtest(103848):   <- vfio_pci_count_devs
103096 irqtest(103848):  <- vfio_pci_walk_wrapper
103100 irqtest(103848):  -> vfio_pci_walk_wrapper
103105 irqtest(103848):   -> vfio_pci_count_devs
103108 irqtest(103848):   <- vfio_pci_count_devs
103112 irqtest(103848):  <- vfio_pci_walk_wrapper
103116 irqtest(103848):  -> vfio_pci_walk_wrapper
103120 irqtest(103848):   -> vfio_pci_count_devs
103124 irqtest(103848):   <- vfio_pci_count_devs
103128 irqtest(103848):  <- vfio_pci_walk_wrapper
103132 irqtest(103848):  -> vfio_pci_walk_wrapper
103136 irqtest(103848):   -> vfio_pci_count_devs
103139 irqtest(103848):   <- vfio_pci_count_devs
103143 irqtest(103848):  <- vfio_pci_walk_wrapper
103147 irqtest(103848):  -> vfio_pci_walk_wrapper
103152 irqtest(103848):   -> vfio_pci_get_unused_devs
103157 irqtest(103848):   <- vfio_pci_get_unused_devs
103161 irqtest(103848):  <- vfio_pci_walk_wrapper
103167 irqtest(103848):  -> vfio_pci_set_power_state
103171 irqtest(103848):  <- vfio_pci_set_power_state
103176 irqtest(103848): <- vfio_pci_release

[-- Attachment #3: vfio_pci_fail.txt --]
[-- Type: text/plain, Size: 21203 bytes --]

     0 irqtest(103741): -> vfio_pci_match
     5 irqtest(103741):  -> get_pf_vdev
     8 irqtest(103741):  <- get_pf_vdev
     9 irqtest(103741): <- vfio_pci_match
     0 irqtest(103741): -> vfio_pci_open
     2 irqtest(103741):  -> vfio_pci_set_power_state
     4 irqtest(103741):  <- vfio_pci_set_power_state
102476 irqtest(103741):  -> pci_restore_msi_state
102479 irqtest(103741):  <- pci_restore_msi_state
102506 irqtest(103741):  -> vfio_config_init
102509 irqtest(103741):   -> vfio_fill_vconfig_bytes
102523 irqtest(103741):   <- vfio_fill_vconfig_bytes
102528 irqtest(103741):   -> vfio_fill_vconfig_bytes
102531 irqtest(103741):   <- vfio_fill_vconfig_bytes
102535 irqtest(103741):   -> vfio_fill_vconfig_bytes
102546 irqtest(103741):   <- vfio_fill_vconfig_bytes
102548 irqtest(103741):   -> vfio_fill_vconfig_bytes
102551 irqtest(103741):   <- vfio_fill_vconfig_bytes
102552 irqtest(103741):  <- vfio_config_init
102555 irqtest(103741):  -> vfio_pci_vf_token_user_add
102557 irqtest(103741):   -> get_pf_vdev
102559 irqtest(103741):   <- get_pf_vdev
102560 irqtest(103741):  <- vfio_pci_vf_token_user_add
102561 irqtest(103741): <- vfio_pci_open
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     2 irqtest(103741): <- vfio_pci_ioctl
     0 irqtest(103741): -> vfio_pci_read
     2 irqtest(103741):  -> vfio_pci_rw
     4 irqtest(103741):   -> vfio_pci_config_rw
     7 irqtest(103741):    -> vfio_basic_config_read
     8 irqtest(103741):     -> vfio_default_config_read
    11 irqtest(103741):      -> vfio_user_config_read
    14 irqtest(103741):      <- vfio_user_config_read
    15 irqtest(103741):     <- vfio_default_config_read
    16 irqtest(103741):    <- vfio_basic_config_read
    18 irqtest(103741):   <- vfio_pci_config_rw
    19 irqtest(103741):  <- vfio_pci_rw
    20 irqtest(103741): <- vfio_pci_read
     0 irqtest(103741): -> vfio_pci_write
     2 irqtest(103741):  -> vfio_pci_rw
     3 irqtest(103741):   -> vfio_pci_config_rw
     5 irqtest(103741):    -> vfio_basic_config_write
     8 irqtest(103741):     -> vfio_default_config_write
     9 irqtest(103741):      -> vfio_user_config_read
    11 irqtest(103741):      <- vfio_user_config_read
    13 irqtest(103741):      -> vfio_user_config_write
    15 irqtest(103741):      <- vfio_user_config_write
    16 irqtest(103741):     <- vfio_default_config_write
    18 irqtest(103741):    <- vfio_basic_config_write
    19 irqtest(103741):   <- vfio_pci_config_rw
    20 irqtest(103741):  <- vfio_pci_rw
    21 irqtest(103741): <- vfio_pci_write
vfio_pci_ioctl was called: 15211
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     2 irqtest(103741): <- vfio_pci_ioctl
     0 irqtest(103741): -> vfio_pci_mmap
    34 irqtest(103741): <- vfio_pci_mmap
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     2 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
     0 irqtest(103741): -> vfio_pci_mmap
     8 irqtest(103741): <- vfio_pci_mmap
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741):  -> vfio_pci_get_irq_count
     3 irqtest(103741):  <- vfio_pci_get_irq_count
     4 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741):  -> vfio_pci_get_irq_count
     2 irqtest(103741):  <- vfio_pci_get_irq_count
     3 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741):  -> vfio_pci_get_irq_count
     3 irqtest(103741):  <- vfio_pci_get_irq_count
     4 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741):  -> vfio_pci_get_irq_count
     2 irqtest(103741):  <- vfio_pci_get_irq_count
     3 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741):  -> vfio_pci_get_irq_count
     2 irqtest(103741):  <- vfio_pci_get_irq_count
     3 irqtest(103741): <- vfio_pci_ioctl
     0 irqtest(103741): -> vfio_pci_mmap_fault
     3 irqtest(103741):  -> __vfio_pci_memory_enabled
     4 irqtest(103741):  <- __vfio_pci_memory_enabled
     7 irqtest(103741): <- vfio_pci_mmap_fault
     0 irqtest(103741): -> vfio_pci_mmap_fault
     1 irqtest(103741):  -> __vfio_pci_memory_enabled
     2 irqtest(103741):  <- __vfio_pci_memory_enabled
     4 irqtest(103741): <- vfio_pci_mmap_fault
     0 irqtest(103741): -> vfio_pci_mmap_close
     2 irqtest(103741): <- vfio_pci_mmap_close
     0 irqtest(103741): -> vfio_pci_mmap_close
     1 irqtest(103741): <- vfio_pci_mmap_close
     0 irqtest(103741): -> vfio_pci_release
     1 irqtest(103741):  -> vfio_pci_vf_token_user_add
     3 irqtest(103741):   -> get_pf_vdev
     4 irqtest(103741):   <- get_pf_vdev
     5 irqtest(103741):  <- vfio_pci_vf_token_user_add
     8 irqtest(103741):  -> vfio_pci_set_irqs_ioctl
    10 irqtest(103741):  <- vfio_pci_set_irqs_ioctl
    12 irqtest(103741):  -> vfio_config_free
    13 irqtest(103741):  <- vfio_config_free
103705 irqtest(103741):  -> pci_restore_msi_state
103714 irqtest(103741):  <- pci_restore_msi_state
103725 irqtest(103741):  -> vfio_pci_walk_wrapper
103731 irqtest(103741):   -> vfio_pci_count_devs
103736 irqtest(103741):   <- vfio_pci_count_devs
103741 irqtest(103741):  <- vfio_pci_walk_wrapper
103758 irqtest(103741):  -> vfio_pci_walk_wrapper
103759 irqtest(103741):   -> vfio_pci_count_devs
103760 irqtest(103741):   <- vfio_pci_count_devs
103761 irqtest(103741):  <- vfio_pci_walk_wrapper
103762 irqtest(103741):  -> vfio_pci_walk_wrapper
103763 irqtest(103741):   -> vfio_pci_count_devs
103765 irqtest(103741):   <- vfio_pci_count_devs
103766 irqtest(103741):  <- vfio_pci_walk_wrapper
103767 irqtest(103741):  -> vfio_pci_walk_wrapper
103768 irqtest(103741):   -> vfio_pci_count_devs
103769 irqtest(103741):   <- vfio_pci_count_devs
103770 irqtest(103741):  <- vfio_pci_walk_wrapper
103771 irqtest(103741):  -> vfio_pci_walk_wrapper
103773 irqtest(103741):   -> vfio_pci_get_unused_devs
103775 irqtest(103741):   <- vfio_pci_get_unused_devs
103776 irqtest(103741):  <- vfio_pci_walk_wrapper
103778 irqtest(103741):  -> vfio_pci_set_power_state
103779 irqtest(103741):  <- vfio_pci_set_power_state
103780 irqtest(103741): <- vfio_pci_release
     0 irqtest(103741): -> vfio_pci_match
     3 irqtest(103741):  -> get_pf_vdev
     4 irqtest(103741):  <- get_pf_vdev
     5 irqtest(103741): <- vfio_pci_match
     0 irqtest(103741): -> vfio_pci_open
     1 irqtest(103741):  -> vfio_pci_set_power_state
     3 irqtest(103741):  <- vfio_pci_set_power_state
103732 irqtest(103741):  -> pci_restore_msi_state
103741 irqtest(103741):  <- pci_restore_msi_state
103789 irqtest(103741):  -> vfio_config_init
103795 irqtest(103741):   -> vfio_fill_vconfig_bytes
103822 irqtest(103741):   <- vfio_fill_vconfig_bytes
103832 irqtest(103741):   -> vfio_fill_vconfig_bytes
103841 irqtest(103741):   <- vfio_fill_vconfig_bytes
103848 irqtest(103741):   -> vfio_fill_vconfig_bytes
103870 irqtest(103741):   <- vfio_fill_vconfig_bytes
103875 irqtest(103741):   -> vfio_fill_vconfig_bytes
103881 irqtest(103741):   <- vfio_fill_vconfig_bytes
103885 irqtest(103741):  <- vfio_config_init
103892 irqtest(103741):  -> vfio_pci_vf_token_user_add
103897 irqtest(103741):   -> get_pf_vdev
103903 irqtest(103741):   <- get_pf_vdev
103918 irqtest(103741):  <- vfio_pci_vf_token_user_add
103919 irqtest(103741): <- vfio_pci_open
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     2 irqtest(103741): <- vfio_pci_ioctl
     0 irqtest(103741): -> vfio_pci_read
     1 irqtest(103741):  -> vfio_pci_rw
     3 irqtest(103741):   -> vfio_pci_config_rw
     5 irqtest(103741):    -> vfio_basic_config_read
     6 irqtest(103741):     -> vfio_default_config_read
     8 irqtest(103741):      -> vfio_user_config_read
    10 irqtest(103741):      <- vfio_user_config_read
    12 irqtest(103741):     <- vfio_default_config_read
    13 irqtest(103741):    <- vfio_basic_config_read
    14 irqtest(103741):   <- vfio_pci_config_rw
    15 irqtest(103741):  <- vfio_pci_rw
    16 irqtest(103741): <- vfio_pci_read
     0 irqtest(103741): -> vfio_pci_write
     1 irqtest(103741):  -> vfio_pci_rw
     2 irqtest(103741):   -> vfio_pci_config_rw
     3 irqtest(103741):    -> vfio_basic_config_write
     6 irqtest(103741):     -> vfio_default_config_write
     8 irqtest(103741):      -> vfio_user_config_read
    10 irqtest(103741):      <- vfio_user_config_read
    11 irqtest(103741):      -> vfio_user_config_write
    13 irqtest(103741):      <- vfio_user_config_write
    14 irqtest(103741):     <- vfio_default_config_write
    16 irqtest(103741):    <- vfio_basic_config_write
    17 irqtest(103741):   <- vfio_pci_config_rw
    18 irqtest(103741):  <- vfio_pci_rw
    19 irqtest(103741): <- vfio_pci_write
vfio_pci_ioctl was called: 15211
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
     0 irqtest(103741): -> vfio_pci_mmap
    16 irqtest(103741): <- vfio_pci_mmap
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     2 irqtest(103741): <- vfio_pci_ioctl
     0 irqtest(103741): -> vfio_pci_mmap
     8 irqtest(103741): <- vfio_pci_mmap
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15212
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103741): -> vfio_pci_ioctl
     2 irqtest(103741):  -> vfio_pci_get_irq_count
     3 irqtest(103741):  <- vfio_pci_get_irq_count
     4 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741):  -> vfio_pci_get_irq_count
     2 irqtest(103741):  <- vfio_pci_get_irq_count
     3 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741):  -> vfio_pci_get_irq_count
     3 irqtest(103741):  <- vfio_pci_get_irq_count
     4 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741):  -> vfio_pci_get_irq_count
     2 irqtest(103741):  <- vfio_pci_get_irq_count
     3 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15213
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741):  -> vfio_pci_get_irq_count
     2 irqtest(103741):  <- vfio_pci_get_irq_count
     3 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15214
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741):  -> vfio_pci_get_irq_count
     3 irqtest(103741):  <- vfio_pci_get_irq_count
     5 irqtest(103741):  -> vfio_pci_set_irqs_ioctl
vfio_pci_set_msi_trigger: irq_type: index: vector: flags: 0x5 0x2 0x0 0x24
vfio_pci_set_msi_trigger: vdev: 0xffff8ea6bc003200
     8 irqtest(103741):   -> vfio_pci_set_msi_trigger
    10 irqtest(103741):    -> vfio_pci_memory_lock_and_enable
    13 irqtest(103741):    <- vfio_pci_memory_lock_and_enable
    15 irqtest(103741):    -> pci_alloc_irq_vectors_affinity
    16 irqtest(103741):     -> __pci_enable_msix_range
    18 irqtest(103741):      -> pci_msi_supported
    20 irqtest(103741):      <- pci_msi_supported
    21 irqtest(103741):      -> pci_msix_vec_count
    23 irqtest(103741):      <- pci_msix_vec_count
    33 irqtest(103741):      -> pci_msix_vec_count
    35 irqtest(103741):      <- pci_msix_vec_count
    38 irqtest(103741):      -> pci_msi_setup_msi_irqs
    43 irqtest(103741):       -> pci_msi_domain_check_cap
    44 irqtest(103741):       <- pci_msi_domain_check_cap
    46 irqtest(103741):       -> pci_msi_domain_calc_hwirq
    48 irqtest(103741):       <- pci_msi_domain_calc_hwirq
   109 irqtest(103741):       -> pci_msi_domain_write_msg
   111 irqtest(103741):        -> __pci_write_msi_msg
   113 irqtest(103741):        <- __pci_write_msi_msg
   114 irqtest(103741):       <- pci_msi_domain_write_msg
   118 irqtest(103741):      <- pci_msi_setup_msi_irqs
   119 irqtest(103741):      -> msi_verify_entries
   120 irqtest(103741):      <- msi_verify_entries
   124 irqtest(103741):      -> __pci_msix_desc_mask_irq
   125 irqtest(103741):      <- __pci_msix_desc_mask_irq
   127 irqtest(103741):      -> populate_msi_sysfs
   132 irqtest(103741):      <- populate_msi_sysfs
   136 irqtest(103741):     <- __pci_enable_msix_range
   137 irqtest(103741):    <- pci_alloc_irq_vectors_affinity
   139 irqtest(103741):    -> vfio_pci_memory_unlock_and_restore
   141 irqtest(103741):    <- vfio_pci_memory_unlock_and_restore
vfio_msi_set_block: start: count: 0x0, 0x1
vfio_msi_set_block: vdev->num_ctx: 0x1
   144 irqtest(103741):    -> vfio_msi_set_block
vfio_msi_set_vector_signal was called: 0 / 7
   147 irqtest(103741):     -> vfio_msi_set_vector_signal
   149 irqtest(103741):      -> pci_irq_vector
   150 irqtest(103741):      <- pci_irq_vector
   153 irqtest(103741):      -> vfio_pci_memory_lock_and_enable
   156 irqtest(103741):      <- vfio_pci_memory_lock_and_enable
   159 irqtest(103741):      -> pci_write_msi_msg
   162 irqtest(103741):       -> __pci_write_msi_msg
   163 irqtest(103741):       <- __pci_write_msi_msg
   164 irqtest(103741):      <- pci_write_msi_msg
   178 irqtest(103741):      -> pci_msi_domain_write_msg
   179 irqtest(103741):       -> __pci_write_msi_msg
   180 irqtest(103741):       <- __pci_write_msi_msg
   181 irqtest(103741):      <- pci_msi_domain_write_msg
   186 irqtest(103741):      -> pci_msi_unmask_irq
   187 irqtest(103741):       -> msi_set_mask_bit
   188 irqtest(103741):        -> __pci_msix_desc_mask_irq
   190 irqtest(103741):        <- __pci_msix_desc_mask_irq
   192 irqtest(103741):       <- msi_set_mask_bit
   193 irqtest(103741):      <- pci_msi_unmask_irq
   213 irqtest(103741):      -> vfio_pci_memory_unlock_and_restore
   216 irqtest(103741):      <- vfio_pci_memory_unlock_and_restore
   217 irqtest(103741):     <- vfio_msi_set_vector_signal
vfio_msi_set_vector_signal returned with: 0
   219 irqtest(103741):    <- vfio_msi_set_block
   221 irqtest(103741):   <- vfio_pci_set_msi_trigger
   222 irqtest(103741):  <- vfio_pci_set_irqs_ioctl
   223 irqtest(103741): <- vfio_pci_ioctl
vfio_pci_ioctl was called: 15214
     0 irqtest(103741): -> vfio_pci_ioctl
     1 irqtest(103741):  -> vfio_pci_get_irq_count
     3 irqtest(103741):  <- vfio_pci_get_irq_count
     5 irqtest(103741):  -> vfio_pci_set_irqs_ioctl
vfio_pci_set_msi_trigger: irq_type: index: vector: flags: 0x2 0x2 0x1 0x24
vfio_pci_set_msi_trigger: vdev: 0xffff8ea6bc003200
     7 irqtest(103741):   -> vfio_pci_set_msi_trigger
vfio_msi_set_block: start: count: 0x1, 0x1
vfio_msi_set_block: vdev->num_ctx: 0x1
     9 irqtest(103741):    -> vfio_msi_set_block
    11 irqtest(103741):    <- vfio_msi_set_block
    12 irqtest(103741):   <- vfio_pci_set_msi_trigger
    13 irqtest(103741):  <- vfio_pci_set_irqs_ioctl
    14 irqtest(103741): <- vfio_pci_ioctl
     0 irqtest(103741): -> vfio_pci_mmap_close
     2 irqtest(103741): <- vfio_pci_mmap_close
     0 irqtest(103741): -> vfio_pci_mmap_close
     2 irqtest(103741): <- vfio_pci_mmap_close
     0 irqtest(103741): -> vfio_pci_release
     2 irqtest(103741):  -> vfio_pci_vf_token_user_add
     3 irqtest(103741):   -> get_pf_vdev
     5 irqtest(103741):   <- get_pf_vdev
     6 irqtest(103741):  <- vfio_pci_vf_token_user_add
     9 irqtest(103741):  -> vfio_pci_set_irqs_ioctl
vfio_pci_set_msi_trigger: irq_type: index: vector: flags: 0x2 0x2 0x0 0x21
vfio_pci_set_msi_trigger: vdev: 0xffff8ea6bc003200
    12 irqtest(103741):   -> vfio_pci_set_msi_trigger
    14 irqtest(103741):    -> vfio_msi_disable
vfio_msi_set_block: start: count: 0x0, 0x1
vfio_msi_set_block: vdev->num_ctx: 0x1
    20 irqtest(103741):     -> vfio_msi_set_block
vfio_msi_set_vector_signal was called: 0 / -1
    22 irqtest(103741):      -> vfio_msi_set_vector_signal
    24 irqtest(103741):       -> pci_irq_vector
    25 irqtest(103741):       <- pci_irq_vector
    26 irqtest(103741):       -> vfio_pci_memory_lock_and_enable
    30 irqtest(103741):       <- vfio_pci_memory_lock_and_enable
    37 irqtest(103741):       -> pci_msi_mask_irq
    39 irqtest(103741):        -> msi_set_mask_bit
    40 irqtest(103741):         -> __pci_msix_desc_mask_irq
    41 irqtest(103741):         <- __pci_msix_desc_mask_irq
    43 irqtest(103741):        <- msi_set_mask_bit
    44 irqtest(103741):       <- pci_msi_mask_irq
    53 irqtest(103741):       -> pci_msi_domain_write_msg
    54 irqtest(103741):        -> __pci_write_msi_msg
    56 irqtest(103741):        <- __pci_write_msi_msg
    57 irqtest(103741):       <- pci_msi_domain_write_msg
    65 irqtest(103741):       -> vfio_pci_memory_unlock_and_restore
    67 irqtest(103741):       <- vfio_pci_memory_unlock_and_restore
    68 irqtest(103741):      <- vfio_msi_set_vector_signal
vfio_msi_set_vector_signal returned with: 0
    77 irqtest(103741):     <- vfio_msi_set_block
    78 irqtest(103741):     -> vfio_pci_memory_lock_and_enable
    81 irqtest(103741):     <- vfio_pci_memory_lock_and_enable
    83 irqtest(103741):     -> pci_free_irq_vectors
    84 irqtest(103741):      -> pci_disable_msix
    88 irqtest(103741):       -> free_msi_irqs
    91 irqtest(103741):        -> default_teardown_msi_irqs
   139 irqtest(103741):        <- default_teardown_msi_irqs
   145 irqtest(103741):       <- free_msi_irqs
   146 irqtest(103741):      <- pci_disable_msix
   148 irqtest(103741):      -> pci_disable_msi
   149 irqtest(103741):      <- pci_disable_msi
   150 irqtest(103741):     <- pci_free_irq_vectors
   151 irqtest(103741):     -> vfio_pci_memory_unlock_and_restore
   154 irqtest(103741):     <- vfio_pci_memory_unlock_and_restore
   155 irqtest(103741):    <- vfio_msi_disable
   156 irqtest(103741):   <- vfio_pci_set_msi_trigger
   158 irqtest(103741):  <- vfio_pci_set_irqs_ioctl
   159 irqtest(103741):  -> vfio_config_free
   160 irqtest(103741):  <- vfio_config_free
103190 irqtest(103741):  -> pci_restore_msi_state
103199 irqtest(103741):  <- pci_restore_msi_state
103210 irqtest(103741):  -> vfio_pci_walk_wrapper
103215 irqtest(103741):   -> vfio_pci_count_devs
103220 irqtest(103741):   <- vfio_pci_count_devs
103224 irqtest(103741):  <- vfio_pci_walk_wrapper
103228 irqtest(103741):  -> vfio_pci_walk_wrapper
103232 irqtest(103741):   -> vfio_pci_count_devs
103236 irqtest(103741):   <- vfio_pci_count_devs
103240 irqtest(103741):  <- vfio_pci_walk_wrapper
103243 irqtest(103741):  -> vfio_pci_walk_wrapper
103247 irqtest(103741):   -> vfio_pci_count_devs
103251 irqtest(103741):   <- vfio_pci_count_devs
103255 irqtest(103741):  <- vfio_pci_walk_wrapper
103258 irqtest(103741):  -> vfio_pci_walk_wrapper
103262 irqtest(103741):   -> vfio_pci_count_devs
103266 irqtest(103741):   <- vfio_pci_count_devs
103269 irqtest(103741):  <- vfio_pci_walk_wrapper
103274 irqtest(103741):  -> vfio_pci_walk_wrapper
103278 irqtest(103741):   -> vfio_pci_get_unused_devs
103284 irqtest(103741):   <- vfio_pci_get_unused_devs
103288 irqtest(103741):  <- vfio_pci_walk_wrapper
103293 irqtest(103741):  -> vfio_pci_set_power_state
103297 irqtest(103741):  <- vfio_pci_set_power_state
103302 irqtest(103741): <- vfio_pci_release

^ permalink raw reply	[flat|nested] 3+ messages in thread

* Re: BUG REPORT: vfio_pci driver
  2021-08-13 18:34 BUG REPORT: vfio_pci driver Russ Weight
@ 2021-08-13 22:09 ` Alex Williamson
  2021-08-17 17:16   ` Russ Weight
  0 siblings, 1 reply; 3+ messages in thread
From: Alex Williamson @ 2021-08-13 22:09 UTC (permalink / raw)
  To: Russ Weight
  Cc: Cornelia Huck, Adler, Michael, Whisonant, Tim, kvm, linux-kernel,
	Tom Rix

On Fri, 13 Aug 2021 11:34:51 -0700
Russ Weight <russell.h.weight@intel.com> wrote:

> Bug Description:
> 
> A bug in the vfio_pci driver was reported in junction with work on FPGA

This looks like the documented behavior of an IRQ index reporting the
VFIO_IRQ_INFO_NORESIZE flag.  We can certainly work towards trying to
remove the flag from this index, but it seems the userspace driver is
currently ignoring the flag and expecting exactly the behavior the flag
indicates is not available.  Thanks,

Alex

> cards. We were able to reproduce and root-cause the bug using system-tap.
> The original bug description is below. An understanding of the referenced
> dfl and opae tools is not required - it is the sequence of IOCTL calls and
> IRQ vectors that matters:
> 
> > I’m trying to get an example AFU working that uses 2 IRQs, active at the same 
> > time. I’m hitting what looks to be a dfl_pci driver bug.
> >
> > The code tries to allocate two IRQ vectors: 0 and 1. I see opaevfio.c doing the 
> > right thing, picking the MSIX index. Allocating either IRQ 0 or IRQ 1 works fine 
> > and I confirm that the VFIO_DEVICE_SET_IRQS looks reasonable, choosing MSIX and 
> > either start of 0 or 1 and count 1.
> >
> > Note that opaevfio.c always passes count 1, so it will make separate calls for 
> > each IRQ vector.
> >
> > When I try to allocate both, I see the following:
> >
> >   * If the VFIO_DEVICE_SET_IRQS ioctl is called first with start 0 and then
> >     start 1 (always count 1), the start 1 (second) ioctl trap returns EINVAL.
> >   * If I set up the vectors in decreasing order, so start 1 followed by start 0,
> >     the program works!
> >   * I ruled out OPAE SDK user space problems by setting up my program to
> >     allocate in increasing order, which would normally fail. I changed only the
> >     ioctl call in user space opaevfio.c, inverting bit 0 of start so that the
> >     driver is called in decreasing index order. Of course this binds the wrong
> >     vectors to the fds, but I don’t care about that for now. This works! From
> >     this, I conclude that it can’t be a user space problem since the difference
> >     between working and failing is solely the order in which IRQ vectors are
> >     bound in ioctl calls.  
> 
> The EINVAL is coming from vfio_msi_set_block() here:
> https://github.com/torvalds/linux/blob/master/drivers/vfio/pci/vfio_pci_intrs.c#L373
> 
> vfio_msi_set_block() is being called from vfio_pci_set_msi_trigger() here on
> the second IRQ request:
> https://github.com/torvalds/linux/blob/master/drivers/vfio/pci/vfio_pci_intrs.c#L530
> 
> We believe the bug is in vfio_pci_set_msi_trigger(), in the 2nd parameter to the call
> to vfio_msi_enable() here:
> https://github.com/torvalds/linux/blob/master/drivers/vfio/pci/vfio_pci_intrs.c#L533
> 
> In both the passing and failing cases, the first IRQ request results in a call
> to vfio_msi_enable() at line 533 and the second IRQ request results in the
> call to vfio_msi_set_block() at line 530. It is during the first IRQ request
> that vfio_msi_enable() sets vdev->num_ctx based on the 2nd parameter (nvec).
> vdev->num_ctx is part of the conditional that results in the EINVAL for the
> failing case.
> 
> In the passing case, vdev->num_ctx is 2. In the failing case, it is 1.
> 
> I am attaching two text files containing trace information from systemtap: one for
> the failing case and one for the passing case. They contain a lot more information
> than is needed, but if you search for vfio_pci_set_msi_trigger and vfio_msi_set_block,
> you will see values for some of the call parameters.
> 
> - Russ
> 


^ permalink raw reply	[flat|nested] 3+ messages in thread

* Re: BUG REPORT: vfio_pci driver
  2021-08-13 22:09 ` Alex Williamson
@ 2021-08-17 17:16   ` Russ Weight
  0 siblings, 0 replies; 3+ messages in thread
From: Russ Weight @ 2021-08-17 17:16 UTC (permalink / raw)
  To: Alex Williamson
  Cc: Cornelia Huck, Adler, Michael, Whisonant, Tim, kvm, linux-kernel,
	Tom Rix

On 8/13/21 3:09 PM, Alex Williamson wrote:
> On Fri, 13 Aug 2021 11:34:51 -0700
> Russ Weight <russell.h.weight@intel.com> wrote:
>
>> Bug Description:
>>
>> A bug in the vfio_pci driver was reported in junction with work on FPGA
> This looks like the documented behavior of an IRQ index reporting the
> VFIO_IRQ_INFO_NORESIZE flag.  We can certainly work towards trying to
> remove the flag from this index, but it seems the userspace driver is
> currently ignoring the flag and expecting exactly the behavior the flag
> indicates is not available.  Thanks,

Thanks for the quick reply, Alex. Yes, we misunderstood the expected
behavior. We have adapted our library code and everything is
working now.

- Russ


>
> Alex
>
>> cards. We were able to reproduce and root-cause the bug using system-tap.
>> The original bug description is below. An understanding of the referenced
>> dfl and opae tools is not required - it is the sequence of IOCTL calls and
>> IRQ vectors that matters:
>>
>>> I’m trying to get an example AFU working that uses 2 IRQs, active at the same 
>>> time. I’m hitting what looks to be a dfl_pci driver bug.
>>>
>>> The code tries to allocate two IRQ vectors: 0 and 1. I see opaevfio.c doing the 
>>> right thing, picking the MSIX index. Allocating either IRQ 0 or IRQ 1 works fine 
>>> and I confirm that the VFIO_DEVICE_SET_IRQS looks reasonable, choosing MSIX and 
>>> either start of 0 or 1 and count 1.
>>>
>>> Note that opaevfio.c always passes count 1, so it will make separate calls for 
>>> each IRQ vector.
>>>
>>> When I try to allocate both, I see the following:
>>>
>>>   * If the VFIO_DEVICE_SET_IRQS ioctl is called first with start 0 and then
>>>     start 1 (always count 1), the start 1 (second) ioctl trap returns EINVAL.
>>>   * If I set up the vectors in decreasing order, so start 1 followed by start 0,
>>>     the program works!
>>>   * I ruled out OPAE SDK user space problems by setting up my program to
>>>     allocate in increasing order, which would normally fail. I changed only the
>>>     ioctl call in user space opaevfio.c, inverting bit 0 of start so that the
>>>     driver is called in decreasing index order. Of course this binds the wrong
>>>     vectors to the fds, but I don’t care about that for now. This works! From
>>>     this, I conclude that it can’t be a user space problem since the difference
>>>     between working and failing is solely the order in which IRQ vectors are
>>>     bound in ioctl calls.  
>> The EINVAL is coming from vfio_msi_set_block() here:
>> https://github.com/torvalds/linux/blob/master/drivers/vfio/pci/vfio_pci_intrs.c#L373
>>
>> vfio_msi_set_block() is being called from vfio_pci_set_msi_trigger() here on
>> the second IRQ request:
>> https://github.com/torvalds/linux/blob/master/drivers/vfio/pci/vfio_pci_intrs.c#L530
>>
>> We believe the bug is in vfio_pci_set_msi_trigger(), in the 2nd parameter to the call
>> to vfio_msi_enable() here:
>> https://github.com/torvalds/linux/blob/master/drivers/vfio/pci/vfio_pci_intrs.c#L533
>>
>> In both the passing and failing cases, the first IRQ request results in a call
>> to vfio_msi_enable() at line 533 and the second IRQ request results in the
>> call to vfio_msi_set_block() at line 530. It is during the first IRQ request
>> that vfio_msi_enable() sets vdev->num_ctx based on the 2nd parameter (nvec).
>> vdev->num_ctx is part of the conditional that results in the EINVAL for the
>> failing case.
>>
>> In the passing case, vdev->num_ctx is 2. In the failing case, it is 1.
>>
>> I am attaching two text files containing trace information from systemtap: one for
>> the failing case and one for the passing case. They contain a lot more information
>> than is needed, but if you search for vfio_pci_set_msi_trigger and vfio_msi_set_block,
>> you will see values for some of the call parameters.
>>
>> - Russ
>>


^ permalink raw reply	[flat|nested] 3+ messages in thread

end of thread, other threads:[~2021-08-17 17:16 UTC | newest]

Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-08-13 18:34 BUG REPORT: vfio_pci driver Russ Weight
2021-08-13 22:09 ` Alex Williamson
2021-08-17 17:16   ` Russ Weight

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).