Windows 7/8 Slow Boot at Windows logo

[soongin]

Hello, I'm trying to set up Windows 8.1 diskless PC environment by using iPXE, ietd on Ubuntu 12.04. Everything works fine except slow speed at Windows logo display stage.

Boot speed after pxe stage is about 1 minute (not that bad, I know), but I figured out that communication between ipxe and iscsi target takes too long. Once if Windows iscsi initiator takes over, it will take only a few secs to boot up. So I think I can make it very fast if I can reduce ipxe<->target communication time.

Below is debug logs from DEBUG=iscsi,scsi.

Code:

192.168.0.109 ipxe: Waiting for link-up on net0...... ok
192.168.0.109 ipxe: Configuring (net0 c0:3f:d5:fd:14:0b)...... ok
pctg ipxe: iSCSI 0x1f5b4 initiator iqn.1991-05.com.abc:daniel-win8
pctg ipxe: iSCSI 0x1f5b4 target 192.168.0.23 iqn.2003-01.org.linux-iscsi.dkim-dev-ubuntu.x8664:sn.80300f64002e
pctg ipxe: iSCSI 0x1f5b4 entering security negotiation
pctg ipxe: SCSI 0x1fa24 created for LUN 0000-0000-0000-0000
pctg ipxe: iSCSI 0x1f5b4 ignoring TargetPortalGroupTag=1
pctg ipxe: iSCSI 0x1f5b4 handling AuthMethod=None
pctg ipxe: iSCSI 0x1f5b4 entering operational negotiation
pctg ipxe: iSCSI 0x1f5b4 ignoring HeaderDigest=None
pctg ipxe: iSCSI 0x1f5b4 ignoring DataDigest=None
pctg ipxe: iSCSI 0x1f5b4 ignoring MaxConnections=1
pctg ipxe: iSCSI 0x1f5b4 ignoring InitialR2T=Yes
pctg ipxe: iSCSI 0x1f5b4 ignoring ImmediateData=No
pctg ipxe: iSCSI 0x1f5b4 ignoring MaxBurstLength=262144
pctg ipxe: iSCSI 0x1f5b4 ignoring DefaultTime2Wait=2
pctg ipxe: iSCSI 0x1f5b4 ignoring DefaultTime2Retain=0
pctg ipxe: iSCSI 0x1f5b4 ignoring MaxOutstandingR2T=1
pctg ipxe: iSCSI 0x1f5b4 ignoring DataPDUInOrder=Yes
pctg ipxe: iSCSI 0x1f5b4 ignoring DataSequenceInOrder=Yes
pctg ipxe: iSCSI 0x1f5b4 ignoring ErrorRecoveryLevel=0
pctg ipxe: iSCSI 0x1f5b4 entering full feature phase
pctg ipxe: SCSI 0x1fa24 waiting for unit to become ready
pctg ipxe: SCSI 0x1fa24 tag 18ae0002 status 02 sense 70 key 00 additional 2900
pctg ipxe: SCSI 0x1fa24 tag 18ae0002 failed: Input/output error (http://ipxe.org/1d704039)
pctg ipxe: SCSI 0x1fa24 tag 18ae0002 retrying (retry 1)
pctg ipxe: SCSI 0x1fa24 tag 18ae0002 is now tag 18ae0003
pctg ipxe: SCSI 0x1fa24 unit is ready
pctg ipxe: Registered SAN device 0x80
pctg ipxe: Booting from SAN device 0x80
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200
pctg ipxe: iSCSI 0x1f5b4 start data out DataSN 0x0 len 0x200

I also dump packet from tcpdump and found 66 bytes packet frame is repeated and it causes boot delay at Windows logo stage.




Once if Windows iscsi initiator takes over, only a few secs to boot up as below.


Is there any way to reduce communication time between ipxe<->iscsi target?

Thanks in advance.

[mcb30]

(2015-09-07 12:05)soongin Wrote:  Hello, I'm trying to set up Windows 8.1 diskless PC environment by using iPXE, ietd on Ubuntu 12.04. Everything works fine except slow speed at Windows logo display stage.

How long does it take from the time that iPXE displays the "Booting from SAN device 0x80" message until the time that the Windows logo starts to fade in?

Michael

[soongin]

(2015-09-07 12:49)mcb30 Wrote:  

(2015-09-07 12:05)soongin Wrote:  Hello, I'm trying to set up Windows 8.1 diskless PC environment by using iPXE, ietd on Ubuntu 12.04. Everything works fine except slow speed at Windows logo display stage.

How long does it take from the time that iPXE displays the "Booting from SAN device 0x80" message until the time that the Windows logo starts to fade in?

Michael

It's about 50 secs.
Once if log fade in, boot up finish in 5sec.

One more thing, I changed iscsi target to LIO and built rom for 10ec8168(kpxe, kkpxe) but same result.

[mcb30]

(2015-09-07 13:10)soongin Wrote:  One more thing, I changed iscsi target to LIO and built rom for 10ec8168(kpxe, kkpxe) but same result.

Which iPXE binary are you using? The .kpxe and .kkpxe suffixes are for use only with the "undionly" driver.

Try using bin/realtek.pxe, and build without DEBUG=iscsi:3 (since that level of debug output will slow it down quite substantially, especially since you're using syslog debug).

If that is still slow, please capture a packet trace and upload it to cloudshark.org.

Thanks,

Michael

[soongin]

(2015-09-07 13:22)mcb30 Wrote:  Which iPXE binary are you using? The .kpxe and .kkpxe suffixes are for use only with the "undionly" driver.

Try using bin/realtek.pxe, and build without DEBUG=iscsi:3 (since that level of debug output will slow it down quite substantially, especially since you're using syslog debug).

If that is still slow, please capture a packet trace and upload it to cloudshark.org.

Thanks,

Michael

Michael,

I tried realtek.pxe(no debug level set) but same result. Since pcacp file is too big (about 10M)to upload to cloudshark, I zipped and linked at ** deleted **

Thank you for your effort.

[mcb30]

(2015-09-08 01:39)soongin Wrote:  I tried realtek.pxe(no debug level set) but same result. Since pcacp file is too big (about 10M)to upload to cloudshark, I zipped and linked at here

Thanks. The packet capture is incomplete, since it shows only the packets sent by iPXE (and not the packets sent by the iSCSI target). Could you capture the whole sequence? You can limit the size by capturing only the packet headers, e.g.

Code:

tcpdump -s 128 -w sanboot.pcap -i eth0

Also, which version of iPXE are you using? (Type "show version" at the shell prompt if you aren't sure.)

Thanks,

Michael

[soongin]

(2015-09-08 08:19)mcb30 Wrote:  

(2015-09-08 01:39)soongin Wrote:  I tried realtek.pxe(no debug level set) but same result. Since pcacp file is too big (about 10M)to upload to cloudshark, I zipped and linked at ** deleted **

Thanks. The packet capture is incomplete, since it shows only the packets sent by iPXE (and not the packets sent by the iSCSI target). Could you capture the whole sequence? You can limit the size by capturing only the packet headers, e.g.

Code:

tcpdump -s 128 -w sanboot.pcap -i eth0

Also, which version of iPXE are you using? (Type "show version" at the shell prompt if you aren't sure.)

Thanks,

Michael

I recaptured ** deleted **
(I limit the src for client, sorry.)
192.168.0.23 is testing server and 192.168.0.109 is diskless client.

I just git the source yesterday and during boot it says iPXE 1.0.0+(3376).

Thanks again.

[soongin]

Today I tried gPxe built from http://rom-o-matic.net/gpxe/gpxe-1.0.1/c...m-o-matic/ with 10ec8168.pxe.

There is no latency at logo stage and finish boot in 15secs.
Hope this helps to debug.

Thank you.

[mcb30]

(2015-09-08 09:32)soongin Wrote:  I recaptured ** deleted **

The link seems to be broken. Could you repost the same capture file?

Also, could you check the link speed indicator on the switch during the iPXE stage? Is it showing a gigabit link?

Thanks,

Michael

[soongin]

(2015-09-10 10:43)mcb30 Wrote:  The link seems to be broken. Could you repost the same capture file?

Also, could you check the link speed indicator on the switch during the iPXE stage? Is it showing a gigabit link?

Thanks,

Michael

Michael,
I thought you already downloaded. Sorry.
I captured again with iPXE and gPXE for your information.
You can download at ** deleted **

All configurations are same and I just switched ROM in dhcp.
It takes about 15secs to boot with gPXE but takes over 1 min with iPXE.
(192.168.0.109: Client PC, 192.168.0.23: Target Server, 192.168.0.120: DHCP Server)

Thanks for your effort.

[mcb30]

(2015-09-10 20:53)soongin Wrote:  You can download at here.

Thank you. Could you answer my question about the link speed:

Quote:Also, could you check the link speed indicator on the switch during the iPXE stage? Is it showing a gigabit link?

Thanks,

Michael

[soongin]

Quote:Also, could you check the link speed indicator on the switch during the iPXE stage? Is it showing a gigabit link?

I checked and it shows orange led color. (both ipxe and gpxe are same.)
After boot, Windows recognize this link as 1Gbps speed. (Same orange color)
I use 8 port gigabit supported switching hub for testing.

Thank you.

[mcb30]

(2015-09-13 05:55)soongin Wrote:  I checked and it shows orange led color. (both ipxe and gpxe are same.)

Thank you. I've checked the packet capture, and we are seeing ~12us between ACKs for full-sized frames, which does imply a 1Gbps link.

There are some odd-looking TCP retransmissions. These seem to always happen for the last packet transmitted by the server in a read request. Since it's always the last packet that gets dropped, fast retransmit doesn't happen and so nothing happens until the server's retransmission timer expires around 200ms later.

It's very suspicious that the drops seem to always affect the last packet in a request. If the link were bad, then we would expect all packets to be affected equally.

Is there anything else running on this machine which could potentially be accessing the network card (e.g. BIOS remote management or network console redirection)?

Could you also please try the hack at http://fpaste.org/266946/, which will continue to poll the NIC for received packets even if the NIC's interrupt register reports that there are no new received packets.

Thanks,

Michael

[soongin]

(2015-09-14 14:17)mcb30 Wrote:  Could you also please try the hack at http://fpaste.org/266946/, which will continue to poll the NIC for received packets even if the NIC's interrupt register reports that there are no new received packets.

I patched (just comment on 2 lines) and it boots up in 20 secs. No delay on Windows logo. Is this issue only affects to Realtek NIC?

Thank you.

[nobluesky]

(2015-09-14 14:17)mcb30 Wrote:  

(2015-09-13 05:55)soongin Wrote:  I checked and it shows orange led color. (both ipxe and gpxe are same.)

Thank you. I've checked the packet capture, and we are seeing ~12us between ACKs for full-sized frames, which does imply a 1Gbps link.

There are some odd-looking TCP retransmissions. These seem to always happen for the last packet transmitted by the server in a read request. Since it's always the last packet that gets dropped, fast retransmit doesn't happen and so nothing happens until the server's retransmission timer expires around 200ms later.

It's very suspicious that the drops seem to always affect the last packet in a request. If the link were bad, then we would expect all packets to be affected equally.

Is there anything else running on this machine which could potentially be accessing the network card (e.g. BIOS remote management or network console redirection)?

Could you also please try the hack at http://fpaste.org/266946/, which will continue to poll the NIC for received packets even if the NIC's interrupt register reports that there are no new received packets.

Thanks,

Michael

hi

I'd like to check your patch but it's expired. could you upload the patch again?

[mcb30]

(2015-09-15 06:42)soongin Wrote:  

(2015-09-14 14:17)mcb30 Wrote:  Could you also please try the hack at http://fpaste.org/266946/, which will continue to poll the NIC for received packets even if the NIC's interrupt register reports that there are no new received packets.

I patched (just comment on 2 lines) and it boots up in 20 secs. No delay on Windows logo. Is this issue only affects to Realtek NIC?

OK, we have progress!

Do you know precisely which Realtek chip you have? You'll have to look at the number printed on the chip itself: the PCI device ID is not quite enough detail.

Thanks,

Michael

[mcb30]

(2015-09-15 14:52)nobluesky Wrote:  

Quote:Could you also please try the hack at http://fpaste.org/266946/, which will continue to poll the NIC for received packets even if the NIC's interrupt register reports that there are no new received packets.

I'd like to check your patch but it's expired. could you upload the patch again?

I don't have it any more, but I'm pretty sure it was:

Code:

--- a/src/drivers/net/realtek.c
+++ b/src/drivers/net/realtek.c
@@ -988,8 +988,8 @@ static void realtek_poll ( struct net_device *netdev ) {

        /* Check for and acknowledge interrupts */
        isr = readw ( rtl->regs + RTL_ISR );
-       if ( ! isr )
-               return;
+       //      if ( ! isr )
+       //              return;
        writew ( isr, rtl->regs + RTL_ISR );

        /* Poll for TX completions, if applicable */
@@ -997,7 +997,7 @@ static void realtek_poll ( struct net_device *netdev ) {
                realtek_poll_tx ( netdev );

        /* Poll for RX completionsm, if applicable */
-       if ( isr & ( RTL_IRQ_RER | RTL_IRQ_ROK ) )
+       //      if ( isr & ( RTL_IRQ_RER | RTL_IRQ_ROK ) )
                realtek_poll_rx ( netdev );

        /* Check link state, if applicable */

Michael

[mcb30]

(2015-09-16 11:06)mcb30 Wrote:  OK, we have progress!

Do you know precisely which Realtek chip you have? You'll have to look at the number printed on the chip itself: the PCI device ID is not quite enough detail.

It would be good to know if this patch also fixes the problem:

Code:

--- a/src/drivers/net/realtek.c
+++ b/src/drivers/net/realtek.c
@@ -997,7 +997,7 @@ static void realtek_poll ( struct net_device *netdev ) {
                realtek_poll_tx ( netdev );

        /* Poll for RX completionsm, if applicable */
-       if ( isr & ( RTL_IRQ_RER | RTL_IRQ_ROK ) )
+       //      if ( isr & ( RTL_IRQ_RER | RTL_IRQ_ROK ) )
                realtek_poll_rx ( netdev );

        /* Check link state, if applicable */

i.e. commenting out the check for IRQ_RER|IRQ_ROK but leaving in place the "if(!isr) return;" near the start of realtek_poll().

If this patch does work to fix the problem, then it means that the chip is reporting some kind of interrupt that we need to add to the list in the IRQ_RER|IRQ_ROK line.

If this patch does not work to fix the problem, then it means that the chip is not reporting any interrupt, i.e. that the chip is broken.

Michael

[soongin]

(2015-09-16 11:21)mcb30 Wrote:  

(2015-09-16 11:06)mcb30 Wrote:  OK, we have progress!

Do you know precisely which Realtek chip you have? You'll have to look at the number printed on the chip itself: the PCI device ID is not quite enough detail.

It would be good to know if this patch also fixes the problem:

Code:

--- a/src/drivers/net/realtek.c
+++ b/src/drivers/net/realtek.c
@@ -997,7 +997,7 @@ static void realtek_poll ( struct net_device *netdev ) {
                realtek_poll_tx ( netdev );

        /* Poll for RX completionsm, if applicable */
-       if ( isr & ( RTL_IRQ_RER | RTL_IRQ_ROK ) )
+       //      if ( isr & ( RTL_IRQ_RER | RTL_IRQ_ROK ) )
                realtek_poll_rx ( netdev );

        /* Check link state, if applicable */

i.e. commenting out the check for IRQ_RER|IRQ_ROK but leaving in place the "if(!isr) return;" near the start of realtek_poll().

If this patch does work to fix the problem, then it means that the chip is reporting some kind of interrupt that we need to add to the list in the IRQ_RER|IRQ_ROK line.

If this patch does not work to fix the problem, then it means that the chip is not reporting any interrupt, i.e. that the chip is broken.

Michael

Sorry about late.
It's not possible to open up the pc case.
From the lshw, it says RTL 8111/8168/9411 PCI Express.
From the Windows device manager(in INF section), it says RTL8168G so I guess it's 8168 chipset.

Also I have interesting results from quick patch.
- w/o patch, it slows to display Windows logo(black screen after sanboot command) and result in slow boot. (boot over 1 min)
- by removing "if ( isr & ( RTL_IRQ_RER | RTL_IRQ_ROK ) )", fast to display windows logo but slow to fade out. (boot about 40 secs)
- by removing "if ( ! isr ) return;" and "if ( isr & ( RTL_IRQ_RER | RTL_IRQ_ROK ) )", fast to display and fast to fade out logo. (boot about 20 secs)

Hope this helps.

[mcb30]

(2015-09-18 05:40)soongin Wrote:  Sorry about late.
It's not possible to open up the pc case.
From the lshw, it says RTL 8111/8168/9411 PCI Express.
From the Windows device manager(in INF section), it says RTL8168G so I guess it's 8168 chipset.

Also I have interesting results from quick patch.
- w/o patch, it slows to display Windows logo(black screen after sanboot command) and result in slow boot. (boot over 1 min)
- by removing "if ( isr & ( RTL_IRQ_RER | RTL_IRQ_ROK ) )", fast to display windows logo but slow to fade out. (boot about 40 secs)
- by removing "if ( ! isr ) return;" and "if ( isr & ( RTL_IRQ_RER | RTL_IRQ_ROK ) )", fast to display and fast to fade out logo. (boot about 20 secs)

I missed your reply; sorry.

One (slight) possibility is that there is a BIOS bug causing the MSRs to be set incorrectly marking that PCI device's BAR as cacheable. You could test this by trying the (new, since your post) 64-bit BIOS version of iPXE. The 64-bit version has to handle page table entries, and will explicitly mark any entries for PCI BARs as being uncacheable.

You can build the 64-bit version using:

Code:

make bin-x86_64-pcbios/realtek.pxe

Michael