Bug 1200980 part.1 Log the behavior of IMEContentObserver for debugging r=smaug
authorMasayuki Nakano <masayuki@d-toybox.com>
Tue, 08 Sep 2015 12:54:14 +0900
changeset 293864 363401fd972c08d2321022704d16f9f05442bc5f
parent 293863 1e8a4d53837fc52c727614b879c5b5eb45899d3a
child 293865 92127319836ac2c4704c92a40e9d4967fcac93ae
push id5245
push userraliiev@mozilla.com
push dateThu, 29 Oct 2015 11:30:51 +0000
treeherdermozilla-beta@dac831dc1bd0 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerssmaug
bugs1200980
milestone43.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1200980 part.1 Log the behavior of IMEContentObserver for debugging r=smaug
dom/events/IMEContentObserver.cpp
dom/events/IMEContentObserver.h
--- a/dom/events/IMEContentObserver.cpp
+++ b/dom/events/IMEContentObserver.cpp
@@ -1,14 +1,16 @@
 /* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
 /* vim: set ts=8 sts=2 et sw=2 tw=80: */
 /* This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
+#include "mozilla/Logging.h"
+
 #include "ContentEventHandler.h"
 #include "IMEContentObserver.h"
 #include "mozilla/AsyncEventDispatcher.h"
 #include "mozilla/AutoRestore.h"
 #include "mozilla/EventStateManager.h"
 #include "mozilla/IMEStateManager.h"
 #include "mozilla/MouseEvents.h"
 #include "mozilla/TextComposition.h"
@@ -32,16 +34,88 @@
 #include "nsPresContext.h"
 #include "nsWeakReference.h"
 #include "WritingModes.h"
 
 namespace mozilla {
 
 using namespace widget;
 
+PRLogModuleInfo* sIMECOLog = nullptr;
+
+static const char*
+ToChar(bool aBool)
+{
+  return aBool ? "true" : "false";
+}
+
+class WritingModeToString final : public nsAutoCString
+{
+public:
+  explicit WritingModeToString(const WritingMode& aWritingMode)
+  {
+    if (!aWritingMode.IsVertical()) {
+      AssignLiteral("Horizontal");
+      return;
+    }
+    if (aWritingMode.IsVerticalLR()) {
+      AssignLiteral("Vertical (LR)");
+      return;
+    }
+    AssignLiteral("Vertical (RL)");
+  }
+  virtual ~WritingModeToString() {}
+};
+
+class SelectionChangeDataToString final : public nsAutoCString
+{
+public:
+  explicit SelectionChangeDataToString(
+             const IMENotification::SelectionChangeDataBase& aData)
+  {
+    if (!aData.IsValid()) {
+      AppendLiteral("{ IsValid()=false }");
+      return;
+    }
+    AppendPrintf("{ mOffset=%u, ", aData.mOffset);
+    if (aData.mString->Length() > 20) {
+      AppendPrintf("mString.Length()=%u, ", aData.mString->Length());
+    } else {
+      AppendPrintf("mString=\"%s\" (Length()=%u), ",
+                   NS_ConvertUTF16toUTF8(*aData.mString).get(),
+                   aData.mString->Length());
+    }
+    AppendPrintf("GetWritingMode()=%s, mReversed=%s, mCausedByComposition=%s, "
+                 "mCausedBySelectionEvent=%s }",
+                 WritingModeToString(aData.GetWritingMode()).get(),
+                 ToChar(aData.mReversed),
+                 ToChar(aData.mCausedByComposition),
+                 ToChar(aData.mCausedBySelectionEvent));
+  }
+  virtual ~SelectionChangeDataToString() {}
+};
+
+class TextChangeDataToString final : public nsAutoCString
+{
+public:
+  explicit TextChangeDataToString(
+             const IMENotification::TextChangeDataBase& aData)
+  {
+    if (!aData.IsValid()) {
+      AppendLiteral("{ IsValid()=false }");
+      return;
+    }
+    AppendPrintf("{ mStartOffset=%u, mRemovedEndOffset=%u, mAddedEndOffset=%u, "
+                 "mCausedByComposition=%s }", aData.mStartOffset,
+                 aData.mRemovedEndOffset, aData.mAddedEndOffset,
+                 ToChar(aData.mCausedByComposition));
+  }
+  virtual ~TextChangeDataToString() {}
+};
+
 /******************************************************************************
  * mozilla::IMEContentObserver
  ******************************************************************************/
 
 NS_IMPL_CYCLE_COLLECTION_CLASS(IMEContentObserver)
 
 NS_IMPL_CYCLE_COLLECTION_UNLINK_BEGIN(IMEContentObserver)
   nsAutoScriptBlocker scriptBlocker;
@@ -97,16 +171,19 @@ IMEContentObserver::IMEContentObserver()
   , mSelectionChangeCausedOnlyByComposition(false)
   , mSelectionChangeCausedOnlyBySelectionEvent(false)
   , mIsPositionChangeEventPending(false)
   , mIsFlushingPendingNotifications(false)
 {
 #ifdef DEBUG
   mTextChangeData.Test();
 #endif
+  if (!sIMECOLog) {
+    sIMECOLog = PR_NewLogModule("IMEContentObserver");
+  }
 }
 
 void
 IMEContentObserver::Init(nsIWidget* aWidget,
                          nsPresContext* aPresContext,
                          nsIContent* aContent,
                          nsIEditor* aEditor)
 {
@@ -251,26 +328,36 @@ IMEContentObserver::NotifyIMEOfBlur()
   // If we hasn't been set focus, we shouldn't send blur notification to IME.
   if (!mIMEHasFocus) {
     return;
   }
 
   // mWidget must have been non-nullptr if IME has focus.
   MOZ_RELEASE_ASSERT(widget);
 
+  nsRefPtr<IMEContentObserver> kungFuDeathGrip(this);
+
+  MOZ_LOG(sIMECOLog, LogLevel::Info,
+    ("IMECO: 0x%p IMEContentObserver::NotifyIMEOfBlur(), "
+     "sending NOTIFY_IME_OF_BLUR", this));
+
   // For now, we need to send blur notification in any condition because
   // we don't have any simple ways to send blur notification asynchronously.
   // After this call, Destroy() or Unlink() will stop observing the content
   // and forget everything.  Therefore, if it's not safe to send notification
   // when script blocker is unlocked, we cannot send blur notification after
   // that and before next focus notification.
   // Anyway, as far as we know, IME doesn't try to query content when it loses
   // focus.  So, this may not cause any problem.
   mIMEHasFocus = false;
   IMEStateManager::NotifyIME(IMENotification(NOTIFY_IME_OF_BLUR), widget);
+
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::NotifyIMEOfBlur(), "
+     "sent NOTIFY_IME_OF_BLUR", this));
 }
 
 void
 IMEContentObserver::UnregisterObservers()
 {
   if (!mIsObserving) {
     return;
   }
@@ -781,77 +868,174 @@ IMEContentObserver::AttributeChanged(nsI
                                                   LINE_BREAK_TYPE_NATIVE);
   NS_ENSURE_SUCCESS_VOID(rv);
 
   TextChangeData data(start, start + mPreAttrChangeLength,
                       start + postAttrChangeLength, causedByComposition);
   MaybeNotifyIMEOfTextChange(data);
 }
 
+void
+IMEContentObserver::SuppressNotifyingIME()
+{
+  mSuppressNotifications++;
+
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::SuppressNotifyingIME(), "
+     "mSuppressNotifications=%u", this, mSuppressNotifications));
+}
+
+void
+IMEContentObserver::UnsuppressNotifyingIME()
+{
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::UnsuppressNotifyingIME(), "
+     "mSuppressNotifications=%u", this, mSuppressNotifications));
+
+  if (!mSuppressNotifications || --mSuppressNotifications) {
+    return;
+  }
+  FlushMergeableNotifications();
+}
+
 NS_IMETHODIMP
 IMEContentObserver::EditAction()
 {
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::EditAction()", this));
+
   mEndOfAddedTextCache.Clear();
   mStartOfRemovingTextRangeCache.Clear();
   FlushMergeableNotifications();
   return NS_OK;
 }
 
 NS_IMETHODIMP
 IMEContentObserver::BeforeEditAction()
 {
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::BeforeEditAction()", this));
+
   mEndOfAddedTextCache.Clear();
   mStartOfRemovingTextRangeCache.Clear();
   return NS_OK;
 }
 
 NS_IMETHODIMP
 IMEContentObserver::CancelEditAction()
 {
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::CancelEditAction()", this));
+
   mEndOfAddedTextCache.Clear();
   mStartOfRemovingTextRangeCache.Clear();
   FlushMergeableNotifications();
   return NS_OK;
 }
 
 void
 IMEContentObserver::PostFocusSetNotification()
 {
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::PostFocusSetNotification()", this));
+
   mIsFocusEventPending = true;
 }
 
 void
 IMEContentObserver::PostTextChangeNotification(
                       const TextChangeDataBase& aTextChangeData)
 {
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::PostTextChangeNotification("
+     "aTextChangeData=%s)",
+     this, TextChangeDataToString(aTextChangeData).get()));
+
   mTextChangeData += aTextChangeData;
   MOZ_ASSERT(mTextChangeData.IsValid(),
              "mTextChangeData must have text change data");
+
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::PostTextChangeNotification(), "
+     "mTextChangeData=%s)",
+     this, TextChangeDataToString(mTextChangeData).get()));
 }
 
 void
 IMEContentObserver::PostSelectionChangeNotification(
                       bool aCausedByComposition,
                       bool aCausedBySelectionEvent)
 {
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::PostSelectionChangeNotification("
+     "aCausedByComposition=%s, aCausedBySelectionEvent=%s)",
+     this, ToChar(aCausedByComposition), ToChar(aCausedBySelectionEvent)));
+
   if (!mIsSelectionChangeEventPending) {
     mSelectionChangeCausedOnlyByComposition = aCausedByComposition;
   } else {
     mSelectionChangeCausedOnlyByComposition =
       mSelectionChangeCausedOnlyByComposition && aCausedByComposition;
   }
   if (!mSelectionChangeCausedOnlyBySelectionEvent) {
     mSelectionChangeCausedOnlyBySelectionEvent = aCausedBySelectionEvent;
   } else {
     mSelectionChangeCausedOnlyBySelectionEvent =
       mSelectionChangeCausedOnlyBySelectionEvent && aCausedBySelectionEvent;
   }
   mIsSelectionChangeEventPending = true;
 }
 
+void
+IMEContentObserver::MaybeNotifyIMEOfFocusSet()
+{
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::MaybeNotifyIMEOfFocusSet()", this));
+
+  PostFocusSetNotification();
+  FlushMergeableNotifications();
+}
+
+void
+IMEContentObserver::MaybeNotifyIMEOfTextChange(
+                      const TextChangeDataBase& aTextChangeData)
+{
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::MaybeNotifyIMEOfTextChange("
+     "aTextChangeData=%s)",
+     this, TextChangeDataToString(aTextChangeData).get()));
+
+  PostTextChangeNotification(aTextChangeData);
+  FlushMergeableNotifications();
+}
+
+void
+IMEContentObserver::MaybeNotifyIMEOfSelectionChange(
+                      bool aCausedByComposition,
+                      bool aCausedBySelectionEvent)
+{
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::MaybeNotifyIMEOfSelectionChange("
+     "aCausedByComposition=%s, aCausedBySelectionEvent=%s)",
+     this, ToChar(aCausedByComposition), ToChar(aCausedBySelectionEvent)));
+
+  PostSelectionChangeNotification(aCausedByComposition,
+                                  aCausedBySelectionEvent);
+  FlushMergeableNotifications();
+}
+
+void
+IMEContentObserver::MaybeNotifyIMEOfPositionChange()
+{
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::MaybeNotifyIMEOfPositionChange()", this));
+  PostPositionChangeNotification();
+  FlushMergeableNotifications();
+}
+
 bool
 IMEContentObserver::UpdateSelectionCache()
 {
   MOZ_ASSERT(IsSafeToNotifyIME());
 
   if (!mUpdatePreference.WantSelectionChange()) {
     return false;
   }
@@ -868,22 +1052,31 @@ IMEContentObserver::UpdateSelectionCache
   }
 
   mSelectionData.mOffset = selection.mReply.mOffset;
   *mSelectionData.mString = selection.mReply.mString;
   mSelectionData.SetWritingMode(selection.GetWritingMode());
   mSelectionData.mReversed = selection.mReply.mReversed;
   mSelectionData.mCausedByComposition = false;
   mSelectionData.mCausedBySelectionEvent = false;
+
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::UpdateSelectionCache(), "
+     "mSelectionData=%s",
+     this, SelectionChangeDataToString(mSelectionData).get()));
+
   return mSelectionData.IsValid();
 }
 
 void
 IMEContentObserver::PostPositionChangeNotification()
 {
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::PostPositionChangeNotification()", this));
+
   mIsPositionChangeEventPending = true;
 }
 
 bool
 IMEContentObserver::IsReflowLocked() const
 {
   nsPresContext* presContext = GetPresContext();
   if (NS_WARN_IF(!presContext)) {
@@ -933,71 +1126,96 @@ IMEContentObserver::IsSafeToNotifyIME() 
   return true;
 }
 
 void
 IMEContentObserver::FlushMergeableNotifications()
 {
   if (!IsSafeToNotifyIME()) {
     // So, if this is already called, this should do nothing.
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p IMEContentObserver::FlushMergeableNotifications(), "
+       "FAILED, due to unsafe to notify IME", this));
     return;
   }
 
   // Notifying something may cause nested call of this method.  For example,
   // when somebody notified one of the notifications may dispatch query content
   // event. Then, it causes flushing layout which may cause another layout
   // change notification.
 
   if (mIsFlushingPendingNotifications) {
     // So, if this is already called, this should do nothing.
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p   IMEContentObserver::FlushMergeableNotifications(), "
+       "FAILED, due to already flushing pending notifications", this));
     return;
   }
 
   AutoRestore<bool> flusing(mIsFlushingPendingNotifications);
   mIsFlushingPendingNotifications = true;
 
   // NOTE: Reset each pending flag because sending notification may cause
   //       another change.
 
   if (mIsFocusEventPending) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p IMEContentObserver::FlushMergeableNotifications(), "
+       "creating FocusSetEvent...", this));
     mIsFocusEventPending = false;
     nsContentUtils::AddScriptRunner(new FocusSetEvent(this));
     // This is the first notification to IME. So, we don't need to notify any
     // more since IME starts to query content after it gets focus.
     ClearPendingNotifications();
     return;
   }
 
   if (mTextChangeData.IsValid()) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p IMEContentObserver::FlushMergeableNotifications(), "
+       "creating TextChangeEvent...", this));
     nsContentUtils::AddScriptRunner(new TextChangeEvent(this, mTextChangeData));
   }
 
   // Be aware, PuppetWidget depends on the order of this. A selection change
   // notification should not be sent before a text change notification because
   // PuppetWidget shouldn't query new text content every selection change.
   if (mIsSelectionChangeEventPending) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p IMEContentObserver::FlushMergeableNotifications(), "
+       "creating SelectionChangeEvent...", this));
     mIsSelectionChangeEventPending = false;
     nsContentUtils::AddScriptRunner(
       new SelectionChangeEvent(this, mSelectionChangeCausedOnlyByComposition,
                                mSelectionChangeCausedOnlyBySelectionEvent));
   }
 
   if (mIsPositionChangeEventPending) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p IMEContentObserver::FlushMergeableNotifications(), "
+       "creating PositionChangeEvent...", this));
     mIsPositionChangeEventPending = false;
     nsContentUtils::AddScriptRunner(new PositionChangeEvent(this));
   }
 
   // If notifications may cause new change, we should notify them now.
   if (mTextChangeData.IsValid() ||
       mIsSelectionChangeEventPending ||
       mIsPositionChangeEventPending) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p IMEContentObserver::FlushMergeableNotifications(), "
+       "posting AsyncMergeableNotificationsFlusher to current thread", this));
     nsRefPtr<AsyncMergeableNotificationsFlusher> asyncFlusher =
       new AsyncMergeableNotificationsFlusher(this);
     NS_DispatchToCurrentThread(asyncFlusher);
   }
+
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::FlushMergeableNotifications(), "
+     "finished", this));
 }
 
 /******************************************************************************
  * mozilla::IMEContentObserver::AChangeEvent
  ******************************************************************************/
 
 bool
 IMEContentObserver::AChangeEvent::CanNotifyIME() const
@@ -1047,137 +1265,218 @@ IMEContentObserver::AChangeEvent::IsSafe
  ******************************************************************************/
 
 NS_IMETHODIMP
 IMEContentObserver::FocusSetEvent::Run()
 {
   if (!CanNotifyIME()) {
     // If IMEContentObserver has already gone, we don't need to notify IME of
     // focus.
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p IMEContentObserver::FocusSetEvent::Run(), FAILED, due to "
+       "impossible to notify IME of focus", this));
     mIMEContentObserver->ClearPendingNotifications();
     return NS_OK;
   }
 
   if (!IsSafeToNotifyIME()) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p   IMEContentObserver::FocusSetEvent::Run(), retrying to "
+       "send NOTIFY_IME_OF_FOCUS...", this));
     mIMEContentObserver->PostFocusSetNotification();
     return NS_OK;
   }
 
   mIMEContentObserver->mIMEHasFocus = true;
   // Initialize selection cache with the first selection data.
   mIMEContentObserver->UpdateSelectionCache();
+
+  MOZ_LOG(sIMECOLog, LogLevel::Info,
+    ("IMECO: 0x%p IMEContentObserver::FocusSetEvent::Run(), "
+     "sending NOTIFY_IME_OF_FOCUS...", this));
+
   IMEStateManager::NotifyIME(IMENotification(NOTIFY_IME_OF_FOCUS),
                              mIMEContentObserver->mWidget);
+
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::FocusSetEvent::Run(), "
+     "sent NOTIFY_IME_OF_FOCUS", this));
   return NS_OK;
 }
 
 /******************************************************************************
  * mozilla::IMEContentObserver::SelectionChangeEvent
  ******************************************************************************/
 
 NS_IMETHODIMP
 IMEContentObserver::SelectionChangeEvent::Run()
 {
   if (!CanNotifyIME()) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p IMEContentObserver::SelectionChangeEvent::Run(), FAILED, "
+       "due to impossible to notify IME of selection change", this));
     return NS_OK;
   }
 
   if (!IsSafeToNotifyIME()) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p   IMEContentObserver::SelectionChangeEvent::Run(), "
+       "retrying to send NOTIFY_IME_OF_SELECTION_CHANGE...", this));
     mIMEContentObserver->PostSelectionChangeNotification(
                            mCausedByComposition, mCausedBySelectionEvent);
     return NS_OK;
   }
 
   SelectionChangeData lastSelChangeData = mIMEContentObserver->mSelectionData;
   if (NS_WARN_IF(!mIMEContentObserver->UpdateSelectionCache())) {
+    MOZ_LOG(sIMECOLog, LogLevel::Error,
+      ("IMECO: 0x%p IMEContentObserver::SelectionChangeEvent::Run(), FAILED, "
+       "due to UpdateSelectionCache() failure", this));
     return NS_OK;
   }
 
   // If the IME doesn't want selection change notifications caused by
   // composition, we should do nothing anymore.
   if (mCausedByComposition &&
       !mIMEContentObserver->
         mUpdatePreference.WantChangesCausedByComposition()) {
     return NS_OK;
   }
 
   // The state may be changed since querying content causes flushing layout.
   if (!CanNotifyIME()) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p IMEContentObserver::SelectionChangeEvent::Run(), FAILED, "
+       "due to flushing layout having changed something", this));
     return NS_OK;
   }
 
   // If the selection isn't changed actually, we shouldn't notify IME of
   // selection change.
   SelectionChangeData& newSelChangeData = mIMEContentObserver->mSelectionData;
   if (lastSelChangeData.IsValid() &&
       lastSelChangeData.mOffset == newSelChangeData.mOffset &&
       lastSelChangeData.String() == newSelChangeData.String() &&
       lastSelChangeData.GetWritingMode() == newSelChangeData.GetWritingMode() &&
       lastSelChangeData.mReversed == newSelChangeData.mReversed) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p IMEContentObserver::SelectionChangeEvent::Run(), not "
+       "notifying IME of NOTIFY_IME_OF_SELECTION_CHANGE due to not changed "
+       "actually", this));
     return NS_OK;
   }
 
+  MOZ_LOG(sIMECOLog, LogLevel::Info,
+    ("IMECO: 0x%p IMEContentObserver::SelectionChangeEvent::Run(), "
+     "sending NOTIFY_IME_OF_SELECTION_CHANGE... newSelChangeData=%s",
+     this, SelectionChangeDataToString(newSelChangeData).get()));
+
   IMENotification notification(NOTIFY_IME_OF_SELECTION_CHANGE);
   notification.SetData(mIMEContentObserver->mSelectionData,
                        mCausedByComposition, mCausedBySelectionEvent);
   IMEStateManager::NotifyIME(notification, mIMEContentObserver->mWidget);
+
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::SelectionChangeEvent::Run(), "
+     "sent NOTIFY_IME_OF_SELECTION_CHANGE", this));
   return NS_OK;
 }
 
 /******************************************************************************
  * mozilla::IMEContentObserver::TextChangeEvent
  ******************************************************************************/
 
 NS_IMETHODIMP
 IMEContentObserver::TextChangeEvent::Run()
 {
   if (!CanNotifyIME()) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p IMEContentObserver::TextChangeEvent::Run(), FAILED, "
+       "due to impossible to notify IME of text change", this));
     return NS_OK;
   }
 
   if (!IsSafeToNotifyIME()) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p   IMEContentObserver::TextChangeEvent::Run(), retrying to "
+       "send NOTIFY_IME_OF_TEXT_CHANGE...", this));
     mIMEContentObserver->PostTextChangeNotification(mTextChangeData);
     return NS_OK;
   }
 
+  MOZ_LOG(sIMECOLog, LogLevel::Info,
+    ("IMECO: 0x%p IMEContentObserver::TextChangeEvent::Run(), "
+     "sending NOTIFY_IME_OF_TEXT_CHANGE... mTextChangeData=%s",
+     this, TextChangeDataToString(mTextChangeData).get()));
+
   IMENotification notification(NOTIFY_IME_OF_TEXT_CHANGE);
   notification.SetData(mTextChangeData);
   IMEStateManager::NotifyIME(notification, mIMEContentObserver->mWidget);
+
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::TextChangeEvent::Run(), "
+     "sent NOTIFY_IME_OF_TEXT_CHANGE", this));
   return NS_OK;
 }
 
 /******************************************************************************
  * mozilla::IMEContentObserver::PositionChangeEvent
  ******************************************************************************/
 
 NS_IMETHODIMP
 IMEContentObserver::PositionChangeEvent::Run()
 {
   if (!CanNotifyIME()) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p IMEContentObserver::PositionChangeEvent::Run(), FAILED, "
+       "due to impossible to notify IME of position change", this));
     return NS_OK;
   }
 
   if (!IsSafeToNotifyIME()) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p   IMEContentObserver::PositionChangeEvent::Run(), "
+       "retrying to send NOTIFY_IME_OF_POSITION_CHANGE...", this));
     mIMEContentObserver->PostPositionChangeNotification();
     return NS_OK;
   }
 
+  MOZ_LOG(sIMECOLog, LogLevel::Info,
+    ("IMECO: 0x%p IMEContentObserver::PositionChangeEvent::Run(), "
+     "sending NOTIFY_IME_OF_POSITION_CHANGE...", this));
+
   IMEStateManager::NotifyIME(IMENotification(NOTIFY_IME_OF_POSITION_CHANGE),
                              mIMEContentObserver->mWidget);
+
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::PositionChangeEvent::Run(), "
+     "sent NOTIFY_IME_OF_POSITION_CHANGE", this));
   return NS_OK;
 }
 
 /******************************************************************************
  * mozilla::IMEContentObserver::AsyncMergeableNotificationsFlusher
  ******************************************************************************/
 
 NS_IMETHODIMP
 IMEContentObserver::AsyncMergeableNotificationsFlusher::Run()
 {
   if (!CanNotifyIME()) {
+    MOZ_LOG(sIMECOLog, LogLevel::Debug,
+      ("IMECO: 0x%p IMEContentObserver::AsyncMergeableNotificationsFlusher::"
+       "Run(), FAILED, due to impossible to flush pending notifications",
+       this));
     return NS_OK;
   }
 
+  MOZ_LOG(sIMECOLog, LogLevel::Info,
+    ("IMECO: 0x%p IMEContentObserver::AsyncMergeableNotificationsFlusher::"
+     "Run(), calling FlushMergeableNotifications()...", this));
+
   mIMEContentObserver->FlushMergeableNotifications();
+
+  MOZ_LOG(sIMECOLog, LogLevel::Debug,
+    ("IMECO: 0x%p IMEContentObserver::AsyncMergeableNotificationsFlusher::"
+     "Run(), called FlushMergeableNotifications()", this));
   return NS_OK;
 }
 
 } // namespace mozilla
--- a/dom/events/IMEContentObserver.h
+++ b/dom/events/IMEContentObserver.h
@@ -89,24 +89,18 @@ public:
   bool IsManaging(nsPresContext* aPresContext, nsIContent* aContent);
   bool IsEditorHandlingEventForComposition() const;
   bool KeepAliveDuringDeactive() const
   {
     return mUpdatePreference.WantDuringDeactive();
   }
   nsIWidget* GetWidget() const { return mWidget; }
   nsIEditor* GetEditor() const { return mEditor; }
-  void SuppressNotifyingIME() { mSuppressNotifications++; }
-  void UnsuppressNotifyingIME()
-  {
-    if (!mSuppressNotifications || --mSuppressNotifications) {
-      return;
-    }
-    FlushMergeableNotifications();
-  }
+  void SuppressNotifyingIME();
+  void UnsuppressNotifyingIME();
   nsPresContext* GetPresContext() const;
   nsresult GetSelectionAndRoot(nsISelection** aSelection,
                                nsIContent** aRoot) const;
 
 private:
   ~IMEContentObserver() {}
 
   enum State {
@@ -117,42 +111,25 @@ private:
   };
   State GetState() const;
   bool IsObservingContent(nsPresContext* aPresContext,
                           nsIContent* aContent) const;
   bool IsReflowLocked() const;
   bool IsSafeToNotifyIME() const;
 
   void PostFocusSetNotification();
-  void MaybeNotifyIMEOfFocusSet()
-  {
-    PostFocusSetNotification();
-    FlushMergeableNotifications();
-  }
+  void MaybeNotifyIMEOfFocusSet();
   void PostTextChangeNotification(const TextChangeDataBase& aTextChangeData);
-  void MaybeNotifyIMEOfTextChange(const TextChangeDataBase& aTextChangeData)
-  {
-    PostTextChangeNotification(aTextChangeData);
-    FlushMergeableNotifications();
-  }
+  void MaybeNotifyIMEOfTextChange(const TextChangeDataBase& aTextChangeData);
   void PostSelectionChangeNotification(bool aCausedByComposition,
                                        bool aCausedBySelectionEvent);
   void MaybeNotifyIMEOfSelectionChange(bool aCausedByComposition,
-                                       bool aCausedBySelectionEvent)
-  {
-    PostSelectionChangeNotification(aCausedByComposition,
-                                    aCausedBySelectionEvent);
-    FlushMergeableNotifications();
-  }
+                                       bool aCausedBySelectionEvent);
   void PostPositionChangeNotification();
-  void MaybeNotifyIMEOfPositionChange()
-  {
-    PostPositionChangeNotification();
-    FlushMergeableNotifications();
-  }
+  void MaybeNotifyIMEOfPositionChange();
 
   void NotifyContentAdded(nsINode* aContainer, int32_t aStart, int32_t aEnd);
   void ObserveEditableNode();
   /**
    *  NotifyIMEOfBlur() notifies IME of blur.
    */
   void NotifyIMEOfBlur();
   /**