Skip to content
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.

Sign up for GitHub

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

Jump to bottom

Display elapsed time in datagen log #4469

Merged
merged 2 commits into from
Dec 21, 2023
Merged

Display elapsed time in datagen log #4469

Changes from 1 commit
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
882d053
Display elapsed time in datagen log
sffc Dec 19, 2023
12f485a
Maybe make the code a little more clear
sffc Dec 20, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
177 changes: 125 additions & 52 deletions provider/datagen/src/driver.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,9 @@ use once_cell::sync::Lazy;
use std::borrow::Cow;
use std::collections::HashMap;
use std::collections::HashSet;
use std::fmt;
use std::time::Duration;
use std::time::Instant;
use writeable::Writeable;

/// Configuration for a data export operation.
Expand Down Expand Up @@ -304,7 +307,8 @@ impl DatagenDriver {
};

keys.clone().into_par_iter().try_for_each(|key| {
log::info!("Generating key {key}");
log::trace!("Generating key {key}");
let instant1 = Instant::now();

if key.metadata().singleton {
if provider.supported_locales_for_key(key)? != [Default::default()] {
Expand All @@ -319,9 +323,25 @@ impl DatagenDriver {
.and_then(DataResponse::take_payload)
.map_err(|e| e.with_req(key, Default::default()))?;

return sink
.flush_singleton(key, &payload)
.map_err(|e| e.with_req(key, Default::default()));
let transform_duration = instant1.elapsed();

sink.flush_singleton(key, &payload)
.map_err(|e| e.with_req(key, Default::default()))?;

let final_duration = instant1.elapsed();
let flush_duration = final_duration - transform_duration;

if final_duration > Duration::new(0, 500_000_000) {
// Print durations if the key took longer than 500 ms
log::info!(
"Generated key {key} ({}, flushed in {})",
DisplayDuration(final_duration),
DisplayDuration(flush_duration)
);
} else {
log::info!("Generated key {key}");
}
return Ok(());
}

let locales_to_export = select_locales_for_key(
Expand All @@ -334,74 +354,110 @@ impl DatagenDriver {
&fallbacker,
)?;

match fallback {
let (slowest_duration, slowest_locale) = match fallback {
FallbackMode::Runtime | FallbackMode::RuntimeManual => {
let payloads = locales_to_export
.into_par_iter()
.filter_map(|locale| {
let instant2 = Instant::now();
load_with_fallback(key, &locale)
.map(|r| r.map(|payload| (locale, payload)))
.map(|r| r.map(|payload| (locale, (payload, instant2.elapsed()))))
})
.collect::<Result<HashMap<_, _>, _>>()?;
let fallbacker = fallbacker.as_ref().map_err(|e| *e)?;
let fallbacker_with_config = fallbacker.for_config(key.fallback_config());
payloads.iter().try_for_each(|(locale, payload)| {
let mut iter = fallbacker_with_config.fallback_for(locale.clone());
while !iter.get().is_und() {
iter.step();
if let Some(inherited_payload) = payloads.get(iter.get()) {
if inherited_payload == payload {
// Found a match: don't need to write anything
log::trace!(
"Deduplicating {key}/{locale} (inherits from {})",
iter.get()
);
return Ok(());
} else {
// Not a match: we must include this
break;
payloads
.iter()
.try_for_each(|(locale, (payload, _duration))| {
let mut iter = fallbacker_with_config.fallback_for(locale.clone());
while !iter.get().is_und() {
iter.step();
if let Some((inherited_payload, _duration)) =
payloads.get(iter.get())
{
if inherited_payload == payload {
// Found a match: don't need to write anything
log::trace!(
"Deduplicating {key}/{locale} (inherits from {})",
iter.get()
);
return Ok(());
} else {
// Not a match: we must include this
break;
}
}
}
}
// Did not find a match: export this payload
sink.put_payload(key, locale, payload).map_err(|e| {
e.with_req(
key,
DataRequest {
locale,
metadata: Default::default(),
},
)
})
})?
}
FallbackMode::Hybrid | FallbackMode::Preresolved => {
locales_to_export.into_par_iter().try_for_each(|locale| {
if let Some(payload) = load_with_fallback(key, &locale) {
sink.put_payload(key, &locale, &payload?)
} else {
Ok(())
}
.map_err(|e| {
e.with_req(
key,
DataRequest {
locale: &locale,
metadata: Default::default(),
},
)
// Did not find a match: export this payload
sink.put_payload(key, locale, payload).map_err(|e| {
e.with_req(
key,
DataRequest {
locale,
metadata: Default::default(),
},
)
})
})?;

// Slowest locale calculation:
payloads
.iter()
.map(|(locale, (_payload, duration))| {
(*duration, locale.write_to_string().into_owned())
})
})?
.max()
}
FallbackMode::Hybrid | FallbackMode::Preresolved => locales_to_export
.into_par_iter()
.map(|locale| {
let instant2 = Instant::now();
load_with_fallback(key, &locale)
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do double-check that the old and new behaviors are the same. I switched things around to avoid duplicating the duration logic.

.transpose()?
.map(|payload| sink.put_payload(key, &locale, &payload))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: I'm not convinced the functional style is clearer here, especially with the timing code, where you kinda actually do need to know where it should run. I think we should revert to the older imperative style here and just add timing

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In general I agree but in this case I was confused why we had an expression like

if let Some(payload) = load_with_fallback(key, &locale) {
    sink.put_payload(key, &locale, &payload?)
} else {
    Ok(())
}
// followed by other chaining logic

Also note that the majority of the diff in this branch is due to changing try_for_each to map so that I can call .max() on the result.

I will do another round of making this more clear though. I realized that I might be losing the error context with the new .transpose()?

.unwrap_or(Ok(()))
.map(|_| (instant2.elapsed(), locale.write_to_string().into_owned()))
.map_err(|e| {
e.with_req(
key,
DataRequest {
locale: &locale,
metadata: Default::default(),
},
)
})
})
.collect::<Result<Vec<_>, DataError>>()?
.into_iter()
.max(),
FallbackMode::PreferredForExporter => unreachable!("resolved"),
};
}
.unwrap_or_default();

let transform_duration = instant1.elapsed();

if fallback == FallbackMode::Runtime {
sink.flush_with_built_in_fallback(key, BuiltInFallbackMode::Standard)
} else {
sink.flush(key)
}
.map_err(|e| e.with_key(key))
.map_err(|e| e.with_key(key))?;

let final_duration = instant1.elapsed();
let flush_duration = final_duration - transform_duration;

if final_duration > Duration::new(0, 500_000_000) {
// Print durations if the key took longer than 500 ms
log::info!(
"Generated key {key} ({}, '{slowest_locale}' in {}, flushed in {})",
DisplayDuration(final_duration),
DisplayDuration(slowest_duration),
DisplayDuration(flush_duration)
);
} else {
log::info!("Generated key {key}");
}
Ok(())
})?;

sink.close()
Expand Down Expand Up @@ -544,6 +600,23 @@ fn select_locales_for_key(
Ok(result)
}

struct DisplayDuration(pub Duration);

impl fmt::Display for DisplayDuration {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
let nanos = self.0.as_nanos();
if nanos > 100_000_000 {
write!(f, "{:.3}s", self.0.as_secs_f64())
} else if nanos > 1_000_000 {
write!(f, "{:.3}ms", (nanos as f64) / 1e6)
} else if nanos > 1_000 {
write!(f, "{:.3}µs", (nanos as f64) / 1e3)
} else {
write!(f, "{}ns", nanos)
}
}
}

#[test]
fn test_collation_filtering() {
use icu_locid::langid;
Expand Down