Replace DCHECK() upon unexpected x11 event time with a workaround

ui/events/x/events_x_utils.cc

 // Copyright (c) 2016 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "ui/events/x/events_x_utils.h"
 
 #include <stddef.h>
 #include <string.h>
 #include <X11/extensions/XInput.h>
 #include <X11/extensions/XInput2.h>
 #include <X11/XKBlib.h>
 #include <X11/Xlib.h>
 #include <X11/Xutil.h>
 #include <cmath>
 
 #include "base/lazy_instance.h"
 #include "base/logging.h"
 #include "base/macros.h"
 #include "base/memory/singleton.h"
+#include "base/metrics/histogram_macros.h"
 #include "build/build_config.h"
 #include "ui/display/display.h"
 #include "ui/display/screen.h"
 #include "ui/events/devices/x11/device_data_manager_x11.h"
 #include "ui/events/devices/x11/device_list_cache_x11.h"
 #include "ui/events/devices/x11/touch_factory_x11.h"
+#include "ui/events/event_utils.h"
 #include "ui/events/keycodes/keyboard_code_conversion_x.h"
 #include "ui/gfx/geometry/point.h"
 #include "ui/gfx/geometry/rect.h"
 #include "ui/gfx/x/x11_atom_cache.h"
 #include "ui/gfx/x/x11_types.h"
 
 namespace {
 
 // Scroll amount for each wheelscroll event. 53 is also the value used for GTK+.
 const int kWheelScrollAmount = 53;
@@ skipping 263 matching lines @@
   if (!start_time)
     start_time = &start_time_;
   if (!end_time)
     end_time = &end_time_;
 
   ui::DeviceDataManagerX11::GetInstance()->GetGestureTimes(xev, start_time,
                                                            end_time);
   return true;
 }
 
+namespace {
 int64_t g_last_seen_timestamp_ms = 0;
-// accumulated rollover time.
 int64_t g_rollover_ms = 0;
+bool g_bogus_x11_timestamps = false;
 base::LazyInstance<std::unique_ptr<base::TickClock>>::Leaky g_tick_clock =
     LAZY_INSTANCE_INITIALIZER;
 
+enum UMAEventTimestampValidity {
+  UMA_EVENT_TIMESTAMPS_HAVE_INVALID_TIMEBASE,
+  UMA_EVENT_TIMESTAMPS_HAVE_VALID_TIMEBASE
+};
+
+}  // namespace
+
 // Takes Xlib Time and returns a time delta that is immune to timer rollover.
 // This function is not thread safe as we do not use a lock.
 base::TimeDelta TimeDeltaFromXEventTime(Time timestamp) {
   int64_t timestamp64 = timestamp;
 
   if (!timestamp)
     return base::TimeDelta();
 
+  if (g_bogus_x11_timestamps)
+    return ui::EventTimeForNow();
+
   // If this is the first event that we get, assume the time stamp roll-over
   // might have happened before the process was started.
   // Register a rollover if the distance between last timestamp and current one
   // is larger than half the width. This avoids false rollovers even in a case
   // where X server delivers reasonably close events out-of-order.
   bool had_recent_rollover =
       !g_last_seen_timestamp_ms ||
       g_last_seen_timestamp_ms - timestamp64 > (UINT32_MAX >> 1);
 
   g_last_seen_timestamp_ms = timestamp64;
   if (!had_recent_rollover)
     return base::TimeDelta::FromMilliseconds(g_rollover_ms + timestamp);
 
   DCHECK(timestamp64 <= UINT32_MAX)
       << "X11 Time does not roll over 32 bit, the below logic is likely wrong";
 
   base::TimeTicks now_ticks = g_tick_clock.Get() != nullptr
                                   ? g_tick_clock.Get()->NowTicks()
                                   : base::TimeTicks::Now();
   int64_t now_ms = (now_ticks - base::TimeTicks()).InMilliseconds();
 
   g_rollover_ms = now_ms & ~static_cast<int64_t>(UINT32_MAX);
   uint32_t delta = static_cast<uint32_t>(now_ms - timestamp);
-  // If using a mock clock, all bets are off -- in some tests, actual X11 events
-  // come through with real timestamps.
-  DCHECK(delta < 60 * 1000 || g_tick_clock.Get() != nullptr)
-      << "Unexpected X11 event time, now: " << now_ticks
-      << " event at: " << timestamp;
+  if (!g_tick_clock.Get()) {
+    if (delta > 60 * 1000) {
+      // x11 timestamps don't seem to be using the same time base as TimeTicks,
+      // so ignore them altogether and always use current time instead.
+      delta = 0;
+      g_bogus_x11_timestamps = true;
+      LOG(WARNING)
+          << "Unexpected x11 timestamps, will use browser time instead.";
+    }
+    UMA_HISTOGRAM_BOOLEAN("Event.TimestampHasValidTimebase",
+                          g_bogus_x11_timestamps
+                              ? UMA_EVENT_TIMESTAMPS_HAVE_INVALID_TIMEBASE
+                              : UMA_EVENT_TIMESTAMPS_HAVE_VALID_TIMEBASE);

[Ilya Sherman, 2016/05/23 18:36:33]

nit: No need to use an enum in the C++ code -- you can just log a boolean value
here.  In my previous comment, I was just asking you to update histograms.xml to
provide labels for users viewing the dashboard :)

+  }
+
   return base::TimeDelta::FromMilliseconds(now_ms - delta);
 }
 
 }  // namespace
 
 namespace ui {
 
 EventType EventTypeFromXEvent(const XEvent& xev) {
   // Allow the DeviceDataManager to block the event. If blocked return
   // ET_UNKNOWN as the type so this event will not be further processed.
@@ skipping 445 matching lines @@
 
   DeviceDataManagerX11::GetInstance()->GetFlingData(xev, vx, vy, vx_ordinal,
                                                     vy_ordinal, is_cancel);
   return true;
 }
 
 void ResetTimestampRolloverCountersForTesting(
     std::unique_ptr<base::TickClock> tick_clock) {
   g_last_seen_timestamp_ms = 0;
   g_rollover_ms = 0;
+  g_bogus_x11_timestamps = false;
   g_tick_clock.Get() = std::move(tick_clock);
 }
 
 }  // namespace ui