cqe dump errors on target while running nvme-of large block read IO

cqe dump errors on target while running nvme-of large block read IO

[Gruher, Joseph R]

Hi folks-

Wanted to put this issue out there and see if anyone had thoughts.

Target system - 100Gb dual port CX5, FW 16.19.1000, through Arista 7060X switch with Ethernet flow control
Initiator system - 25Gb dual port CX4, FW 14.18.2000, through Arista 7060X switch with Ethernet flow control

We attach 16 drives from target to initiator, but are only running IO on four of them in this test, two drives per network port on initiator/target.  Drives in use are Intel P3700 400GB.

We are running Ubuntu 16.10 with the 4.11-rc6 kernel and this patch from Max:

diff --git a/drivers/infiniband/hw/mlx5/qp.c b/drivers/infiniband/hw/mlx5/qp.c index ad8a263..c38c4fa 100644
--- a/drivers/infiniband/hw/mlx5/qp.c
+++ b/drivers/infiniband/hw/mlx5/qp.c
@@ -3737,8 +3737,7 @@ static void dump_wqe(struct mlx5_ib_qp *qp, int idx, int size_16)

  static u8 get_fence(u8 fence, struct ib_send_wr *wr)
  {
-       if (unlikely(wr->opcode == IB_WR_LOCAL_INV &&
-                    wr->send_flags & IB_SEND_FENCE))
+       if (wr->opcode == IB_WR_LOCAL_INV || wr->opcode == IB_WR_REG_MR)
                 return MLX5_FENCE_MODE_STRONG_ORDERING;

         if (unlikely(fence)) {

For the most part we can run FIO IO on the initiator against the attached subsystems without problems.  4KB random read and write, 64KB sequential writes are working OK on this setup.  We seem to encounter errors when we run a 64KB sequential read workload.  I would not the 64KB sequential read workload is the only one which generates enough traffic that we could bottleneck on the initiator NIC throughput - not sure if that is relevant, or just a coincidence.  We can reproduce these errors fairly reliably at this time.  See attached dmesg and example below:

[12728.885267] mlx5_1:dump_cqe:262:(pid 2943): dump error cqe
[12728.885271] 00000000 00000000 00000000 00000000
[12728.885272] 00000000 00000000 00000000 00000000
[12728.885274] 00000000 00000000 00000000 00000000
[12728.885275] 00000000 00008813 08000240 0255bcd3
[12728.885852] mlx5_1:dump_cqe:262:(pid 2829): dump error cqe
[12728.885855] 00000000 00000000 00000000 00000000
[12728.885857] 00000000 00000000 00000000 00000000
[12728.885859] 00000000 00000000 00000000 00000000
[12728.885861] 00000000 00008813 08000239 c2e59fd3
[12735.782466] nvmet: ctrl 17 keep-alive timer (15 seconds) expired!
[12735.784949] nvmet: ctrl 17 fatal error occurred!

These target side error prints seem correlated with IO failures and disconnect/reconnect events on the initiator so they are a problem.  Any ideas?  Any additional info we can provide?

Thanks,
Joe
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: initiator-dmesg.txt
URL: <http://lists.infradead.org/pipermail/linux-nvme/attachments/20170412/5dcfdcd1/attachment-0002.txt>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: target-dmesg.txt
URL: <http://lists.infradead.org/pipermail/linux-nvme/attachments/20170412/5dcfdcd1/attachment-0003.txt>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: joe16b.json
Type: application/octet-stream
Size: 6393 bytes
Desc: joe16b.json
URL: <http://lists.infradead.org/pipermail/linux-nvme/attachments/20170412/5dcfdcd1/attachment-0001.obj>

cqe dump errors on target while running nvme-of large block read IO

[Max Gurtovoy]

On 4/12/2017 7:41 PM, Gruher, Joseph R wrote:
> Hi folks-
>
> Wanted to put this issue out there and see if anyone had thoughts.
>
> Target system - 100Gb dual port CX5, FW 16.19.1000, through Arista 7060X switch with Ethernet flow control
> Initiator system - 25Gb dual port CX4, FW 14.18.2000, through Arista 7060X switch with Ethernet flow control
>
> We attach 16 drives from target to initiator, but are only running IO on four of them in this test, two drives per network port on initiator/target.  Drives in use are Intel P3700 400GB.
>
> We are running Ubuntu 16.10 with the 4.11-rc6 kernel and this patch from Max:
>
> diff --git a/drivers/infiniband/hw/mlx5/qp.c b/drivers/infiniband/hw/mlx5/qp.c index ad8a263..c38c4fa 100644
> --- a/drivers/infiniband/hw/mlx5/qp.c
> +++ b/drivers/infiniband/hw/mlx5/qp.c
> @@ -3737,8 +3737,7 @@ static void dump_wqe(struct mlx5_ib_qp *qp, int idx, int size_16)
>
>   static u8 get_fence(u8 fence, struct ib_send_wr *wr)
>   {
> -       if (unlikely(wr->opcode == IB_WR_LOCAL_INV &&
> -                    wr->send_flags & IB_SEND_FENCE))
> +       if (wr->opcode == IB_WR_LOCAL_INV || wr->opcode == IB_WR_REG_MR)
>                  return MLX5_FENCE_MODE_STRONG_ORDERING;
>
>          if (unlikely(fence)) {
>
> For the most part we can run FIO IO on the initiator against the attached subsystems without problems.  4KB random read and write, 64KB sequential writes are working OK on this setup.  We seem to encounter errors when we run a 64KB sequential read workload.  I would not the 64KB sequential read workload is the only one which generates enough traffic that we could bottleneck on the initiator NIC throughput - not sure if that is relevant, or just a coincidence.  We can reproduce these errors fairly reliably at this time.  See attached dmesg and example below:
>
> [12728.885267] mlx5_1:dump_cqe:262:(pid 2943): dump error cqe
> [12728.885271] 00000000 00000000 00000000 00000000
> [12728.885272] 00000000 00000000 00000000 00000000
> [12728.885274] 00000000 00000000 00000000 00000000
> [12728.885275] 00000000 00008813 08000240 0255bcd3
> [12728.885852] mlx5_1:dump_cqe:262:(pid 2829): dump error cqe
> [12728.885855] 00000000 00000000 00000000 00000000
> [12728.885857] 00000000 00000000 00000000 00000000
> [12728.885859] 00000000 00000000 00000000 00000000
> [12728.885861] 00000000 00008813 08000239 c2e59fd3
> [12735.782466] nvmet: ctrl 17 keep-alive timer (15 seconds) expired!
> [12735.784949] nvmet: ctrl 17 fatal error occurred!
>
> These target side error prints seem correlated with IO failures and disconnect/reconnect events on the initiator so they are a problem.  Any ideas?  Any additional info we can provide?

hi Joe,
can you run and repro it with null_blk backing store instead the nvme ? 
you can emulate the delay of the nvme device using module param 
completion_nsec.
is it reproducable in case B2B connectivity ?

>
> Thanks,
> Joe
>

cqe dump errors on target while running nvme-of large block read IO

[Gruher, Joseph R]

> hi Joe,
> can you run and repro it with null_blk backing store instead the nvme ?
> you can emulate the delay of the nvme device using module param
> completion_nsec.
> is it reproducable in case B2B connectivity ?

Hey Max,

I ran overnight using null_blk devices but was unable to reproduce in that configuration.  I set completion_nsec to 50000.  Although my measured completion latencies in FIO were more like 17-18usec so not sure why they did not come in closer to 50usec.  Anyway, failure did not reproduce using null_blk instead of real NVMe SSDs.

By B2B connectivity do you mean direct target-to-initiator connection with no switch?  I don't think that is possible in this configuration since target uses a 100Gb QSFP NIC and initiator uses a 25Gb SFP28 NIC.  I could perhaps swap the target side NIC for a matching 25Gb device and run direct connected that way if we think we need that data point, we would need to first establish if the failure even happens in that configuration, based on other testing we've done on an all-25Gb configuration I suspect it may not.

cqe dump errors on target while running nvme-of large block read IO

[Max Gurtovoy]

On 4/14/2017 7:38 PM, Gruher, Joseph R wrote:
>> hi Joe,
>> can you run and repro it with null_blk backing store instead the nvme ?
>> you can emulate the delay of the nvme device using module param
>> completion_nsec.
>> is it reproducable in case B2B connectivity ?
>
> Hey Max,
>
> I ran overnight using null_blk devices but was unable to reproduce in that configuration.  I set completion_nsec to 50000.  Although my measured completion latencies in FIO were more like 17-18usec so not sure why they did not come in closer to 50usec.  Anyway, failure did not reproduce using null_blk instead of real NVMe SSDs.

Hi,
you should set also the irqmode=2 (timer) and run local fio with 
iodepth=1 and numjobs=1 to verify the latency (worked for me).
Let's try to repro again with the new configuration, to be sure that 
this is not a transport issue.

Thanks.

>
> By B2B connectivity do you mean direct target-to-initiator connection with no switch?  I don't think that is possible in this configuration since target uses a 100Gb QSFP NIC and initiator uses a 25Gb SFP28 NIC.  I could perhaps swap the target side NIC for a matching 25Gb device and run direct connected that way if we think we need that data point, we would need to first establish if the failure even happens in that configuration, based on other testing we've done on an all-25Gb configuration I suspect it may not.
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-rdma" in
> the body of a message to majordomo at vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>

cqe dump errors on target while running nvme-of large block read IO

[Sagi Grimberg]

>>> hi Joe,
>>> can you run and repro it with null_blk backing store instead the nvme ?
>>> you can emulate the delay of the nvme device using module param
>>> completion_nsec.
>>> is it reproducable in case B2B connectivity ?
>>
>> Hey Max,
>>
>> I ran overnight using null_blk devices but was unable to reproduce in
>> that configuration.  I set completion_nsec to 50000.  Although my
>> measured completion latencies in FIO were more like 17-18usec so not
>> sure why they did not come in closer to 50usec.  Anyway, failure did
>> not reproduce using null_blk instead of real NVMe SSDs.
>
> Hi,
> you should set also the irqmode=2 (timer) and run local fio with
> iodepth=1 and numjobs=1 to verify the latency (worked for me).
> Let's try to repro again with the new configuration, to be sure that
> this is not a transport issue.

The backend has absolutely nothing to do with these errors.

The target side cqe dumps indicate failures for RDMA write operations,
because we don't ask for completions on those we don't see logging from
the nvmet-rdma code, we simply trigger fatal errors from the rain of
flush errors that follow the queue-pair moving to error state.

These errors are either from:
1. mapping error on the host side - not sure given we don't see
any error completions/events from the rdma device. However, can you
turn on dynamic debug to see QP events?

echo "func nvme_rdma_qp_event +p" > /sys/kernel/debug/dynamic_debug/control

2. retry exhaustions due to network congestion - likely due to the
topology used.

3. Maybe something I'm missing...

The fact that null_blk didn't reproduce this was probably because it is
less bursty (which can cause network congestion).

On the host side we see I/O failures which immediately followed by
reconnect. On reconnects we stop all incoming IO and fail all IO
inflight so we can safely handle the reestablishment of the controller
queues. The fact that we fail the IO and remove the buffer mappings
correlates with the cqe dumps we see on the target.

So what I suspect happening is:
1. target tries to ingest a lot servicing large reads (more than 25G)
2. either flow control stop the target device (in case flow
control works as expected) or target retries handling drops.
3. these rdma writes stall so much that the host gives up on
I/O timeout (30 seconds)
4. host error recovery kicks in, host stops queues and fast fail
inflight IO, removing buffer mappings
5. target retries finally passes switch congestion, makes it to the
host but the buffer mappings are gone, host device fails rdma write
operations.
6. target generates these CQE dumps.

If this is the case, I'm not exactly sure how to resolve this.

Joseph, are you sure that flow control is correctly configured
and working reliably?

Perhaps the experts in Linux-rdma can help...

cqe dump errors on target while running nvme-of large block read IO

[Gruher, Joseph R]

> you should set also the irqmode=2 (timer) and run local fio with
> iodepth=1 and numjobs=1 to verify the latency (worked for me).
> Let's try to repro again with the new configuration, to be sure that this is not a
> transport issue.

Adding irqmode=2 definitely corrected the latency behavior.  Now for 1 job with QD=1 on 4K random reads I get average latency 74usec and writes are 67usec.  I set the null_blk devices to 50000nsec so adding in some latency for NVMf this seems reasonable.

I believe I was able to reproduce an instance of the problem using the null_blk devices as the backend.  We configured 16 null_blk devices an attached four to initiator 1 and four to initiator 2.  Initiators are each using both ports of a dual-ported 25Gb CX4 and target is using both ports of a dual-ported 100Gb CX5 (dual ports are on separate subnets).  Then we ran a variety of workloads overnight.  The dmesg logs are attached.  We see "dump error cqe" at various points in the target dmesg and we see IO errors and reconnects on both initiators.

Thanks,
Joe
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: init1.txt
URL: <http://lists.infradead.org/pipermail/linux-nvme/attachments/20170420/6e4e0538/attachment-0003.txt>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: init2.txt
URL: <http://lists.infradead.org/pipermail/linux-nvme/attachments/20170420/6e4e0538/attachment-0004.txt>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: target.txt
URL: <http://lists.infradead.org/pipermail/linux-nvme/attachments/20170420/6e4e0538/attachment-0005.txt>

cqe dump errors on target while running nvme-of large block read IO

[Gruher, Joseph R]

> These errors are either from:
> 1. mapping error on the host side - not sure given we don't see any error
> completions/events from the rdma device. However, can you turn on dynamic
> debug to see QP events?
> 
> echo "func nvme_rdma_qp_event +p" >
> /sys/kernel/debug/dynamic_debug/control

Yes, I can try this out.  Will this just print to dmesg or do I need to collect a log from somewhere?

> The fact that null_blk didn't reproduce this was probably because it is less
> bursty (which can cause network congestion).

See email I just now sent in reply to Max (this same thread).  I believe we reproduced the same issue with null_blk last night after correctly configuring some latency into the null_blk devices.

> Joseph, are you sure that flow control is correctly configured and working
> reliably?

I believe it is set up correctly.  Running ethtool against the NIC interfaces in use reports:
	Supported pause frame use: Symmetric Receive-only

And all ports in use on the Arista 7060X switch report it turned on in both directions:
	flowcontrol send on
	flowcontrol receive on

If there's anywhere else we can check, or any direct test of flow control we can run, happy to try it.  Should we be OK with only Rx flow control at the NIC (this seems to be the default behavior) or is it recommended to set up Tx flow control as well?

cqe dump errors on target while running nvme-of large block read IO

[Gruher, Joseph R]

> Joseph, are you sure that flow control is correctly configured and working
> reliably?

Folks, I have to apologize here.  Flow control was at one point configured correctly, but we had a power outage in our lab two weeks ago.  We thought the switch had come back up OK, but late week we were double-checking all the ports in use and we found one port had lost some settings and no longer had flow control enabled (it had also reverted from 100Gb to 50Gb for some reason).  After fixing the port settings we ran IO through the weekend and the early part of this week on a variety of workloads.  We don't seem to be able to reproduce the failure after fixing the port settings.  It looks like this one may have been caused by the lost flow control setting on the switch.  Sorry for the confusion!

cqe dump errors on target while running nvme-of large block read IO

[Sagi Grimberg]

> Folks, I have to apologize here.  Flow control was at one point configured correctly, but we had a power outage in our lab two weeks ago.
> We thought the switch had come back up OK, but late week we were double-checking all the ports in use and we found one port had lost some
> settings and no longer had flow control enabled (it had also reverted from 100Gb to 50Gb for some reason).  After fixing the port settings
> we ran IO through the weekend and the early part of this week on a variety of workloads.  We don't seem to be able to reproduce the failure
> after fixing the port settings.  It looks like this one may have been caused by the lost flow control setting on the switch.  Sorry for the confusion!

Yep, don't expect RoCE to work without flow-control.

cqe dump errors on target while running nvme-of large block read IO

[Majd Dibbiny]

> On Apr 27, 2017,@2:57 AM, Sagi Grimberg <sagi@grimberg.me> wrote:
> 
> 
>> Folks, I have to apologize here.  Flow control was at one point configured correctly, but we had a power outage in our lab two weeks ago.
>> We thought the switch had come back up OK, but late week we were double-checking all the ports in use and we found one port had lost some
>> settings and no longer had flow control enabled (it had also reverted from 100Gb to 50Gb for some reason).  After fixing the port settings
>> we ran IO through the weekend and the early part of this week on a variety of workloads.  We don't seem to be able to reproduce the failure
>> after fixing the port settings.  It looks like this one may have been caused by the lost flow control setting on the switch.  Sorry for the confusion!
> 
> Yep, don't expect RoCE to work without flow-control.
Sagi and all,

Starting in next release, for ConnectX-4 and above PFC isn't required as long as ECN is enabled.

With current release we also expect to get good results with ECN and no PFC.

Joseph - is ECN enabled on your system?

Thanks
> --
> To unsubscribe from this list: send the line "unsubscribe linux-rdma" in
> the body of a message to majordomo at vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

cqe dump errors on target while running nvme-of large block read IO

[Christoph Hellwig]

On Thu, Apr 27, 2017@04:29:27AM +0000, Majd Dibbiny wrote:
> Starting in next release, for ConnectX-4 and above PFC isn't required as long as ECN is enabled.

What does "release" mean in this context?  Firmware version?

cqe dump errors on target while running nvme-of large block read IO

[Majd Dibbiny]

> On Apr 27, 2017,@2:39 PM, Christoph Hellwig <hch@infradead.org> wrote:
> 
>> On Thu, Apr 27, 2017@04:29:27AM +0000, Majd Dibbiny wrote:
>> Starting in next release, for ConnectX-4 and above PFC isn't required as long as ECN is enabled.
> 
> What does "release" mean in this context?  Firmware version?
Yes, next Firmware release.

cqe dump errors on target while running nvme-of large block read IO

[Gruher, Joseph R]

> Starting in next release, for ConnectX-4 and above PFC isn't required as long as
> ECN is enabled.
> 
> With current release we also expect to get good results with ECN and no PFC.
> 
> Joseph - is ECN enabled on your system?

No, we haven't done anything to set up ECN, so I assume it is not enabled.