1793834 - Add some window event data to an about page for debugging

Status: RESOLVED FIXED

(Core :: Widget: Win32, task, P3)

Description

[David Parks [:handyman]]

In order to better debug window position and sizing and multi-monitor issues (and probably others), we need better window message logging. Some basic window message logging improvements are covered in bug 1788271. This bug is to go a step further and record some message "times" and payloads/responses, and display them in an about page or some similar mechanism.

For example, we can count messages as they come in to nsWindow::ProcessMessage and store the count ID for the latest of a few message types, along with the payload and our response to the message. This would not be just the lParam and wParam but also any primitive payload data they might reference through pointers. E.g. the WINDOWPOS structure in the lParam for WM_WINDOWPOSCHANGING. Storing the message count ID with them allows us to order them -- many messages partially or completely overwrite the data from others so this is crucial. Also, we sometimes see bugs from messages that arrived in an unexpected order.

By storing a few types of messages this way, along with the display geometry information, we should be able to use it to reproduce window geometry calculations in the event that they lead to a bad state, like unresponsive window chrome or not-drawn pixels. This will not be much data and will be stored per-window.

We can display the information in an about page, which would require some window to be at least usable. That is fine for the kinds of bugs mentioned here.

Comment 1

[Greg Stoll :gstoll]

Attachment: How the page looks with the messages section open

Comment 2

[Greg Stoll :gstoll]

Attachment: How the page looks with the messages section closed

Comment 3

[Greg Stoll :gstoll]

Attachment: Bug 1793834 - part 1/12: adding a mostly-empty about:windows-messages page r=Gijs

Comment 4

[Greg Stoll :gstoll]

Attachment: Bug 1793834 - part 2/12: also log HWND in message logs r=handyman

This is helpful for the normal event log, and also necessary since we want to group the messages up by window in the about page.

Depends on D161148

Comment 5

[Greg Stoll :gstoll]

Attachment: Bug 1793834 - part 3/12: always record a few special messages for about page r=handyman

This is the list of messages that handyman and rkraesig suggested.

Since we're recording WM_GETMINMAXINFO, we now have better logging for that message.

Depends on D161149

Comment 6

[Greg Stoll :gstoll]

Attachment: Bug 1793834 - part 4/12: log window messages and expose entry point for retrieving them r=handyman

Depends on D161150

Comment 7

[Greg Stoll :gstoll]

Attachment: Bug 1793834 - part 5: return window messages for about page from C++ code r=handyman

Depends on D161151

Comment 8

[Greg Stoll :gstoll]

Attachment: Bug 1793834 - part 6/12: show messages from all windows r=Gijs

Depends on D161152

Comment 9

[Greg Stoll :gstoll]

Attachment: Bug 1793834 - part 7/12: bold current window r=Gijs

Depends on D161153

Comment 10

[Greg Stoll :gstoll]

Attachment: Bug 1793834 - part 7: delete entries when a window closes r=handyman

It seemed like a bad idea to hold on to entries forever after a window closes, even though we're not talking about a lot of memory per window. I went back and forth a bit on how to handle this; my first solution just removed the current window's messages when we got the "domwindowclosed" event, but the HWND would get a few more messages before it actually closed. This solution:

• doesn't add any extra overhead when we're logging messages (since this happens frequently, perf matters most here)
• prevents us from an unbounded memory leak; after a window closes it will keep a few extra messages around until the time the next window closes
• should be relatively quick; the 99th percentile of open windows is somewhere around 7, so this shouldn't take too long.

Depends on D161154

Comment 11

[Greg Stoll :gstoll]

Attachment: Bug 1793834 - part 8: add preference for number of messages to keep r=handyman

One thing to note is that if the user shrinks this number we won't reclaim any memory - this is because I wanted to avoid doing any more work than necessary when we're logging messages. Let me know if you think this is a problem!

Depends on D161155

Comment 12

[Greg Stoll :gstoll]

Attachment: Bug 1793834 - part 9: add copy to clipboard button and styling and localize text r=Gijs,bigiri

Depends on D161156

Comment 13

[Greg Stoll :gstoll]

Attachment: Bug 1793834 - part 11/12: Localize text r=Gijs

Depends on D161157

Comment 14

[Greg Stoll :gstoll]

Attachment: Bug 1793834 - part 10: some styling r=bigiri

Depends on D161158

Comment 15

[:Gijs (he/him)]

This is a lot of patches. Can someone describe why we're going with Yet Another About Page, rather than reusing e.g. MOZ_LOG (via about:logging), which seems like it'd be appropriate for something like this and would also allow seeing it in connection/relation to other MOZ_LOG enabled functionality? Apologies if there's an obvious reason not to do that that I'm missing...

Comment 16

[Florian Quèze [:florian]]

(In reply to :Gijs (he/him) from comment #15)

This is a lot of patches. Can someone describe why we're going with Yet Another About Page, rather than reusing e.g. MOZ_LOG

I almost wrote here a similar question yesterday, as the profiler has markers for WindowProc messages, probably less detailed than the logging considered here, but I wonder if it would be possible to improve them enough to fit the need here. MOZ_LOG is also visible in profiles.

After reading the comments here, my understanding of why something different has been implemented is that by keeping some information around all the time, it would be possible to troubleshoot what happened, after the fact, without knowing steps to reproduce.

Comment 17

[Greg Stoll :gstoll]

(In reply to Florian Quèze [:florian] from comment #16)

After reading the comments here, my understanding of why something different has been implemented is that by keeping some information around all the time, it would be possible to troubleshoot what happened, after the fact, without knowing steps to reproduce.

Yes, this is the idea - often these bugs are hard to reproduce, and so when someone gets into this state we can ask them to load the about page and send in that data, as opposed to having to have logging turned on to begin with.

Also, my apologies for the number of patches; I'm new at mozilla and still getting used to the stack of patches concept.

Comment 18

[Greg Stoll :gstoll]

Attachment: Bug 1793834 - part 6: show window messages in about page r=bigiri

Depends on D161152

Comment 19

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a39300a8ddff
part 1/12: adding a mostly-empty about:windows-messages page r=Gijs,fluent-reviewers,flod
https://hg.mozilla.org/integration/autoland/rev/d16ff7dbd155
part 2/12: also log HWND in message logs r=handyman
https://hg.mozilla.org/integration/autoland/rev/2d19fa85af4e
part 3/12: always record a few special messages for about page r=handyman
https://hg.mozilla.org/integration/autoland/rev/034466342a3b
part 4/12: log window messages and expose entry point for retrieving them r=handyman
https://hg.mozilla.org/integration/autoland/rev/a49eff0693ce
part 5: return window messages for about page from C++ code r=handyman
https://hg.mozilla.org/integration/autoland/rev/2ae1429c886a
part 6: show window messages in about page r=bigiri
https://hg.mozilla.org/integration/autoland/rev/c34df1dc8ff8
part 7: delete entries when a window closes r=handyman
https://hg.mozilla.org/integration/autoland/rev/34f582bdc341
part 8: add preference for number of messages to keep r=handyman
https://hg.mozilla.org/integration/autoland/rev/9130ed00888e
part 9: add copy to clipboard button and styling and localize text r=Gijs,bigiri,fluent-reviewers,flod

Comment 20

[Cristian Tuns]

Backed out for causing mochitest failures on browser_preferences_usage.js

• Backout link
• Push with failures
• Failure Log
• Failure line: TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_preferences_usage.js | widget.windows.messages_to_log should not be accessed more than 40 times. - 60 <= 40 - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/browser_preferences_usage.js :: checkPrefGetters :: line 42

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/bfd6a2697b3b
part 1/12: adding a mostly-empty about:windows-messages page r=Gijs,fluent-reviewers,flod
https://hg.mozilla.org/integration/autoland/rev/3c2fd06bcfe8
part 2/12: also log HWND in message logs r=handyman
https://hg.mozilla.org/integration/autoland/rev/9cb0638f941d
part 3/12: always record a few special messages for about page r=handyman
https://hg.mozilla.org/integration/autoland/rev/9dabd35bafe5
part 4/12: log window messages and expose entry point for retrieving them r=handyman
https://hg.mozilla.org/integration/autoland/rev/c55341738f3b
part 5: return window messages for about page from C++ code r=handyman
https://hg.mozilla.org/integration/autoland/rev/ce4be86b4c3f
part 6: show window messages in about page r=bigiri
https://hg.mozilla.org/integration/autoland/rev/c5c8cf87125d
part 7: delete entries when a window closes r=handyman
https://hg.mozilla.org/integration/autoland/rev/9243bbde3d5e
part 8: add preference for number of messages to keep r=handyman
https://hg.mozilla.org/integration/autoland/rev/ebcce528c4a9
part 9: add copy to clipboard button and styling and localize text r=Gijs,bigiri,fluent-reviewers,flod

Comment 22

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/bfd6a2697b3b
https://hg.mozilla.org/mozilla-central/rev/3c2fd06bcfe8
https://hg.mozilla.org/mozilla-central/rev/9cb0638f941d
https://hg.mozilla.org/mozilla-central/rev/9dabd35bafe5
https://hg.mozilla.org/mozilla-central/rev/c55341738f3b
https://hg.mozilla.org/mozilla-central/rev/ce4be86b4c3f
https://hg.mozilla.org/mozilla-central/rev/c5c8cf87125d
https://hg.mozilla.org/mozilla-central/rev/9243bbde3d5e
https://hg.mozilla.org/mozilla-central/rev/ebcce528c4a9