Title: [286694] branches/safari-612-branch/Source/WebKit
Revision
286694
Author
alanc...@apple.com
Date
2021-12-08 12:23:44 -0800 (Wed, 08 Dec 2021)

Log Message

Cherry-pick r286512. rdar://problem/85928816

    Add more logging for MomentumEventDispatcher
    https://bugs.webkit.org/show_bug.cgi?id=233811

    Reviewed by Simon Fraser.

    Add a temporary event log to MomentumEventDispatcher, to debug delta/offset/curve issues.

    * WebProcess/WebPage/EventDispatcher.h:
    (WebKit::EventDispatcher::queue):
    * WebProcess/WebPage/MomentumEventDispatcher.cpp:
    (WebKit::MomentumEventDispatcher::handleWheelEvent):
    Accumulate event deltas. Also accumulate event deltas for the
    fingers-down phase in the "generated" offset. Store the phase and
    momentum phase smooshed into a single field.

    (WebKit::MomentumEventDispatcher::dispatchSyntheticMomentumEvent):
    Accumulate generated deltas.

    (WebKit::MomentumEventDispatcher::didEndMomentumPhase):
    Attempt to dump the log 1 second after each momentum phase. We'll skip
    it if another scroll has started since.

    (WebKit::MomentumEventDispatcher::setScrollingAccelerationCurve):
    (WebKit::MomentumEventDispatcher::startDisplayLink):
    (WebKit::MomentumEventDispatcher::stopDisplayLink):
    (WebKit::MomentumEventDispatcher::consumeDeltaForCurrentTime):
    (WebKit::MomentumEventDispatcher::buildOffsetTableWithInitialDelta):
    (WebKit::MomentumEventDispatcher::computeNextDelta):
    Adopt more MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING. Error logging
    we leave outside of this, because that we'll keep around.

    (WebKit::MomentumEventDispatcher::pushLogEntry):
    (WebKit::MomentumEventDispatcher::flushLog):
    Dump the event log in an easy-to-copy-into-a-CSV format.

    * WebProcess/WebPage/MomentumEventDispatcher.h:

    git-svn-id: https://svn.webkit.org/repository/webkit/trunk@286512 268f45cc-cd09-0410-ab3c-d52691b4dbfc

Modified Paths

Diff

Modified: branches/safari-612-branch/Source/WebKit/ChangeLog (286693 => 286694)


--- branches/safari-612-branch/Source/WebKit/ChangeLog	2021-12-08 20:23:41 UTC (rev 286693)
+++ branches/safari-612-branch/Source/WebKit/ChangeLog	2021-12-08 20:23:44 UTC (rev 286694)
@@ -1,5 +1,88 @@
 2021-12-03  Alan Coon  <alanc...@apple.com>
 
+        Cherry-pick r286512. rdar://problem/85928816
+
+    Add more logging for MomentumEventDispatcher
+    https://bugs.webkit.org/show_bug.cgi?id=233811
+    
+    Reviewed by Simon Fraser.
+    
+    Add a temporary event log to MomentumEventDispatcher, to debug delta/offset/curve issues.
+    
+    * WebProcess/WebPage/EventDispatcher.h:
+    (WebKit::EventDispatcher::queue):
+    * WebProcess/WebPage/MomentumEventDispatcher.cpp:
+    (WebKit::MomentumEventDispatcher::handleWheelEvent):
+    Accumulate event deltas. Also accumulate event deltas for the
+    fingers-down phase in the "generated" offset. Store the phase and
+    momentum phase smooshed into a single field.
+    
+    (WebKit::MomentumEventDispatcher::dispatchSyntheticMomentumEvent):
+    Accumulate generated deltas.
+    
+    (WebKit::MomentumEventDispatcher::didEndMomentumPhase):
+    Attempt to dump the log 1 second after each momentum phase. We'll skip
+    it if another scroll has started since.
+    
+    (WebKit::MomentumEventDispatcher::setScrollingAccelerationCurve):
+    (WebKit::MomentumEventDispatcher::startDisplayLink):
+    (WebKit::MomentumEventDispatcher::stopDisplayLink):
+    (WebKit::MomentumEventDispatcher::consumeDeltaForCurrentTime):
+    (WebKit::MomentumEventDispatcher::buildOffsetTableWithInitialDelta):
+    (WebKit::MomentumEventDispatcher::computeNextDelta):
+    Adopt more MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING. Error logging
+    we leave outside of this, because that we'll keep around.
+    
+    (WebKit::MomentumEventDispatcher::pushLogEntry):
+    (WebKit::MomentumEventDispatcher::flushLog):
+    Dump the event log in an easy-to-copy-into-a-CSV format.
+    
+    * WebProcess/WebPage/MomentumEventDispatcher.h:
+    
+    
+    git-svn-id: https://svn.webkit.org/repository/webkit/trunk@286512 268f45cc-cd09-0410-ab3c-d52691b4dbfc
+
+    2021-12-03  Tim Horton  <timothy_hor...@apple.com>
+
+            Add more logging for MomentumEventDispatcher
+            https://bugs.webkit.org/show_bug.cgi?id=233811
+
+            Reviewed by Simon Fraser.
+
+            Add a temporary event log to MomentumEventDispatcher, to debug delta/offset/curve issues.
+
+            * WebProcess/WebPage/EventDispatcher.h:
+            (WebKit::EventDispatcher::queue):
+            * WebProcess/WebPage/MomentumEventDispatcher.cpp:
+            (WebKit::MomentumEventDispatcher::handleWheelEvent):
+            Accumulate event deltas. Also accumulate event deltas for the
+            fingers-down phase in the "generated" offset. Store the phase and
+            momentum phase smooshed into a single field.
+
+            (WebKit::MomentumEventDispatcher::dispatchSyntheticMomentumEvent):
+            Accumulate generated deltas.
+
+            (WebKit::MomentumEventDispatcher::didEndMomentumPhase):
+            Attempt to dump the log 1 second after each momentum phase. We'll skip
+            it if another scroll has started since.
+
+            (WebKit::MomentumEventDispatcher::setScrollingAccelerationCurve):
+            (WebKit::MomentumEventDispatcher::startDisplayLink):
+            (WebKit::MomentumEventDispatcher::stopDisplayLink):
+            (WebKit::MomentumEventDispatcher::consumeDeltaForCurrentTime):
+            (WebKit::MomentumEventDispatcher::buildOffsetTableWithInitialDelta):
+            (WebKit::MomentumEventDispatcher::computeNextDelta):
+            Adopt more MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING. Error logging
+            we leave outside of this, because that we'll keep around.
+
+            (WebKit::MomentumEventDispatcher::pushLogEntry):
+            (WebKit::MomentumEventDispatcher::flushLog):
+            Dump the event log in an easy-to-copy-into-a-CSV format.
+
+            * WebProcess/WebPage/MomentumEventDispatcher.h:
+
+2021-12-03  Alan Coon  <alanc...@apple.com>
+
         Cherry-pick r285526. rdar://problem/85928816
 
     Add runtime flag for momentum scrolling

Modified: branches/safari-612-branch/Source/WebKit/WebProcess/WebPage/EventDispatcher.h (286693 => 286694)


--- branches/safari-612-branch/Source/WebKit/WebProcess/WebPage/EventDispatcher.h	2021-12-08 20:23:41 UTC (rev 286693)
+++ branches/safari-612-branch/Source/WebKit/WebProcess/WebPage/EventDispatcher.h	2021-12-08 20:23:44 UTC (rev 286694)
@@ -65,6 +65,8 @@
     static Ref<EventDispatcher> create();
     ~EventDispatcher();
 
+    WorkQueue& queue() { return m_queue.get(); }
+
 #if ENABLE(SCROLLING_THREAD)
     void addScrollingTreeForPage(WebPage*);
     void removeScrollingTreeForPage(WebPage*);

Modified: branches/safari-612-branch/Source/WebKit/WebProcess/WebPage/MomentumEventDispatcher.cpp (286693 => 286694)


--- branches/safari-612-branch/Source/WebKit/WebProcess/WebPage/MomentumEventDispatcher.cpp	2021-12-08 20:23:41 UTC (rev 286693)
+++ branches/safari-612-branch/Source/WebKit/WebProcess/WebPage/MomentumEventDispatcher.cpp	2021-12-08 20:23:44 UTC (rev 286694)
@@ -93,8 +93,10 @@
     if (event.phase() == WebWheelEvent::PhaseBegan || event.phase() == WebWheelEvent::PhaseChanged) {
         didReceiveScrollEvent(event);
 
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
         if (auto lastActivePhaseDelta = event.rawPlatformDelta())
             m_lastActivePhaseDelta = *lastActivePhaseDelta;
+#endif
     }
 
     if (event.phase() == WebWheelEvent::PhaseEnded)
@@ -105,9 +107,20 @@
 
     bool isMomentumEventDuringSyntheticGesture = isMomentumEvent && m_currentGesture.active;
 
-#if !RELEASE_LOG_DISABLED
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
     if (isMomentumEventDuringSyntheticGesture)
         m_currentGesture.accumulatedEventOffset += event.delta();
+
+    auto combinedPhase = (event.phase() << 8) | (event.momentumPhase());
+    m_currentLogState.latestEventPhase = combinedPhase;
+    m_currentLogState.totalEventOffset += event.delta().height();
+    if (!isMomentumEventDuringSyntheticGesture) {
+        // Log events that we don't block to the generated offsets log as well,
+        // even though we didn't technically generate them, just passed them through.
+        m_currentLogState.latestGeneratedPhase = combinedPhase;
+        m_currentLogState.totalGeneratedOffset += event.delta().height();
+    }
+    pushLogEntry();
 #endif
 
     // Consume any normal momentum events while we're inside a synthetic momentum gesture.
@@ -159,6 +172,12 @@
         time,
         { });
     m_dispatcher.internalWheelEvent(m_currentGesture.pageIdentifier, syntheticEvent, m_lastRubberBandableEdges, EventDispatcher::WheelEventOrigin::MomentumEventDispatcher);
+
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
+    m_currentLogState.latestGeneratedPhase = phase;
+    m_currentLogState.totalGeneratedOffset += appKitAcceleratedDelta.height();
+    pushLogEntry();
+#endif
 }
 
 void MomentumEventDispatcher::didStartMomentumPhase(WebCore::PageIdentifier pageIdentifier, const WebWheelEvent& event)
@@ -194,7 +213,12 @@
 
     dispatchSyntheticMomentumEvent(WebWheelEvent::PhaseEnded, { });
 
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
     RELEASE_LOG(ScrollAnimations, "MomentumEventDispatcher saw momentum end phase with total offset %.1f %.1f, duration %f (event offset would have been %.1f %.1f)", m_currentGesture.currentOffset.width(), m_currentGesture.currentOffset.height(), (MonotonicTime::now() - m_currentGesture.startTime).seconds(), m_currentGesture.accumulatedEventOffset.width(), m_currentGesture.accumulatedEventOffset.height());
+    m_dispatcher.queue().dispatchAfter(1_s, [this] {
+        flushLog();
+    });
+#endif
 
     stopDisplayLink();
 
@@ -205,7 +229,7 @@
 {
     m_accelerationCurves.set(pageIdentifier, curve);
 
-#if USE_MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
     WTF::TextStream stream(WTF::TextStream::LineMode::SingleLine);
     stream << curve;
     RELEASE_LOG(ScrollAnimations, "MomentumEventDispatcher set curve %s", stream.release().utf8().data());
@@ -231,7 +255,9 @@
 
     // FIXME: Switch down to lower-than-full-speed frame rates for the tail end of the curve.
     WebProcess::singleton().parentProcessConnection()->send(Messages::WebProcessProxy::StartDisplayLink(m_observerID, displayID, WebCore::FullSpeedFramesPerSecond), 0);
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
     RELEASE_LOG(ScrollAnimations, "MomentumEventDispatcher starting display link for display %d", displayID);
+#endif
 }
 
 void MomentumEventDispatcher::stopDisplayLink()
@@ -243,7 +269,9 @@
     }
 
     WebProcess::singleton().parentProcessConnection()->send(Messages::WebProcessProxy::StopDisplayLink(m_observerID, displayID), 0);
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
     RELEASE_LOG(ScrollAnimations, "MomentumEventDispatcher stopping display link for display %d", displayID);
+#endif
 }
 
 void MomentumEventDispatcher::pageScreenDidChange(WebCore::PageIdentifier pageID, WebCore::PlatformDisplayID displayID)
@@ -263,7 +291,7 @@
     auto animationTime = MonotonicTime::now() - m_currentGesture.startTime;
     auto desiredOffset = offsetAtTime(animationTime);
 
-#if !USE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
+#if !ENABLE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
     // Intentional delta rounding (but at the end!).
     WebCore::FloatSize delta = roundedIntSize(desiredOffset - m_currentGesture.currentOffset);
 #else
@@ -326,7 +354,7 @@
 
 void MomentumEventDispatcher::buildOffsetTableWithInitialDelta(WebCore::FloatSize initialUnacceleratedDelta)
 {
-#if USE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
     m_currentGesture.carryOffset = { };
 #endif
     m_currentGesture.offsetTable.clear();
@@ -342,7 +370,9 @@
         m_currentGesture.offsetTable.append(accumulatedOffset);
     } while (std::abs(unacceleratedDelta.width()) > 0.5 || std::abs(unacceleratedDelta.height()) > 0.5);
 
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
     RELEASE_LOG(ScrollAnimations, "MomentumEventDispatcher built table with %ld frames, initial delta %f %f, distance %f %f (initial delta from last changed event %f %f)", m_currentGesture.offsetTable.size(), initialUnacceleratedDelta.width(), initialUnacceleratedDelta.height(), accumulatedOffset.width(), accumulatedOffset.height(), m_lastActivePhaseDelta.width(), m_lastActivePhaseDelta.height());
+#endif
 }
 
 static float interpolate(float a, float b, float t)
@@ -396,7 +426,7 @@
 
     auto quantizedUnacceleratedDelta = unacceleratedDelta;
 
-#if USE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
     // Round and carry.
     int32_t quantizedX = std::round(quantizedUnacceleratedDelta.width());
     int32_t quantizedY = std::round(quantizedUnacceleratedDelta.height());
@@ -441,9 +471,11 @@
         float averageFrameIntervalMS = averageFrameInterval.milliseconds();
         float averageDelta = totalDelta / count;
 
-#if !RELEASE_LOG_DISABLED
-        if (!m_currentGesture.didLogInitialQueueState)
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
+        if (!m_currentGesture.didLogInitialQueueState) {
             RELEASE_LOG(ScrollAnimations, "MomentumEventDispatcher initial historical deltas: average delta %f, average time %fms, event count %d", averageDelta, averageFrameIntervalMS, count);
+            m_currentGesture.didLogInitialQueueState = true;
+        }
 #endif
 
         constexpr float velocityGainA = fromFixedPoint(2.f);
@@ -464,11 +496,36 @@
         accelerateAxis(m_deltaHistoryY, quantizedUnacceleratedDelta.height())
     );
 
-    m_currentGesture.didLogInitialQueueState = true;
-
     return { unacceleratedDelta, acceleratedDelta };
 }
 
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
+
+void MomentumEventDispatcher::pushLogEntry()
+{
+    m_currentLogState.time = MonotonicTime::now();
+    m_log.append(m_currentLogState);
+}
+
+void MomentumEventDispatcher::flushLog()
+{
+    if ((MonotonicTime::now() - m_currentLogState.time) < 500_ms)
+        return;
+
+    if (m_log.isEmpty())
+        return;
+
+    auto startTime = m_log[0].time;
+    RELEASE_LOG(ScrollAnimations, "MomentumEventDispatcher event log: time,generatedOffset,generatedPhase,eventOffset,eventPhase");
+    for (const auto& entry : m_log)
+        RELEASE_LOG(ScrollAnimations, "MomentumEventDispatcher event log: %f,%f,%d,%f,%d", (entry.time - startTime).seconds(), entry.totalGeneratedOffset, entry.latestGeneratedPhase, entry.totalEventOffset, entry.latestEventPhase);
+
+    m_log.clear();
+    m_currentLogState = { };
+}
+
+#endif
+
 } // namespace WebKit
 
 #endif

Modified: branches/safari-612-branch/Source/WebKit/WebProcess/WebPage/MomentumEventDispatcher.h (286693 => 286694)


--- branches/safari-612-branch/Source/WebKit/WebProcess/WebPage/MomentumEventDispatcher.h	2021-12-08 20:23:41 UTC (rev 286693)
+++ branches/safari-612-branch/Source/WebKit/WebProcess/WebPage/MomentumEventDispatcher.h	2021-12-08 20:23:44 UTC (rev 286694)
@@ -28,8 +28,8 @@
 #if ENABLE(MOMENTUM_EVENT_DISPATCHER)
 
 // FIXME: Remove this once we decide which version we want.
-#define USE_MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING 0
-#define USE_MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING 1
+#define ENABLE_MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING 0
+#define ENABLE_MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING 1
 
 #include "DisplayLinkObserverID.h"
 #include "ScrollingAccelerationCurve.h"
@@ -90,6 +90,25 @@
     void didReceiveScrollEventWithInterval(WebCore::FloatSize, Seconds);
     void didReceiveScrollEvent(const WebWheelEvent&);
 
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
+    void pushLogEntry();
+    void flushLog();
+
+    WebCore::FloatSize m_lastActivePhaseDelta;
+
+    struct LogEntry {
+        MonotonicTime time;
+
+        float totalGeneratedOffset { 0 };
+        float totalEventOffset { 0 };
+
+        uint32_t latestGeneratedPhase { 0 };
+        uint32_t latestEventPhase { 0 };
+    };
+    LogEntry m_currentLogState;
+    Vector<LogEntry> m_log;
+#endif
+
     struct Delta {
         float rawPlatformDelta;
         Seconds frameInterval;
@@ -103,9 +122,6 @@
     WallTime m_lastEndedEventTimestamp;
     std::optional<WebWheelEvent> m_lastIncomingEvent;
     WebCore::RectEdges<bool> m_lastRubberBandableEdges;
-#if !RELEASE_LOG_DISABLED
-    WebCore::FloatSize m_lastActivePhaseDelta;
-#endif
 
     struct {
         bool active { false };
@@ -119,12 +135,12 @@
 
         Vector<WebCore::FloatSize> offsetTable;
 
-#if !RELEASE_LOG_DISABLED
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
         WebCore::FloatSize accumulatedEventOffset;
         bool didLogInitialQueueState { false };
 #endif
 
-#if USE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
+#if ENABLE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
         WebCore::FloatSize carryOffset;
 #endif
     } m_currentGesture;
_______________________________________________
webkit-changes mailing list
webkit-changes@lists.webkit.org
https://lists.webkit.org/mailman/listinfo/webkit-changes

Reply via email to