search

YaLTeR / niri

A scrollable-tiling Wayland compositor.
https://matrix.to/#/#niri:matrix.org
GNU General Public License v3.0
3.29k stars 93 forks source link

Going between direct scanout and compositing causes a several second freeze #310

Open mike7d7 opened 4 months ago

mike7d7 commented 4 months ago

Sometimes a fullscreened window causes lag when switching to another window, it freezes for about 5 seconds and then everything is back to normal, and also the other way around, when switching from another window to the fullscreened window.

The video isn't lagging, that's what I see on my monitor. I move the cursor in circles so it's easier to show how it freezes and unfreezes. Also the audio doesn't have any issues, so I guess it is only niri freezing.

https://github.com/YaLTeR/niri/assets/104018233/8cf67b1e-367d-46a0-9b0d-e4a6a13b9519

System Information

niri.save2.log

YaLTeR commented 4 months ago

Huh, wtf. Never seen this (and I play plenty of Lazer).

Sometimes

Is there perhaps any more specific condition that you've noticed when it happens? Also does it just happen for a few minutes then stops?

Seems like I don't currently have a debug flag to disable direct scanout; this is what I'd test.

mike7d7 commented 4 months ago

Is there perhaps any more specific condition that you've noticed when it happens?

Not really, it's pretty random, I've had this issue not only with osu!, but also with Cities Skylines on Gamescope, Zoom web version in Firefox and Youtube in Firefox. The only constants are that I always have firefox opened and it affects a fullscreened window.

I'm currently trying to find a way to reproduce, if I find a way I'll add a comment explaining how to.

Also does it just happen for a few minutes then stops?

It doesn't stop until I restart niri.

YaLTeR commented 4 months ago

I just pushed a flag to disable direct scanout, could you rebuild niri and try if it helps next time you hit this issue?

debug {
    disable-direct-scanout
}
mike7d7 commented 4 months ago

Thanks, I'll rebuild and test with the new flag.

YaLTeR commented 4 months ago

Any news?

mike7d7 commented 4 months ago

I tested the new flag and haven't had the issue ever since.

YaLTeR commented 4 months ago

I see. It is really weird that you get a freeze on direct scanout, but I'm not sure if there's an easy way to diagnose.

YaLTeR commented 4 months ago

I'll close the issue because I'm not sure there's anything actionable I can do here at the moment, but feel free to reopen if some new details come up.

YaLTeR commented 4 months ago

Something that may help to debug this is getting a DRM debug log, if you feel like it. The process is described here: https://gitlab.freedesktop.org/wlroots/wlroots/-/wikis/DRM-Debugging

Specifically, you'd need to do this:

  1. Run normally and wait until the issue reproduces.
  2. As soon as it reproduces, open a terminal, enable DRM debugging and dmesg logging to file.
  3. Reproduce the freeze.
  4. Disable dmesg logging to file and DRM debugging.
  5. Upload the log here.

Running niri with RUST_LOG=debug during the process and uploading the results could also help (this will enable debug logging for Smithay, whereas by default it's only enabled for niri itself).

mike7d7 commented 3 months ago

I updated to version 0.1.6 and enabled direct scanout to try and reproduce the issue, I got a DRM debug log of the issue while playing osu! lazer. I still have no idea how to reproduce other than a fullscreen app and wait to see the error. dmesg.log

YaLTeR commented 3 months ago

Thanks! cc @cmeissl who can maybe tell what's wrong from this

mike7d7 commented 3 months ago

I also got niri's log with RUST_LOG=debug. The error happened at around 3:37 and it seems that it outputs DEBUG smithay::wayland::text_input::text_input_handle: discarding text-input request without IME running several times. niri.log

YaLTeR commented 3 months ago

Thanks. That does not seem particularly related.

liuhq commented 3 months ago

I just pushed a flag to disable direct scanout, could you rebuild niri and try if it helps next time you hit this issue?

debug {
    disable-direct-scanout
}

I will also get freeze when enter fullscreen (whether mete+shift+f or media site’s own fullscreen), then add this debug flag can “fixed” it.

GPU: Nvidia - 4060 Driver: nvidia-open system: archlinux

liuhq commented 3 months ago

Thanks. That does not seem particularly related.

I found a warn message when entered the fullscreen mode. Maybe it caused? 

2024-06-07T13:54:39.348366Z  WARN smithay::backend::drm: using legacy fbadd

and some Creating new Output to follow it: 

2024-06-07T13:54:39.705998Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:40.706112Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:41.706399Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:42.706572Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:43.706712Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:44.706842Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:45.707134Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:46.707465Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:47.707647Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:48.707926Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:49.708295Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:50.708610Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
cmeissl commented 3 months ago

Thanks! cc @cmeissl who can maybe tell what's wrong from this

Sorry for late reply. The only thing that stood out from the log is that it seems to disable and re-enable the plane in the commit. The log contains multiple entries of Disabling DRM plane and Enabling DRM plane for the same plane on the same CRTC. 

[ 8939.578232] amdgpu 0000:06:00.0: [drm:drm_ioctl [drm]] comm="niri" pid=968, dev=0xe200, auth=1, DRM_IOCTL_MODE_ATOMIC
[ 8939.578293] amdgpu 0000:06:00.0: [drm:drm_atomic_state_init [drm]] Allocated atomic state 00000000f7b3d62a
[ 8939.578344] [drm:drm_mode_object_get [drm]] OBJ ID: 144 (2)
[ 8939.578399] amdgpu 0000:06:00.0: [drm:drm_atomic_get_plane_state [drm]] Added [PLANE:70:plane-5] 00000000e352ad5e state to 00000000f7b3d62a
[ 8939.578449] [drm:drm_mode_object_get [drm]] OBJ ID: 143 (2)
[ 8939.578502] amdgpu 0000:06:00.0: [drm:drm_atomic_get_crtc_state [drm]] Added [CRTC:91:crtc-0] 00000000f3e87da9 state to 00000000f7b3d62a
[ 8939.578555] amdgpu 0000:06:00.0: [drm:drm_atomic_set_fb_for_plane [drm]] Set [FB:146] for [PLANE:70:plane-5] state 00000000e352ad5e
[ 8939.578605] [drm:drm_mode_object_get [drm]] OBJ ID: 146 (3)
[ 8939.578658] [drm:drm_mode_object_put.part.0 [drm]] OBJ ID: 144 (3)
[ 8939.578709] [drm:drm_mode_object_put.part.0 [drm]] OBJ ID: 146 (4)
[ 8939.578761] [drm:drm_mode_object_put.part.0 [drm]] OBJ ID: 146 (3)
[ 8939.578815] amdgpu 0000:06:00.0: [drm:drm_atomic_check_only [drm]] checking 00000000f7b3d62a
[ 8939.578867] [drm:dm_update_plane_state [amdgpu]] Disabling DRM plane: 70 on DRM crtc 91
[ 8939.579433] amdgpu 0000:06:00.0: [drm:drm_atomic_get_private_obj_state [drm]] Added new private object 00000000077291bd state 000000000f9fc57b to 00000000f7b3d62a
[ 8939.579497] [drm:dm_update_plane_state [amdgpu]] Enabling DRM plane: 70 on DRM crtc 91
[ 8939.580068] amdgpu 0000:06:00.0: [drm:drm_atomic_nonblocking_commit [drm]] committing 00000000f7b3d62a nonblocking
[ 8939.580327] amdgpu 0000:06:00.0: [drm:drm_calc_timestamping_constants [drm]] crtc 91: hwmode: htotal 2720, vtotal 1481, vdisplay 1440
[ 8939.580388] amdgpu 0000:06:00.0: [drm:drm_calc_timestamping_constants [drm]] crtc 91: clock 664670 kHz framedur 6060631 linedur 4092

I have no AMD hardware at hand so that might also be expected, but it sounds suspicious. Especially the hwmode part sounds like it does modesetting.

@migue07juegos Can you please also post the output of drm_info? A trace log of smithay would also be nice to have as it might give a hint on where it is blocked. (A release build of niri will compile time disable trace log entries, so you either have to change the release_max_level_debug in Cargo.toml or run a debug build).

cmeissl commented 3 months ago

Thanks. That does not seem particularly related.

I found a warn message when entered the fullscreen mode. Maybe it caused?

2024-06-07T13:54:39.348366Z  WARN smithay::backend::drm: using legacy fbadd

and some Creating new Output to follow it:

2024-06-07T13:54:39.705998Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:40.706112Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:41.706399Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:42.706572Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:43.706712Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:44.706842Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:45.707134Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:46.707465Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:47.707647Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:48.707926Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:49.708295Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }
2024-06-07T13:54:50.708610Z  INFO new: smithay::output: Creating new Output name="" name="" physical=PhysicalProperties { size: Size<smithay::utils::geometry::Raw> { w: 0, h: 0 }, subpixel: Unknown, make: "", model: "" }

Creating new Output is completely unrelated, it is just how niri builds temporary outputs.

The warning about legacy fbadd is definitely suspicious, but imo should not cause a freeze. What this means is that we tried to add a framebuffer handle for some dmabuf but had to fallback to the legacy method. (Note that this might happen every time, but we only output it the first time it happens)

mike7d7 commented 2 months ago

@cmeissl here is the output of drm_info. drm-info.txt

I'm currently trying to get the trace log, but I haven't had the issue yet since recompiling and activating direct scanout. If I get the error again I'll add a message with the trace log.