Re: lpfc on latest 5.9 is very chatty on modprobe

[Laurence Oberman <loberman@redhat.com>]

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,