Time-bracket reading /proc information to help trace analysis

Bug: 132277336
Change-Id: I56c116dc3a9f53e52d8061ef0b57bb02d9ab9157
(cherry pick from commit 4fe75a5fa77a39ad4ec8ae6eac9447bcc9d6cc03)

7 files changed, 81 insertions, 4 deletions

diff --git a/protos/perfetto/trace/perfetto_trace.proto b/protos/perfetto/trace/perfetto_trace.proto
index d57288446..52676a241 100644
--- a/protos/perfetto/trace/perfetto_trace.proto
+++ b/protos/perfetto/trace/perfetto_trace.proto
@@ -2706,6 +2706,15 @@ message ProcessStats {
     optional int64 oom_score_adj = 10;
   }
   repeated Process processes = 1;
+
+  // The time at which we finish collecting this batch of samples;
+  // the top-level packet timestamp is the time at which
+  // we begin collection.
+  // TODO(dancol): analysis might be improved by
+  // time-bracketing each sample as well as the whole
+  // ProcessStats, but doing that is probably gated on
+  // a vdso for CLOCK_BOOTTIME.
+  optional uint64 collection_end_timestamp = 2;
 }
 
 // End of protos/perfetto/trace/ps/process_stats.proto
@@ -2752,6 +2761,11 @@ message ProcessTree {
   // #2 { processes: [{pid: 20, ...}], threads: [{pid: 13, tgid: 10}] }
   repeated Process processes = 1;
   repeated Thread threads = 2;
+
+  // The time at which we finish collecting this process tree;
+  // the top-level packet timestamp is the time at which
+  // we begin collection.
+  optional uint64 collection_end_timestamp = 3;
 }
 
 // End of protos/perfetto/trace/ps/process_tree.proto
@@ -2807,6 +2821,11 @@ message SysStats {
   // Populated only if SOFTIRQ_COUNTS in config.stat_counters.
   optional uint64 num_softirq_total = 7;    // Total num of softirqs since boot.
   repeated InterruptCount num_softirq = 8;  // Per-softirq count.
+
+  // The time at which we finish collecting this set of samples;
+  // the top-level packet timestamp is the time at which
+  // we begin collection.
+  optional uint64 collection_end_timestamp = 9;
 }
 
 // End of protos/perfetto/trace/sys_stats/sys_stats.proto
diff --git a/protos/perfetto/trace/ps/process_stats.proto b/protos/perfetto/trace/ps/process_stats.proto
index 49e8237c4..5db028f81 100644
--- a/protos/perfetto/trace/ps/process_stats.proto
+++ b/protos/perfetto/trace/ps/process_stats.proto
@@ -43,4 +43,13 @@ message ProcessStats {
     optional int64 oom_score_adj = 10;
   }
   repeated Process processes = 1;
+
+  // The time at which we finish collecting this batch of samples;
+  // the top-level packet timestamp is the time at which
+  // we begin collection.
+  // TODO(dancol): analysis might be improved by
+  // time-bracketing each sample as well as the whole
+  // ProcessStats, but doing that is probably gated on
+  // a vdso for CLOCK_BOOTTIME.
+  optional uint64 collection_end_timestamp = 2;
 }
diff --git a/protos/perfetto/trace/ps/process_tree.proto b/protos/perfetto/trace/ps/process_tree.proto
index 50579e52d..cf83d12b3 100644
--- a/protos/perfetto/trace/ps/process_tree.proto
+++ b/protos/perfetto/trace/ps/process_tree.proto
@@ -58,4 +58,9 @@ message ProcessTree {
   // #2 { processes: [{pid: 20, ...}], threads: [{pid: 13, tgid: 10}] }
   repeated Process processes = 1;
   repeated Thread threads = 2;
+
+  // The time at which we finish collecting this process tree;
+  // the top-level packet timestamp is the time at which
+  // we begin collection.
+  optional uint64 collection_end_timestamp = 3;
 }
diff --git a/protos/perfetto/trace/sys_stats/sys_stats.proto b/protos/perfetto/trace/sys_stats/sys_stats.proto
index 7b298bf9c..4b10ecfca 100644
--- a/protos/perfetto/trace/sys_stats/sys_stats.proto
+++ b/protos/perfetto/trace/sys_stats/sys_stats.proto
@@ -69,4 +69,9 @@ message SysStats {
   // Populated only if SOFTIRQ_COUNTS in config.stat_counters.
   optional uint64 num_softirq_total = 7;    // Total num of softirqs since boot.
   repeated InterruptCount num_softirq = 8;  // Per-softirq count.
+
+  // The time at which we finish collecting this set of samples;
+  // the top-level packet timestamp is the time at which
+  // we begin collection.
+  optional uint64 collection_end_timestamp = 9;
 }
diff --git a/src/traced/probes/ps/process_stats_data_source.cc b/src/traced/probes/ps/process_stats_data_source.cc
index 524a8b468..e994c2d7e 100644
--- a/src/traced/probes/ps/process_stats_data_source.cc
+++ b/src/traced/probes/ps/process_stats_data_source.cc
@@ -136,6 +136,9 @@ base::WeakPtr<ProcessStatsDataSource> ProcessStatsDataSource::GetWeakPtr()
 void ProcessStatsDataSource::WriteAllProcesses() {
   PERFETTO_METATRACE("WriteAllProcesses", 0);
   PERFETTO_DCHECK(!cur_ps_tree_);
+
+  CacheProcFsScanStartTimestamp();
+
   base::ScopedDir proc_dir = OpenProcDir();
   if (!proc_dir)
     return;
@@ -199,6 +202,9 @@ void ProcessStatsDataSource::Flush(FlushRequestID,
 }
 
 void ProcessStatsDataSource::WriteProcessOrThread(int32_t pid) {
+  // In case we're called from outside WriteAllProcesses()
+  CacheProcFsScanStartTimestamp();
+
   std::string proc_status = ReadProcPidFile(pid, "status");
   if (proc_status.empty())
     return;
@@ -280,8 +286,7 @@ void ProcessStatsDataSource::StartNewPacketIfNeeded() {
   if (cur_packet_)
     return;
   cur_packet_ = writer_->NewTracePacket();
-  uint64_t now = static_cast<uint64_t>(base::GetBootTimeNs().count());
-  cur_packet_->set_timestamp(now);
+  cur_packet_->set_timestamp(CacheProcFsScanStartTimestamp());
 
   if (did_clear_incremental_state_) {
     cur_packet_->set_incremental_state_cleared(true);
@@ -319,9 +324,17 @@ ProcessStatsDataSource::GetOrCreateStatsProcess(int32_t pid) {
 void ProcessStatsDataSource::FinalizeCurPacket() {
   PERFETTO_DCHECK(!cur_ps_tree_ || cur_packet_);
   PERFETTO_DCHECK(!cur_ps_stats_ || cur_packet_);
-  cur_ps_tree_ = nullptr;
-  cur_ps_stats_ = nullptr;
+  uint64_t now = static_cast<uint64_t>(base::GetBootTimeNs().count());
+  if (cur_ps_tree_) {
+    cur_ps_tree_->set_collection_end_timestamp(now);
+    cur_ps_tree_ = nullptr;
+  }
+  if (cur_ps_stats_) {
+    cur_ps_stats_->set_collection_end_timestamp(now);
+    cur_ps_stats_ = nullptr;
+  }
   cur_ps_stats_process_ = nullptr;
+  cur_procfs_scan_start_timestamp_ = 0;
   cur_packet_ = TraceWriter::TracePacketHandle{};
 }
 
@@ -349,6 +362,7 @@ void ProcessStatsDataSource::WriteAllProcessStats() {
   // TODO(primiano): Have a pid cache to avoid wasting cycles reading kthreads
   // proc files over and over. Same for non-whitelist processes (see above).
 
+  CacheProcFsScanStartTimestamp();
   PERFETTO_METATRACE("WriteAllProcessStats", 0);
   base::ScopedDir proc_dir = OpenProcDir();
   if (!proc_dir)
@@ -505,6 +519,13 @@ bool ProcessStatsDataSource::WriteMemCounters(int32_t pid,
   return proc_status_has_mem_counters;
 }
 
+uint64_t ProcessStatsDataSource::CacheProcFsScanStartTimestamp() {
+  if (!cur_procfs_scan_start_timestamp_)
+    cur_procfs_scan_start_timestamp_ =
+        static_cast<uint64_t>(base::GetBootTimeNs().count());
+  return cur_procfs_scan_start_timestamp_;
+}
+
 void ProcessStatsDataSource::ClearIncrementalState() {
   PERFETTO_DLOG("ProcessStatsDataSource clearing incremental state.");
   seen_pids_.clear();
diff --git a/src/traced/probes/ps/process_stats_data_source.h b/src/traced/probes/ps/process_stats_data_source.h
index efea49487..c0288f1f3 100644
--- a/src/traced/probes/ps/process_stats_data_source.h
+++ b/src/traced/probes/ps/process_stats_data_source.h
@@ -104,11 +104,26 @@ class ProcessStatsDataSource : public ProbesDataSource {
   void WriteAllProcessStats();
   bool WriteMemCounters(int32_t pid, const std::string& proc_status);
 
+  // Read and "latch" the current procfs scan-start timestamp, which
+  // we reset only in FinalizeCurPacket.
+  uint64_t CacheProcFsScanStartTimestamp();
+
   // Common fields used for both process/tree relationships and stats/counters.
   base::TaskRunner* const task_runner_;
   std::unique_ptr<TraceWriter> writer_;
   TraceWriter::TracePacketHandle cur_packet_;
 
+  // Cached before-scan timestamp; zero means cached time is absent.
+  // By the time we create the trace packet into which we dump procfs
+  // scan results, we've already read at least one bit of data from
+  // procfs, and by that point, it's too late to snap a timestamp from
+  // before we started looking at procfs at all, which is what trace
+  // analysis wants.  To solve this problem, we record the scan-start
+  // timestamp here when we first open something in procfs and use
+  // that time when we create the packet.
+  // We reset this field after each FinalizeCurPacket().
+  uint64_t cur_procfs_scan_start_timestamp_ = 0;
+
   // Fields for keeping track of the state of process/tree relationships.
   protos::pbzero::ProcessTree* cur_ps_tree_ = nullptr;
   bool record_thread_names_ = false;
diff --git a/src/traced/probes/sys_stats/sys_stats_data_source.cc b/src/traced/probes/sys_stats/sys_stats_data_source.cc
index befe3966c..217b196a7 100644
--- a/src/traced/probes/sys_stats/sys_stats_data_source.cc
+++ b/src/traced/probes/sys_stats/sys_stats_data_source.cc
@@ -174,6 +174,9 @@ void SysStatsDataSource::ReadSysStats() {
   if (stat_ticks_ && tick_ % stat_ticks_ == 0)
     ReadStat(sys_stats);
 
+  sys_stats->set_collection_end_timestamp(
+      static_cast<uint64_t>(base::GetBootTimeNs().count()));
+
   tick_++;
 }