⚠ Archived content — this site is no longer maintained.   Current WebKit documentation is at docs.webkit.org.

Changeset 286512 in webkit


Ignore:
Timestamp:
Dec 3, 2021, 1:10:00 PM (5 years ago)
Author:
timothy_horton@apple.com
Message:

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:
Location:
trunk/Source/WebKit
Files:
4 edited

Legend:

Unmodified
Added
Removed

  • trunk/Source/WebKit/ChangeLog

    r286508 r286512  
     12021-12-03  Tim Horton  <timothy_horton@apple.com>
     2
     3        Add more logging for MomentumEventDispatcher
     4        https://bugs.webkit.org/show_bug.cgi?id=233811
     5
     6        Reviewed by Simon Fraser.
     7
     8        Add a temporary event log to MomentumEventDispatcher, to debug delta/offset/curve issues.
     9
     10        * WebProcess/WebPage/EventDispatcher.h:
     11        (WebKit::EventDispatcher::queue):
     12        * WebProcess/WebPage/MomentumEventDispatcher.cpp:
     13        (WebKit::MomentumEventDispatcher::handleWheelEvent):
     14        Accumulate event deltas. Also accumulate event deltas for the
     15        fingers-down phase in the "generated" offset. Store the phase and
     16        momentum phase smooshed into a single field.
     17
     18        (WebKit::MomentumEventDispatcher::dispatchSyntheticMomentumEvent):
     19        Accumulate generated deltas.
     20
     21        (WebKit::MomentumEventDispatcher::didEndMomentumPhase):
     22        Attempt to dump the log 1 second after each momentum phase. We'll skip
     23        it if another scroll has started since.
     24
     25        (WebKit::MomentumEventDispatcher::setScrollingAccelerationCurve):
     26        (WebKit::MomentumEventDispatcher::startDisplayLink):
     27        (WebKit::MomentumEventDispatcher::stopDisplayLink):
     28        (WebKit::MomentumEventDispatcher::consumeDeltaForCurrentTime):
     29        (WebKit::MomentumEventDispatcher::buildOffsetTableWithInitialDelta):
     30        (WebKit::MomentumEventDispatcher::computeNextDelta):
     31        Adopt more MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING. Error logging
     32        we leave outside of this, because that we'll keep around.
     33
     34        (WebKit::MomentumEventDispatcher::pushLogEntry):
     35        (WebKit::MomentumEventDispatcher::flushLog):
     36        Dump the event log in an easy-to-copy-into-a-CSV format.
     37
     38        * WebProcess/WebPage/MomentumEventDispatcher.h:
     39
    1402021-12-03  Robert Jenner  <Jenner@apple.com>
    241

  • trunk/Source/WebKit/WebProcess/WebPage/EventDispatcher.h

    r286346 r286512  
    6464    static Ref<EventDispatcher> create();
    6565    ~EventDispatcher();
     66
     67    WorkQueue& queue() { return m_queue.get(); }
    6668
    6769#if ENABLE(SCROLLING_THREAD)

  • trunk/Source/WebKit/WebProcess/WebPage/MomentumEventDispatcher.cpp

    r286483 r286512  
    9494        didReceiveScrollEvent(event);
    9595
     96#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
    9697        if (auto lastActivePhaseDelta = event.rawPlatformDelta())
    9798            m_lastActivePhaseDelta = *lastActivePhaseDelta;
     99#endif
    98100    }
    99101
    … …  
    106108    bool isMomentumEventDuringSyntheticGesture = isMomentumEvent && m_currentGesture.active;
    107109
    108 #if !RELEASE_LOG_DISABLED
     110#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
    109111    if (isMomentumEventDuringSyntheticGesture)
    110112        m_currentGesture.accumulatedEventOffset += event.delta();
     113
     114    auto combinedPhase = (event.phase() << 8) | (event.momentumPhase());
     115    m_currentLogState.latestEventPhase = combinedPhase;
     116    m_currentLogState.totalEventOffset += event.delta().height();
     117    if (!isMomentumEventDuringSyntheticGesture) {
     118        // Log events that we don't block to the generated offsets log as well,
     119        // even though we didn't technically generate them, just passed them through.
     120        m_currentLogState.latestGeneratedPhase = combinedPhase;
     121        m_currentLogState.totalGeneratedOffset += event.delta().height();
     122    }
     123    pushLogEntry();
    111124#endif
    112125
    … …  
    160173        { });
    161174    m_dispatcher.internalWheelEvent(m_currentGesture.pageIdentifier, syntheticEvent, m_lastRubberBandableEdges, EventDispatcher::WheelEventOrigin::MomentumEventDispatcher);
     175
     176#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
     177    m_currentLogState.latestGeneratedPhase = phase;
     178    m_currentLogState.totalGeneratedOffset += appKitAcceleratedDelta.height();
     179    pushLogEntry();
     180#endif
    162181}
    163182
    … …  
    195214    dispatchSyntheticMomentumEvent(WebWheelEvent::PhaseEnded, { });
    196215
     216#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
    197217    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());
     218    m_dispatcher.queue().dispatchAfter(1_s, [this] {
     219        flushLog();
     220    });
     221#endif
    198222
    199223    stopDisplayLink();
    … …  
    206230    m_accelerationCurves.set(pageIdentifier, curve);
    207231
    208 #if USE_MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING
     232#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
    209233    WTF::TextStream stream(WTF::TextStream::LineMode::SingleLine);
    210234    stream << curve;
    … …  
    232256    // FIXME: Switch down to lower-than-full-speed frame rates for the tail end of the curve.
    233257    WebProcess::singleton().parentProcessConnection()->send(Messages::WebProcessProxy::StartDisplayLink(m_observerID, displayID, WebCore::FullSpeedFramesPerSecond), 0);
     258#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
    234259    RELEASE_LOG(ScrollAnimations, "MomentumEventDispatcher starting display link for display %d", displayID);
     260#endif
    235261}
    236262
    … …  
    244270
    245271    WebProcess::singleton().parentProcessConnection()->send(Messages::WebProcessProxy::StopDisplayLink(m_observerID, displayID), 0);
     272#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
    246273    RELEASE_LOG(ScrollAnimations, "MomentumEventDispatcher stopping display link for display %d", displayID);
     274#endif
    247275}
    248276
    … …  
    264292    auto desiredOffset = offsetAtTime(animationTime);
    265293
    266 #if !USE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
     294#if !ENABLE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
    267295    // Intentional delta rounding (but at the end!).
    268296    WebCore::FloatSize delta = roundedIntSize(desiredOffset - m_currentGesture.currentOffset);
    … …  
    327355void MomentumEventDispatcher::buildOffsetTableWithInitialDelta(WebCore::FloatSize initialUnacceleratedDelta)
    328356{
    329 #if USE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
     357#if ENABLE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
    330358    m_currentGesture.carryOffset = { };
    331359#endif
    … …  
    343371    } while (std::abs(unacceleratedDelta.width()) > 0.5 || std::abs(unacceleratedDelta.height()) > 0.5);
    344372
     373#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
    345374    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());
     375#endif
    346376}
    347377
    … …  
    397427    auto quantizedUnacceleratedDelta = unacceleratedDelta;
    398428
    399 #if USE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
     429#if ENABLE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
    400430    // Round and carry.
    401431    int32_t quantizedX = std::round(quantizedUnacceleratedDelta.width());
    … …  
    442472        float averageDelta = totalDelta / count;
    443473
    444 #if !RELEASE_LOG_DISABLED
    445         if (!m_currentGesture.didLogInitialQueueState)
     474#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
     475        if (!m_currentGesture.didLogInitialQueueState) {
    446476            RELEASE_LOG(ScrollAnimations, "MomentumEventDispatcher initial historical deltas: average delta %f, average time %fms, event count %d", averageDelta, averageFrameIntervalMS, count);
     477            m_currentGesture.didLogInitialQueueState = true;
     478        }
    447479#endif
    448480
    … …  
    465497    );
    466498
    467     m_currentGesture.didLogInitialQueueState = true;
    468 
    469499    return { unacceleratedDelta, acceleratedDelta };
    470500}
    471501
     502#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
     503
     504void MomentumEventDispatcher::pushLogEntry()
     505{
     506    m_currentLogState.time = MonotonicTime::now();
     507    m_log.append(m_currentLogState);
     508}
     509
     510void MomentumEventDispatcher::flushLog()
     511{
     512    if ((MonotonicTime::now() - m_currentLogState.time) < 500_ms)
     513        return;
     514
     515    if (m_log.isEmpty())
     516        return;
     517
     518    auto startTime = m_log[0].time;
     519    RELEASE_LOG(ScrollAnimations, "MomentumEventDispatcher event log: time,generatedOffset,generatedPhase,eventOffset,eventPhase");
     520    for (const auto& entry : m_log)
     521        RELEASE_LOG(ScrollAnimations, "MomentumEventDispatcher event log: %f,%f,%d,%f,%d", (entry.time - startTime).seconds(), entry.totalGeneratedOffset, entry.latestGeneratedPhase, entry.totalEventOffset, entry.latestEventPhase);
     522
     523    m_log.clear();
     524    m_currentLogState = { };
     525}
     526
     527#endif
     528
    472529} // namespace WebKit
    473530

  • trunk/Source/WebKit/WebProcess/WebPage/MomentumEventDispatcher.h

    r286483 r286512  
    2929
    3030// FIXME: Remove this once we decide which version we want.
    31 #define USE_MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING 0
    32 #define USE_MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING 1
     31#define ENABLE_MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING 0
     32#define ENABLE_MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING 1
    3333
    3434#include "DisplayLinkObserverID.h"
    … …  
    9191    void didReceiveScrollEvent(const WebWheelEvent&);
    9292
     93#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
     94    void pushLogEntry();
     95    void flushLog();
     96
     97    WebCore::FloatSize m_lastActivePhaseDelta;
     98
     99    struct LogEntry {
     100        MonotonicTime time;
     101
     102        float totalGeneratedOffset { 0 };
     103        float totalEventOffset { 0 };
     104
     105        uint32_t latestGeneratedPhase { 0 };
     106        uint32_t latestEventPhase { 0 };
     107    };
     108    LogEntry m_currentLogState;
     109    Vector<LogEntry> m_log;
     110#endif
     111
    93112    struct Delta {
    94113        float rawPlatformDelta;
    … …  
    104123    std::optional<WebWheelEvent> m_lastIncomingEvent;
    105124    WebCore::RectEdges<bool> m_lastRubberBandableEdges;
    106 #if !RELEASE_LOG_DISABLED
    107     WebCore::FloatSize m_lastActivePhaseDelta;
    108 #endif
    109125
    110126    struct {
    … …  
    120136        Vector<WebCore::FloatSize> offsetTable;
    121137
    122 #if !RELEASE_LOG_DISABLED
     138#if ENABLE(MOMENTUM_EVENT_DISPATCHER_TEMPORARY_LOGGING)
    123139        WebCore::FloatSize accumulatedEventOffset;
    124140        bool didLogInitialQueueState { false };
    125141#endif
    126142
    127 #if USE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
     143#if ENABLE(MOMENTUM_EVENT_DISPATCHER_PREMATURE_ROUNDING)
    128144        WebCore::FloatSize carryOffset;
    129145#endif
Note: See TracChangeset for help on using the changeset viewer.