script: Create a CrossProcessInstant to enable serializable monotonic time (#33282)

Up until now, Servo was using a very old version of time to get a
cross-process monotonic timestamp (using `time::precise_time_ns()`).
This change replaces the usage of old time with a new serializable
monotonic time called `CrossProcessInstant` and uses it where `u64`
timestamps were stored before. The standard library doesn't provide this
functionality because it isn't something you can do reliably on all
platforms. The idea is that we do our best and then fall back
gracefully.

This is a big change, because Servo was using `u64` timestamps all over
the place some as raw values taken from `time::precise_time_ns()` and
some as relative offsets from the "navigation start," which is a concept
similar to DOM's `timeOrigin` (but not exactly the same). It's very
difficult to fix this situation without fixing it everywhere as the
`Instant` concept is supposed to be opaque. The good thing is that this
change clears up all ambiguity when passing times as a `time::Duration`
is unit agnostic and a `CrossProcessInstant` represents an absolute
moment in time.

The `time` version of `Duration` is used because it can both be negative
and is also serializable.

Good things:
 - No need too pass around `time` and `time_precise` any longer.
   `CrossProcessInstant` is also precise and monotonic.
 - The distinction between a time that is unset or at `0` (at some kind
   of timer epoch) is now gone.

There still a lot of work to do to clean up timing, but this is the
first step. In general, I've tried to preserve existing behavior, even
when not spec compliant, as much as possible. I plan to submit followup
PRs fixing some of the issues I've noticed.

Signed-off-by: Martin Robinson <mrobinson@igalia.com>
This commit is contained in:
Martin Robinson 2024-09-05 11:50:09 -07:00 committed by GitHub
parent 35baf056f6
commit 312cf0df08
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
51 changed files with 854 additions and 665 deletions

View file

@ -2,8 +2,7 @@
* License, v. 2.0. If a copy of the MPL was not distributed with this
* file, You can obtain one at https://mozilla.org/MPL/2.0/. */
use std::time::{SystemTime, UNIX_EPOCH};
use base::cross_process_instant::CrossProcessInstant;
use ipc_channel::ipc;
use metrics::{InteractiveFlag, InteractiveMetrics, ProfilerMetadataFactory, ProgressiveWebMetric};
use profile_traits::time::{ProfilerChan, TimerMetadata};
@ -25,7 +24,7 @@ fn test_interactive() -> InteractiveMetrics {
assert_eq!((&interactive).get_navigation_start(), None);
assert_eq!(interactive.get_tti(), None);
interactive.set_navigation_start(time::precise_time_ns());
interactive.set_navigation_start(CrossProcessInstant::now());
interactive
}
@ -56,21 +55,24 @@ fn test_set_mta() {
let profiler_metadata_factory = DummyProfilerMetadataFactory {};
let interactive = test_interactive();
let t = time::precise_time_ns();
let now = CrossProcessInstant::now();
interactive.maybe_set_tti(
&profiler_metadata_factory,
InteractiveFlag::TimeToInteractive(t),
InteractiveFlag::TimeToInteractive(now),
);
let mta = interactive.get_main_thread_available();
assert!(mta.is_some());
assert_eq!(mta, Some(t));
let main_thread_available_time = interactive.get_main_thread_available();
assert!(main_thread_available_time.is_some());
assert_eq!(main_thread_available_time, Some(now));
//try to overwrite
interactive.maybe_set_tti(
&profiler_metadata_factory,
InteractiveFlag::TimeToInteractive(time::precise_time_ns()),
InteractiveFlag::TimeToInteractive(CrossProcessInstant::now()),
);
assert_eq!(
interactive.get_main_thread_available(),
main_thread_available_time
);
assert_eq!(interactive.get_main_thread_available(), mta);
assert_eq!(interactive.get_tti(), None);
}
@ -79,23 +81,22 @@ fn test_set_tti_dcl() {
let profiler_metadata_factory = DummyProfilerMetadataFactory {};
let interactive = test_interactive();
let t = time::precise_time_ns();
let now = CrossProcessInstant::now();
interactive.maybe_set_tti(
&profiler_metadata_factory,
InteractiveFlag::TimeToInteractive(t),
InteractiveFlag::TimeToInteractive(now),
);
let mta = interactive.get_main_thread_available();
assert!(mta.is_some());
let main_thread_available_time = interactive.get_main_thread_available();
assert!(main_thread_available_time.is_some());
interactive.maybe_set_tti(
&profiler_metadata_factory,
InteractiveFlag::DOMContentLoaded,
);
let dcl = interactive.get_dom_content_loaded();
assert!(dcl.is_some());
let dom_content_loaded_time = interactive.get_dom_content_loaded();
assert!(dom_content_loaded_time.is_some());
let interactive_time = dcl.unwrap() - (&interactive).get_navigation_start().unwrap();
assert_eq!(interactive.get_tti(), Some(interactive_time));
assert_eq!(interactive.get_tti(), dom_content_loaded_time);
}
#[test]
@ -110,19 +111,15 @@ fn test_set_tti_mta() {
let dcl = interactive.get_dom_content_loaded();
assert!(dcl.is_some());
let t = SystemTime::now()
.duration_since(UNIX_EPOCH)
.unwrap_or_default()
.as_nanos() as u64;
let time = CrossProcessInstant::now();
interactive.maybe_set_tti(
&profiler_metadata_factory,
InteractiveFlag::TimeToInteractive(t),
InteractiveFlag::TimeToInteractive(time),
);
let mta = interactive.get_main_thread_available();
assert!(mta.is_some());
let interactive_time = mta.unwrap() - (&interactive).get_navigation_start().unwrap();
assert_eq!(interactive.get_tti(), Some(interactive_time));
assert_eq!(interactive.get_tti(), mta);
}
// TODO InteractiveWindow tests

View file

@ -2,6 +2,7 @@
* License, v. 2.0. If a copy of the MPL was not distributed with this
* file, You can obtain one at https://mozilla.org/MPL/2.0/. */
use base::cross_process_instant::CrossProcessInstant;
use base::id::TEST_PIPELINE_ID;
use base::Epoch;
use ipc_channel::ipc;
@ -22,17 +23,18 @@ fn test_paint_metrics_construction() {
let profiler_chan = ProfilerChan(sender);
let (layout_sender, _) = ipc::channel().unwrap();
let (script_sender, _) = ipc::channel().unwrap();
let start_time = CrossProcessInstant::now();
let paint_time_metrics = PaintTimeMetrics::new(
TEST_PIPELINE_ID,
profiler_chan,
layout_sender,
script_sender,
ServoUrl::parse("about:blank").unwrap(),
0,
start_time,
);
assert_eq!(
(&paint_time_metrics).get_navigation_start(),
Some(0),
Some(start_time),
"navigation start is set properly"
);
assert_eq!(
@ -52,13 +54,14 @@ fn test_common(display_list_is_contentful: bool, epoch: Epoch) -> PaintTimeMetri
let profiler_chan = ProfilerChan(sender);
let (layout_sender, _) = ipc::channel().unwrap();
let (script_sender, _) = ipc::channel().unwrap();
let start_time = CrossProcessInstant::now();
let mut paint_time_metrics = PaintTimeMetrics::new(
TEST_PIPELINE_ID,
profiler_chan,
layout_sender,
script_sender,
ServoUrl::parse("about:blank").unwrap(),
0,
start_time,
);
let dummy_profiler_metadata_factory = DummyProfilerMetadataFactory {};
@ -79,7 +82,7 @@ fn test_common(display_list_is_contentful: bool, epoch: Epoch) -> PaintTimeMetri
"first contentful paint is None"
);
let navigation_start = time::precise_time_ns();
let navigation_start = CrossProcessInstant::now();
paint_time_metrics.set_navigation_start(navigation_start);
assert_eq!(
(&paint_time_metrics).get_navigation_start().unwrap(),
@ -94,7 +97,7 @@ fn test_common(display_list_is_contentful: bool, epoch: Epoch) -> PaintTimeMetri
fn test_first_paint_setter() {
let epoch = Epoch(0);
let paint_time_metrics = test_common(false, epoch);
let now = time::precise_time_ns();
let now = CrossProcessInstant::now();
paint_time_metrics.maybe_set_metric(epoch, now);
assert!(
paint_time_metrics.get_first_paint().is_some(),
@ -111,7 +114,7 @@ fn test_first_paint_setter() {
fn test_first_contentful_paint_setter() {
let epoch = Epoch(0);
let paint_time_metrics = test_common(true, epoch);
let now = time::precise_time_ns();
let now = CrossProcessInstant::now();
paint_time_metrics.maybe_set_metric(epoch, now);
assert!(
paint_time_metrics.get_first_contentful_paint().is_some(),

View file

@ -16,4 +16,4 @@ ipc-channel = { workspace = true }
profile = { path = "../../../components/profile" }
profile_traits = { workspace = true }
servo_config = { path = "../../../components/config" }
time_03 = { workspace = true }

View file

@ -3,13 +3,13 @@
* file, You can obtain one at https://mozilla.org/MPL/2.0/. */
use std::thread;
use std::time::Duration;
use ipc_channel::ipc;
use profile::time;
use profile_traits::ipc as ProfiledIpc;
use profile_traits::time::{ProfilerCategory, ProfilerData, ProfilerMsg};
use servo_config::opts::OutputOptions;
use time_03::Duration;
#[test]
fn time_profiler_smoke_test() {
@ -24,24 +24,41 @@ fn time_profiler_smoke_test() {
#[test]
fn time_profiler_stats_test() {
let even_data = vec![
1.234, 3.24567, 3.54578, 5.0, 5.324, 7.345, 9.2345, 10.2342345, 13.2599, 15.0,
Duration::seconds_f64(1.234),
Duration::seconds_f64(3.246),
Duration::seconds_f64(3.546),
Duration::seconds_f64(5.000),
Duration::seconds_f64(5.324),
Duration::seconds_f64(7.345),
Duration::seconds_f64(9.235),
Duration::seconds_f64(10.234),
Duration::seconds_f64(13.250),
Duration::seconds_f64(15.000),
];
let (even_mean, even_median, even_min, even_max) = time::Profiler::get_statistics(&even_data);
assert_eq!(7.34230845, even_mean);
assert_eq!(7.345, even_median);
assert_eq!(1.234, even_min);
assert_eq!(15.0, even_max);
assert_eq!(7341, even_mean.whole_milliseconds());
assert_eq!(Duration::seconds_f64(7.345), even_median);
assert_eq!(Duration::seconds_f64(1.234), even_min);
assert_eq!(Duration::seconds_f64(15.000), even_max);
let odd_data = vec![
1.234, 3.24567, 3.54578, 5.0, 5.324, 7.345, 9.2345, 10.2342345, 13.2599,
Duration::seconds_f64(1.234),
Duration::seconds_f64(3.246),
Duration::seconds_f64(3.546),
Duration::seconds_f64(5.000),
Duration::seconds_f64(5.324),
Duration::seconds_f64(7.345),
Duration::seconds_f64(9.235),
Duration::seconds_f64(10.234),
Duration::seconds_f64(13.250),
];
let (odd_mean, odd_median, odd_min, odd_max) = time::Profiler::get_statistics(&odd_data);
assert_eq!(6.491453833333334, odd_mean);
assert_eq!(5.324, odd_median);
assert_eq!(1.234, odd_min);
assert_eq!(13.2599, odd_max);
assert_eq!(6490, odd_mean.whole_milliseconds());
assert_eq!(Duration::seconds_f64(5.324), odd_median);
assert_eq!(Duration::seconds_f64(1.234), odd_min);
assert_eq!(Duration::seconds_f64(13.250), odd_max);
}
#[test]
@ -49,7 +66,7 @@ fn channel_profiler_test() {
let chan = time::Profiler::create(&Some(OutputOptions::Stdout(5.0)), None);
let (profiled_sender, profiled_receiver) = ProfiledIpc::channel(chan.clone()).unwrap();
thread::spawn(move || {
thread::sleep(Duration::from_secs(2));
thread::sleep(std::time::Duration::from_secs(2));
profiled_sender.send(43).unwrap();
});
@ -64,7 +81,7 @@ fn channel_profiler_test() {
match receiver.recv().unwrap() {
// asserts that the time spent in the sleeping thread is more than 1500 milliseconds
ProfilerData::Record(time_data) => assert!(time_data[0] > 1.5e3),
ProfilerData::Record(time_data) => assert!(time_data[0] > Duration::milliseconds(1500)),
ProfilerData::NoRecords => assert!(false),
};
}
@ -74,7 +91,7 @@ fn bytes_channel_profiler_test() {
let chan = time::Profiler::create(&Some(OutputOptions::Stdout(5.0)), None);
let (profiled_sender, profiled_receiver) = ProfiledIpc::bytes_channel(chan.clone()).unwrap();
thread::spawn(move || {
thread::sleep(Duration::from_secs(2));
thread::sleep(std::time::Duration::from_secs(2));
profiled_sender.send(&[1, 2, 3]).unwrap();
});
@ -89,7 +106,7 @@ fn bytes_channel_profiler_test() {
match receiver.recv().unwrap() {
// asserts that the time spent in the sleeping thread is more than 1500 milliseconds
ProfilerData::Record(time_data) => assert!(time_data[0] > 1.5e3),
ProfilerData::Record(time_data) => assert!(time_data[0] > Duration::milliseconds(1500)),
ProfilerData::NoRecords => assert!(false),
};
}
@ -98,7 +115,12 @@ fn bytes_channel_profiler_test() {
#[test]
#[should_panic]
fn time_profiler_unsorted_stats_test() {
let unsorted_data = vec![5.0, 7.5, 1.0, 8.9];
let unsorted_data = vec![
Duration::microseconds(5000),
Duration::microseconds(7500),
Duration::microseconds(1000),
Duration::microseconds(890),
];
time::Profiler::get_statistics(&unsorted_data);
}