Add traces for events related to TSF.

This patch adds some traces in the APIs that are called when the IME
on Windows tries to position the candidate window and start a new
composition. These traces would be really useful while trying to
debug IME related issues which are also hard to debug in a debugger
as they are sensitive to timings and focus loss.

Bug: 1152893, 1151301

Change-Id: I1f0e36d4f9524190efb6b3404d0eb96ee5c85679
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2572800
Commit-Queue: Anupam Snigdha <snianu@microsoft.com>
Reviewed-by: Yohei Yukawa <yukawa@chromium.org>
Reviewed-by: Avi Drissman <avi@chromium.org>
Reviewed-by: danakj <danakj@chromium.org>
Cr-Commit-Position: refs/heads/master@{#834436}

base/trace_event/builtin_categories.h

@@ -88,6 +88,7 @@
   X("headless")                                                          \
   X("hwoverlays")                                                        \
   X("identity")                                                          \
+  X("ime")                                                               \
   X("IndexedDB")                                                         \
   X("input")                                                             \
   X("io")                                                                \

content/browser/renderer_host/render_widget_host_view_aura.cc

@@ -689,6 +689,7 @@ gfx::Size RenderWidgetHostViewAura::GetVisibleViewportSize() {
 }
 
 void RenderWidgetHostViewAura::SetInsets(const gfx::Insets& insets) {
+  TRACE_EVENT0("vk", "RenderWidgetHostViewAura::SetInsets");
   if (insets != insets_) {
     insets_ = insets;
     window_->AllocateLocalSurfaceId();
@@ -1229,8 +1230,11 @@ gfx::Rect RenderWidgetHostViewAura::GetCaretBounds() const {
 
   const TextInputManager::SelectionRegion* region =
       text_input_manager_->GetSelectionRegion();
-  return ConvertRectToScreen(
+  gfx::Rect caret_rect = ConvertRectToScreen(
       gfx::RectBetweenSelectionBounds(region->anchor, region->focus));
+  TRACE_EVENT1("ime", "RenderWidgetHostViewAura::GetCaretBounds", "caret_rect",
+               caret_rect.ToString());
+  return caret_rect;
 }
 
 bool RenderWidgetHostViewAura::GetCompositionCharacterBounds(
@@ -1247,6 +1251,8 @@ bool RenderWidgetHostViewAura::GetCompositionCharacterBounds(
   if (index >= composition_range_info->character_bounds.size())
     return false;
   *rect = ConvertRectToScreen(composition_range_info->character_bounds[index]);
+  TRACE_EVENT1("ime", "RenderWidgetHostViewAura::GetCompositionCharacterBounds",
+               "comp_char_rect", rect->ToString());
   return true;
 }
 
@@ -1521,16 +1527,22 @@ void RenderWidgetHostViewAura::GetActiveTextInputControlLayoutBounds(
     const ui::mojom::TextInputState* state =
         text_input_manager_->GetTextInputState();
     if (state) {
-      if (state->edit_context_control_bounds)
+      if (state->edit_context_control_bounds) {
         *control_bounds =
             ConvertRectToScreen(state->edit_context_control_bounds.value());
+        TRACE_EVENT1(
+            "ime",
+            "RenderWidgetHostViewAura::GetActiveTextInputControlLayoutBounds",
+            "control_bounds_rect", control_bounds->value().ToString());
+      }
       // Selection bounds are currently populated only for EditContext.
       // For editable elements we use GetCompositionCharacterBounds.
-      if (state->edit_context_selection_bounds)
+      if (state->edit_context_selection_bounds) {
         *selection_bounds =
             ConvertRectToScreen(state->edit_context_selection_bounds.value());
       }
     }
+  }
 }
 
 void RenderWidgetHostViewAura::SetActiveCompositionForAccessibility(

content/browser/renderer_host/text_input_manager.cc

@@ -117,6 +117,19 @@ void TextInputManager::UpdateTextInputState(
   // TextInputState.
   bool changed = ShouldUpdateTextInputState(*text_input_state_map_[view],
                                             text_input_state);
+  TRACE_EVENT2(
+      "ime", "TextInputManager::UpdateTextInputState", "changed", changed,
+      "text_input_state - type, selection, composition, "
+      "show_ime_if_needed, control_bounds",
+      std::to_string(text_input_state.type) + ", " +
+          text_input_state.selection.ToString() + ", " +
+          (text_input_state.composition.has_value()
+               ? text_input_state.composition->ToString()
+               : "") +
+          ", " + std::to_string(text_input_state.show_ime_if_needed) + ", " +
+          (text_input_state.edit_context_control_bounds.has_value()
+               ? text_input_state.edit_context_control_bounds->ToString()
+               : ""));
   text_input_state_map_[view] = text_input_state.Clone();
   for (const auto& ime_text_span_info :
        text_input_state_map_[view]->ime_text_spans_info) {

ui/base/ime/win/tsf_bridge.cc

@@ -12,6 +12,7 @@
 #include "base/stl_util.h"
 #include "base/task/current_thread.h"
 #include "base/threading/thread_local_storage.h"
+#include "base/trace_event/trace_event.h"
 #include "base/win/scoped_variant.h"
 #include "ui/base/ime/input_method_delegate.h"
 #include "ui/base/ime/text_input_client.h"
@@ -614,6 +615,7 @@ TSFBridge::~TSFBridge() {}
 
 // static
 HRESULT TSFBridge::Initialize() {
+  TRACE_EVENT0("ime", "TSFBridge::Initialize");
   if (!base::CurrentUIThread::IsSet()) {
     return E_FAIL;
   }
@@ -662,6 +664,7 @@ void TSFBridge::ReplaceThreadLocalTSFBridge(TSFBridge* new_instance) {
 
 // static
 void TSFBridge::Shutdown() {
+  TRACE_EVENT0("ime", "TSFBridge::Shutdown");
   if (!base::CurrentUIThread::IsSet()) {
   }
   ReplaceThreadLocalTSFBridge(nullptr);

ui/base/ime/win/tsf_text_store.cc

@@ -13,6 +13,7 @@
 
 #include "base/logging.h"
 #include "base/numerics/ranges.h"
+#include "base/trace_event/trace_event.h"
 #include "base/win/scoped_variant.h"
 #include "ui/base/ime/text_input_client.h"
 #include "ui/base/ime/win/tsf_input_scope.h"
@@ -47,7 +48,9 @@ bool GetWindowClientRect(HWND window_handle,
 
 }  // namespace
 
-TSFTextStore::TSFTextStore() {}
+TSFTextStore::TSFTextStore() {
+  TRACE_EVENT0("ime", "TSFTextStore::TSFTextStore");
+}
 
 TSFTextStore::~TSFTextStore() {}
 
@@ -214,6 +217,9 @@ HRESULT TSFTextStore::GetScreenExt(TsViewCookie view_cookie, RECT* rect) {
     rect->right = right_bottom.x;
     rect->bottom = right_bottom.y;
   }
+
+  TRACE_EVENT1("ime", "TSFTextStore::GetScreenExt", "control_bounding_rect",
+               gfx::Rect(*rect).ToString());
   return S_OK;
 }
 
@@ -408,6 +414,8 @@ HRESULT TSFTextStore::GetTextExt(TsViewCookie view_cookie,
                                                    result_rect.value())
               .ToRECT();
   *clipped = FALSE;
+  TRACE_EVENT1("ime", "TSFTextStore::GetTextExt", "selection_bounding_rect",
+               gfx::Rect(*rect).ToString());
   return S_OK;
 }
 
@@ -802,6 +810,7 @@ HRESULT TSFTextStore::SetText(DWORD flags,
                               const wchar_t* text_buffer,
                               ULONG text_buffer_size,
                               TS_TEXTCHANGE* text_change) {
+  TRACE_EVENT0("ime", "TSFTextStore::SetText");
   if (!HasReadWriteLock())
     return TS_E_NOLOCK;
 
@@ -838,6 +847,7 @@ HRESULT TSFTextStore::UnadviseSink(IUnknown* unknown) {
 
 HRESULT TSFTextStore::OnStartComposition(ITfCompositionView* composition_view,
                                          BOOL* ok) {
+  TRACE_EVENT0("ime", "TSFTextStore::OnStartComposition");
   if (ok)
     *ok = TRUE;
 
@@ -851,6 +861,7 @@ HRESULT TSFTextStore::OnUpdateComposition(ITfCompositionView* composition_view,
 }
 
 HRESULT TSFTextStore::OnEndComposition(ITfCompositionView* composition_view) {
+  TRACE_EVENT0("ime", "TSFTextStore::OnEndComposition");
   return S_OK;
 }
 
@@ -911,6 +922,7 @@ void TSFTextStore::DispatchKeyEvent(ui::EventType type,
 HRESULT TSFTextStore::OnEndEdit(ITfContext* context,
                                 TfEditCookie read_only_edit_cookie,
                                 ITfEditRecord* edit_record) {
+  TRACE_EVENT0("ime", "TSFTextStore::OnEndEdit");
   if (!context || !edit_record)
     return E_INVALIDARG;
 
@@ -980,6 +992,7 @@ HRESULT TSFTextStore::OnEndEdit(ITfContext* context,
 
 bool TSFTextStore::GetDisplayAttribute(TfGuidAtom guid_atom,
                                        TF_DISPLAYATTRIBUTE* attribute) {
+  TRACE_EVENT0("ime", "TSFTextStore::GetDisplayAttribute");
   GUID guid;
   if (FAILED(category_manager_->GetGUID(guid_atom, &guid)))
     return false;
@@ -1088,6 +1101,7 @@ bool TSFTextStore::GetCompositionStatus(
 }
 
 bool TSFTextStore::TerminateComposition() {
+  TRACE_EVENT0("ime", "TSFTextStore::TerminateComposition");
   if (context_ && has_composition_range_) {
     Microsoft::WRL::ComPtr<ITfContextOwnerCompositionServices> service;
 
@@ -1108,6 +1122,10 @@ void TSFTextStore::CalculateTextandSelectionDiffAndNotifyIfNeeded() {
       is_tic_write_in_progress_)
     return;
 
+  // TODO(snianu) Perhaps we can do the diff at the TextInputManager layer and
+  // only report the diffs?
+  TRACE_EVENT0("ime",
+               "TSFTextStore::CalculateTextandSelectionDiffAndNotifyIfNeeded");
   gfx::Range latest_buffer_range_from_client;
   base::string16 latest_buffer_from_client;
   gfx::Range latest_selection_from_client;
@@ -1212,10 +1230,17 @@ void TSFTextStore::CalculateTextandSelectionDiffAndNotifyIfNeeded() {
     // into us during notification.
     is_notification_in_progress_ = true;
     if (notify_text_change && text_changed) {
+      TRACE_EVENT2(
+          "ime", "TSFTextStore::CalculateTextandSelectionDiffAndNotifyIfNeeded",
+          "text_change_start", std::to_string(text_change.acpStart),
+          "text_change_end", std::to_string(text_change.acpNewEnd));
       text_store_acp_sink_->OnTextChange(0, &text_change);
     }
 
     if (notify_selection_change && selection_changed) {
+      TRACE_EVENT1(
+          "ime", "TSFTextStore::CalculateTextandSelectionDiffAndNotifyIfNeeded",
+          "new_selection", selection_.ToString());
       text_store_acp_sink_->OnSelectionChange();
     }
     is_notification_in_progress_ = false;
@@ -1261,6 +1286,7 @@ bool TSFTextStore::CancelComposition() {
   // TODO(IME): Check other platforms to see if |CancelComposition()| is
   //            actually working or not.
 
+  TRACE_EVENT0("ime", "TSFTextStore::CancelComposition");
   return ConfirmComposition();
 }
 
@@ -1301,8 +1327,11 @@ void TSFTextStore::SendOnLayoutChange() {
   if (is_notification_in_progress_)
     return;
   CalculateTextandSelectionDiffAndNotifyIfNeeded();
-  if (text_store_acp_sink_ && (text_store_acp_sink_mask_ & TS_AS_LAYOUT_CHANGE))
+  if (text_store_acp_sink_ &&
+      (text_store_acp_sink_mask_ & TS_AS_LAYOUT_CHANGE)) {
+    TRACE_EVENT0("ime", "TSFTextStore::SendOnLayoutChange");
     text_store_acp_sink_->OnLayoutChange(TS_LC_CHANGE, 0);
+  }
 }
 
 bool TSFTextStore::HasReadLock() const {