* lpfc on latest 5.9 is very chatty on modprobe
@ 2020-09-10 16:36 Laurence Oberman
2020-09-11 15:09 ` Laurence Oberman
0 siblings, 1 reply; 4+ messages in thread
From: Laurence Oberman @ 2020-09-10 16:36 UTC (permalink / raw)
To: linux-scsi
Hello
I was testing lpfc on 5.9 and noticed a lot more logging on modprobe.
Even when lpfc_log_verbose = 0
root@segstorage3 ~]# cat /sys/class/scsi_host/host*/lpfc_log_verbose
0x0
0x0
0x0
0x0
Wondered if its been there for a while and its just because I now
started testing.
[ 143.398194] scsi host3: Emulex LPe12000 PCIe Fibre Channel Adapter
on PCI bus 0e device 00 irq 213
[ 145.598711] scsi host4: Emulex LPe12000 PCIe Fibre Channel Adapter
on PCI bus 0e device 01 irq 216
[ 147.877559] lpfc 0000:0b:00.0: 2:6101 Disabling NVME support: Not
supported by firmware (0 0) x3
[ 147.929264] lpfc 0000:0b:00.0: 2:2574 IO channels: hdwQ 64 IRQ 64
MRQ: 0
[ 147.974727] scsi host5: Emulex LPe16000 16Gb PCIe Fibre Channel
Adapter on PCI bus 0b device 00 irq 219 PCI resettable
[ 149.156406] lpfc 0000:0b:00.0: 2:3176 Port Name 0 Physical Link is
functional
[ 149.284537] lpfc 0000:0b:00.1: 3:6101 Disabling NVME support: Not
supported by firmware (0 0) x3
[ 149.336809] lpfc 0000:0b:00.1: 3:2574 IO channels: hdwQ 64 IRQ 64
MRQ: 0
[ 149.388033] scsi host6: Emulex LPe16000 16Gb PCIe Fibre Channel
Adapter on PCI bus 0b device 01 irq 284 PCI resettable
[ 150.848392] lpfc 0000:0b:00.1: 3:3176 Port Name 1 Physical Link is
functional
[ 151.477690] lpfc 0000:0b:00.0: 2:1303 Link Up Event x1 received
Data: x1 x0 x20 x0 x0 x0 0
[ 151.526732] lpfc 0000:0b:00.0: start 183 end 182 cnt 256
[ 151.559193] lpfc 0000:0b:00.0: 183: [ 148.759023] 2:2593 WQ setup:
wq[35]-id=35 assoc=35, cq[35]-id=35
[ 151.617510] lpfc 0000:0b:00.0: 184: [ 148.763089] 2:(0):0356
Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4 x4
x24 xb8000000 x24 x1000 CQ: x0 x0 x0 x90000000
[ 151.715751] lpfc 0000:0b:00.0: 185: [ 148.763090] 2:6087 CQ setup:
cq[36]-id=36, parent eq[36]-id=36
[ 151.772034] lpfc 0000:0b:00.0: 186: [ 148.767155] 2:(0):0356
Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0 x4 x4
x240024 x4008504 x0 xcf400000 CQ: x0 x0 x0 x90000000
[ 151.872722] lpfc 0000:0b:00.0: 187: [ 148.767156] 2:2593 WQ setup:
wq[36]-id=36 assoc=36, cq[36]-id=36
[ 151.929396] lpfc 0000:0b:00.0: 188: [ 148.771220] 2:(0):0356
Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4 x4
x25 xb8000000 x25 x1000 CQ: x0 x0 x0 x90000000
[ 152.030050] lpfc 0000:0b:00.0: 189: [ 148.771221] 2:6087 CQ setup:
cq[37]-id=37, parent eq[37]-id=37
[ 152.085622] lpfc 0000:0b:00.0: 190: [ 148.775285] 2:(0):0356
Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0 x4 x4
x250025 x4008504 x0 xbc7e0000 CQ: x0 x0 x0 x90000000
[ 152.185681] lpfc 0000:0b:00.0: 191: [ 148.775287] 2:2593 WQ setup:
wq[37]-id=37 assoc=37, cq[37]-id=37
[ 152.243645] lpfc 0000:0b:00.0: 192: [ 148.779351] 2:(0):0356
Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4 x4
x26 xb8000000 x26 x1000 CQ: x0 x0 x0 x90000000
[ 152.341442] lpfc 0000:0b:00.0: 193: [ 148.779352] 2:6087 CQ setup:
cq[38]-id=38, parent eq[38]-id=38
[ 152.399734] lpfc 0000:0b:00.0: 194: [ 148.783416] 2:(0):0356
Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0 x4 x4
x260026 x4008504 x0 x5ef40000 CQ: x0 x0 x0 x90000000
[ 152.501390] lpfc 0000:0b:00.0: 195: [ 148.783417] 2:2593 WQ setup:
wq[38]-id=38 assoc=38, cq[38]-id=38
[ 152.557531] lpfc 0000:0b:00.0: 196: [ 148.787481] 2:(0):0356
Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4 x4
x27 xb8000000 x27 x1000 CQ: x0 x0 x0 x90000000
..
..
[ 190.872503] lpfc 0000:0b:00.0: start 109 end 115 cnt 6
[ 190.872506] lpfc 0000:0b:00.0: 109: [ 190.871058] 2:(0):0117 Xmit
ELS response x1 to remote NPORT x20300 I/O tag: xb92, size: x8
port_state x20 rpi x10 fc_flag x800110
[ 190.872507] lpfc 0000:0b:00.0: 110: [ 190.871060] 2:(0):0129 Xmit
ELS RJT xb00 response tag xb92 xri xffff, did x20300, nlp_flag
x80000000, nlp_state x7, rpi x10
[ 190.872509] lpfc 0000:0b:00.0: 111: [ 190.871085] 2:(0):0110 ELS
response tag xb92 completes Data: x0 x0 x0 x20300 x80000000 x7 x10
[ 190.872511] lpfc 0000:0b:00.0: 112: [ 190.872497] 2:2538 Received
frame rctl:x22, type:x1, frame Data:220a0300 00010600 01290000 00000000
0048ffff 00000000 00000000
[ 190.872512] lpfc 0000:0b:00.0: 113: [ 190.872500] 2:(0):0929 FIND
node DID Data: xffff896e4faf2c00 x10600 x80000000 x7001801 xc
xffff896e4faf1200
[ 190.872514] lpfc 0000:0b:00.0: 114: [ 190.872501] 2:(0):0112 ELS
command x14001023 received from NPORT x10600 Data: x20 x800110 xa0300
xa0300
[ 190.872515] lpfc 0000:0b:00.0: 2:(0):0115 Unknown ELS command
x14001023 received from NPORT x10600
[ 190.873239] lpfc 0000:0b:00.0: start 115 end 121 cnt 6
[ 190.873241] lpfc 0000:0b:00.0: 115: [ 190.872517] 2:(0):0117 Xmit
ELS response x1 to remote NPORT x10600 I/O tag: xb8f, size: x8
port_state x20 rpi xc fc_flag x800110
[ 190.873243] lpfc 0000:0b:00.0: 116: [ 190.872519] 2:(0):0129 Xmit
ELS RJT xb00 response tag xb8f xri xffff, did x10600, nlp_flag
x80000000, nlp_state x7, rpi xc
[ 190.873244] lpfc 0000:0b:00.0: 117: [ 190.872545] 2:(0):0110 ELS
response tag xb8f completes Data: x0 x0 x0 x10600 x80000000 x7 xc
[ 190.873246] lpfc 0000:0b:00.0: 118: [ 190.873234] 2:2538 Received
frame rctl:x22, type:x1, frame Data:220a0300 00010700 01290000 00000000
008cffff 00000000 00000000
[ 190.873249] lpfc 0000:0b:00.0: 119: [ 190.873236] 2:(0):0929 FIND
node DID Data: xffff896e4faf0600 x10700 x80000000 x7001801 xd
xffff896e4faf3600
I have not investogated the masking changes yet, decided to first ask.
Thanks
Laurence
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: lpfc on latest 5.9 is very chatty on modprobe
2020-09-10 16:36 lpfc on latest 5.9 is very chatty on modprobe Laurence Oberman
@ 2020-09-11 15:09 ` Laurence Oberman
2020-09-11 15:55 ` Laurence Oberman
0 siblings, 1 reply; 4+ messages in thread
From: Laurence Oberman @ 2020-09-11 15:09 UTC (permalink / raw)
To: linux-scsi; +Cc: dick Kennedy, Ewan Milne
On Thu, 2020-09-10 at 12:36 -0400, Laurence Oberman wrote:
> Hello
>
> I was testing lpfc on 5.9 and noticed a lot more logging on modprobe.
> Even when lpfc_log_verbose = 0
>
> root@segstorage3 ~]# cat /sys/class/scsi_host/host*/lpfc_log_verbose
> 0x0
> 0x0
> 0x0
> 0x0
>
> Wondered if its been there for a while and its just because I now
> started testing.
>
> [ 143.398194] scsi host3: Emulex LPe12000 PCIe Fibre Channel Adapter
> on PCI bus 0e device 00 irq 213
> [ 145.598711] scsi host4: Emulex LPe12000 PCIe Fibre Channel Adapter
> on PCI bus 0e device 01 irq 216
> [ 147.877559] lpfc 0000:0b:00.0: 2:6101 Disabling NVME support: Not
> supported by firmware (0 0) x3
> [ 147.929264] lpfc 0000:0b:00.0: 2:2574 IO channels: hdwQ 64 IRQ 64
> MRQ: 0
> [ 147.974727] scsi host5: Emulex LPe16000 16Gb PCIe Fibre Channel
> Adapter on PCI bus 0b device 00 irq 219 PCI resettable
> [ 149.156406] lpfc 0000:0b:00.0: 2:3176 Port Name 0 Physical Link is
> functional
> [ 149.284537] lpfc 0000:0b:00.1: 3:6101 Disabling NVME support: Not
> supported by firmware (0 0) x3
> [ 149.336809] lpfc 0000:0b:00.1: 3:2574 IO channels: hdwQ 64 IRQ 64
> MRQ: 0
> [ 149.388033] scsi host6: Emulex LPe16000 16Gb PCIe Fibre Channel
> Adapter on PCI bus 0b device 01 irq 284 PCI resettable
> [ 150.848392] lpfc 0000:0b:00.1: 3:3176 Port Name 1 Physical Link is
> functional
> [ 151.477690] lpfc 0000:0b:00.0: 2:1303 Link Up Event x1 received
> Data: x1 x0 x20 x0 x0 x0 0
> [ 151.526732] lpfc 0000:0b:00.0: start 183 end 182 cnt 256
> [ 151.559193] lpfc 0000:0b:00.0: 183: [ 148.759023] 2:2593 WQ
> setup:
> wq[35]-id=35 assoc=35, cq[35]-id=35
> [ 151.617510] lpfc 0000:0b:00.0: 184: [ 148.763089] 2:(0):0356
> Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4 x4
> x24 xb8000000 x24 x1000 CQ: x0 x0 x0 x90000000
> [ 151.715751] lpfc 0000:0b:00.0: 185: [ 148.763090] 2:6087 CQ
> setup:
> cq[36]-id=36, parent eq[36]-id=36
> [ 151.772034] lpfc 0000:0b:00.0: 186: [ 148.767155] 2:(0):0356
> Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0 x4 x4
> x240024 x4008504 x0 xcf400000 CQ: x0 x0 x0 x90000000
> [ 151.872722] lpfc 0000:0b:00.0: 187: [ 148.767156] 2:2593 WQ
> setup:
> wq[36]-id=36 assoc=36, cq[36]-id=36
> [ 151.929396] lpfc 0000:0b:00.0: 188: [ 148.771220] 2:(0):0356
> Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4 x4
> x25 xb8000000 x25 x1000 CQ: x0 x0 x0 x90000000
> [ 152.030050] lpfc 0000:0b:00.0: 189: [ 148.771221] 2:6087 CQ
> setup:
> cq[37]-id=37, parent eq[37]-id=37
> [ 152.085622] lpfc 0000:0b:00.0: 190: [ 148.775285] 2:(0):0356
> Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0 x4 x4
> x250025 x4008504 x0 xbc7e0000 CQ: x0 x0 x0 x90000000
> [ 152.185681] lpfc 0000:0b:00.0: 191: [ 148.775287] 2:2593 WQ
> setup:
> wq[37]-id=37 assoc=37, cq[37]-id=37
> [ 152.243645] lpfc 0000:0b:00.0: 192: [ 148.779351] 2:(0):0356
> Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4 x4
> x26 xb8000000 x26 x1000 CQ: x0 x0 x0 x90000000
> [ 152.341442] lpfc 0000:0b:00.0: 193: [ 148.779352] 2:6087 CQ
> setup:
> cq[38]-id=38, parent eq[38]-id=38
> [ 152.399734] lpfc 0000:0b:00.0: 194: [ 148.783416] 2:(0):0356
> Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0 x4 x4
> x260026 x4008504 x0 x5ef40000 CQ: x0 x0 x0 x90000000
> [ 152.501390] lpfc 0000:0b:00.0: 195: [ 148.783417] 2:2593 WQ
> setup:
> wq[38]-id=38 assoc=38, cq[38]-id=38
> [ 152.557531] lpfc 0000:0b:00.0: 196: [ 148.787481] 2:(0):0356
> Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4 x4
> x27 xb8000000 x27 x1000 CQ: x0 x0 x0 x90000000
> ..
> ..
> [ 190.872503] lpfc 0000:0b:00.0: start 109 end 115 cnt 6
> [ 190.872506] lpfc 0000:0b:00.0: 109: [ 190.871058] 2:(0):0117 Xmit
> ELS response x1 to remote NPORT x20300 I/O tag: xb92, size: x8
> port_state x20 rpi x10 fc_flag x800110
> [ 190.872507] lpfc 0000:0b:00.0: 110: [ 190.871060] 2:(0):0129 Xmit
> ELS RJT xb00 response tag xb92 xri xffff, did x20300, nlp_flag
> x80000000, nlp_state x7, rpi x10
> [ 190.872509] lpfc 0000:0b:00.0: 111: [ 190.871085] 2:(0):0110 ELS
> response tag xb92 completes Data: x0 x0 x0 x20300 x80000000 x7 x10
> [ 190.872511] lpfc 0000:0b:00.0: 112: [ 190.872497] 2:2538 Received
> frame rctl:x22, type:x1, frame Data:220a0300 00010600 01290000
> 00000000
> 0048ffff 00000000 00000000
> [ 190.872512] lpfc 0000:0b:00.0: 113: [ 190.872500] 2:(0):0929 FIND
> node DID Data: xffff896e4faf2c00 x10600 x80000000 x7001801 xc
> xffff896e4faf1200
> [ 190.872514] lpfc 0000:0b:00.0: 114: [ 190.872501] 2:(0):0112 ELS
> command x14001023 received from NPORT x10600 Data: x20 x800110 xa0300
> xa0300
> [ 190.872515] lpfc 0000:0b:00.0: 2:(0):0115 Unknown ELS command
> x14001023 received from NPORT x10600
> [ 190.873239] lpfc 0000:0b:00.0: start 115 end 121 cnt 6
> [ 190.873241] lpfc 0000:0b:00.0: 115: [ 190.872517] 2:(0):0117 Xmit
> ELS response x1 to remote NPORT x10600 I/O tag: xb8f, size: x8
> port_state x20 rpi xc fc_flag x800110
> [ 190.873243] lpfc 0000:0b:00.0: 116: [ 190.872519] 2:(0):0129 Xmit
> ELS RJT xb00 response tag xb8f xri xffff, did x10600, nlp_flag
> x80000000, nlp_state x7, rpi xc
> [ 190.873244] lpfc 0000:0b:00.0: 117: [ 190.872545] 2:(0):0110 ELS
> response tag xb8f completes Data: x0 x0 x0 x10600 x80000000 x7 xc
> [ 190.873246] lpfc 0000:0b:00.0: 118: [ 190.873234] 2:2538 Received
> frame rctl:x22, type:x1, frame Data:220a0300 00010700 01290000
> 00000000
> 008cffff 00000000 00000000
> [ 190.873249] lpfc 0000:0b:00.0: 119: [ 190.873236] 2:(0):0929 FIND
> node DID Data: xffff896e4faf0600 x10700 x80000000 x7001801 xd
> xffff896e4faf3600
>
> I have not investogated the masking changes yet, decided to first
> ask.
>
> Thanks
> Laurence
Hi Dick I dont see this when booting 5.5, which was when I last tested,
and before I start the long arduous code review and maybe bisect I
would rather have you look at it.
Can you look at this please and let me know.
Its not happeniong on latest RHEL8 but could happen if we take latest
code in.
Regards
Laurence
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: lpfc on latest 5.9 is very chatty on modprobe
2020-09-11 15:09 ` Laurence Oberman
@ 2020-09-11 15:55 ` Laurence Oberman
[not found] ` <CAGx+d6dhGuJdUfisgvVfaTJ5aT7D9hP+WQcaD485iF=tuKqv7w@mail.gmail.com>
0 siblings, 1 reply; 4+ messages in thread
From: Laurence Oberman @ 2020-09-11 15:55 UTC (permalink / raw)
To: linux-scsi; +Cc: dick Kennedy, Ewan Milne
On Fri, 2020-09-11 at 11:09 -0400, Laurence Oberman wrote:
> On Thu, 2020-09-10 at 12:36 -0400, Laurence Oberman wrote:
> > Hello
> >
> > I was testing lpfc on 5.9 and noticed a lot more logging on
> > modprobe.
> > Even when lpfc_log_verbose = 0
> >
> > root@segstorage3 ~]# cat
> > /sys/class/scsi_host/host*/lpfc_log_verbose
> > 0x0
> > 0x0
> > 0x0
> > 0x0
> >
> > Wondered if its been there for a while and its just because I now
> > started testing.
> >
> > [ 143.398194] scsi host3: Emulex LPe12000 PCIe Fibre Channel
> > Adapter
> > on PCI bus 0e device 00 irq 213
> > [ 145.598711] scsi host4: Emulex LPe12000 PCIe Fibre Channel
> > Adapter
> > on PCI bus 0e device 01 irq 216
> > [ 147.877559] lpfc 0000:0b:00.0: 2:6101 Disabling NVME support:
> > Not
> > supported by firmware (0 0) x3
> > [ 147.929264] lpfc 0000:0b:00.0: 2:2574 IO channels: hdwQ 64 IRQ
> > 64
> > MRQ: 0
> > [ 147.974727] scsi host5: Emulex LPe16000 16Gb PCIe Fibre Channel
> > Adapter on PCI bus 0b device 00 irq 219 PCI resettable
> > [ 149.156406] lpfc 0000:0b:00.0: 2:3176 Port Name 0 Physical Link
> > is
> > functional
> > [ 149.284537] lpfc 0000:0b:00.1: 3:6101 Disabling NVME support:
> > Not
> > supported by firmware (0 0) x3
> > [ 149.336809] lpfc 0000:0b:00.1: 3:2574 IO channels: hdwQ 64 IRQ
> > 64
> > MRQ: 0
> > [ 149.388033] scsi host6: Emulex LPe16000 16Gb PCIe Fibre Channel
> > Adapter on PCI bus 0b device 01 irq 284 PCI resettable
> > [ 150.848392] lpfc 0000:0b:00.1: 3:3176 Port Name 1 Physical Link
> > is
> > functional
> > [ 151.477690] lpfc 0000:0b:00.0: 2:1303 Link Up Event x1 received
> > Data: x1 x0 x20 x0 x0 x0 0
> > [ 151.526732] lpfc 0000:0b:00.0: start 183 end 182 cnt 256
> > [ 151.559193] lpfc 0000:0b:00.0: 183: [ 148.759023] 2:2593 WQ
> > setup:
> > wq[35]-id=35 assoc=35, cq[35]-id=35
> > [ 151.617510] lpfc 0000:0b:00.0: 184: [ 148.763089] 2:(0):0356
> > Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4
> > x4
> > x24 xb8000000 x24 x1000 CQ: x0 x0 x0 x90000000
> > [ 151.715751] lpfc 0000:0b:00.0: 185: [ 148.763090] 2:6087 CQ
> > setup:
> > cq[36]-id=36, parent eq[36]-id=36
> > [ 151.772034] lpfc 0000:0b:00.0: 186: [ 148.767155] 2:(0):0356
> > Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0 x4
> > x4
> > x240024 x4008504 x0 xcf400000 CQ: x0 x0 x0 x90000000
> > [ 151.872722] lpfc 0000:0b:00.0: 187: [ 148.767156] 2:2593 WQ
> > setup:
> > wq[36]-id=36 assoc=36, cq[36]-id=36
> > [ 151.929396] lpfc 0000:0b:00.0: 188: [ 148.771220] 2:(0):0356
> > Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4
> > x4
> > x25 xb8000000 x25 x1000 CQ: x0 x0 x0 x90000000
> > [ 152.030050] lpfc 0000:0b:00.0: 189: [ 148.771221] 2:6087 CQ
> > setup:
> > cq[37]-id=37, parent eq[37]-id=37
> > [ 152.085622] lpfc 0000:0b:00.0: 190: [ 148.775285] 2:(0):0356
> > Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0 x4
> > x4
> > x250025 x4008504 x0 xbc7e0000 CQ: x0 x0 x0 x90000000
> > [ 152.185681] lpfc 0000:0b:00.0: 191: [ 148.775287] 2:2593 WQ
> > setup:
> > wq[37]-id=37 assoc=37, cq[37]-id=37
> > [ 152.243645] lpfc 0000:0b:00.0: 192: [ 148.779351] 2:(0):0356
> > Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4
> > x4
> > x26 xb8000000 x26 x1000 CQ: x0 x0 x0 x90000000
> > [ 152.341442] lpfc 0000:0b:00.0: 193: [ 148.779352] 2:6087 CQ
> > setup:
> > cq[38]-id=38, parent eq[38]-id=38
> > [ 152.399734] lpfc 0000:0b:00.0: 194: [ 148.783416] 2:(0):0356
> > Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0 x4
> > x4
> > x260026 x4008504 x0 x5ef40000 CQ: x0 x0 x0 x90000000
> > [ 152.501390] lpfc 0000:0b:00.0: 195: [ 148.783417] 2:2593 WQ
> > setup:
> > wq[38]-id=38 assoc=38, cq[38]-id=38
> > [ 152.557531] lpfc 0000:0b:00.0: 196: [ 148.787481] 2:(0):0356
> > Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0 x4
> > x4
> > x27 xb8000000 x27 x1000 CQ: x0 x0 x0 x90000000
> > ..
> > ..
> > [ 190.872503] lpfc 0000:0b:00.0: start 109 end 115 cnt 6
> > [ 190.872506] lpfc 0000:0b:00.0: 109: [ 190.871058] 2:(0):0117
> > Xmit
> > ELS response x1 to remote NPORT x20300 I/O tag: xb92, size: x8
> > port_state x20 rpi x10 fc_flag x800110
> > [ 190.872507] lpfc 0000:0b:00.0: 110: [ 190.871060] 2:(0):0129
> > Xmit
> > ELS RJT xb00 response tag xb92 xri xffff, did x20300, nlp_flag
> > x80000000, nlp_state x7, rpi x10
> > [ 190.872509] lpfc 0000:0b:00.0: 111: [ 190.871085] 2:(0):0110
> > ELS
> > response tag xb92 completes Data: x0 x0 x0 x20300 x80000000 x7 x10
> > [ 190.872511] lpfc 0000:0b:00.0: 112: [ 190.872497] 2:2538
> > Received
> > frame rctl:x22, type:x1, frame Data:220a0300 00010600 01290000
> > 00000000
> > 0048ffff 00000000 00000000
> > [ 190.872512] lpfc 0000:0b:00.0: 113: [ 190.872500] 2:(0):0929
> > FIND
> > node DID Data: xffff896e4faf2c00 x10600 x80000000 x7001801 xc
> > xffff896e4faf1200
> > [ 190.872514] lpfc 0000:0b:00.0: 114: [ 190.872501] 2:(0):0112
> > ELS
> > command x14001023 received from NPORT x10600 Data: x20 x800110
> > xa0300
> > xa0300
> > [ 190.872515] lpfc 0000:0b:00.0: 2:(0):0115 Unknown ELS command
> > x14001023 received from NPORT x10600
> > [ 190.873239] lpfc 0000:0b:00.0: start 115 end 121 cnt 6
> > [ 190.873241] lpfc 0000:0b:00.0: 115: [ 190.872517] 2:(0):0117
> > Xmit
> > ELS response x1 to remote NPORT x10600 I/O tag: xb8f, size: x8
> > port_state x20 rpi xc fc_flag x800110
> > [ 190.873243] lpfc 0000:0b:00.0: 116: [ 190.872519] 2:(0):0129
> > Xmit
> > ELS RJT xb00 response tag xb8f xri xffff, did x10600, nlp_flag
> > x80000000, nlp_state x7, rpi xc
> > [ 190.873244] lpfc 0000:0b:00.0: 117: [ 190.872545] 2:(0):0110
> > ELS
> > response tag xb8f completes Data: x0 x0 x0 x10600 x80000000 x7 xc
> > [ 190.873246] lpfc 0000:0b:00.0: 118: [ 190.873234] 2:2538
> > Received
> > frame rctl:x22, type:x1, frame Data:220a0300 00010700 01290000
> > 00000000
> > 008cffff 00000000 00000000
> > [ 190.873249] lpfc 0000:0b:00.0: 119: [ 190.873236] 2:(0):0929
> > FIND
> > node DID Data: xffff896e4faf0600 x10700 x80000000 x7001801 xd
> > xffff896e4faf3600
> >
> > I have not investogated the masking changes yet, decided to first
> > ask.
> >
> > Thanks
> > Laurence
>
> Hi Dick I dont see this when booting 5.5, which was when I last
> tested,
> and before I start the long arduous code review and maybe bisect I
> would rather have you look at it.
> Can you look at this please and let me know.
> Its not happeniong on latest RHEL8 but could happen if we take latest
> code in.
>
> Regards
> Laurence
>
Dick
Seems to be all these changes like below. all chamhed to
LOG_TRACE_EVENT
- lpfc_printf_vlog(vport, KERN_ERR, LOG_INIT |
LOG_VPORT,
+ lpfc_printf_vlog(vport, KERN_ERR,
LOG_TRACE_EVENT,
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: lpfc on latest 5.9 is very chatty on modprobe
[not found] ` <CAGx+d6dhGuJdUfisgvVfaTJ5aT7D9hP+WQcaD485iF=tuKqv7w@mail.gmail.com>
@ 2020-09-11 19:18 ` Laurence Oberman
0 siblings, 0 replies; 4+ messages in thread
From: Laurence Oberman @ 2020-09-11 19:18 UTC (permalink / raw)
To: Dick Kennedy; +Cc: linux-scsi, Ewan Milne
On Fri, 2020-09-11 at 13:57 -0400, Dick Kennedy wrote:
> Yes we have been removing some of those trace events to eliminate the
> false logs.
>
> All of the successful scsi task management commands will generate
> false logs. We have a patch for that coming.
> All of the successful vport deletes will also generate the false
> logs.
>
> But other than that I can say that having it in there has made my
> life a little easier.
>
>
> On Fri, Sep 11, 2020 at 11:55 AM Laurence Oberman <
> loberman@redhat.com> wrote:
> > On Fri, 2020-09-11 at 11:09 -0400, Laurence Oberman wrote:
> > > On Thu, 2020-09-10 at 12:36 -0400, Laurence Oberman wrote:
> > > > Hello
> > > >
> > > > I was testing lpfc on 5.9 and noticed a lot more logging on
> > > > modprobe.
> > > > Even when lpfc_log_verbose = 0
> > > >
> > > > root@segstorage3 ~]# cat
> > > > /sys/class/scsi_host/host*/lpfc_log_verbose
> > > > 0x0
> > > > 0x0
> > > > 0x0
> > > > 0x0
> > > >
> > > > Wondered if its been there for a while and its just because I
> > now
> > > > started testing.
> > > >
> > > > [ 143.398194] scsi host3: Emulex LPe12000 PCIe Fibre Channel
> > > > Adapter
> > > > on PCI bus 0e device 00 irq 213
> > > > [ 145.598711] scsi host4: Emulex LPe12000 PCIe Fibre Channel
> > > > Adapter
> > > > on PCI bus 0e device 01 irq 216
> > > > [ 147.877559] lpfc 0000:0b:00.0: 2:6101 Disabling NVME
> > support:
> > > > Not
> > > > supported by firmware (0 0) x3
> > > > [ 147.929264] lpfc 0000:0b:00.0: 2:2574 IO channels: hdwQ 64
> > IRQ
> > > > 64
> > > > MRQ: 0
> > > > [ 147.974727] scsi host5: Emulex LPe16000 16Gb PCIe Fibre
> > Channel
> > > > Adapter on PCI bus 0b device 00 irq 219 PCI resettable
> > > > [ 149.156406] lpfc 0000:0b:00.0: 2:3176 Port Name 0 Physical
> > Link
> > > > is
> > > > functional
> > > > [ 149.284537] lpfc 0000:0b:00.1: 3:6101 Disabling NVME
> > support:
> > > > Not
> > > > supported by firmware (0 0) x3
> > > > [ 149.336809] lpfc 0000:0b:00.1: 3:2574 IO channels: hdwQ 64
> > IRQ
> > > > 64
> > > > MRQ: 0
> > > > [ 149.388033] scsi host6: Emulex LPe16000 16Gb PCIe Fibre
> > Channel
> > > > Adapter on PCI bus 0b device 01 irq 284 PCI resettable
> > > > [ 150.848392] lpfc 0000:0b:00.1: 3:3176 Port Name 1 Physical
> > Link
> > > > is
> > > > functional
> > > > [ 151.477690] lpfc 0000:0b:00.0: 2:1303 Link Up Event x1
> > received
> > > > Data: x1 x0 x20 x0 x0 x0 0
> > > > [ 151.526732] lpfc 0000:0b:00.0: start 183 end 182 cnt 256
> > > > [ 151.559193] lpfc 0000:0b:00.0: 183: [ 148.759023] 2:2593 WQ
> > > > setup:
> > > > wq[35]-id=35 assoc=35, cq[35]-id=35
> > > > [ 151.617510] lpfc 0000:0b:00.0: 184: [ 148.763089]
> > 2:(0):0356
> > > > Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0
> > x4
> > > > x4
> > > > x24 xb8000000 x24 x1000 CQ: x0 x0 x0 x90000000
> > > > [ 151.715751] lpfc 0000:0b:00.0: 185: [ 148.763090] 2:6087 CQ
> > > > setup:
> > > > cq[36]-id=36, parent eq[36]-id=36
> > > > [ 151.772034] lpfc 0000:0b:00.0: 186: [ 148.767155]
> > 2:(0):0356
> > > > Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0
> > x4
> > > > x4
> > > > x240024 x4008504 x0 xcf400000 CQ: x0 x0 x0 x90000000
> > > > [ 151.872722] lpfc 0000:0b:00.0: 187: [ 148.767156] 2:2593 WQ
> > > > setup:
> > > > wq[36]-id=36 assoc=36, cq[36]-id=36
> > > > [ 151.929396] lpfc 0000:0b:00.0: 188: [ 148.771220]
> > 2:(0):0356
> > > > Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0
> > x4
> > > > x4
> > > > x25 xb8000000 x25 x1000 CQ: x0 x0 x0 x90000000
> > > > [ 152.030050] lpfc 0000:0b:00.0: 189: [ 148.771221] 2:6087 CQ
> > > > setup:
> > > > cq[37]-id=37, parent eq[37]-id=37
> > > > [ 152.085622] lpfc 0000:0b:00.0: 190: [ 148.775285]
> > 2:(0):0356
> > > > Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0
> > x4
> > > > x4
> > > > x250025 x4008504 x0 xbc7e0000 CQ: x0 x0 x0 x90000000
> > > > [ 152.185681] lpfc 0000:0b:00.0: 191: [ 148.775287] 2:2593 WQ
> > > > setup:
> > > > wq[37]-id=37 assoc=37, cq[37]-id=37
> > > > [ 152.243645] lpfc 0000:0b:00.0: 192: [ 148.779351]
> > 2:(0):0356
> > > > Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0
> > x4
> > > > x4
> > > > x26 xb8000000 x26 x1000 CQ: x0 x0 x0 x90000000
> > > > [ 152.341442] lpfc 0000:0b:00.0: 193: [ 148.779352] 2:6087 CQ
> > > > setup:
> > > > cq[38]-id=38, parent eq[38]-id=38
> > > > [ 152.399734] lpfc 0000:0b:00.0: 194: [ 148.783416]
> > 2:(0):0356
> > > > Mailbox cmd x9b (xc/x1) Status x0 Data: x1 x54 x0 x0 x0 xc01 x0
> > x4
> > > > x4
> > > > x260026 x4008504 x0 x5ef40000 CQ: x0 x0 x0 x90000000
> > > > [ 152.501390] lpfc 0000:0b:00.0: 195: [ 148.783417] 2:2593 WQ
> > > > setup:
> > > > wq[38]-id=38 assoc=38, cq[38]-id=38
> > > > [ 152.557531] lpfc 0000:0b:00.0: 196: [ 148.787481]
> > 2:(0):0356
> > > > Mailbox cmd x9b (x1/xc) Status x0 Data: x1 x44 x0 x0 x0 x10c x0
> > x4
> > > > x4
> > > > x27 xb8000000 x27 x1000 CQ: x0 x0 x0 x90000000
> > > > ..
> > > > ..
> > > > [ 190.872503] lpfc 0000:0b:00.0: start 109 end 115 cnt 6
> > > > [ 190.872506] lpfc 0000:0b:00.0: 109: [ 190.871058]
> > 2:(0):0117
> > > > Xmit
> > > > ELS response x1 to remote NPORT x20300 I/O tag: xb92, size: x8
> > > > port_state x20 rpi x10 fc_flag x800110
> > > > [ 190.872507] lpfc 0000:0b:00.0: 110: [ 190.871060]
> > 2:(0):0129
> > > > Xmit
> > > > ELS RJT xb00 response tag xb92 xri xffff, did x20300, nlp_flag
> > > > x80000000, nlp_state x7, rpi x10
> > > > [ 190.872509] lpfc 0000:0b:00.0: 111: [ 190.871085]
> > 2:(0):0110
> > > > ELS
> > > > response tag xb92 completes Data: x0 x0 x0 x20300 x80000000 x7
> > x10
> > > > [ 190.872511] lpfc 0000:0b:00.0: 112: [ 190.872497] 2:2538
> > > > Received
> > > > frame rctl:x22, type:x1, frame Data:220a0300 00010600 01290000
> > > > 00000000
> > > > 0048ffff 00000000 00000000
> > > > [ 190.872512] lpfc 0000:0b:00.0: 113: [ 190.872500]
> > 2:(0):0929
> > > > FIND
> > > > node DID Data: xffff896e4faf2c00 x10600 x80000000 x7001801 xc
> > > > xffff896e4faf1200
> > > > [ 190.872514] lpfc 0000:0b:00.0: 114: [ 190.872501]
> > 2:(0):0112
> > > > ELS
> > > > command x14001023 received from NPORT x10600 Data: x20 x800110
> > > > xa0300
> > > > xa0300
> > > > [ 190.872515] lpfc 0000:0b:00.0: 2:(0):0115 Unknown ELS
> > command
> > > > x14001023 received from NPORT x10600
> > > > [ 190.873239] lpfc 0000:0b:00.0: start 115 end 121 cnt 6
> > > > [ 190.873241] lpfc 0000:0b:00.0: 115: [ 190.872517]
> > 2:(0):0117
> > > > Xmit
> > > > ELS response x1 to remote NPORT x10600 I/O tag: xb8f, size: x8
> > > > port_state x20 rpi xc fc_flag x800110
> > > > [ 190.873243] lpfc 0000:0b:00.0: 116: [ 190.872519]
> > 2:(0):0129
> > > > Xmit
> > > > ELS RJT xb00 response tag xb8f xri xffff, did x10600, nlp_flag
> > > > x80000000, nlp_state x7, rpi xc
> > > > [ 190.873244] lpfc 0000:0b:00.0: 117: [ 190.872545]
> > 2:(0):0110
> > > > ELS
> > > > response tag xb8f completes Data: x0 x0 x0 x10600 x80000000 x7
> > xc
> > > > [ 190.873246] lpfc 0000:0b:00.0: 118: [ 190.873234] 2:2538
> > > > Received
> > > > frame rctl:x22, type:x1, frame Data:220a0300 00010700 01290000
> > > > 00000000
> > > > 008cffff 00000000 00000000
> > > > [ 190.873249] lpfc 0000:0b:00.0: 119: [ 190.873236]
> > 2:(0):0929
> > > > FIND
> > > > node DID Data: xffff896e4faf0600 x10700 x80000000 x7001801 xd
> > > > xffff896e4faf3600
> > > >
> > > > I have not investogated the masking changes yet, decided to
> > first
> > > > ask.
> > > >
> > > > Thanks
> > > > Laurence
> > >
> > > Hi Dick I dont see this when booting 5.5, which was when I last
> > > tested,
> > > and before I start the long arduous code review and maybe bisect
> > I
> > > would rather have you look at it.
> > > Can you look at this please and let me know.
> > > Its not happeniong on latest RHEL8 but could happen if we take
> > latest
> > > code in.
> > >
> > > Regards
> > > Laurence
> > >
> >
> > Dick
> > Seems to be all these changes like below. all chamhed to
> > LOG_TRACE_EVENT
> >
> > - lpfc_printf_vlog(vport, KERN_ERR, LOG_INIT
> > |
> > LOG_VPORT,
> > + lpfc_printf_vlog(vport, KERN_ERR,
> > LOG_TRACE_EVENT,
> >
OK, Perfect, Thanks Dick
Regards
Laurence
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2020-09-11 19:18 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-09-10 16:36 lpfc on latest 5.9 is very chatty on modprobe Laurence Oberman
2020-09-11 15:09 ` Laurence Oberman
2020-09-11 15:55 ` Laurence Oberman
[not found] ` <CAGx+d6dhGuJdUfisgvVfaTJ5aT7D9hP+WQcaD485iF=tuKqv7w@mail.gmail.com>
2020-09-11 19:18 ` Laurence Oberman
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).