1943789 - Firefox internal D&D - Dragging a link or highlighted text sometimes freezes UI on Linux with NVIDIA drivers at 120Hz or 144Hz

Status: RESOLVED FIXED

(Core :: Widget: Gtk, defect)

Description

[Jonathan]

Attachment: Screenshot from 2025-01-25 21-53-17.png

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:134.0) Gecko/20100101 Firefox/134.0

Steps to reproduce:

Repeatedly drag and drop a link or highlighted text to an empty space on the same page.
Nvidia driver 550, on Ubuntu 24.04.1. Observed behavior on snap, deb, and mozilla build tar.bz2.
I observed this on 144hz and 120hz, but not 60hz.
mozregression says: Differential Revision: https://phabricator.services.mozilla.com/D217080 , screenshot of mozregression attached.

Actual results:

Sometimes, the UI will freeze for a few seconds.

Expected results:

The UI shouldn't freeze.

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

The Bugbug bot thinks this bug should belong to the 'Core::Layout: Text and Fonts' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Comment 2

[Jonathan]

I tested adding mSynthMouseMoveEvent.Forget(); back in, it fixes the problem.

Comment 3

[Jonathan]

Related: Bug 707859

Comment 4

[:Gijs (he/him)]

Could someone who can reproduce this use the Firefox profiler to record a performance profile of the hang and share it?

Comment 5

[Jan Jaeschke [:jjaschke]]

FWIW, I can't repro, but I'm on Ubuntu 24.10, nvidia-driver-560-open, 144Hz display, today's Nightly.

Or I don't understand the steps to reproduce correctly.

Comment 6

[Jonathan]

Video to help reproduce: https://jontempfirefoxvideo.s3.eu-west-1.amazonaws.com/firefox_drag.mkv

Profiler Link: https://share.firefox.dev/4jAxphG (not recorded at same time as video)
If you filter markers for "drag", there's a hang between 6.65s and 16.2.

Comment 7

[:Gijs (he/him)]

(In reply to Jonathan from comment #6)

Profiler Link: https://share.firefox.dev/4jAxphG (not recorded at same time as video)
If you filter markers for "drag", there's a hang between 6.65s and 16.2.

Thanks. Looks like we mostly hang in a while loop of PR_Sleep(10), with this stack:

PR_Sleep [/home/jon/projects/firefox/mozilla-unified/nsprpub/pr/src/pthreads/ptthread.c]
nsDragSession::GetDragData(_GdkAtom*) [/home/jon/projects/firefox/mozilla-unified/widget/gtk/nsDragService.cpp]
nsDragSession::GetData(nsITransferable*, unsigned int) [/home/jon/projects/firefox/mozilla-unified/widget/gtk/nsDragService.cpp]
mozilla::dom::DataTransferItem::FillInExternalData() [/home/jon/projects/firefox/mozilla-unified/dom/events/DataTransferItem.cpp]

here: https://searchfox.org/mozilla-central/rev/a965e3c683ecc035dee1de72bd33a8d91b1203ed/widget/gtk/nsDragService.cpp#1450-1461 . The timeout there is allegedly 1000000 microseconds, ie 1 second. Maybe we're hitting the timeout every time anything asks for the transferable info? Hopefully Masayuki understands this better...

Comment 8

[Jonathan]

Attachment: log3.txt-main.154472.moz_log

Log file with log modules: timestamp,sync,WidgetDrag:5

Comment 9

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)]

I have no idea... needinfo? to some folks.

It's really odd that it'd be fixed if synthesize a mousemove forgetting a synthesizing mousemove request. IIRC, synthesized mousemove is kicked by the refresh driver and refresh driver uses 60fps even if actual display refreshes different speed. So, my change caused calling PresShell::ProcessSynthMouseMoveEvent a lot during a drag session and nsContentUtils::GetDragSession() is called a lot. It retrieves the service and its current session. However, I have no idea why it could cause freeze in the stack in the profiler.

Comment 10

[Masayuki Nakano [:masayuki] (he/him)(JST, +0900)]

(Well, forgetting the synthesize mousemove request and request the dragsession to synthesize mousemove when ending the session could be better, but I'm not sure it'd fix this bug.)

Comment 11

[Martin Stránský [:stransky] (ni? me)]

There's the relevant part of the log:

2025-01-27 22:29:07.440892 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00] nsDragSession::GetDragData(7ee6ac6feac0) requested 'text/uri-list'
2025-01-27 22:29:07.440900 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   adding drag context available flavor text/x-moz-url
2025-01-27 22:29:07.440907 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   adding drag context available flavor _NETSCAPE_URL
2025-01-27 22:29:07.440914 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   adding drag context available flavor text/x-moz-url-data
2025-01-27 22:29:07.440921 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   adding drag context available flavor text/x-moz-url-desc
2025-01-27 22:29:07.440928 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   adding drag context available flavor application/x-moz-custom-clipdata
2025-01-27 22:29:07.440935 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   adding drag context available flavor text/_moz_htmlcontext
2025-01-27 22:29:07.440943 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   adding drag context available flavor text/_moz_htmlinfo
2025-01-27 22:29:07.440949 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   adding drag context available flavor text/html
2025-01-27 22:29:07.440958 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   adding drag context available flavor text/plain
2025-01-27 22:29:07.440964 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   adding drag context available flavor text/plain;charset=utf-8
2025-01-27 22:29:07.440972 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   text/uri-list is missing
2025-01-27 22:29:07.440979 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00] nsDragSession::GetDragData(7ee6ac6feac0) requested 'application/vnd.portal.files'
2025-01-27 22:29:07.440987 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   application/vnd.portal.files is missing
2025-01-27 22:29:07.440994 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00] nsDragSession::GetDragData(7ee6ac6feac0) requested 'application/vnd.portal.filetransfer'
2025-01-27 22:29:07.441002 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   application/vnd.portal.filetransfer is missing
2025-01-27 22:29:07.441009 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00] nsDragSession::GetDragData(7ee6ac6feac0) requested 'text/x-moz-url'
2025-01-27 22:29:07.441047 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee69af7b00]   about to start inner iteration, mWaitingForDragDataRequests 1
2025-01-27 22:29:07.441058 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   doing iteration, mWaitingForDragDataRequests 1 ...

So we're asked for 'text/uri-list' MIME but it's missing so we're looking for 'text/x-moz-url' but it's missing too but we're trying to repeatedly query missing formats. That's fixed in by Bug 1935083 (FF 135).

Comment 12

[Jonathan]

No, it's not fixed. Mozregression found the commit where I'm seeing this problem. I additionally just tested builds: 2025-01-27, 2025-01-15, 2025-01-01, 2024-12-05, 2024-12-15, and the bug is in all of them.
I now have a debug build locally, if more information or a debugging screen share is required.

Comment 13

[:Gijs (he/him)]

Martin, could you take another look given comment #12? Thank you!

Comment 14

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1907967

Comment 15

[Jonathan]

Where there is the hang in the log file, you see
doing iteration, mWaitingForDragDataRequests 2 , then 3, 4 etc.
I looked around that code and saw this:
PR_Sleep(PR_MillisecondsToInterval(10)); /* sleep for 10 ms/iteration */
https://searchfox.org/mozilla-central/rev/a965e3c683ecc035dee1de72bd33a8d91b1203ed/widget/gtk/nsDragService.cpp#1455

I'm guesing this is a sleep timing related bug. Where did 10ms come from? For 60Hz, 1000ms/60 = 16.666ms, which is over 10ms. 1000/120 = 8.333ms, 1000/144 = 6.944ms, which is under 10ms.
I changed it to 5ms, and the problem goes away. I doubt just changing the sleep duration is the correct solution, but I don't know enough about what's happening to suggest a proper fix.

Comment 16

[Martin Stránský [:stransky] (ni? me)]

Okay, looking again to the log and it looks like we fail to get any data from clipboard - we try different mime types but we failed for any of them.
Can you attach WidgetDrag:5 log with 5ms sleep interval?
Thanks.

Comment 17

[Martin Stránský [:stransky] (ni? me)]

One relation to https://phabricator.services.mozilla.com/D217080 (IIRC) is that we consider the D&D operation finished but OS considers it still open (or vice versa). So there's difference of D&D state on application/system sides.

Comment 18

[Martin Stránský [:stransky] (ni? me)]

(In reply to Martin Stránský [:stransky] (ni? me) from comment #17)

One relation to https://phabricator.services.mozilla.com/D217080 (IIRC) is that we consider the D&D operation finished but OS considers it still open (or vice versa). So there's difference of D&D state on application/system sides.

Hm, that may be actually caused by the timeout. When first D&D operation is terminated on our side by timeout, we fail to do any next D&D.
I wonder if we need to terminate it on OS side somehow.

Comment 19

[Jonathan]

Attachment: 5ms.log-main.10681.moz_log

5ms.log-main.10681.moz_log is from PR_Sleep(PR_MillisecondsToInterval(5));. Also have 1ms and 50ms logs if you want. 1ms doesn't freeze, 50ms does.

Comment 20

[Jonathan]

I can reproduce this issue at 60hz with an increased sleep time.

Comment 21

[Martin Stránský [:stransky] (ni? me)]

Hm, If Firefox is D&D data provider and also requests D&D data, looks like we fail to provide data if we're already requesting it.

2025-01-27 22:29:20.076705 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   doing iteration, mWaitingForDragDataRequests 12 ...
2025-01-27 22:29:20.087705 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   doing iteration, mWaitingForDragDataRequests 12 ...
2025-01-27 22:29:20.098673 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   failed to get D&D data in time!
2025-01-27 22:29:20.098689 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   failed to get all data, mWaitingForDragDataRequests 12
2025-01-27 22:29:20.098698 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   text/plain failed to get from system
2025-01-27 22:29:20.098727 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00] nsDragSession::SetCanDrop 1
2025-01-27 22:29:20.098742 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   clear mTargetWindow mTargetWidget and other data
2025-01-27 22:29:20.098777 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00] nsDragSession::RunScheduledTask() task eDragTaskLeave mTargetWindow 7ee6d7783c00 mPendingWindow 0
2025-01-27 22:29:20.098785 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   dispatch eDragExit (7ee6d7783c00)
2025-01-27 22:29:20.098793 UTC - [Parent 154472: Main Thread]: D/WidgetDrag nsWindow::DispatchDragEvent eDragExit
2025-01-27 22:29:20.099194 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00] nsDragSession::EndDragSessionImpl(0) 0
2025-01-27 22:29:20.099221 UTC - [Parent 154472: Main Thread]: D/WidgetDrag [D 1][7ee6a9af7b00]   quit, selected task eDragTaskLeave
2025-01-27 22:29:20.100910 UTC - [Parent 154472: Main Thread]: D/WidgetDrag mShell::drag_data_received
2025-01-27 22:29:20.100925 UTC - [Parent 154472: Main Thread]: D/WidgetDrag nsWindow::OnDragDataReceived
2025-01-27 22:29:20.112984 UTC - [Parent 154472: Main Thread]: D/WidgetDrag mShell::drag_data_received

Comment 22

[Jonathan]

Now that I think about it, why is there a sleep at all? The GTK docs say this about looping gtk_main_iteration: https://docs.gtk.org/gtk3/func.events_pending.html
Wouldn't a sleep just block the UI thread? If you block it for too long (more than your refresh rate), then the main event loop won't get a chance to process events.

Comment 23

[Jonathan]

Attachment: Bug 1943789 - Remove sleep so UI doesn't freeze r?stransky

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4d0760b6d5c3
Remove sleep so UI doesn't freeze r=stransky

Comment 25

[Sandor Molnar[:smolnar]]

https://hg.mozilla.org/mozilla-central/rev/4d0760b6d5c3

Comment 26

[BugBot [:suhaib / :marco/ :calixte]]

The patch landed in nightly and beta is affected.
:jonath4n, is this bug important enough to require an uplift?

• If yes, please nominate the patch for beta approval.
• If no, please set status-firefox136 to wontfix.

For more information, please visit BugBot documentation.