Date: Sat, 05 Mar 2016 13:50:08 -0800 From: John Baldwin <jhb@freebsd.org> To: Harry Schmalzbauer <freebsd@omnilan.de> Cc: FreeBSD Stable <freebsd-stable@freebsd.org>, Mark Saad <nonesuch@longcount.org> Subject: Re: ahci-timeout regression in beta3 Message-ID: <6707098.Q23tZsJLSN@ralph.baldwin.cx> In-Reply-To: <56DACCE1.80606@omnilan.de> References: <56D350B6.6090906@omnilan.de> <10965531.zQdbXDLmAc@ralph.baldwin.cx> <56DACCE1.80606@omnilan.de>
next in thread | previous in thread | raw e-mail | index | archive | help
On Saturday, March 05, 2016 01:11:13 PM Harry Schmalzbauer wrote: > Bez=C3=BCglich John Baldwin's Nachricht vom 02.03.2016 18:32 (localti= me): > > On Monday, February 29, 2016 07:29:03 PM Harry Schmalzbauer wrote: > >> Bez=C3=BCglich Harry Schmalzbauer's Nachricht vom 28.02.2016 20:5= 5 (localtime): > >>> Hello, > >>> > >>> I have a remote machine with a probably defective ODD, but until = r294989 > >>> (from Jan 28th) I could boot with just these warnings: > >>> (cd1:ahcich1:0:0:0): READ(10). CDB: 28 00 00 38 85 e0 00 00 01 00= > >>> (cd1:ahcich1:0:0:0): CAM status: SCSI Status Error > >>> (cd1:ahcich1:0:0:0): SCSI status: Check Condition > >>> (cd1:ahcich1:0:0:0): SCSI sense: MEDIUM ERROR asc:11,0 (Unrecover= ed read > >>> error) > >>> (cd1:ahcich1:0:0:0): Error 5, Unretryable error > >>> (cd1:ahcich1:0:0:0): cddone: got error 0x5 back > >>> =E2=80=A6 > >>> > >>> beta3 doesn't boot anymore, it's hanging with ahci-timeouts: > >>> ahcich2: Timeout on slot 11 port 0 > >>> ahcich2: is 00000008 cs 00000000 ss 00000000 rs 00000800 tfd 40 d= err > >>> 00000000 cmd 0004cb17 > >>> (ada1:ahcich2:0:0:0): READ_FPDMA_QUEUED. ACB: 60 01 ae a3 50 40 5= d 01 00 > >>> 00 00 00 > >>> ... > >>> (aprobe0:ahcich2:0:0:0) ATA_IDENTIFY. ACB eec 00 00 00 00 40 00 0= 0 00 00 > >>> 00 00 > >>> (aprobe0:ahcich2:0:0:0) CAM status: Command timeout > >>> (aprobe0:ahcich2:0:0:0) Error 5, Retry was blocked > >>> ada1 detached > >>> ... > >>> The numbers (first ACB) and also the channel varies from time to = time > >> > >> I could narrow it down to r295480 > >> (https://svnweb.freebsd.org/base?view=3Drevision&revision=3D295480= ) > >> > >> Reverting that lets the machine boot again. > >> > >> I captured verbose boot messages, finding out that problem relaxes= with > >> verbose-booting, since ahci seems to recover: > >> =E2=80=A6 > >> TSC timecounter discards lower 1 bit(s) > >> Timecounter "TSC-low" frequency 1746033500 Hz quality -100 > >> ahcich2: Timeout on slot 12 port 0 > >> ahcich2: is 00000008 cs 00000000 ss 00000000 rs 00001000 tfd 40 se= rr > >> 00000000 cmd 0004cc17 > >> ahcich2: AHCI reset... > >> (ada1:ahcich2:0:0:0): READ_FPDMA_QUEUED. ACB: 60 04 71 a3 50 40 5d= 01 00 > >> 00 00 00 > >> (ada1:ahcich2:0:0:0): CAM status: Command timeout > >> (ada1:ahcich2:0:0:0): Retrying command > >> ahcich2: SATA connect time=3D100us status=3D00000123 > >> ahcich2: AHCI reset: device found > >> ahcich2: AHCI reset: device ready after 100ms > >> ahcich1: SNTF 0x0001 > >> ahcich1: SNTF 0x0001 > >> =E2=80=A6 > >> > >> I have checked twice that r295480 introduces boot failure here. > >> > >> I have absolutely no idea where/how/why/what race happens... > >> > >> Thanks for any hints, > >=20 > > That is most bizarre. Does HEAD boot fine on this machine? The ch= ange > > in question probably alters the timing of startup a bit since the r= andom > > kthread is placed on the run queue later which might affect the rel= ative > > order of kthreads as they start executing, but that would just mean= it is > > exposting a race in some other part of the system. >=20 >=20 > Bizarre it is... > HEAD (r295683, 02/17/2016) boots fine. >=20 > BETA3 fails. >=20 > This time I checked with vendor-ISO images, while before it was a cus= tom > setup rollout with local patches and special hw adaptions. Now I'm su= re > it's not site-related. >=20 > With BETA3-iso, where booting fails, "random: unblocking device." > happens after timecounter initialization and before attaching ses0/cd= X/adaX. > With HEAD-iso, where booting succeeds, "random: unblocking device." > happens way after ses0/adaX/cdX attached, right before rc. Yes, HEAD's /dev/random has many more changes than were put into 10 for= BETA3. > On HEAD, ahci-devices attach in the same order as with -stable pre-r2= 95480. > Since r295480, cdX attaches before adaX on -stable and while searchin= g > for the cluprit, I had observed that attaching-order was a clear > indicator whether machine boots or not. >=20 > Sorry, I can't provide more useful info at this time, I just can > describe simple symptoms :-( >=20 >=20 > While playing with that machine I remember having had such a bizarre > problem before, arising with r284665. Here's what I found in my kerne= l > config: > # Don't build kernel with RACCT by default, which was enabled with r2= 84665, > # since ahci(4) fails when using MSI with ahcichX timeout! > nooptions RACCT # Resource accounting framewo= rk > nooptions RACCT_DEFAULT_TO_DISABLED # Set > kern.racct.enable=3D0 by default > nooptions RCTL # Resource limits >=20 > Perhpas it's related?! > https://lists.freebsd.org/pipermail/freebsd-stable/2015-July/082706.h= tml I think it's related in the sense that there is a timing race in ahci a= nd that the /dev/random and RACCT changes alter the timing enough to trigg= er the race simply by changing the relative order of SYSINIT's during boot= (and/or the amount of time between the ahci driver doing its initial probe and the second probe that is run for the interrupt config hooks t= hat actually probes the attached SATA devices). --=20 John Baldwin
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?6707098.Q23tZsJLSN>