-
Notifications
You must be signed in to change notification settings - Fork 5.5k
Fix inconsistent process start time #121935
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: main
Are you sure you want to change the base?
Changes from all commits
a127e2b
e579b6f
03a59b4
3c538b5
58aa814
cf3b124
8dc36ce
1dabd29
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -1277,6 +1277,105 @@ public void TestProcessStartTime() | |
| } | ||
| } | ||
| } | ||
|
|
||
| [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] | ||
| [PlatformSpecific(TestPlatforms.Linux | TestPlatforms.Android)] | ||
| public void StartTime_IsDeterministicAcrossProcesses() | ||
| { | ||
| // Makes sure multiple independent processes reading the same target process's | ||
| // StartTime all agree on the result — or at least agree as much as the math allows. | ||
| // | ||
| // We spawn 5 separate child processes, each one reads StartTime 10 times and | ||
| // reports all readings back. Then we look at all 50 values together and make sure | ||
| // they're all consistent. If the boot-time offset is stable, they should all | ||
| // cluster around the same value. If something is broken they'll scatter. | ||
| // | ||
| // The /10 thing: last digit of Ticks is floating-point noise (double only has | ||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. It is not clear what the "/10 thing" is this referring to. The actual code that this is referring to is ~50 lines below.
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Stating why we do /10 when measuring, it is also repeated ~50 lines later, if you think we can remove it from here, I am ok with it |
||
| // ~15-16 significant digits but Ticks needs 17-18), so two processes doing the | ||
| // same conversion independently can land on adjacent values purely by chance. | ||
| // Chopping the last digit before comparing filters that out without hiding | ||
| // any real drift. Or maybe I'm overthinking it and it's fine either way. | ||
|
|
||
| const int NumProcesses = 5; | ||
| const int ReadingsPerProcess = 10; | ||
|
|
||
| Process target = CreateProcessLong(); | ||
| target.Start(); | ||
|
|
||
| try | ||
| { | ||
| int targetPid = target.Id; | ||
| var allReadings = new List<long>(NumProcesses * ReadingsPerProcess); | ||
|
|
||
| for (int i = 0; i < NumProcesses; i++) | ||
| { | ||
| using (RemoteInvokeHandle handle = RemoteExecutor.Invoke( | ||
| (string pidStr, string countStr) => | ||
| { | ||
| int pid = int.Parse(pidStr); | ||
| int count = int.Parse(countStr); | ||
|
|
||
| // Take multiple readings inside this process and print each one. | ||
| // We re-read StartTime each time to make sure caching isn't | ||
| // masking a problem — every call should go back to /proc. | ||
| for (int j = 0; j < count; j++) | ||
| { | ||
| // Force a fresh Process object each iteration so we're not | ||
| // just reading a cached value from the same instance | ||
| using Process fresh = Process.GetProcessById(pid); | ||
| Console.WriteLine(fresh.StartTime.Ticks); | ||
| } | ||
|
|
||
| return RemoteExecutor.SuccessExitCode; | ||
| }, | ||
| targetPid.ToString(), | ||
| ReadingsPerProcess.ToString(), | ||
| new RemoteInvokeOptions { StartInfo = new ProcessStartInfo { RedirectStandardOutput = true, RedirectStandardError = true } })) | ||
| { | ||
| foreach (ProcessOutputLine line in handle.Process.ReadAllLines()) | ||
| { | ||
| Assert.False(line.StandardError); | ||
| Assert.True( | ||
| long.TryParse(line.Content, out long ticks), | ||
| $"Child process {i + 1} returned non-numeric output: '{line}'"); | ||
|
|
||
| allReadings.Add(ticks); | ||
| } | ||
| } | ||
|
|
||
| Assert.True( | ||
| allReadings.Count >= (i + 1) * ReadingsPerProcess, | ||
| $"Child process {i + 1} returned fewer than {ReadingsPerProcess} readings"); | ||
| } | ||
|
|
||
| Assert.Equal(NumProcesses * ReadingsPerProcess, allReadings.Count); | ||
|
|
||
| // Chop last digit off everything before comparing — that digit is just | ||
| // floating-point noise from the jiffies → double → Ticks conversion and | ||
| // tells us nothing real about whether the values agree. | ||
| List<long> normalized = allReadings.Select(t => t / 10).ToList(); | ||
|
|
||
| long referenceValue = normalized[0]; | ||
|
|
||
| // All 50 readings across all 5 processes should agree on the same value. | ||
| // If they don't, the boot-time offset is drifting between processes which | ||
| // is exactly the bug this PR is fixing. | ||
| Assert.All(normalized, reading => | ||
| Assert.True( | ||
| reading == referenceValue, | ||
| $"StartTime reading diverged: got {reading * 10} ticks, " + | ||
| $"expected ~{referenceValue * 10} ticks " + | ||
| $"(diff: {Math.Abs(reading - referenceValue) * 10} ticks = " + | ||
| $"{TimeSpan.FromTicks(Math.Abs(reading - referenceValue) * 10).TotalMilliseconds:F4} ms). " + | ||
| $"All readings: [{string.Join(", ", allReadings)}]")); | ||
| } | ||
| finally | ||
| { | ||
| target.Kill(); | ||
| target.WaitForExit(); | ||
| target.Dispose(); | ||
| } | ||
| } | ||
|
|
||
| [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))] | ||
| public void ProcessStartTime_Deterministic_Across_Instances() | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -100,7 +100,7 @@ int64_t SystemNative_GetBootTimeTicks(void) | |
|
|
||
| int64_t sinceBootTicks = ((int64_t)ts.tv_sec * SecondsToTicks) + (ts.tv_nsec / TicksToNanoSeconds); | ||
|
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Do the tests need to account to for the thread being rescheduled at this point? We can see very significant drift when that happens. I think the test as written is going to be flaky.
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I thought of using Yield(), but it is a no-op if nothing else wants to run so reads could stay on the same scheduling slice. Sleep(1) blocks for at least one timer tick, forcing a real
Member
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I do not think you can reliably trick the scheduler into not rescheduling it. Also, these tricks are expensive. I think the best way to make this reliable may be to read CLOCK_BOOTTIME second time, and keep looping if it is too far from the first read.
Contributor
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Can you provide the fix yourself for the test part? |
||
|
|
||
| result = clock_gettime(CLOCK_REALTIME_COARSE, &ts); | ||
| result = clock_gettime(CLOCK_REALTIME, &ts); | ||
|
adamsitnik marked this conversation as resolved.
adamsitnik marked this conversation as resolved.
|
||
| assert(result == 0); | ||
|
|
||
| int64_t sinceEpochTicks = ((int64_t)ts.tv_sec * SecondsToTicks) + (ts.tv_nsec / TicksToNanoSeconds); | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Do we need 5 processes? 2 (or 3 max) should be enough. Launching child processes is relatively expensive.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
2 seemed too few, two processes could read same number by coincidence, the more processes count the less coincide chance, if you think we are ok with 3 let's do that.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The test does not need to find the problem 100% of the time. It is ok if the test finds the problem only fraction of the time.