Why the creation time gotten from WaitForInputIdle is later than the calling of App constructor in WPF?

Question

I want to test the startup time duration for a WPF program, such as the simplest WPF one through the VS2019.
In the App constructor(you might need to manually create it in case it is not there), I am writing the following log into a file for later reference:

         System.IO.File.WriteAllText(@"C:\Users\Public\wpfTest.txt",
            string.Format("Entering: {1} {2}",
                          DateTime.Now.ToString("hh.mm.ss.ffffff"),
                          Environment.NewLine));

Then in create another win32 console project with name AppLauncher which accept a cmdline parameter.
The parameter is the .exe file name with full path that we want to measure to get the startup time duration.
The usage format is: AppLauncher c:\temp\WpfTest.exe

Then you will find that the App constructor in the WpfTest.exe is earlier than the creation time from WaitForInputIdle.

So here comes the question: Why the creation time gotten from WaitForInputIdle is later than the calling of App constructor in WPF?

In my testing environment, from the App constructor, the log is: Entering: 08.05.47.810338
The Applauncher output is: Start Time: 8:5:47.835

As we could see: the former is earlier than the latter.

=====================================================================================

The code snippet for the AppLauncher(please note that line 48 is using the Windows API GetProcessTimes to get the creation time):

// AppLauncher.cpp : This file contains the 'main' function. Program execution begins and ends there.
//

#include <Windows.h>
#include <tchar.h>
#include <iostream>

using namespace std;

int _tmain(int argc, TCHAR* argv[], TCHAR* envp[])
{
   STARTUPINFO si;
   PROCESS_INFORMATION pi;

   ZeroMemory(&si, sizeof(si));
   si.cb = sizeof(si);
   ZeroMemory(&pi, sizeof(pi));

   FILETIME loadEndTime;
   SYSTEMTIME currLocalTime;

   SYSTEMTIME currTime;
   ::GetSystemTime(&currTime);
   SystemTimeToFileTime(&currTime, &loadEndTime);

   BOOL ret = ::CreateProcess(NULL, argv[1], NULL, NULL, FALSE, 0, NULL, NULL, &si, &pi);
   if (!ret) {
      DWORD dwError = GetLastError();
      cout << "Failed to start " << wstring(argv[1]).c_str() << ", error: " << dwError << endl;
   }

   ::GetSystemTime(&currTime);
   SystemTimeToFileTime(&currTime, &loadEndTime);


   WaitForInputIdle(pi.hProcess, 5000);

   FILETIME creationTime, exitTime, kernelTime, userTime;

   ::GetSystemTime(&currTime);
   SystemTimeToFileTime(&currTime, &loadEndTime);

   SystemTimeToTzSpecificLocalTime(NULL, &currTime, &currLocalTime);
   cout << "Start Time: " << currLocalTime.wHour << ":"
        << currLocalTime.wMinute << ":" << currLocalTime.wSecond
        << "." << currLocalTime.wMilliseconds << endl;

   ::GetProcessTimes(pi.hProcess, &creationTime, &exitTime, &kernelTime, &userTime);

   CloseHandle(pi.hProcess);
   CloseHandle(pi.hThread);

   LONGLONG diffInTicks = ((LARGE_INTEGER*)&loadEndTime)->QuadPart - ((LARGE_INTEGER*)&creationTime)->QuadPart;
   cout << "Start Used Time: " << diffInTicks / 10000 << " ms" << endl;

   return 0;
}

Answer 1

Maybe the time difference, which seems insignificant, reflects the delays needed to format and write the text to log file, to exit the constructor and to achieve the “Input Idle” state.