arc: Fix arc-graphics-tracing timestamp parsing

When processing systrace events, a decimal timestamp in seconds like
"123.456000" was being parsed as a pair of int32_t's separated by the
dot, and then converted into an microsecond integer value by scaling the
integer seconds value appropriately, and adding the fractional part.

However if the number of seconds was large enough, the multiplication
would overflow an int32_t, resulting in an incorrect timestamp being
computed, which then caused those events to be filtered out as they were
not in the expected range.

The fix was to simply implicitly convert to an int64_t to hold the
result of the multiplication.

This was enough to fix the bug.

However the parsing makes a potentially unsafe and unchecked assumption
that the number of digits after the decimal point is always the expected
amount. If it was ever different, the computed timestamps would be
incorrect.

I also went and corrected most of the code to use a uniform type for the
timestamp of uint64_t, as parts of the code used int64_t, and other
parts used double. Doubles are still used however for JSON serialization
and deserialization.

To verify the timestamp parsing, I added some specific tests to the unit
test.

TEST=Unit tests pass, arc-graphics-tracing works
BUG=b:132907802

Change-Id: I8608fae90eb4708f5c6abd7088ca4b859aeab91f
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1616325Reviewed-by: Yury Khmel <khmel@chromium.org>
Commit-Queue: Lloyd Pique <lpique@chromium.org>
Cr-Commit-Position: refs/heads/master@{#660971}

chrome/browser/chromeos/arc/tracing/arc_cpu_event.cc

@@ -8,7 +8,7 @@
 
 namespace arc {
 
-ArcCpuEvent::ArcCpuEvent(int64_t timestamp, Type type, uint32_t tid)
+ArcCpuEvent::ArcCpuEvent(uint64_t timestamp, Type type, uint32_t tid)
     : timestamp(timestamp), type(type), tid(tid) {}
 
 bool ArcCpuEvent::operator==(const ArcCpuEvent& other) const {
@@ -16,7 +16,7 @@ bool ArcCpuEvent::operator==(const ArcCpuEvent& other) const {
 }
 
 bool AddCpuEvent(CpuEvents* cpu_events,
-                 int64_t timestamp,
+                 uint64_t timestamp,
                  ArcCpuEvent::Type type,
                  uint32_t tid) {
   // Base validation.
@@ -112,7 +112,7 @@ bool AddCpuEvent(CpuEvents* cpu_events,
 
 bool AddAllCpuEvent(AllCpuEvents* all_cpu_events,
                     uint32_t cpu_id,
-                    int64_t timestamp,
+                    uint64_t timestamp,
                     ArcCpuEvent::Type type,
                     uint32_t tid) {
   if (all_cpu_events->size() <= cpu_id)
@@ -144,7 +144,7 @@ bool LoadCpuEvents(const base::Value* value, CpuEvents* cpu_events) {
   if (!value || !value->is_list())
     return false;
 
-  int64_t previous_timestamp = 0;
+  uint64_t previous_timestamp = 0;
   for (const auto& entry : value->GetList()) {
     if (!entry.is_list() || entry.GetList().size() != 3)
       return false;
@@ -163,7 +163,7 @@ bool LoadCpuEvents(const base::Value* value, CpuEvents* cpu_events) {
     }
     if (!entry.GetList()[1].is_double() && !entry.GetList()[1].is_int())
       return false;
-    const int64_t timestamp = entry.GetList()[1].GetDouble();
+    const uint64_t timestamp = entry.GetList()[1].GetDouble();
     if (timestamp < previous_timestamp)
       return false;
     if (!entry.GetList()[2].is_int())

chrome/browser/chromeos/arc/tracing/arc_cpu_event.h

@@ -21,11 +21,11 @@ struct ArcCpuEvent {
     kActive,      // Task is started on CPU.
   };
 
-  ArcCpuEvent(int64_t timestamp, Type type, uint32_t tid);
+  ArcCpuEvent(uint64_t timestamp, Type type, uint32_t tid);
 
   bool operator==(const ArcCpuEvent& other) const;
 
-  int64_t timestamp;
+  uint64_t timestamp;
   Type type;
   uint32_t tid;
 };
@@ -38,7 +38,7 @@ using AllCpuEvents = std::vector<CpuEvents>;
 // Helper that adds CPU event into |cpu_events|. Returns true in case event was
 // created and added or false if it breaks any constraint.
 bool AddCpuEvent(CpuEvents* cpu_events,
-                 int64_t timestamp,
+                 uint64_t timestamp,
                  ArcCpuEvent::Type type,
                  uint32_t tid);
 
@@ -47,7 +47,7 @@ bool AddCpuEvent(CpuEvents* cpu_events,
 // created and added or false if it breaks any constraint.
 bool AddAllCpuEvent(AllCpuEvents* all_cpu_events,
                     uint32_t cpu_id,
-                    int64_t timestamp,
+                    uint64_t timestamp,
                     ArcCpuEvent::Type type,
                     uint32_t tid);
 

chrome/browser/chromeos/arc/tracing/arc_system_model.cc

@@ -86,7 +86,7 @@ void ArcSystemModel::Reset() {
   memory_events_.clear();
 }
 
-void ArcSystemModel::Trim(int64_t trim_timestamp) {
+void ArcSystemModel::Trim(uint64_t trim_timestamp) {
   const ArcCpuEvent cpu_trim_point(
       trim_timestamp, ArcCpuEvent::Type::kActive /* does not matter */,
       0 /* tid, does not matter */);

chrome/browser/chromeos/arc/tracing/arc_system_model.h

@@ -42,7 +42,7 @@ class ArcSystemModel {
   // |trim_timestamp| are consolidated with their timestamps aligned
   // to |trim_timestamp|. Events on or after |trim_timestamp| are left
   // in the model unchanged.
-  void Trim(int64_t trim_timestamp);
+  void Trim(uint64_t trim_timestamp);
 
   void CopyFrom(const ArcSystemModel& other);
   base::DictionaryValue Serialize() const;

chrome/browser/chromeos/arc/tracing/arc_system_model_unittest.cc

@@ -13,7 +13,7 @@ using ArcSystemModelTest = testing::Test;
 TEST_F(ArcSystemModelTest, TrimByTimestampCPU) {
   ArcSystemModel model;
 
-  constexpr int64_t trim_timestamp = 25;
+  constexpr uint64_t trim_timestamp = 25;
   constexpr int idle_tid = 0;
   constexpr int non_idle_tid = 100;
 
@@ -66,7 +66,7 @@ TEST_F(ArcSystemModelTest, TrimByTimestampCPU) {
 
   ASSERT_EQ(3U, cpu_events_1.size());
   EXPECT_EQ(ArcCpuEvent::Type::kIdleIn, cpu_events_1[0].type);
-  EXPECT_EQ(32, cpu_events_1[0].timestamp);
+  EXPECT_EQ(32u, cpu_events_1[0].timestamp);
 
   ASSERT_EQ(2U, cpu_events_2.size());
   EXPECT_EQ(ArcCpuEvent::Type::kWakeUp, cpu_events_2[0].type);
@@ -80,7 +80,7 @@ TEST_F(ArcSystemModelTest, TrimByTimestampCPU) {
 TEST_F(ArcSystemModelTest, TrimByTimestampMemory) {
   ArcSystemModel model;
 
-  constexpr int64_t trim_timestamp = 25;
+  constexpr uint64_t trim_timestamp = 25;
 
   // First of ArcValueEvent::Type::kMemTotal should be clamped to
   // |trim_timestamp|.

chrome/browser/chromeos/arc/tracing/arc_tracing_event.cc

@@ -120,25 +120,26 @@ void ArcTracingEvent::SetPhase(char phase) {
   dictionary_.SetKey(kKeyPhase, base::Value(std::string() + phase));
 }
 
-int64_t ArcTracingEvent::GetTimestamp() const {
+uint64_t ArcTracingEvent::GetTimestamp() const {
   return GetDoubleFromDictionary(GetDictionary(), kKeyTimestamp,
                                  0.0 /* default_value */);
 }
 
-void ArcTracingEvent::SetTimestamp(double timestamp) {
-  dictionary_.SetKey(kKeyTimestamp, base::Value(timestamp));
+void ArcTracingEvent::SetTimestamp(uint64_t timestamp) {
+  dictionary_.SetKey(kKeyTimestamp,
+                     base::Value(static_cast<double>(timestamp)));
 }
 
-int64_t ArcTracingEvent::GetDuration() const {
+uint64_t ArcTracingEvent::GetDuration() const {
   return GetDoubleFromDictionary(GetDictionary(), kKeyDuration,
                                  0.0 /* default_value */);
 }
 
-void ArcTracingEvent::SetDuration(double duration) {
-  dictionary_.SetKey(kKeyDuration, base::Value(duration));
+void ArcTracingEvent::SetDuration(uint64_t duration) {
+  dictionary_.SetKey(kKeyDuration, base::Value(static_cast<double>(duration)));
 }
 
-int64_t ArcTracingEvent::GetEndTimestamp() const {
+uint64_t ArcTracingEvent::GetEndTimestamp() const {
   return GetTimestamp() + GetDuration();
 }
 

chrome/browser/chromeos/arc/tracing/arc_tracing_event.h

@@ -63,18 +63,18 @@ class ArcTracingEvent {
   void SetPhase(char phase);
 
   // Gets timestamp of the start of the event. Return 0 if not set.
-  int64_t GetTimestamp() const;
+  uint64_t GetTimestamp() const;
   // Sets timestamp of the start of the event.
-  void SetTimestamp(double timestamp);
+  void SetTimestamp(uint64_t timestamp);
 
   // Gets duration of the event.  Return 0 if not set. It is optional for some
   // events.
-  int64_t GetDuration() const;
+  uint64_t GetDuration() const;
   // Sets duration of the event.
-  void SetDuration(double duration);
+  void SetDuration(uint64_t duration);
 
   // Gets timestamp of the end of the event.
-  int64_t GetEndTimestamp() const;
+  uint64_t GetEndTimestamp() const;
 
   // Returns base representation of the event as a |base::DictionaryValue|.
   const base::DictionaryValue* GetDictionary() const;

chrome/browser/chromeos/arc/tracing/arc_tracing_graphics_model.cc

@@ -659,7 +659,7 @@ ssize_t FindAcquireReleasePair(
 // |timestamp|. Returns |kInvalidBufferIndex| in case event is not found.
 ssize_t FindNotLaterThan(const ArcTracingGraphicsModel::BufferEvents& events,
                          BufferEventType type,
-                         int64_t timestamp) {
+                         uint64_t timestamp) {
   if (events.empty() || events[0].timestamp > timestamp)
     return kInvalidBufferIndex;
 
@@ -1146,8 +1146,8 @@ void ArcTracingGraphicsModel::NormalizeTimestamps() {
     all_buffers.emplace_back(&buffer);
   all_buffers.emplace_back(&chrome_top_level_.global_events());
 
-  int64_t min = std::numeric_limits<int64_t>::max();
-  int64_t max = std::numeric_limits<int64_t>::min();
+  uint64_t min = std::numeric_limits<uint64_t>::max();
+  uint64_t max = std::numeric_limits<uint64_t>::min();
   for (const BufferEvents* buffer : all_buffers) {
     if (!buffer->empty()) {
       min = std::min(min, buffer->front().timestamp);

chrome/browser/chromeos/arc/tracing/arc_tracing_graphics_model.h

@@ -92,7 +92,7 @@ class ArcTracingGraphicsModel {
     bool operator==(const BufferEvent& other) const;
 
     BufferEventType type;
-    int64_t timestamp;
+    uint64_t timestamp;
     std::string content;
   };
 

chrome/browser/chromeos/arc/tracing/arc_tracing_model.cc

@@ -102,7 +102,7 @@ struct GraphicsEventsContext {
 };
 
 bool HandleGraphicsEvent(GraphicsEventsContext* context,
-                         double timestamp,
+                         uint64_t timestamp,
                          uint32_t tid,
                          const std::string& line,
                          size_t event_position) {
@@ -166,7 +166,7 @@ bool HandleGraphicsEvent(GraphicsEventsContext* context,
 }
 
 bool HandleCpuIdle(AllCpuEvents* all_cpu_events,
-                   double timestamp,
+                   uint64_t timestamp,
                    uint32_t cpu_id,
                    uint32_t tid,
                    const std::string& line,
@@ -191,7 +191,7 @@ bool HandleCpuIdle(AllCpuEvents* all_cpu_events,
 }
 
 bool HandleSchedWakeUp(AllCpuEvents* all_cpu_events,
-                       double timestamp,
+                       uint64_t timestamp,
                        uint32_t cpu_id,
                        uint32_t tid,
                        const std::string& line,
@@ -247,7 +247,7 @@ bool HandleSchedWakeUp(AllCpuEvents* all_cpu_events,
 }
 
 bool HandleSchedSwitch(AllCpuEvents* all_cpu_events,
-                       double timestamp,
+                       uint64_t timestamp,
                        uint32_t cpu_id,
                        uint32_t tid,
                        const std::string& line,
@@ -266,7 +266,7 @@ bool HandleSchedSwitch(AllCpuEvents* all_cpu_events,
 }
 
 bool HandleGpuFreq(ValueEvents* value_events,
-                   double timestamp,
+                   uint64_t timestamp,
                    const std::string& line,
                    size_t event_position) {
   int new_freq = -1;
@@ -402,8 +402,8 @@ bool ArcTracingModel::ProcessEvent(base::ListValue* events) {
   // for others may appear after children. Sort by ts time.
   std::sort(parsed_events.begin(), parsed_events.end(),
             [](const auto& lhs, const auto& rhs) {
-              const int64_t lhs_timestamp = lhs->GetTimestamp();
-              const int64_t rhs_timestamp = rhs->GetTimestamp();
+              const uint64_t lhs_timestamp = lhs->GetTimestamp();
+              const uint64_t rhs_timestamp = rhs->GetTimestamp();
               if (lhs_timestamp != rhs_timestamp)
                 return lhs_timestamp < rhs->GetTimestamp();
               return lhs->GetDuration() > rhs->GetDuration();
@@ -496,12 +496,14 @@ bool ArcTracingModel::ConvertSysTraces(const std::string& sys_traces) {
     }
     const size_t separator_position =
         ParseUint32(line, pos_dot + 1, ':', &timestamp_low);
-    if (separator_position == std::string::npos) {
+    // We expect to have parsed exactly six digits after the decimal point, to
+    // match the scaling factor used just below.
+    if (separator_position != pos_dot + 7) {
       LOG(ERROR) << "Cannot parse timestamp in trace event: " << line;
       return false;
     }
 
-    const double timestamp = 1000000L * timestamp_high + timestamp_low;
+    const uint64_t timestamp = 1000000LL * timestamp_high + timestamp_low;
     if (timestamp < min_timestamp_ || timestamp >= max_timestamp_)
       continue;
 

chrome/browser/chromeos/arc/tracing/arc_tracing_model_unittest.cc

@@ -76,7 +76,7 @@ bool ValidateGrahpicsEvents(const GraphicsEvents& events,
                             const std::set<GraphicsEventType>& allowed_types) {
   if (events.empty())
     return false;
-  int64_t previous_timestamp = 0;
+  uint64_t previous_timestamp = 0;
   std::set<GraphicsEventType> used_types;
   for (const auto& event : events) {
     if (event.timestamp < previous_timestamp) {
@@ -190,7 +190,8 @@ TEST_F(ArcTracingModelTest, TopLevel) {
   // Check trimmed by VSYNC.
   EXPECT_EQ(GraphicsEventType::kVsync,
             graphics_model.android_top_level().global_events()[0].type);
-  EXPECT_EQ(0, graphics_model.android_top_level().global_events()[0].timestamp);
+  EXPECT_EQ(0U,
+            graphics_model.android_top_level().global_events()[0].timestamp);
 
   EXPECT_EQ(2U, graphics_model.chrome_top_level().buffer_events().size());
   for (const auto& chrome_top_level_band :
@@ -256,6 +257,91 @@ TEST_F(ArcTracingModelTest, TopLevel) {
   EnsureGraphicsModelsEqual(graphics_model, graphics_model_loaded);
 }
 
+// Validates basic system event timestamp processing
+TEST_F(ArcTracingModelTest, SystemTraceEventTimestampParsing) {
+  {
+    std::string tracing_data =
+        "{\"traceEvents\":[],\"systemTraceEvents\":\""
+        // clang-format off
+        "  surfaceflinger-9772  [000] ...0 80156.539255: tracing_mark_write: B|15|acquireBuffer\n"
+        // clang-format on
+        "\"}";
+
+    ArcTracingModel model;
+    ASSERT_TRUE(model.Build(tracing_data));
+
+    const ArcTracingModel::TracingEventPtrs events =
+        model.Select("android:acquireBuffer");
+    ASSERT_EQ(1u, events.size());
+    EXPECT_EQ(15, events[0]->GetPid());
+    EXPECT_EQ("android", events[0]->GetCategory());
+    EXPECT_EQ("acquireBuffer", events[0]->GetName());
+    EXPECT_EQ('X', events[0]->GetPhase());
+    EXPECT_EQ(80156539255UL, events[0]->GetTimestamp());
+    EXPECT_EQ(0U, events[0]->GetDuration());
+  }
+
+  {
+    // Too few digits after the timestamp decimal point should be an error
+    std::string bad_tracing_data_1 =
+        "{\"traceEvents\":[],\"systemTraceEvents\":\""
+        // clang-format off
+        "  surfaceflinger-9772  [000] ...0 999.12345: tracing_mark_write: B|15|acquireBuffer\n"
+        // clang-format on
+        "\"}";
+    ArcTracingModel model;
+    EXPECT_FALSE(model.Build(bad_tracing_data_1));
+  }
+
+  {
+    // Too many digits after the timestamp decimal point should be an error
+    std::string bad_tracing_data_2 =
+        "{\"traceEvents\":[],\"systemTraceEvents\":\""
+        // clang-format off
+        "  surfaceflinger-9772  [000] ...0 999.1234567: tracing_mark_write: B|15|acquireBuffer\n"
+        // clang-format on
+        "\"}";
+    ArcTracingModel model;
+    EXPECT_FALSE(model.Build(bad_tracing_data_2));
+  }
+}
+
+TEST_F(ArcTracingModelTest, SystemTraceEventCpuEventProcessing) {
+  std::string tracing_data =
+      "{\"traceEvents\":[],\"systemTraceEvents\":\""
+      // clang-format off
+      "          <idle>-0     [000] d..0 123.000001: cpu_idle: state=0 cpu_id=0\n"
+      "          <idle>-0     [000] dn.0 123.000002: cpu_idle: state=4294967295 cpu_id=0\n"
+      "          <idle>-0     [000] dnh3 123.000003: sched_wakeup: comm=foo pid=15821 prio=115 target_cpu=000\n"
+      "          <idle>-0     [000] d..3 123.000004: sched_switch: prev_comm=bar prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=baz next_pid=15821 next_prio=115\n"
+      // clang-format on
+      "\"}";
+
+  ArcTracingModel model;
+  ASSERT_TRUE(model.Build(tracing_data));
+
+  const AllCpuEvents& cpu_events = model.system_model().all_cpu_events();
+  ASSERT_EQ(1u, cpu_events.size());
+  CpuEvents cpu0_events = cpu_events[0];
+  ASSERT_EQ(4u, cpu0_events.size());
+
+  EXPECT_EQ(123000001UL, cpu0_events[0].timestamp);
+  EXPECT_EQ(ArcCpuEvent::Type::kIdleIn, cpu0_events[0].type);
+  EXPECT_EQ(0u, cpu0_events[0].tid);
+
+  EXPECT_EQ(123000002UL, cpu0_events[1].timestamp);
+  EXPECT_EQ(ArcCpuEvent::Type::kIdleOut, cpu0_events[1].type);
+  EXPECT_EQ(0u, cpu0_events[1].tid);
+
+  EXPECT_EQ(123000003UL, cpu0_events[2].timestamp);
+  EXPECT_EQ(ArcCpuEvent::Type::kWakeUp, cpu0_events[2].type);
+  EXPECT_EQ(15821u, cpu0_events[2].tid);
+
+  EXPECT_EQ(123000004UL, cpu0_events[3].timestamp);
+  EXPECT_EQ(ArcCpuEvent::Type::kActive, cpu0_events[3].type);
+  EXPECT_EQ(15821u, cpu0_events[3].tid);
+}
+
 TEST_F(ArcTracingModelTest, Event) {
   const ArcTracingEvent event(base::JSONReader::Read(kTestEvent).value());
 
@@ -265,9 +351,9 @@ TEST_F(ArcTracingModelTest, Event) {
   EXPECT_EQ(kExo, event.GetCategory());
   EXPECT_EQ(kSurfaceAttach, event.GetName());
   EXPECT_EQ(kPhaseX, event.GetPhase());
-  EXPECT_EQ(14241877057L, event.GetTimestamp());
-  EXPECT_EQ(10, event.GetDuration());
-  EXPECT_EQ(14241877067L, event.GetEndTimestamp());
+  EXPECT_EQ(14241877057UL, event.GetTimestamp());
+  EXPECT_EQ(10U, event.GetDuration());
+  EXPECT_EQ(14241877067UL, event.GetEndTimestamp());
   EXPECT_NE(nullptr, event.GetDictionary());
   EXPECT_EQ(kBufferIdValue, event.GetArgAsString(kBufferId, std::string()));
   EXPECT_EQ(kDefault, event.GetArgAsString(kBufferIdBad, kDefault));
@@ -411,8 +497,8 @@ TEST_F(ArcTracingModelTest, TimeMinMax) {
   model_with_time_filter.SetMinMaxTime(100001L, 100003L);
   EXPECT_TRUE(model_with_time_filter.Build(tracing_data));
   ASSERT_EQ(2U, model_with_time_filter.GetRoots().size());
-  EXPECT_EQ(100001L, model_with_time_filter.GetRoots()[0]->GetTimestamp());
-  EXPECT_EQ(100002L, model_with_time_filter.GetRoots()[1]->GetTimestamp());
+  EXPECT_EQ(100001UL, model_with_time_filter.GetRoots()[0]->GetTimestamp());
+  EXPECT_EQ(100002UL, model_with_time_filter.GetRoots()[1]->GetTimestamp());
 
   ArcTracingModel model_with_empty_time_filter;
   model_with_empty_time_filter.SetMinMaxTime(99999L, 100000L);
@@ -468,10 +554,10 @@ TEST_F(ArcTracingModelTest, EventsContainerTrim) {
       &events, trim_timestamp,
       {ArcTracingGraphicsModel::BufferEventType::kChromeOSDraw});
   ASSERT_EQ(3U, events.global_events().size());
-  EXPECT_EQ(25, events.global_events()[0].timestamp);
+  EXPECT_EQ(25U, events.global_events()[0].timestamp);
   ASSERT_EQ(1U, events.buffer_events().size());
   ASSERT_EQ(2U, events.buffer_events()[0].size());
-  EXPECT_EQ(40, events.buffer_events()[0][0].timestamp);
+  EXPECT_EQ(40U, events.buffer_events()[0][0].timestamp);
   EXPECT_EQ(ArcTracingGraphicsModel::BufferEventType::kChromeOSDraw,
             events.buffer_events()[0][0].type);
 }

chrome/browser/chromeos/arc/tracing/arc_value_event.h

@@ -30,7 +30,7 @@ struct ArcValueEvent {
 
   bool operator==(const ArcValueEvent& other) const;
 
-  int64_t timestamp;
+  uint64_t timestamp;
   Type type;
   /**
    * kMemTotal - kb.