Skip to content

Commit a3f4d67

Browse files
committed
Condense fetch log time trace
#1762 added automatic fetch trace logging for each individual file extracted from a `.zip` file. Many of these operations are very fast, especially for `otatools.zip` and take many lines of logs. These should be condensed since they don't contribute much to the overall time and make the trace harder to read. Sample new output: ``` Performance stats: PreFetch actions: started: 2025-11-25 15:52:13, duration: 1 s - GetBuilds: 1 s Host Package: started: 2025-11-25 15:52:14, duration: 3 m 13 s - Download: 3 m 6 s, 851 MiB - Extract: 6 s - 2 operations omitted with a combined duration of 12 ms. Default: started: 2025-11-25 15:52:14, duration: 7 m 33 s - Downloaded 'misc_info.txt': 1 s, 9000 B - Downloaded 'aosp_cf_x86_64_only_phone-img-14496483.zip': 7 m 23 s, 1135 MiB - Extracted 'super.img' from 'aosp_cf_x86_64_only_phone-img-14496483.zip': 7 s, 1339 MiB - Desparsed [/super.img]: 933 ms, 8192 MiB - 22 operations omitted with a combined duration of 549 ms. Kernel: started: 2025-11-25 15:59:47, duration: 8 ms - 4 operations omitted with a combined duration of 8 ms. OTA Tools: started: 2025-11-25 15:59:47, duration: 1 m 54 s - Downloaded 'otatools.zip': 1 m 51 s, 486 MiB - 14653 operations omitted with a combined duration of 3 s. ``` Bug: b/463765667
1 parent 2a786b0 commit a3f4d67

File tree

1 file changed

+39
-4
lines changed

1 file changed

+39
-4
lines changed

base/cvd/cuttlefish/host/commands/cvd/fetch/fetch_tracer.cpp

Lines changed: 39 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -33,7 +33,7 @@ namespace {
3333

3434
struct Phase {
3535
std::string name;
36-
std::chrono::seconds duration;
36+
std::chrono::milliseconds duration;
3737
std::optional<size_t> size_bytes;
3838
};
3939

@@ -49,6 +49,14 @@ struct FetchTracer::TraceImpl {
4949

5050
namespace {
5151

52+
std::chrono::milliseconds FullDuration(const FetchTracer::TraceImpl& trace) {
53+
std::chrono::milliseconds total_duration;
54+
for (const Phase& phase : trace.phases) {
55+
total_duration += phase.duration;
56+
}
57+
return total_duration;
58+
}
59+
5260
std::string FormatByteSize(uint64_t size) {
5361
if (size < 10240) {
5462
return fmt::format("{} B", size);
@@ -69,16 +77,42 @@ std::string FormatByteSize(uint64_t size) {
6977
return fmt::format("{} TiB", size);
7078
}
7179

80+
std::string FormatDuration(std::chrono::milliseconds duration_ms) {
81+
if (duration_ms < std::chrono::milliseconds(1000)) {
82+
return fmt::format("{} ms", duration_ms.count());
83+
}
84+
std::chrono::seconds duration_s =
85+
std::chrono::duration_cast<std::chrono::seconds>(duration_ms);
86+
if (duration_s < std::chrono::seconds(60)) {
87+
return fmt::format("{} s", duration_s.count());
88+
} else {
89+
return fmt::format("{} m {} s", duration_s.count() / 60,
90+
duration_s.count() % 60);
91+
}
92+
}
93+
7294
std::string ToStyledString(const FetchTracer::TraceImpl& trace,
7395
std::string indent_prefix) {
7496
std::stringstream ss;
97+
size_t omitted_count = 0;
98+
std::chrono::milliseconds omitted_time(0);
7599
for (const Phase& phase : trace.phases) {
76-
ss << indent_prefix << phase.name << ": " << phase.duration.count() << "s";
100+
if (phase.duration < std::chrono::milliseconds(500)) {
101+
omitted_count++;
102+
omitted_time += phase.duration;
103+
continue;
104+
}
105+
ss << indent_prefix << phase.name << ": " << FormatDuration(phase.duration);
77106
if (phase.size_bytes) {
78107
ss << ", " << FormatByteSize(*phase.size_bytes);
79108
}
80109
ss << '\n';
81110
}
111+
if (omitted_count > 0) {
112+
ss << indent_prefix;
113+
ss << omitted_count << " operations omitted with a combined duration of "
114+
<< FormatDuration(omitted_time) << ".\n";
115+
}
82116
return ss.str();
83117
}
84118

@@ -91,7 +125,8 @@ void FetchTracer::Trace::CompletePhase(std::string phase_name,
91125
auto now = std::chrono::steady_clock::now();
92126
impl_.phases.push_back(Phase{
93127
std::move(phase_name),
94-
std::chrono::duration_cast<std::chrono::seconds>(now - impl_.phase_start),
128+
std::chrono::duration_cast<std::chrono::milliseconds>(now -
129+
impl_.phase_start),
95130
size_bytes});
96131
impl_.phase_start = now;
97132
}
@@ -110,7 +145,7 @@ std::string FetchTracer::ToStyledString() const {
110145
std::chrono::system_clock::to_time_t(trace->trace_start);
111146
ss << name << ":\n";
112147
ss << " started: " << std::put_time(std::localtime(&start_time), "%F %T")
113-
<< '\n';
148+
<< ", duration: " << FormatDuration(FullDuration(*trace)) << '\n';
114149
ss << cuttlefish::ToStyledString(*trace, " - ");
115150
}
116151
return ss.str();

0 commit comments

Comments
 (0)