Why network initialization takes longer then 10 seconds in boot start phase?

This is my virtual storport driver log.

Please see this log first.

I commented for each line in detail.

// DriverEntry function is called
[ForeDisk] DriverEntry() driverObject=0xFFFFDB8CF2B06060, registryPath=\Registry\Machine\System\CurrentControlSet\Services\TenyearsStorPort

// StorPortInitialize() function is being called.
[ForeDisk] DriverEntry()->StorPortInitialize() BEGIN

// StorPortInitialize() function is finished with status STATUS_SUCCESS
[ForeDisk] DriverEntry()->StorPortInitialize() END (status=0x00000000)

// Just log begin line
2018-05-01 17:12:06.107.461 0000.000.001 ================================================================

// My virtual storport driver name and version
2018-05-01 17:12:06.107.461 0000.000.222 foreDisk version ‘1.00 Debug’

// hwStorFindAdapter() is called.
2018-05-01 17:12:06.107.461 0000.000.426 hwStorFindAdapter() deviceExtension=0xFFFFDB8CF29FA550, hwContext=0xFFFFDB8CF19F2E40, busInformation=0xFFFFDB8CF2B50050, lowerDevice=0xFFFFDB8CF19F2E40, argumentString=, configInfo=0xFFFFDB8CF2B502D0, again=0xFFFFEB8E182060B0

// WSK is initialized. (In another system thread A)
2018-05-01 17:12:06.107.461 0000.000.434 WSK initialized. status=0x00000000

// hwStorInitialize() function is called.
2018-05-01 17:12:06.107.461 0000.000.001 hwStorInitialize()

// hwStorAdapterControl() function is called.
2018-05-01 17:12:06.107.461 0000.000.576 hwStorAdapterControl() (QuerySupportedControlTypes)

// RAW socket is created. (In system thread A)
2018-05-01 17:12:06.123.087 0000.021.123 RAW socket created. status=0x00000000

// UDP socket is created. (In system thread A)
2018-05-01 17:12:06.123.087 0000.000.520 UDP socket created. status=0x00000000

// On board network adapter “Realtek PCIe Gbe…” is Ethernet type and IfOperStatusDown status and NET_IF_ADMIN_STATUS_UP status.
2018-05-01 17:12:06.123.087 0000.000.248 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=2, AdminStatus=1

// 1 second elapsed.
2018-05-01 17:12:07.138.724 0001.005.934 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=2, AdminStatus=1

// 2 seconds elapsed.
2018-05-01 17:12:08.138.737 0001.000.004 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=2, AdminStatus=1

// 3 seconds elapsed.
2018-05-01 17:12:09.138.750 0001.000.000 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=2, AdminStatus=1

// 4 seconds elapsed.
2018-05-01 17:12:10.138.763 0001.000.011 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=2, AdminStatus=1

// 5 seconds elapsed. OperStatus is changed to IfOperStatusUp status finally.
2018-05-01 17:12:11.138.776 0001.000.023 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1

// RAW socket has sent a DHCP reqeust packet. (But the packet is not sent actually. I watched using wireshark on another peer computer.)
2018-05-01 17:12:11.138.776 0000.000.323 DHCP request [4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47)

// Resend DHCP request packet 1 second later. (1 second elapsed)
2018-05-01 17:12:12.138.789 0000.999.680 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1
2018-05-01 17:12:12.138.789 0000.000.282 DHCP request [4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47)

// Resend DHCP request packet 1 second later. (2 seconds elapsed)
2018-05-01 17:12:13.138.801 0000.999.731 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1
2018-05-01 17:12:13.138.801 0000.000.289 DHCP request [4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47)

// Resend DHCP request packet 1 second later. (3 seconds elapsed)
2018-05-01 17:12:14.138.814 0000.999.720 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1
2018-05-01 17:12:14.138.814 0000.000.322 DHCP request [4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47)

// Resend DHCP request packet 1 second later. (4 seconds elapsed)
2018-05-01 17:12:15.138.827 0000.999.696 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1
2018-05-01 17:12:15.138.827 0000.000.292 DHCP request [4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47)

// Resend DHCP request packet 1 second later. (5 seconds elapsed)
2018-05-01 17:12:16.138.840 0000.999.714 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1
2018-05-01 17:12:16.138.840 0000.000.293 DHCP request [4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47)

// Resend DHCP request packet 1 second later. (6 seconds elapsed)
2018-05-01 17:12:17.138.853 0000.999.718 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1
2018-05-01 17:12:17.138.853 0000.000.298 DHCP request [4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47)

// Resend DHCP request packet 1 second later. (7 seconds elapsed)
2018-05-01 17:12:18.138.866 0000.999.719 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1
2018-05-01 17:12:18.138.866 0000.000.287 DHCP request [4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47)

// Resend DHCP request packet 1 second later. (8 seconds elapsed)
2018-05-01 17:12:19.138.879 0000.999.719 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1
2018-05-01 17:12:19.138.879 0000.000.314 DHCP request [4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47)

// Resend DHCP request packet 1 second later. (9 seconds elapsed)
2018-05-01 17:12:20.138.892 0000.999.699 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1
2018-05-01 17:12:20.138.892 0000.000.278 DHCP request [4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47)

// DHCP response packet is received! IP address is manually set to 192.168.0.81 using CreateUnicastIpAddressEntry() function. Windows sends ARP gratuitous packet now.
2018-05-01 17:12:20.138.892 0000.002.018 DHCP response [4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) (192.168.0.81)

// IP conflict detection waiting (1 second)
2018-05-01 17:12:21.138.905 0000.997.718 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1

// IP conflict detection waiting (2 seconds)
2018-05-01 17:12:22.138.918 0001.000.009 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1

// IP conflict detection waiting (3 seconds)
2018-05-01 17:12:23.138.930 0001.000.013 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1

// IP conflict detection waiting (4 seconds)
2018-05-01 17:12:24.138.943 0001.000.019 Network Interface[4] Realtek PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1, OperStatus=1, AdminStatus=1

// Finally WSK UDP socket has received storage information from server.
2018-05-01 17:12:24.170.194 0000.031.716 LogicalUnitInfosCount=1
2018-05-01 17:12:24.170.194 0000.000.186 LogicalUnitInfos[0] key=0xF07ED102, name=VMDK-Windows10

// Normal storport callback function calls.
2018-05-01 17:12:24.170.194 0000.000.576 hwStorStartIoPnp() (PNP2, QueryCapabilities, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x9, QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0, SrbFlags=0x00000100, DataTransferLength=0x8)
2018-05-01 17:12:24.170.194 0000.001.494 hwStorStartIoIoControl() (IO_CONTROL, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0xFE, QueueAction=0x20, CdbLength=0x0, SenseInfoBufferLength=0xFF, SrbFlags=0x00300142, DataTransferLength=0x22C)
2018-05-01 17:12:24.170.194 0000.000.385 hwStorStartIoIoControl() (IO_CONTROL, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0xFE, QueueAction=0x20, CdbLength=0x0, SenseInfoBufferLength=0xFF, SrbFlags=0x00000142, DataTransferLength=0x110)
2018-05-01 17:12:24.170.194 0000.000.425 hwStorStartIoIoControl() (IO_CONTROL, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x0, QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0, SrbFlags=0x000000C0, DataTransferLength=0x50)
2018-05-01 17:12:24.170.194 0000.000.214 hwStorStartIoPnp() (PNP2, QueryCapabilities, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x9, QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0, SrbFlags=0x00000100, DataTransferLength=0x8)
2018-05-01 17:12:24.170.194 0000.000.772 SessionId=0xFFA790EC
2018-05-01 17:12:24.170.194 0000.001.608 hwStorStartIoPnp() (PNP2, QueryCapabilities, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x9, QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0, SrbFlags=0x00000100, DataTransferLength=0x8)

// RAW socket is closed. It is no longer needed. All packets are sent and received by UDP socket.
2018-05-01 17:12:24.170.194 0000.000.779 RAW socket closed. status=0x00000000

// Windows reads disk successfully.
2018-05-01 17:12:24.170.194 0000.000.546 UdpPacketProc::receivedPong() ping=0.000.390 us
2018-05-01 17:12:26.297.837 0002.120.157 timeout! number=260, timeout=10 ms, resendCount=1
2018-05-01 17:12:26.326.471 0000.035.944 hwStorStartIo() (WMI)
2018-05-01 17:12:26.326.471 0000.000.603 hwStorStartIo() (WMI)
2018-05-01 17:12:34.791.624 0008.467.282 hwStorStartIoIoControl() (IO_CONTROL, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x0, QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0, SrbFlags=0x00000100, DataTransferLength=0x5C)
2018-05-01 17:12:34.791.624 0000.001.509 hwStorStartIoIoControl() (IO_CONTROL, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x0, QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0, SrbFlags=0x00000100, DataTransferLength=0x6C)
2018-05-01 17:12:39.832.438 0005.030.739 hwStorStartIoIoControl() (IO_CONTROL, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x0, QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0, SrbFlags=0x000000C0, DataTransferLength=0x34)

As you can see network initialization takes too long time. Windows waits too long in boot animation screen.

(1) Network adapter status changes from DOWN to UP. (takes 5 seconds)

(2) First packet is sent through the network adapter. (takes 10 seconds)

(3) ARP gratuitous is sent. Checking IP conflict… (takes 3 seconds)

I think I cannot reduce step (1) and step (3) maybe?

But I think step (2) can be reduced. It just looks like a TCP/IP initialization or binding delay? or NDIS delay? (I don’t know well about network driver composition part…)

How can I reduce these delays? Should I program a special network protocol driver? Can I send a packet directly through network adapter not using WSK?

Thank you for any suggestions.

Are you using StorPortNotification(LinkUp, …)
and StorPortNotification(LinkDown, …) in your code? I’ve found this to
delay storport.

On Wed, May 2, 2018 at 9:59 PM xxxxx@hanmail.net
wrote:

> This is my virtual storport driver log.
>
> Please see this log first.
>
> I commented for each line in detail.
>
>
>
>
>
> // DriverEntry function is called
> [ForeDisk] DriverEntry() driverObject=0xFFFFDB8CF2B06060,
> registryPath=\Registry\Machine\System\CurrentControlSet\Services\TenyearsStorPort
>
> // StorPortInitialize() function is being called.
> [ForeDisk] DriverEntry()->StorPortInitialize() BEGIN
>
> // StorPortInitialize() function is finished with status STATUS_SUCCESS
> [ForeDisk] DriverEntry()->StorPortInitialize() END (status=0x00000000)
>
> // Just log begin line
> 2018-05-01 17:12:06.107.461 0000.000.001
> ================================================================
>
> // My virtual storport driver name and version
> 2018-05-01 17:12:06.107.461 0000.000.222 foreDisk version ‘1.00 Debug’
>
> // hwStorFindAdapter() is called.
> 2018-05-01 17:12:06.107.461 0000.000.426 hwStorFindAdapter()
> deviceExtension=0xFFFFDB8CF29FA550, hwContext=0xFFFFDB8CF19F2E40,
> busInformation=0xFFFFDB8CF2B50050, lowerDevice=0xFFFFDB8CF19F2E40,
> argumentString=, configInfo=0xFFFFDB8CF2B502D0, again=0xFFFFEB8E182060B0
>
> // WSK is initialized. (In another system thread A)
> 2018-05-01 17:12:06.107.461 0000.000.434 WSK initialized.
> status=0x00000000
>
> // hwStorInitialize() function is called.
> 2018-05-01 17:12:06.107.461 0000.000.001 hwStorInitialize()
>
> // hwStorAdapterControl() function is called.
> 2018-05-01 17:12:06.107.461 0000.000.576 hwStorAdapterControl()
> (QuerySupportedControlTypes)
>
> // RAW socket is created. (In system thread A)
> 2018-05-01 17:12:06.123.087 0000.021.123 RAW socket created.
> status=0x00000000
>
> // UDP socket is created. (In system thread A)
> 2018-05-01 17:12:06.123.087 0000.000.520 UDP socket created.
> status=0x00000000
>
> // On board network adapter “Realtek PCIe Gbe…” is Ethernet type and
> IfOperStatusDown status and NET_IF_ADMIN_STATUS_UP status.
> 2018-05-01 17:12:06.123.087 0000.000.248 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=2, AdminStatus=1
>
> // 1 second elapsed.
> 2018-05-01 17:12:07.138.724 0001.005.934 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=2, AdminStatus=1
>
> // 2 seconds elapsed.
> 2018-05-01 17:12:08.138.737 0001.000.004 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=2, AdminStatus=1
>
> // 3 seconds elapsed.
> 2018-05-01 17:12:09.138.750 0001.000.000 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=2, AdminStatus=1
>
> // 4 seconds elapsed.
> 2018-05-01 17:12:10.138.763 0001.000.011 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=2, AdminStatus=1
>
> // 5 seconds elapsed. OperStatus is changed to IfOperStatusUp status
> finally.
> 2018-05-01 17:12:11.138.776 0001.000.023 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
>
> // RAW socket has sent a DHCP reqeust packet. (But the packet is not sent
> actually. I watched using wireshark on another peer computer.)
> 2018-05-01 17:12:11.138.776 0000.000.323 DHCP request [4] Realtek PCIe
> GbE Family Controller (C0-3F-D5-A8-AE-47)
>
> // Resend DHCP request packet 1 second later. (1 second elapsed)
> 2018-05-01 17:12:12.138.789 0000.999.680 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
> 2018-05-01 17:12:12.138.789 0000.000.282 DHCP request [4] Realtek PCIe
> GbE Family Controller (C0-3F-D5-A8-AE-47)
>
> // Resend DHCP request packet 1 second later. (2 seconds elapsed)
> 2018-05-01 17:12:13.138.801 0000.999.731 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
> 2018-05-01 17:12:13.138.801 0000.000.289 DHCP request [4] Realtek PCIe
> GbE Family Controller (C0-3F-D5-A8-AE-47)
>
> // Resend DHCP request packet 1 second later. (3 seconds elapsed)
> 2018-05-01 17:12:14.138.814 0000.999.720 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
> 2018-05-01 17:12:14.138.814 0000.000.322 DHCP request [4] Realtek PCIe
> GbE Family Controller (C0-3F-D5-A8-AE-47)
>
> // Resend DHCP request packet 1 second later. (4 seconds elapsed)
> 2018-05-01 17:12:15.138.827 0000.999.696 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
> 2018-05-01 17:12:15.138.827 0000.000.292 DHCP request [4] Realtek PCIe
> GbE Family Controller (C0-3F-D5-A8-AE-47)
>
> // Resend DHCP request packet 1 second later. (5 seconds elapsed)
> 2018-05-01 17:12:16.138.840 0000.999.714 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
> 2018-05-01 17:12:16.138.840 0000.000.293 DHCP request [4] Realtek PCIe
> GbE Family Controller (C0-3F-D5-A8-AE-47)
>
> // Resend DHCP request packet 1 second later. (6 seconds elapsed)
> 2018-05-01 17:12:17.138.853 0000.999.718 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
> 2018-05-01 17:12:17.138.853 0000.000.298 DHCP request [4] Realtek PCIe
> GbE Family Controller (C0-3F-D5-A8-AE-47)
>
> // Resend DHCP request packet 1 second later. (7 seconds elapsed)
> 2018-05-01 17:12:18.138.866 0000.999.719 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
> 2018-05-01 17:12:18.138.866 0000.000.287 DHCP request [4] Realtek PCIe
> GbE Family Controller (C0-3F-D5-A8-AE-47)
>
> // Resend DHCP request packet 1 second later. (8 seconds elapsed)
> 2018-05-01 17:12:19.138.879 0000.999.719 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
> 2018-05-01 17:12:19.138.879 0000.000.314 DHCP request [4] Realtek PCIe
> GbE Family Controller (C0-3F-D5-A8-AE-47)
>
> // Resend DHCP request packet 1 second later. (9 seconds elapsed)
> 2018-05-01 17:12:20.138.892 0000.999.699 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
> 2018-05-01 17:12:20.138.892 0000.000.278 DHCP request [4] Realtek PCIe
> GbE Family Controller (C0-3F-D5-A8-AE-47)
>
> // DHCP response packet is received! IP address is manually set to
> 192.168.0.81 using CreateUnicastIpAddressEntry() function. Windows sends
> ARP gratuitous packet now.
> 2018-05-01 17:12:20.138.892 0000.002.018 DHCP response [4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) (192.168.0.81)
>
> // IP conflict detection waiting (1 second)
> 2018-05-01 17:12:21.138.905 0000.997.718 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
>
> // IP conflict detection waiting (2 seconds)
> 2018-05-01 17:12:22.138.918 0001.000.009 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
>
> // IP conflict detection waiting (3 seconds)
> 2018-05-01 17:12:23.138.930 0001.000.013 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
>
> // IP conflict detection waiting (4 seconds)
> 2018-05-01 17:12:24.138.943 0001.000.019 Network Interface[4] Realtek
> PCIe GbE Family Controller (C0-3F-D5-A8-AE-47) Type=6, HardwareInterface=1,
> OperStatus=1, AdminStatus=1
>
> // Finally WSK UDP socket has received storage information from server.
> 2018-05-01 17:12:24.170.194 0000.031.716 LogicalUnitInfosCount=1
> 2018-05-01 17:12:24.170.194 0000.000.186 LogicalUnitInfos[0]
> key=0xF07ED102, name=VMDK-Windows10
>
> // Normal storport callback function calls.
> 2018-05-01 17:12:24.170.194 0000.000.576 hwStorStartIoPnp() (PNP2,
> QueryCapabilities, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x9,
> QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0,
> SrbFlags=0x00000100, DataTransferLength=0x8)
> 2018-05-01 17:12:24.170.194 0000.001.494 hwStorStartIoIoControl()
> (IO_CONTROL, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0xFE,
> QueueAction=0x20, CdbLength=0x0, SenseInfoBufferLength=0xFF,
> SrbFlags=0x00300142, DataTransferLength=0x22C)
> 2018-05-01 17:12:24.170.194 0000.000.385 hwStorStartIoIoControl()
> (IO_CONTROL, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0xFE,
> QueueAction=0x20, CdbLength=0x0, SenseInfoBufferLength=0xFF,
> SrbFlags=0x00000142, DataTransferLength=0x110)
> 2018-05-01 17:12:24.170.194 0000.000.425 hwStorStartIoIoControl()
> (IO_CONTROL, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x0,
> QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0,
> SrbFlags=0x000000C0, DataTransferLength=0x50)
> 2018-05-01 17:12:24.170.194 0000.000.214 hwStorStartIoPnp() (PNP2,
> QueryCapabilities, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x9,
> QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0,
> SrbFlags=0x00000100, DataTransferLength=0x8)
> 2018-05-01 17:12:24.170.194 0000.000.772 SessionId=0xFFA790EC
> 2018-05-01 17:12:24.170.194 0000.001.608 hwStorStartIoPnp() (PNP2,
> QueryCapabilities, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x9,
> QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0,
> SrbFlags=0x00000100, DataTransferLength=0x8)
>
> // RAW socket is closed. It is no longer needed. All packets are sent and
> received by UDP socket.
> 2018-05-01 17:12:24.170.194 0000.000.779 RAW socket closed.
> status=0x00000000
>
> // Windows reads disk successfully.
> 2018-05-01 17:12:24.170.194 0000.000.546 UdpPacketProc::receivedPong()
> ping=0.000.390 us
> 2018-05-01 17:12:26.297.837 0002.120.157
> timeout! number=260, timeout=10 ms, resendCount=1
> 2018-05-01 17:12:26.326.471 0000.035.944 hwStorStartIo() (WMI)
> 2018-05-01 17:12:26.326.471 0000.000.603 hwStorStartIo() (WMI)
> 2018-05-01 17:12:34.791.624 0008.467.282 hwStorStartIoIoControl()
> (IO_CONTROL, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x0,
> QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0,
> SrbFlags=0x00000100, DataTransferLength=0x5C)
> 2018-05-01 17:12:34.791.624 0000.001.509 hwStorStartIoIoControl()
> (IO_CONTROL, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x0,
> QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0,
> SrbFlags=0x00000100, DataTransferLength=0x6C)
> 2018-05-01 17:12:39.832.438 0005.030.739 hwStorStartIoIoControl()
> (IO_CONTROL, PathId=0x0, TargetId=0x0, Lun=0x0, QueueTag=0x0,
> QueueAction=0x0, CdbLength=0x0, SenseInfoBufferLength=0x0,
> SrbFlags=0x000000C0, DataTransferLength=0x34)
>
>
>
>
>
> As you can see network initialization takes too long time. Windows waits
> too long in boot animation screen.
>
> (1) Network adapter status changes from DOWN to UP. (takes 5 seconds)
>
> (2) First packet is sent through the network adapter. (takes 10 seconds)
>
> (3) ARP gratuitous is sent. Checking IP conflict… (takes 3 seconds)
>
> I think I cannot reduce step (1) and step (3) maybe?
>
> But I think step (2) can be reduced. It just looks like a TCP/IP
> initialization or binding delay? or NDIS delay? (I don’t know well about
> network driver composition part…)
>
> How can I reduce these delays? Should I program a special network protocol
> driver? Can I send a packet directly through network adapter not using WSK?
>
> Thank you for any suggestions.
>
> —
> NTDEV is sponsored by OSR
>
> Visit the list online at: <
> http://www.osronline.com/showlists.cfm?list=ntdev&gt;
>
> MONTHLY seminars on crash dump analysis, WDF, Windows internals and
> software drivers!
> Details at http:
>
> To unsubscribe, visit the List Server section of OSR Online at <
> http://www.osronline.com/page.cfm?name=ListServer&gt;
>


Jamey Kirby
Disrupting the establishment since 1964

This is a personal email account and as such, emails are not subject to
archiving. Nothing else really matters.
</http:>

No sir. I never called StorPortNotification() function.

I have got some more logs.

TCP/IP protocol driver sends some packets in step (2) but not my raw packets.

I have captured packets by wireshark.

—> Step (2) (takes 10 seconds)
9.949492 : ICMPv6 / Neighbor Solicitation for fe80::1dca:b4bb:50f:de06
9.949555 : ICMPv6 / Router Solicitation
9.949603 : ICMPv6 / Multicast Listener Report Message v2
10.450793 : ICMPv6 / Multicast Listener Report Message v2
10.952116 : ICMPv6 / Neighbor Advertisement fe80::1dca:b4bb:50f:de06 (ovr) is at 00:0c:29:a8:fa:93
13.960307 : ICMPv6 / Router Solicitation from 00:0c:29:a8:fa:93
16.466749 : ARP / Who has 169.254.222.6? Tell 0.0.0.0
17.469285 : ARP / Who has 169.254.222.6? Tell 0.0.0.0
17.986472 : ICMPv6 / Router Solicitation from 00:0c:29:a8:fa:93
18.487704 : ARP / Who has 169.254.222.6? Tell 0.0.0.0
19.475174 : ARP / Gratuitous ARP for 169.254.222.6 (Request)
—> Step (3)
19.962177 : DHCP / DHCP Discover - Transaction ID 0xc25147dd (THIS IS MY RAW PACKET!!!)

What is TCP/IP protocol doing in step (2)? ICMPv6? Is it necessary?

I have disabled TCP/IPv6 at network adapter settings and ICMPv6 packets disappeared but it took same 10 seconds just starting with ARP packet.

If I cannot shorten this delay then which one is better option building a NDIS filter driver or building a custom protocol driver?