Why am I getting INSANELY incorrect values for the run duration of a process?

Question

Basically, I want to time the run duration of an external process not triggered by my code. In order to achieve this, I am subscribing to the events of the specific process starting and ending, by the process name, using the following code (based on this answer):

private ManagementEventWatcher ProcessStartWatcher(string processName)
{
    string queryString =
        "SELECT TargetInstance" +
        "  FROM __InstanceCreationEvent " +
        "WITHIN  1 " +
        " WHERE TargetInstance ISA 'Win32_Process' " +
        "   AND TargetInstance.Name = '" + processName + "'";

    // The dot in the scope means use the current machine
    string scope = @"\\.\root\CIMV2";

    // Create a watcher and listen for events
    ManagementEventWatcher watcher = new ManagementEventWatcher(scope, queryString);
    watcher.EventArrived += ProcessStarted;
    watcher.Start();
    return watcher;
}

private ManagementEventWatcher ProcessEndWatcher(string processName)
{
    string queryString =
        "SELECT TargetInstance" +
        "  FROM __InstanceDeletionEvent " +
        "WITHIN  1 " +
        " WHERE TargetInstance ISA 'Win32_Process' " +
        "   AND TargetInstance.Name = '" + processName + "'";

    // The dot in the scope means use the current machine
    string scope = @"\\.\root\CIMV2";

    // Create a watcher and listen for events
    ManagementEventWatcher watcher = new ManagementEventWatcher(scope, queryString);
    watcher.EventArrived += ProcessEnded;
    watcher.Start();
    return watcher;
}

private void ProcessStarted(object sender, EventArrivedEventArgs e)
{
    this.processStart = DateTime.Now;
}

private void ProcessEnded(object sender, EventArrivedEventArgs e)
{
    // use time recorded from ProcessStarted to calculate run duration, write to log file
    this.logger.addRuntimeData((DateTime.Now - this.processStart).TotalSeconds);
}

The addRuntimeData(double seconds) method is defined as:

public void addRuntimeData(double seconds)
{
    this.runDurations.Add(seconds);
    if (this.runDurations.Count > Properties.Settings.Default.MaxRunDurationData)
        this.runDurations.RemoveAt(0);
    this.updateLog();
}

public void updateLog()
{
    this.logfileDirectory = Properties.Settings.Default.LogfileDirectory;
    this.logfileFullPath = logfileDirectory + this.task.Name.toValidFilename() + this.logfileExtension;
    Directory.CreateDirectory(logfileDirectory); // create directory if it does not already exist
    this.toXElement().Save(this.logfileFullPath); // generate the XML and write it to the log file
}

Right now, I am just attempting to time a test process I wrote, and all the test process does is a single call to Console.WriteLine("Test process");, so appropriate values for the recorded duration should roughly be in the range 0-2 seconds.

Sometimes, I get values that are appropriate, and sometimes I get values that are literally not possible to have been recorded, such as 63619141321.2978 seconds. This is equal to roughly 2017.3 years, which makes me think that it might have something to do with the start time being recorded as 01/01/0001 00:00:01 or something like that; is it possible that the issue has something to do with this?

If this is an issue that I can't help (like, for example, if it has something to do with how/when the OS triggers the messages), is there a way that I can filter out these obviously invalid data points?

Answer 1

You're basically right about 01/01/0001 00:00:01.

Creating a DateTime object starts it at 1/1/0001 12:00:00 AM. You commented that processStart is declared without initialization which means it will have the default start time of 1/1/0001 12:00:00 AM. I'm guessing that ProcessEnd is being fired before ProcessStart is being fired.

The Below code produces a similar result as you described and uses a DateTime that is not changed after being declared.

private static DateTime date;

public static void Main(string[] args) {
    const double largeVal = 63619141321;

    Console.WriteLine(date.ToString());

    double totalSeconds = (DateTime.Now - date).TotalSeconds;
    Console.WriteLine(totalSeconds - largeVal);

    Console.WriteLine("Press any key to continue . . . ");
    Console.ReadKey(true);
}

Answer 2

The underlying issue is that ManagementEventWatcher is fundamentally a polling mechanism and the end event might get picked up before a start event for a very short process. If the start time has never been initialized (default value is 1/1/0001) then you'd see what you've described. Practically speaking that might not be a realistic use case, but it can happen, as you've observed. I think the best way to fix it is to just do away with recording the start time from the process start event.

You don't really need to see the process started event to calculate the total run time. You can grab the Win32_Process instance off of the end event and use the CreationDate to calculate the total run time of the process. I noticed that TerminationDate was not necessarily set yet. In that case, I just use the current time the end event was fired:

private static void ProcessEnded(object sender, EventArrivedEventArgs e)
{
    Console.WriteLine($"Process ended event at: {DateTime.Now}");
    var targetProcess = e.NewEvent.Properties["TargetInstance"].Value as ManagementBaseObject;
    if (targetProcess != null)
    {
        Console.WriteLine("Properties:");
        foreach (PropertyData data in targetProcess.Properties)
        {
            Console.WriteLine($"{data.Name} = {data.Value}");
        }

        DateTime creationDate = GetDateTimeOrDefault(targetProcess.Properties["CreationDate"], DateTime.Now);
        DateTime terminationDate = GetDateTimeOrDefault(targetProcess.Properties["TerminationDate"], DateTime.Now);

        var totalRunTime = (terminationDate - creationDate).TotalSeconds;
        Console.WriteLine($"Creation: {creationDate}, Termination: {terminationDate}, Elapsed: {totalRunTime}");
        // this.logger.addRuntimeData(totalRunTime);
    }
    else
    {
        Console.WriteLine("Could not get target process");
    }
}

private static DateTime GetDateTimeOrDefault(PropertyData managementDateProperty, DateTime defaultValue)
{
    string dateString = managementDateProperty.Value as string;
    if (!string.IsNullOrEmpty(dateString))
    {
        return ManagementDateTimeConverter.ToDateTime(dateString);
    }
    else
    {
        return defaultValue;
    }
}