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.