Oshi: Process StartTime not exact on windows

[jflefebvre06]

On windows, process startTime is not equals to ProcessHandle().info().startInstant()

public static void main(final String[] args) {

        System.out.println("Start");

        final OperatingSystem operatingSystem = new SystemInfo().getOperatingSystem();
        ProcessHandle.allProcesses().filter(p -> p.info().startInstant().isPresent()).forEach(p -> {

            final OSProcess oshiProcess = operatingSystem.getProcess((int) p.pid());

            final Instant processInstant = p.info().startInstant().orElseThrow();
            final Instant oshiInstant = Instant.ofEpochMilli(oshiProcess.getStartTime());

            if (processInstant.equals(oshiInstant)) {
                System.out.println("Same");
            } else {
                final long deltaMilli = oshiInstant.toEpochMilli() - processInstant.toEpochMilli();

                System.out.println(deltaMilli + " milli delta " + oshiInstant + " - " + processInstant);
            }
        });

        System.out.println("End");

    }

Start
5 milli delta 2020-07-15T04:47:37.022Z - 2020-07-15T04:47:37.017Z
2 milli delta 2020-07-15T04:47:37.045Z - 2020-07-15T04:47:37.043Z
3 milli delta 2020-07-15T04:47:37.086Z - 2020-07-15T04:47:37.083Z
2 milli delta 2020-07-15T04:47:37.168Z - 2020-07-15T04:47:37.166Z
3 milli delta 2020-07-15T04:47:37.503Z - 2020-07-15T04:47:37.500Z
3 milli delta 2020-07-15T04:47:38.072Z - 2020-07-15T04:47:38.069Z
2 milli delta 2020-07-15T04:47:38.670Z - 2020-07-15T04:47:38.668Z
1 milli delta 2020-07-15T04:47:38.905Z - 2020-07-15T04:47:38.904Z
1 milli delta 2020-07-15T04:47:39.291Z - 2020-07-15T04:47:39.290Z
1 milli delta 2020-07-15T04:47:39.461Z - 2020-07-15T04:47:39.460Z
1 milli delta 2020-07-15T04:47:39.948Z - 2020-07-15T04:47:39.947Z
1 milli delta 2020-07-15T04:47:40.156Z - 2020-07-15T04:47:40.155Z
2 milli delta 2020-07-15T04:47:40.939Z - 2020-07-15T04:47:40.937Z
1 milli delta 2020-07-15T04:47:41.208Z - 2020-07-15T04:47:41.207Z
1 milli delta 2020-07-15T04:47:44.124Z - 2020-07-15T04:47:44.123Z
2 milli delta 2020-07-15T04:47:47.081Z - 2020-07-15T04:47:47.079Z
3 milli delta 2020-07-15T04:47:51.486Z - 2020-07-15T04:47:51.483Z
2 milli delta 2020-07-15T04:47:51.928Z - 2020-07-15T04:47:51.926Z
2 milli delta 2020-07-15T04:47:52.649Z - 2020-07-15T04:47:52.647Z
2 milli delta 2020-07-15T04:47:53.959Z - 2020-07-15T04:47:53.957Z
2 milli delta 2020-07-15T04:47:54.101Z - 2020-07-15T04:47:54.099Z
2 milli delta 2020-07-15T04:47:54.567Z - 2020-07-15T04:47:54.565Z
2 milli delta 2020-07-15T04:47:55.149Z - 2020-07-15T04:47:55.147Z
2 milli delta 2020-07-15T04:48:13.603Z - 2020-07-15T04:48:13.601Z
2 milli delta 2020-07-15T04:48:15.259Z - 2020-07-15T04:48:15.257Z
2 milli delta 2020-07-15T04:48:53.523Z - 2020-07-15T04:48:53.521Z
2 milli delta 2020-07-15T04:49:39.656Z - 2020-07-15T04:49:39.654Z
2 milli delta 2020-07-15T04:49:54.703Z - 2020-07-15T04:49:54.701Z
1 milli delta 2020-07-15T04:50:29.008Z - 2020-07-15T04:50:29.007Z
1 milli delta 2020-07-15T04:50:29.010Z - 2020-07-15T04:50:29.009Z
1 milli delta 2020-07-15T04:50:58.988Z - 2020-07-15T04:50:58.987Z
2 milli delta 2020-07-15T04:52:42.591Z - 2020-07-15T04:52:42.589Z
1 milli delta 2020-07-15T04:53:42.127Z - 2020-07-15T04:53:42.126Z
2 milli delta 2020-07-15T04:53:42.187Z - 2020-07-15T04:53:42.185Z
2 milli delta 2020-07-15T04:53:42.295Z - 2020-07-15T04:53:42.293Z
1 milli delta 2020-07-15T04:53:42.314Z - 2020-07-15T04:53:42.313Z
1 milli delta 2020-07-15T04:53:42.422Z - 2020-07-15T04:53:42.421Z
1 milli delta 2020-07-15T04:53:42.518Z - 2020-07-15T04:53:42.517Z
1 milli delta 2020-07-15T04:53:42.554Z - 2020-07-15T04:53:42.553Z
1 milli delta 2020-07-15T04:53:42.588Z - 2020-07-15T04:53:42.587Z
1 milli delta 2020-07-15T04:54:02.978Z - 2020-07-15T04:54:02.977Z
1 milli delta 2020-07-15T04:57:42.372Z - 2020-07-15T04:57:42.371Z
1 milli delta 2020-07-15T04:58:54.476Z - 2020-07-15T04:58:54.475Z
2 milli delta 2020-07-15T05:37:43.781Z - 2020-07-15T05:37:43.779Z
1 milli delta 2020-07-15T05:44:38.584Z - 2020-07-15T05:44:38.583Z
2 milli delta 2020-07-15T05:44:39.490Z - 2020-07-15T05:44:39.488Z
2 milli delta 2020-07-15T06:09:15.083Z - 2020-07-15T06:09:15.081Z
1 milli delta 2020-07-15T06:10:16.633Z - 2020-07-15T06:10:16.632Z
2 milli delta 2020-07-15T06:20:21.683Z - 2020-07-15T06:20:21.681Z
2 milli delta 2020-07-15T06:20:32.777Z - 2020-07-15T06:20:32.775Z
1 milli delta 2020-07-15T06:41:11.321Z - 2020-07-15T06:41:11.320Z
1 milli delta 2020-07-15T06:41:23.419Z - 2020-07-15T06:41:23.418Z
2 milli delta 2020-07-15T07:25:59.846Z - 2020-07-15T07:25:59.844Z
1 milli delta 2020-07-15T07:26:04.230Z - 2020-07-15T07:26:04.229Z
1 milli delta 2020-07-15T07:27:08.536Z - 2020-07-15T07:27:08.535Z
End

No delta on unix.

[dbwiddis]

What's a few milliseconds between friends? :)

OSHI derives the process start time from the registry's HKEY_PERFORMANCE_DATA. This is equivalent to grabbing the value from the Process Performance Counters.

Java 9+'s ProcessHandle gets the start time from the GetProcessTimes() function.

The counters used in both cases are in 100-nanosecond units (Windows FILETIME), converted to milliseconds.

I don't know which one is more authoritative, given that the windows clock ticks are in 1/64 second increments (15.625 milliseconds). ~It appears from this page that the performance counters are less accurate (10 to 16 ms resolution is mentioned) for performance reasons.~

Given that OSHI targets Java 8, and we are already fetching the start time along with other process data (and it's in the same clock-tick units as the user and kernel time used for % CPU calculations) I'm content with the situation as-is.

Do you need more precision on these start times?

[dbwiddis]

Hmm, it's not a matter of precision. I compared the elapsed time between the various timestamps and it's almost always exactly equal, plus or minus a millisecond. And it's very consistent with the counter shortly after the process times value.

Somewhere internally in Windows, it's recording one start time in one location (getProcessTimes), and a few milliseconds later, recording a different start time in a different location (counters). Since both times are probably recorded as part of the "startup routine" of a process, I suspect an argument can be made that they're both correct, depending on your interpretation of exactly when a process is started.

I could replicate the ProcessHandle code in OSHI using JNA but it'd be a lot less efficient than the JDK's native implementation. Maybe this would be a good use case for a multi-release JAR.

[jflefebvre06]

In our program we need to retreive ProcessHandle from oshi process and ProcessHandle equality is defined by same pid and same startInstant.

Code from openjdk

 @Override
    public boolean equals(Object obj) {
        if (this == obj) {
            return true;
        }
        if (obj instanceof ProcessHandleImpl) {
            ProcessHandleImpl other = (ProcessHandleImpl) obj;
            return (pid == other.pid) &&
                    (startTime == other.startTime
                        || startTime == 0
                        || other.startTime == 0);
        }
        return false;
    }

[dbwiddis]

equality is defined by same pid and same startInstant.

(Or a startInstant of 0, apparently.)

Since OSHI doesn't produce that type of object we/you are free to define equality however we wish, and I think PID equality (and possibly parent PID equality) along with an an "approximately equal" (similar to floating point equality within some epsilon) startInstant would be sufficient. You could simply:

• Collect the JDK handles and put them in a map of pid-to-handle
• For each OSHI process, look up the PID to get a potential handle.
  
  
  
  • Sanity-check the handle to verify parent pid matches and start time is earlier than OSHI's start time (plus 16 milliseconds).
  
  

Some observations after more research:

• Performance counters (OSHI's source) use the QPC for timestamps. Per MSDN docs:
  
  
  
  • The QPC provides 1 microsecond (or better) resolution
  
  
  • The QPC is independent of and isn't synchronized to any external time reference.
  
  
  • The QPC is "typically the best method to use to time-stamp events and measure small time intervals that occur on the same system or virtual machine."
  
  
• Performance counters therefore provide a high-resolution, and accurate measure of process CPU usage, with very accurate up time values. (Kernel and User times are still processor-tick based.) However, the price of the resolution on elapsed time means not synchronizing with the system clock, as demonstrated above.
• The GetProcessTimes() function used internally in JDK9+uses a different clock for "start time". Since it's only measuring the value once it doesn't need the "interval" precision of the performance counter. And, in fact, it's pretty horrible for measuring CPU usage:
  
  
  
  • I assume this uses a "wall time" based timestamp
  
  
  • It doesn't provide an "up time" measurement.
    
    
    
    
    
    • There is no record of the timestamp at which time the snapshot was obtained, so one is forced to use System.currentMillis() either before or after (or both & average) the timestamp to attempt to get an "accurate" uptime.
    
    
    
  
  

So user and kernel time are probably similar in both (they increment in 1-tick units of 15.625 ms). Uptime is more accurate in the performance counter, and start time probably "matches wall clock time" in the JDK version.

• Collecting the the snapshot and iterating all processes is very efficient on JDK9+, as the entire procedure executes in native code.
• As a JDK8 target, OSHI would have to perform a native call for every process, incurring some latency, to get the same data, and then iterate through the process to attempt to match equality in exactly the way I'm suggesting you do, and adjusting the start time only. This would let you perform an "equality" check, but provide little benefit otherwise.
• Given the performance hit for very limited benefit, and the fact that the code on OSHI would be slower than doing it from within a JDK9+ external project, I'm not inclined to do this unless OSHI switches to a multi-release JAR project. If we do switch, then adding a new getter that returns a ProcessHandle seems like a good new feature.

[dbwiddis]

Umm... ok. After digging into this... there's no difference in the raw data. This is a bug in OSHI... while I have a 100ns perf time counter available, we just subtract off "now" captured from System.currentTimeMillis().

So this is an easily fixable problem.....

[dbwiddis]

OK, #1302 should fix this. It's updated in SNAPSHOT, can you test?

[jflefebvre06]

For better compatibility with ProcessHandle change pid type from int to long ?

[dbwiddis]

change pid type from int to long

Unfortunately that would break the API.

It's a good idea, though, since the PID on AIX is long internally and while Windows is 32-bit, it's unsigned. But it would require a major version bump and that's probably not happening for a while.

[dbwiddis]

Also I just updated the SNAPSHOT. There was still some rounding happening before some unnecessary subtraction which could have led to an off-by-1ms issue. I'm now directly storing the creation time so it should exactly match.