Going between direct scanout and compositing causes a several second freeze

[migue07juegos]

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.

compressed.mp4

System Information

• niri version: niri 0.1.5 (fd6c8c7)

• GPU: AMD RX 6800

• CPU: AMD Ryzen 7 3800X

niri.save2.log

[YaLTeR]

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.

[migue07juegos]

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]

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
}

[migue07juegos]

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

[YaLTeR]

Any news?

[migue07juegos]

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

[YaLTeR]

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]

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]

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).

[migue07juegos]

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]

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

[migue07juegos]

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]

Thanks. That does not seem particularly related.

[liuhq]

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]

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]

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]

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)

[migue07juegos]

@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.