Re: [PATCH 22/71] ncr5380: Eliminate selecting state

[Ondrej Zary <linux@rainbow-software.org>]

On Thursday 26 November 2015 11:23:01 Finn Thain wrote:
> 
> On Wed, 25 Nov 2015, Ondrej Zary wrote:
> 
> > On Wednesday 25 November 2015 04:17:09 Finn Thain wrote:
> > > 
> > > On Tue, 24 Nov 2015, Ondrej Zary wrote:
> > > 
> > > > 
> > > > Bisecting slow module initialization pointed to this commit.
> > > > 
> > > > Before this commit (2 seconds):
> > > > [   60.317374] scsi host2: Generic NCR5380/NCR53C400 SCSI, io_port 0x0, n_io_port 0, base 0xd8000, irq 0, can_queue 16, cmd_per_lun 2, sg_tablesize 128, this_id 7, flags { NCR53C400 }, USLEEP_POLL 3, USLEEP_SLEEP 50, options { AUTOPROBE_IRQ PSEUDO_DMA }
> > > > [   60.780715] scsi 2:0:1:0: Direct-Access     QUANTUM  LP240S GM240S01X 4.6  PQ: 0 ANSI: 2 CCS
> > > > [   62.606260] sd 2:0:1:0: Attached scsi generic sg1 type 0
> > > > 
> > > > 
> > > > After this commit (22 seconds):
> > > > [  137.511711] scsi host2: Generic NCR5380/NCR53C400 SCSI, io_port 0x0, n_io_port 0, base 0xd8000, irq 0, can_queue 16, cmd_per_lun 2, sg_tablesize 128, this_id 7, flags { NCR53C400 }, USLEEP_POLL 3, USLEEP_SLEEP 50, options { AUTOPROBE_IRQ PSEUDO_DMA }
> > > > [  145.028532] clocksource: timekeeping watchdog: Marking clocksource 'tsc' as unstable because the skew is too large:
> > > > [  145.029767] clocksource:                       'acpi_pm' wd_now: a49738 wd_last: f4da04 mask: ffffff
> > > > [  145.029828] clocksource:                       'tsc' cs_now: 2ea624698e cs_last: 2c710aa17f mask: ffffffffffffffff
> > > > [  145.032733] clocksource: Switched to clocksource acpi_pm
> > > > [  145.236951] scsi 2:0:1:0: Direct-Access     QUANTUM  LP240S GM240S01X 4.6  PQ: 0 ANSI: 2 CCS
> > > > [  159.959308] sd 2:0:1:0: Attached scsi generic sg1 type 0
> > > > 
> > > > 
> > > 
> > > This problem doesn't show up on my hardware, and I'd like to know where 
> > > those 22 seconds are being spent. Would you please apply the entire series 
> > > and add,
> > > #define NDEBUG (NDEBUG_ARBITRATION | NDEBUG_SELECTION | NDEBUG_MAIN)
> > > to the top of g_NCR5380.c and send me the messages logged during modprobe?
> > 
> > [  397.014581] scsi host2: Generic NCR5380/NCR53C400 SCSI, io_port 0x0, n_io_port 0, base 0xd8000, irq 0, can_queue 16, cmd_per_lun 2, sg_tablesize 128, this_id 7, flags { NO_DMA_FIXUP }, options { AUTOPROBE_IRQ PSEUDO_DMA }
> > [  412.099695] STATUS_REG: 00
> > BASR: 08
> > ICR: 00
> > MODE: 00
> > [  412.103625] STATUS_REG: 00
> > BASR: 08
> > ICR: 00
> > MODE: 00
> > [  412.110503] scsi 2:0:1:0: Direct-Access     QUANTUM  LP240S GM240S01X 4.6  PQ: 0 ANSI: 2 CCS
> > [  412.110892] STATUS_REG: 00
> > BASR: 08
> > ICR: 00
> > MODE: 00
> > [  412.114154] STATUS_REG: 00
> > BASR: 08
> > ICR: 00
> > MODE: 00
> > [  412.119733] STATUS_REG: 00
> > BASR: 08
> > ICR: 00
> > MODE: 00
> > [  427.198108] STATUS_REG: 00
> > BASR: 08
> > ICR: 00
> > MODE: 00
> > [  442.276586] STATUS_REG: 00
> > BASR: 08
> > ICR: 00
> > MODE: 00
> > [  457.354592] STATUS_REG: 00
> > BASR: 08
> > ICR: 00
> > MODE: 00
> > [  472.432999] STATUS_REG: 00
> > BASR: 08
> > ICR: 00
> > MODE: 00
> > [  487.513027] sd 2:0:1:0: Attached scsi generic sg1 type 0
> > 
> > 
> 
> I see that the delay increased from 22 seconds to 90 seconds. Perhaps that 
> is because the remaining patches were applied.

The remaining patches were not applied. The delay varies, probably depending
on the state of the external drive.

> Anyway, it seems to confirm that this delay comes from scanning the six 
> unused SCSI bus IDs. Each one takes 15 seconds. Could be a five second 
> timeout and three retries. It's hard to tell because the dsprintk() 
> logging didn't show up. Can you try modprobe after,
> # echo 1 > /sys/module/printk/parameters/ignore_loglevel
> And maybe also,
> # scsi_logging_level -sS7

[  156.014234] scsi host2: Generic NCR5380/NCR53C400 SCSI, io_port 0x0, n_io_port 0, base 0xd8000, irq 0, can_queue 16, cmd_per_lun 2, sg_tablesize 128, this_id 7, flags { NO_DMA_FIXUP }, options { AUTOPROBE_IRQ PSEUDO_DMA }
[  156.020369] scsi host2: scsi_scan_host_selected: <4294967295:4294967295:18446744073709551615>
[  156.020777] scsi 2:0:0:0: scsi scan: INQUIRY pass 1 length 36
[  156.022046] scsi host2: main: dequeued de045600
[  156.022109] STATUS_REG: 00
BASR: 00
ICR: 00
MODE: 00
[  156.022451] scsi host2: starting arbitration, id = 7
[  156.022740] scsi host2: won arbitration
[  156.022806] scsi host2: selecting target 0
[  171.097450] scsi host2: target did not respond within 250ms
[  171.097508] scsi host2: main: select complete
[  171.099554] scsi 2:0:0:0: scsi scan: INQUIRY failed with code 0x40000
[  171.103200] scsi 2:0:1:0: scsi scan: INQUIRY pass 1 length 36
[  171.105246] scsi host2: main: dequeued df6b9f00
[  171.105350] STATUS_REG: 00
BASR: 08
ICR: 00
MODE: 00
[  171.105664] scsi host2: starting arbitration, id = 7
[  171.105752] scsi host2: won arbitration
[  171.105822] scsi host2: selecting target 1
[  171.105977] scsi host2: target 1 selected, going into MESSAGE OUT phase.
[  171.106042] scsi host2: nexus established.
[  171.106093] scsi host2: main: select complete
[  171.106145] scsi host2: main: performing information transfer
[  171.108531] scsi 2:0:1:0: scsi scan: INQUIRY successful with code 0x0
[  171.108639] scsi 2:0:1:0: scsi scan: INQUIRY pass 2 length 130
[  171.109401] scsi host2: main: dequeued df6b9f00
[  171.109485] STATUS_REG: 00
BASR: 08
ICR: 00
MODE: 00
[  171.109779] scsi host2: starting arbitration, id = 7
[  171.109878] scsi host2: won arbitration
[  171.109954] scsi host2: selecting target 1
[  171.110112] scsi host2: target 1 selected, going into MESSAGE OUT phase.
[  171.110181] scsi host2: nexus established.
[  171.110236] scsi host2: main: select complete
[  171.110286] scsi host2: main: performing information transfer
[  171.114811] scsi 2:0:1:0: scsi scan: INQUIRY successful with code 0x0
[  171.114928] scsi 2:0:1:0: Direct-Access     QUANTUM  LP240S GM240S01X 4.6  PQ: 0 ANSI: 2 CCS
[  171.115011] scsi target2:0:1: scsi scan: Sequential scan
[  171.115856] scsi 2:0:1:1: scsi scan: INQUIRY pass 1 length 36
[  171.116008] scsi host2: main: dequeued df6b9800
[  171.116039] STATUS_REG: 00
BASR: 08
ICR: 00
MODE: 00
[  171.116736] scsi host2: starting arbitration, id = 7
[  171.116843] scsi host2: won arbitration
[  171.116898] scsi host2: selecting target 1
[  171.117117] scsi host2: target 1 selected, going into MESSAGE OUT phase.
[  171.117182] scsi host2: nexus established.
[  171.117234] scsi host2: main: select complete
[  171.117287] scsi host2: main: performing information transfer
[  171.119674] scsi 2:0:1:1: scsi scan: INQUIRY successful with code 0x0
[  171.119781] scsi 2:0:1:1: scsi scan: INQUIRY pass 2 length 130
[  171.119898] scsi host2: main: dequeued df6b9800
[  171.119962] STATUS_REG: 00
BASR: 08
ICR: 00
MODE: 00
[  171.121426] scsi host2: starting arbitration, id = 7
[  171.121537] scsi host2: won arbitration
[  171.121592] scsi host2: selecting target 1
[  171.121766] scsi host2: target 1 selected, going into MESSAGE OUT phase.
[  171.121834] scsi host2: nexus established.
[  171.121889] scsi host2: main: select complete
[  171.121940] scsi host2: main: performing information transfer
[  171.126361] scsi 2:0:1:1: scsi scan: INQUIRY successful with code 0x0
[  171.126470] scsi 2:0:1:1: scsi scan: peripheral qualifier of 3, device not added
[  171.127735] scsi 2:0:2:0: scsi scan: INQUIRY pass 1 length 36
[  171.127920] scsi host2: main: dequeued df6b9800
[  171.127982] STATUS_REG: 00
BASR: 08
ICR: 00
MODE: 00
[  171.128648] scsi host2: starting arbitration, id = 7
[  171.128754] scsi host2: won arbitration
[  171.128811] scsi host2: selecting target 2
[  186.203734] scsi host2: target did not respond within 250ms
[  186.203794] scsi host2: main: select complete
[  186.205355] scsi 2:0:2:0: scsi scan: INQUIRY failed with code 0x40000
[  186.208989] scsi 2:0:3:0: scsi scan: INQUIRY pass 1 length 36
[  186.209178] scsi host2: main: dequeued df6b9f00
[  186.209242] STATUS_REG: 00
BASR: 08
ICR: 00
MODE: 00
[  186.209570] scsi host2: starting arbitration, id = 7
[  186.209660] scsi host2: won arbitration
[  186.209731] scsi host2: selecting target 3
[  201.284666] scsi host2: target did not respond within 250ms
[  201.284726] scsi host2: main: select complete
[  201.286193] scsi 2:0:3:0: scsi scan: INQUIRY failed with code 0x40000
[  201.287455] scsi 2:0:4:0: scsi scan: INQUIRY pass 1 length 36
[  201.287609] scsi host2: main: dequeued df6b9900
[  201.287673] STATUS_REG: 00
BASR: 08
ICR: 00
MODE: 00
[  201.287973] scsi host2: starting arbitration, id = 7
[  201.288766] scsi host2: won arbitration
[  201.288855] scsi host2: selecting target 4
[  216.363793] scsi host2: target did not respond within 250ms
[  216.363853] scsi host2: main: select complete
[  216.363947] scsi 2:0:4:0: scsi scan: INQUIRY failed with code 0x40000
[  216.366469] scsi 2:0:5:0: scsi scan: INQUIRY pass 1 length 36
[  216.366633] scsi host2: main: dequeued df6b9f00
[  216.366696] STATUS_REG: 00
BASR: 08
ICR: 00
MODE: 00
[  216.366997] scsi host2: starting arbitration, id = 7
[  216.367153] scsi host2: won arbitration
[  216.367208] scsi host2: selecting target 5
[  231.442079] scsi host2: target did not respond within 250ms
[  231.442136] scsi host2: main: select complete
[  231.442214] scsi 2:0:5:0: scsi scan: INQUIRY failed with code 0x40000
[  231.445050] scsi 2:0:6:0: scsi scan: INQUIRY pass 1 length 36
[  231.445329] scsi host2: main: dequeued df6b9c00
[  231.445392] STATUS_REG: 00
BASR: 08
ICR: 00
MODE: 00
[  231.445682] scsi host2: starting arbitration, id = 7
[  231.445784] scsi host2: won arbitration
[  231.445855] scsi host2: selecting target 6
[  246.521110] scsi host2: target did not respond within 250ms
[  246.521171] scsi host2: main: select complete
[  246.521253] scsi 2:0:6:0: scsi scan: INQUIRY failed with code 0x40000
[  246.525098] sd 2:0:1:0: Attached scsi generic sg1 type 0


> It seems like the 53C400 chip doesn't arbitrate like a 53C80, but that 
> doesn't make sense given it contains a 53C80 logic block. Perhaps some 
> extra initialization is needed. Which card(s) are affected?

All of them: HP C2502 (53C400A), Canon FG2-5202 (53C400) and DTCT-436P.
 
> Aside from trying to figure out why the chip behaves oddly, we could also 
> try to figure out whether the driver and its main loop is causing problems 
> for other tasks i.e. timekeeping watchdog. Does this patch make any 
> difference?

The timekeeping warning does not appear when all 71 patches are applied.
Reverse-bisected it - the warning disappears after:
[PATCH 50/71] ncr5380: Change instance->host_lock to hostdata->lock

-- 
Ondrej Zary