| Summary: | Frame rate drops after suspend/resume cycle | ||
|---|---|---|---|
| Product: | [Plasma] kwin | Reporter: | Patrick Silva <bugseforuns> |
| Component: | general | Assignee: | KWin default assignee <kwin-bugs-null> |
| Status: | RESOLVED UNMAINTAINED | ||
| Severity: | normal | CC: | bug2017, katyaberezyaka, odzinic |
| Priority: | NOR | ||
| Version: | 5.18.0 | ||
| Target Milestone: | --- | ||
| Platform: | Arch Linux | ||
| OS: | Linux | ||
| Latest Commit: | Version Fixed In: | ||
| Attachments: |
X11 before suspend
X11 after suspend Wayland before suspend Wayland after suspend |
||
Created attachment 125985 [details]
X11 after suspend
Created attachment 125986 [details]
Wayland before suspend
Created attachment 125987 [details]
Wayland after suspend
It would helpful to have dmesg output. Also, is the issue still present after restarting kwin_x11? Side note: run kwin_x11 --replace from command line to restart kwin_x11 Restart kwin does not solve this issue. I need to relogin or reboot. Here is the output of dmesg -T after resume on X11: [Fri Feb 14 12:40:19 2020] perf: interrupt took too long (2580 > 2500), lowering kernel.perf_event_max_sample_rate to 77400 [Fri Feb 14 12:40:21 2020] audit: type=1130 audit(1581694825.953:137): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' [Fri Feb 14 12:40:21 2020] r8169 0000:04:00.0 enp4s0: Link is Down [Fri Feb 14 12:40:22 2020] audit: type=1131 audit(1581694826.313:138): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=atop comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' [Fri Feb 14 12:40:22 2020] PM: suspend entry (deep) [Fri Feb 14 12:40:22 2020] Filesystems sync: 0.554 seconds [Fri Feb 14 12:40:22 2020] Freezing user space processes ... (elapsed 0.003 seconds) done. [Fri Feb 14 12:40:22 2020] OOM killer disabled. [Fri Feb 14 12:40:22 2020] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done. [Fri Feb 14 12:40:22 2020] printk: Suspending console(s) (use no_console_suspend to debug) [Fri Feb 14 12:40:22 2020] sd 3:0:0:0: [sdc] Synchronizing SCSI cache [Fri Feb 14 12:40:22 2020] sd 1:0:0:0: [sdb] Synchronizing SCSI cache [Fri Feb 14 12:40:22 2020] sd 3:0:0:0: [sdc] Stopping disk [Fri Feb 14 12:40:22 2020] sd 1:0:0:0: [sdb] Stopping disk [Fri Feb 14 12:40:22 2020] sd 0:0:0:0: [sda] Synchronizing SCSI cache [Fri Feb 14 12:40:22 2020] sd 0:0:0:0: [sda] Stopping disk [Fri Feb 14 12:40:23 2020] ACPI: Preparing to enter system sleep state S3 [Fri Feb 14 12:40:23 2020] PM: Saving platform NVS memory [Fri Feb 14 12:40:23 2020] Disabling non-boot CPUs ... [Fri Feb 14 12:40:23 2020] smpboot: CPU 1 is now offline [Fri Feb 14 12:40:23 2020] ACPI: Low-level resume complete [Fri Feb 14 12:40:23 2020] PM: Restoring platform NVS memory [Fri Feb 14 12:40:23 2020] Enabling non-boot CPUs ... [Fri Feb 14 12:40:23 2020] x86: Booting SMP configuration: [Fri Feb 14 12:40:23 2020] smpboot: Booting Node 0 Processor 1 APIC 0x2 [Fri Feb 14 12:40:23 2020] CPU1 is up [Fri Feb 14 12:40:23 2020] ACPI: Waking up from system sleep state S3 [Fri Feb 14 12:40:23 2020] sd 0:0:0:0: [sda] Starting disk [Fri Feb 14 12:40:23 2020] sd 1:0:0:0: [sdb] Starting disk [Fri Feb 14 12:40:23 2020] sd 3:0:0:0: [sdc] Starting disk [Fri Feb 14 12:40:23 2020] OOM killer enabled. [Fri Feb 14 12:40:23 2020] Restarting tasks ... done. [Fri Feb 14 12:40:23 2020] video LNXVIDEO:00: Restoring backlight state [Fri Feb 14 12:40:23 2020] PM: suspend exit [Fri Feb 14 12:40:23 2020] pci_bus 0000:03: Allocating resources [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: bridge window [io 0x1000-0x0fff] to [bus 03] add_size 1000 [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: bridge window [mem 0x00100000-0x000fffff 64bit pref] to [bus 03] add_size 200000 add_align 100000 [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: bridge window [mem 0x00100000-0x000fffff] to [bus 03] add_size 200000 add_align 100000 [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: BAR 14: no space for [mem size 0x00200000] [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: BAR 14: failed to assign [mem size 0x00200000] [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: BAR 15: no space for [mem size 0x00200000 64bit pref] [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: BAR 15: failed to assign [mem size 0x00200000 64bit pref] [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: BAR 13: no space for [io size 0x1000] [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: BAR 13: failed to assign [io size 0x1000] [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: BAR 14: no space for [mem size 0x00200000] [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: BAR 14: failed to assign [mem size 0x00200000] [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: BAR 15: no space for [mem size 0x00200000 64bit pref] [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: BAR 15: failed to assign [mem size 0x00200000 64bit pref] [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: BAR 13: no space for [io size 0x1000] [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: BAR 13: failed to assign [io size 0x1000] [Fri Feb 14 12:40:23 2020] pci 0000:02:00.0: PCI bridge to [bus 03] [Fri Feb 14 12:40:23 2020] audit: type=1130 audit(1581694832.253:139): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=atop comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' [Fri Feb 14 12:40:23 2020] Process accounting resumed [Fri Feb 14 12:40:23 2020] audit: type=1130 audit(1581694832.263:140): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' [Fri Feb 14 12:40:23 2020] audit: type=1131 audit(1581694832.263:141): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-suspend comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' [Fri Feb 14 12:40:23 2020] RTL8211E Gigabit Ethernet r8169-400:00: attached PHY driver [RTL8211E Gigabit Ethernet] (mii_bus:phy_addr=r8169-400:00, irq=IGNORE) [Fri Feb 14 12:40:23 2020] ata5: SATA link up 1.5 Gbps (SStatus 113 SControl 300) [Fri Feb 14 12:40:23 2020] ata5.00: ACPI cmd ef/10:06:00:00:00:00 (SET FEATURES) succeeded [Fri Feb 14 12:40:23 2020] ata5.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out [Fri Feb 14 12:40:23 2020] ata5.00: ACPI cmd b1/c1:00:00:00:00:00 (DEVICE CONFIGURATION OVERLAY) filtered out [Fri Feb 14 12:40:23 2020] r8169 0000:04:00.0 enp4s0: Link is Down [Fri Feb 14 12:40:23 2020] ata5.00: ACPI cmd ef/10:06:00:00:00:00 (SET FEATURES) succeeded [Fri Feb 14 12:40:23 2020] ata5.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out [Fri Feb 14 12:40:23 2020] ata5.00: ACPI cmd b1/c1:00:00:00:00:00 (DEVICE CONFIGURATION OVERLAY) filtered out [Fri Feb 14 12:40:23 2020] ata5.00: configured for UDMA/100 [Fri Feb 14 12:40:26 2020] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300) [Fri Feb 14 12:40:26 2020] r8169 0000:04:00.0 enp4s0: Link is Up - 1Gbps/Full - flow control rx/tx [Fri Feb 14 12:40:26 2020] IPv6: ADDRCONF(NETDEV_CHANGE): enp4s0: link becomes ready [Fri Feb 14 12:40:26 2020] ata1.00: configured for UDMA/133 [Fri Feb 14 12:40:28 2020] ata2: link is slow to respond, please be patient (ready=0) [Fri Feb 14 12:40:28 2020] ata4: link is slow to respond, please be patient (ready=0) [Fri Feb 14 12:40:28 2020] ata2: SATA link up 6.0 Gbps (SStatus 133 SControl 300) [Fri Feb 14 12:40:28 2020] ata2.00: configured for UDMA/133 [Fri Feb 14 12:40:29 2020] ata4: SATA link up 6.0 Gbps (SStatus 133 SControl 300) [Fri Feb 14 12:40:29 2020] ata4.00: configured for UDMA/133 [Fri Feb 14 12:40:32 2020] audit: type=1131 audit(1581694840.596:142): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=NetworkManager-dispatcher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' I have the same problem here. (Intel i7-4720 with hd4600, Gentoo, linux-5.5.5, mesa-20.0, xorg-1.20.7, qt-5.14.1, frameworks-5.67.0, kwin-5.18.1) I've disabled most desktop effects (except present windows, desktop cube and show fps) It looks like disabling the blur can bring back 60fps for low activity, but playing youtube videos on chrome lets the frame rate drop down to ~15fps. kwin_x11 --replace did not fix the problem. Logging out and logging in did not fix the problem on my last try. I had to reboot. The problem was present with kwin-5.17 too, changing to the low latency patch did not help. But I think logging out fixed the problem (at that time I was running an older linux-4.20) yes, the problem persists with Plasma 5.18.1 on my desktop computer. I have just tested Wayland session on another computer (laptop) running Neon unstable edition and the problem did not occur this time. Framerate is still 60fps after suspend/resume. Operating System: KDE neon Unstable Edition KDE Plasma Version: 5.18.80 KDE Frameworks Version: 5.68.0 Qt Version: 5.14.1 Kernel Version: 5.3.0-28-generic OS Type: 64-bit Processors: 4 × Intel® Core™ i3-3110M CPU @ 2.40GHz Memory: 7,7 GiB of RAM Graphics Processor: Mesa DRI Intel® Ivybridge Mobile I have just noticed that I can't reproduce this problem on my problematic machine with kernel 5.4.21-1 LTS. But fps is still permanently lower (50fps) on Wayland session. Operating System: Arch Linux KDE Plasma Version: 5.18.1 KDE Frameworks Version: 5.67.0 Qt Version: 5.14.1 Kernel Version: 5.4.21 OS Type: 64-bit Processors: 2 × Intel® Celeron® CPU G1820 @ 2.70GHz Memory: 7,7 GiB of RAM Since my reboot on the 23rd I could not reproduce that problem with 4 resume cycles. I had no relevant updates, so the same machine might or might not reproduce the problem. One question is: Does it needs to be triggered on the first resume cycle? I can reproduce this problem all the time with kernel 5.5.5.arch1-1. For some reason refresh rate of my monitor was set to 50hz in "Display configuration" kcm only on Wayland. I changed it to 60hz and refresh rate went back to 50hz after relogin. Then I tried to set 60hz again and "Display configuration" kcm crashed. I tried again and finally it worked. Operating System: Arch Linux KDE Plasma Version: 5.18.2 KDE Frameworks Version: 5.67.0 Qt Version: 5.14.1 I'm trying to understand what, what the plot in the showfps effect mean. The most left blue bar is obviously the same fps value as displayed numerically. The left (colorful) plot show the compositors rendering time: <=10ms green, <=20ms yellow, <=50ms red, >50ms black The right plot plots the log10 of the refreshed window pixel (maxes out at ~15 Mpixel) Currently I'm running on the low latency patched kwin-5.8.2 (maybe later I can switch back) It makes it more visible if everything is running correctly as the green rendering plot shrinks to a thin line (2-3ms). The main problem I see are windows generating endless amount of refresh events, even if their content does not change. Typically this state can be cleared by dragging the window into a tile position (left, right, top left, but not maximized) One way to bring an window into that state is loosing focus to an different window that covers the affected window. Another way is to go to suspend and resume. After dragging all the windows at least one time into a corner clears that state and the rendering time is down to 2-3ms again. I can reproduce the same behavior with the unpatched version of kwin too (which has worse performance). At this point I can't say if the suspend resume cylce has anything to do with that, except that it messes somehow with the window states. A very similar thing can be reproduces by locking the screen (closing the lid). In my current session both events have the same behavior. All 4 images from Patrick show that at least one window is already on refresh rampage, after resume it is just at least one to much to. I can't reproduce this problem with kernel 5.6.2. Apparently it was a regression related to haswell cpus. Operating System: Arch Linux KDE Plasma Version: 5.18.4 KDE Frameworks Version: 5.68.0 Qt Version: 5.14.2 Kernel Version: 5.6.2-arch1-2 OS Type: 64-bit Processors: 2 × Intel® Celeron® CPU G1820 @ 2.70GHz Memory: 7,7 GiB of RAM For me it has also improved with linux-2.6.3 too. But it also confirms, that we have two performance problems. The major one probably haswell and suspend specific. And the second one that the compositor is refreshing windows that don't change at all. (See comment 11) If both issues hit at the same time, the frame rate drops. I am getting this same issue with X11. I found that this happens to me even if I just suspend/resume kwin (ctrl+shift+f12). FPS starts dropping from 100+ to 30-60 from simply playing an animation or watching a video. Operating System: Manjaro Linux KDE Plasma Version: 5.19.4 KDE Frameworks Version: 5.73.0 Qt Version: 5.15.0 Kernel Version: 5.7.17-2-MANJARO OS Type: 64-bit Processors: 8 × Intel® Core™ i7-6700K CPU @ 4.00GHz Memory: 15.6 GiB of RAM Graphics Processor: GeForce GTX 1080 Ti/PCIe/SSE2 This bug was reported against an outdated version of KWin. We have made many changes since the. If the issue persists in newer versions can you reopen the bug report updating the version number. |
Created attachment 125984 [details] X11 before suspend SUMMARY I noticed weird cursor movements and choppy scrolling in internet browser on my system after suspend/resume cycle. I enabled "Show fps" effect in "Desktop effects" kcm and saw that frame rate drops from 60 to 45 on X11 and from 50 to 25 on Wayland after suspend/resume cycle, as we can see in the attached screenshots. STEPS TO REPRODUCE 1. start X11 session 2. suspend your system and wake up it 3. open any app (Kate, for example) and move cursor on it: cursor lags 4. do logout 5. start Wayland session 6. repeat the steps 2 and 3: cursor lags again EXPECTED RESULT frame rate should not change after suspend/resume cycle SOFTWARE/OS VERSIONS Operating System: Arch Linux KDE Plasma Version: 5.18.0 KDE Frameworks Version: 5.67.0 Qt Version: 5.14.1