From owner-freebsd-current@freebsd.org Tue May 24 19:10:50 2016 Return-Path: Delivered-To: freebsd-current@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id CB3D9B49C8A for ; Tue, 24 May 2016 19:10:50 +0000 (UTC) (envelope-from ken@kdm.org) Received: from mailman.ysv.freebsd.org (unknown [127.0.1.3]) by mx1.freebsd.org (Postfix) with ESMTP id B512F1470 for ; Tue, 24 May 2016 19:10:50 +0000 (UTC) (envelope-from ken@kdm.org) Received: by mailman.ysv.freebsd.org (Postfix) id B47ADB49C89; Tue, 24 May 2016 19:10:50 +0000 (UTC) Delivered-To: current@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id B41F6B49C88 for ; Tue, 24 May 2016 19:10:50 +0000 (UTC) (envelope-from ken@kdm.org) Received: from mithlond.kdm.org (mithlond.kdm.org [96.89.93.250]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client CN "A1-33714", Issuer "A1-33714" (not verified)) by mx1.freebsd.org (Postfix) with ESMTPS id 73A73146B for ; Tue, 24 May 2016 19:10:49 +0000 (UTC) (envelope-from ken@kdm.org) Received: from mithlond.kdm.org (localhost [127.0.0.1]) by mithlond.kdm.org (8.15.2/8.14.9) with ESMTPS id u4OJAgIt070200 (version=TLSv1.2 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=NO); Tue, 24 May 2016 15:10:42 -0400 (EDT) (envelope-from ken@mithlond.kdm.org) Received: (from ken@localhost) by mithlond.kdm.org (8.15.2/8.14.9/Submit) id u4OJAfSV070199; Tue, 24 May 2016 15:10:41 -0400 (EDT) (envelope-from ken) Date: Tue, 24 May 2016 15:10:41 -0400 From: "Kenneth D. Merry" To: Gary Jennejohn Cc: current@freebsd.org Subject: Re: AHCI/ADA regression? Message-ID: <20160524191041.GB66830@mithlond.kdm.org> References: <20160521100949.6179a697@ernst.home> <20160523175105.GA50102@mithlond.kdm.org> <20160524155828.7119d8a1@ernst.home> <20160524144125.GA66261@mithlond.kdm.org> <20160524200051.42d0e6cb@ernst.home> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20160524200051.42d0e6cb@ernst.home> User-Agent: Mutt/1.5.23 (2014-03-12) X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.4.3 (mithlond.kdm.org [127.0.0.1]); Tue, 24 May 2016 15:10:42 -0400 (EDT) X-Spam-Status: No, score=-2.9 required=5.0 tests=ALL_TRUSTED,BAYES_00, HEADER_FROM_DIFFERENT_DOMAINS autolearn=ham autolearn_force=no version=3.4.1 X-Spam-Checker-Version: SpamAssassin 3.4.1 (2015-04-28) on mithlond.kdm.org X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.22 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 24 May 2016 19:10:50 -0000 On Tue, May 24, 2016 at 20:00:51 +0200, Gary Jennejohn wrote: > On Tue, 24 May 2016 10:41:25 -0400 > "Kenneth D. Merry" wrote: > > > > The question in my mind is - why are "empty" multiplier ports being > > > probed with the new code but not with the old code? > > > > If the HBA says that it supports port multipliers, the kernel should always > > look for them. It probes the port multiplier first, before moving on to > > look for regular targets. > > > > So, from that standpoint, it should not be any different. It sounds like > > we're either getting further in the port multiplier probe process, or there > > is something different about the way things are behaving. > > > > If you can determine which commands are timing out, that may give us an > > idea about where it is in the probe process. > > > > Here is one way we may be able to track things down... Build a kernel with > > these options: > > > > options CAMDEBUG > > options CAM_DEBUG_FLAGS=CAM_DEBUG_PROBE > > > > If you build a kernel before and after the change with those options, it > > will hopefully allow us to compare the probe sequence and get a clue about > > where to look for the problem. > > > > OK, both the old and new kernel versions do an extremely fast intial > probe with these results (note: obtained with grep over dmesg.boot): > > (aprobe0:ahcich0:0:15:0): Probe started > (aprobe0:ahcich0:0:15:0): Probe PROBE_INVALID to PROBE_RESET > (aprobe1:ahcich1:0:15:0): Probe started > (aprobe1:ahcich1:0:15:0): Probe PROBE_INVALID to PROBE_RESET > (aprobe2:ahcich2:0:15:0): Probe started > (aprobe2:ahcich2:0:15:0): Probe PROBE_INVALID to PROBE_RESET > (aprobe3:ahcich3:0:15:0): Probe started > (aprobe3:ahcich3:0:15:0): Probe PROBE_INVALID to PROBE_RESET > (aprobe4:ahcich4:0:15:0): Probe started > (aprobe4:ahcich4:0:15:0): Probe PROBE_INVALID to PROBE_RESET > (aprobe5:ahcich5:0:15:0): Probe started > (aprobe5:ahcich5:0:15:0): Probe PROBE_INVALID to PROBE_RESET > (aprobe4:ahcich4:0:15:0): Probe PROBE_RESET to PROBE_RESET > (aprobe4:ahcich4:0:15:0): Probe PROBE_RESET to PROBE_INVALID > (aprobe4:ahcich4:0:15:0): Probe completed > (aprobe4:ahcich4:0:0:0): Probe started > (aprobe4:ahcich4:0:0:0): Probe PROBE_INVALID to PROBE_RESET > (aprobe4:ahcich4:0:0:0): Probe PROBE_RESET to PROBE_INVALID > (aprobe4:ahcich4:0:0:0): Probe completed > (aprobe0:ahcich0:0:15:0): Probe PROBE_RESET to PROBE_RESET > (aprobe2:ahcich2:0:15:0): Probe PROBE_RESET to PROBE_RESET > (aprobe0:ahcich0:0:15:0): SIGNATURE: 0000 > (aprobe0:ahcich0:0:15:0): Probe PROBE_RESET to PROBE_INVALID > (aprobe0:ahcich0:0:15:0): Probe completed > (aprobe2:ahcich2:0:15:0): SIGNATURE: 0000 > (aprobe2:ahcich2:0:15:0): Probe PROBE_RESET to PROBE_INVALID > (aprobe2:ahcich2:0:15:0): Probe completed > (aprobe0:ahcich0:0:0:0): Probe started > (aprobe0:ahcich0:0:0:0): Probe PROBE_INVALID to PROBE_RESET > (aprobe2:ahcich2:0:0:0): Probe started > (aprobe2:ahcich2:0:0:0): Probe PROBE_INVALID to PROBE_RESET > (aprobe3:ahcich3:0:15:0): Probe PROBE_RESET to PROBE_RESET > (aprobe5:ahcich5:0:15:0): Probe PROBE_RESET to PROBE_RESET > (aprobe0:ahcich0:0:0:0): SIGNATURE: 0000 > (aprobe0:ahcich0:0:0:0): Probe PROBE_RESET to PROBE_IDENTIFY > (aprobe2:ahcich2:0:0:0): SIGNATURE: 0000 > (aprobe2:ahcich2:0:0:0): Probe PROBE_RESET to PROBE_IDENTIFY > (aprobe1:ahcich1:0:15:0): Probe PROBE_RESET to PROBE_RESET > (aprobe3:ahcich3:0:15:0): SIGNATURE: 0000 > (aprobe3:ahcich3:0:15:0): Probe PROBE_RESET to PROBE_INVALID > (aprobe3:ahcich3:0:15:0): Probe completed > (aprobe5:ahcich5:0:15:0): SIGNATURE: 0000 > (aprobe5:ahcich5:0:15:0): Probe PROBE_RESET to PROBE_INVALID > (aprobe5:ahcich5:0:15:0): Probe completed > (aprobe1:ahcich1:0:15:0): SIGNATURE: eb14 > (aprobe1:ahcich1:0:15:0): Probe PROBE_RESET to PROBE_INVALID > (aprobe1:ahcich1:0:15:0): Probe completed > (aprobe1:ahcich3:0:0:0): Probe started > (aprobe1:ahcich3:0:0:0): Probe PROBE_INVALID to PROBE_RESET > (aprobe3:ahcich5:0:0:0): Probe started > (aprobe3:ahcich5:0:0:0): Probe PROBE_INVALID to PROBE_RESET > (aprobe4:ahcich1:0:0:0): Probe started > (aprobe4:ahcich1:0:0:0): Probe PROBE_INVALID to PROBE_RESET > (aprobe1:ahcich3:0:0:0): SIGNATURE: 0000 > (aprobe1:ahcich3:0:0:0): Probe PROBE_RESET to PROBE_IDENTIFY > (aprobe3:ahcich5:0:0:0): SIGNATURE: 0000 > (aprobe3:ahcich5:0:0:0): Probe PROBE_RESET to PROBE_IDENTIFY > (aprobe4:ahcich1:0:0:0): SIGNATURE: eb14 > (aprobe4:ahcich1:0:0:0): Probe PROBE_RESET to PROBE_IDENTIFY > (aprobe0:ahcich0:0:0:0): Probe PROBE_IDENTIFY to PROBE_SETMODE > (aprobe1:ahcich3:0:0:0): Probe PROBE_IDENTIFY to PROBE_SETMODE > (aprobe3:ahcich5:0:0:0): Probe PROBE_IDENTIFY to PROBE_SETMODE > (aprobe0:ahcich0:0:0:0): Probe PROBE_SETMODE to PROBE_SET_MULTI > (aprobe1:ahcich3:0:0:0): Probe PROBE_SETMODE to PROBE_SETDMAAA > (aprobe3:ahcich5:0:0:0): Probe PROBE_SETMODE to PROBE_SETDMAAA > (aprobe0:ahcich0:0:0:0): Probe PROBE_SET_MULTI to PROBE_DONE > (aprobe0:ahcich0:0:0:0): Probe completed > (aprobe1:ahcich3:0:0:0): Probe PROBE_SETDMAAA to PROBE_SET_MULTI > (aprobe4:ahcich1:0:0:0): Probe PROBE_IDENTIFY to PROBE_SETMODE > (aprobe3:ahcich5:0:0:0): Probe PROBE_SETDMAAA to PROBE_SET_MULTI > (aprobe1:ahcich3:0:0:0): Probe PROBE_SET_MULTI to PROBE_DONE > (aprobe1:ahcich3:0:0:0): Probe completed > (aprobe3:ahcich5:0:0:0): Probe PROBE_SET_MULTI to PROBE_DONE > (aprobe3:ahcich5:0:0:0): Probe completed > (aprobe2:ahcich2:0:0:0): Probe PROBE_IDENTIFY to PROBE_SETMODE > (aprobe4:ahcich1:0:0:0): Probe PROBE_SETMODE to PROBE_INQUIRY > (aprobe2:ahcich2:0:0:0): Probe PROBE_SETMODE to PROBE_SETDMAAA > (aprobe2:ahcich2:0:0:0): Probe PROBE_SETDMAAA to PROBE_SET_MULTI > (aprobe2:ahcich2:0:0:0): Probe PROBE_SET_MULTI to PROBE_DONE > (aprobe2:ahcich2:0:0:0): Probe completed > (aprobe4:ahcich1:0:0:0): Probe PROBE_INQUIRY to PROBE_FULL_INQUIRY > (aprobe4:ahcich1:0:0:0): Probe PROBE_FULL_INQUIRY to PROBE_DONE > (aprobe4:ahcich1:0:0:0): Probe completed > > it looks like the code is basically checking to see how many ports are > on a multiplier since it looks at port 0 and port 15. Okay. > [I don't have a dmesg.boot for the "broken" kernel, but I saw the > probe messages going shooting past and it was obviuos that they > were the same] > > The old code stops there. > > The new code starts probing for what appear to be random ports on a > multiplier, like 0, 7, 20, 17, etc. These always result in timeouts. I'm guessing you would have seen "SIGNATURE: 9669" in the logs with the new code in that case. That is the only way we should have gotten into probing a port multiplier. > These probes always start with "Probe PROBE_INVALID to PROBE_IDENTIFY" > Why the new code doesn't accept the PROBE_INVALID and skip over it > I don't understand. PROBE_INVALID is a state in the ATA probe state machine. It is where all of the probes start, and where probes end if they have "failed" in the sense that we're not going to continue. The probe messages are intermixed, so you'd have to match them up by the probe peripheral driver instance number (aprobe2, aprobe4, etc.) to see the sequence for one particular device. > After I noticed that the same ports had been probed several times on > achich2 with no apparent end in sight I rebooted. This behavior is > extremely poor. Can you send full dmesg output from the working kernel? It looks like you have some ATAPI devcies on your machine (signature eb14). They would likely be attaching to the da(4) driver if they are disks, and that is a different code path. Thanks, Ken -- Kenneth Merry ken@FreeBSD.ORG