From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from eggs.gnu.org ([2001:4830:134:3::10]:55714) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1X2Rfs-0002dL-Cw for qemu-devel@nongnu.org; Wed, 02 Jul 2014 17:02:47 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1X2Rfk-0006CR-5g for qemu-devel@nongnu.org; Wed, 02 Jul 2014 17:02:40 -0400 Received: from cantor2.suse.de ([195.135.220.15]:59733 helo=mx2.suse.de) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1X2Rfj-0006CN-RF for qemu-devel@nongnu.org; Wed, 02 Jul 2014 17:02:32 -0400 Message-ID: <53B47366.6000101@suse.de> Date: Wed, 02 Jul 2014 23:02:30 +0200 From: Alexander Graf MIME-Version: 1.0 References: <1404147350-28904-1-git-send-email-somlo@cmu.edu> <1404147350-28904-3-git-send-email-somlo@cmu.edu> <20140630175554.GA2871@redhat.com> <20140702090207.GA2945@crash.ini.cmu.edu> <53B3CE04.5020700@suse.de> <20140702204959.GY1688@ERROL.INI.CMU.EDU> In-Reply-To: <20140702204959.GY1688@ERROL.INI.CMU.EDU> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Subject: Re: [Qemu-devel] e1000 autoneg timing, piix/osx List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: "Gabriel L. Somlo" Cc: "pbonzini@redhat.com" , "qemu-devel@nongnu.org" , "stefanha@redhat.com" , "Michael S. Tsirkin" On 02.07.14 22:49, Gabriel L. Somlo wrote: > On Wed, Jul 02, 2014 at 11:16:52AM +0200, Alexander Graf wrote: >>>> Are you sure there's not just simply some irq unmasking event >>>> after 5500ms we don't handle properly? >>> I poked around a bit, and the e1000 interrupt mask register is NOT the >>> problem (the LSC mask bit is clear at all times). If anything, maybe >>> the PIIX southbridge (or something further up "north") is masking PCI >>> interrupts (at least from e1000) until roughly 5500 ms into the boot >>> process ? Any ideas on how I could go about verifying this (without >>> access to the guest source, obviously :) ) would be very helpful... >> Yeah, maybe the interrupt is masked and doesn't get delivered properly? See >> if you can trace when the e1000 emulation starts kicking an interrupt and >> when the guest tries to fetch it (there should be an ack register for IRQs >> somewhere). >> >> If we kick it but the guest doesn't react, the problem is further down - >> check whether the IRQ ever got injected into the guest with trace points. >> >> If we don't kick it, we mask it somewhere in the e1000 emulation and need to >> make sure we do kick once we unmask :). I don't know whether the LSC mask is >> the only one involved. > So it turns out everything I thought I knew (which was little indeed) > was more or less wrong. The problem, as far as I'm observing it now, > is that on PIIX, the OS X guest obsessively reads the ICR in a tight > loop. It reads the injected LSC (and probably discards it) before > unmasking the corresponding interrupt bit; later on, when it unmasks > LSC, giving the emulated e1000 hardware a chance to raise the irq > line, the actual LSC event has been flushed from the ICR, and the > driver does not detect the link coming up. > > Here's how things work normally on Q35 (with INTERRUPT and PHY debugging > enabled, // my comments on the side): > > e1000: set_imc ffffffff > e1000: set_ics 0, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_imc ffffffff > e1000: set_ics 0, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_imc ffffffff > e1000: set_ics 0, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_imc ffffffff > e1000: set_ics 0, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_imc ffffffff > e1000: set_ics 0, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_imc ffffffff > e1000: set_ics 0, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: Start link auto negotiation > e1000: Auto negotiation is completed > e1000: set_ics 4, ICR 0, IMR 0 // autoneg timer injects LSC > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_ics 2, ICR 4, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_ics 2, ICR 6, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_ims df // guest unmasks interrupts > e1000: set_ics 0, ICR 6, IMR df > e1000: set_interrupt_cause: mit_irq_level=1 // first raising irq edge > e1000: ICR read: 6 // guest receives LSC (+more) > > ... and things work nicely from here on out :) > > > On PIIX, however, things look like this: > > e1000: set_imc ffffffff > e1000: set_ics 0, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_imc ffffffff > e1000: set_ics 0, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_imc ffffffff > e1000: set_ics 0, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > > ... <8155 "ICR read" repetitions deleted> ... > > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_imc ffffffff > e1000: set_ics 0, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_imc ffffffff > e1000: set_ics 0, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_imc ffffffff > e1000: set_ics 0, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: Start link auto negotiation > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > > ... <145 "ICR read" repetitions deleted> ... > > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: Auto negotiation is completed > e1000: set_ics 4, ICR 0, IMR 0 // autoneg timer injects LSC > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 4 // guest reads (and discards?) LSC > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > > ... <23 "ICR read" repetitions deleted> ... > > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_ics 2, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 2 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_ics 2, ICR 0, IMR 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_ims df // guest unmasks interrupts > e1000: set_ics 0, ICR 2, IMR df > e1000: set_interrupt_cause: mit_irq_level=1 // first raising irq edge > e1000: ICR read: 2 // too late, LSC is gone :( > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_imc 2 > e1000: set_ics 0, ICR 0, IMR dd > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_ims df > e1000: set_ics 0, ICR 0, IMR df > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_ics 80, ICR 0, IMR df > e1000: set_interrupt_cause: mit_irq_level=1 > e1000: set_ics 3, ICR 80, IMR df > e1000: set_interrupt_cause: mit_irq_level=1 > e1000: ICR read: 83 > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_imc 82 > e1000: set_ics 0, ICR 0, IMR 5d > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: set_ims df > e1000: set_ics 0, ICR 0, IMR df > e1000: set_interrupt_cause: mit_irq_level=0 > e1000: ICR read: 0 > e1000: set_interrupt_cause: mit_irq_level=0 > > ... and so on... > > > Any clue as to why ICR gets read like that on PIIX, but not Q35 ? Maybe it's using MSI on q35? :) Maybe we also share the same IRQ line with another device on PIIX that gets polled all the time? IDE maybe? Either way, why does the bit get cleared even though it hasn't been raised? What does real hardware do with interrupts that have been masked? Alex