Bug 92982

Summary: slow switching to KD_GRAPHICS (KMS?)
Product: DRI Reporter: royvandervegt
Component: DRM/RadeonAssignee: Default DRI bug account <dri-devel>
Status: RESOLVED MOVED QA Contact:
Severity: normal    
Priority: medium    
Version: unspecified   
Hardware: x86-64 (AMD64)   
OS: Linux (All)   
Whiteboard:
i915 platform: i915 features:
Attachments:
Description Flags
cpu and glxinfo
none
perf stat
none
perf report
none
Dmesg output drm.debug=14 none

Description royvandervegt 2015-11-17 19:49:26 UTC
Created attachment 119748 [details]
cpu and glxinfo

I have been experiencing this problem since late 2013 when I started using Linux, but I was never able to pinpoint the root cause.
When X starts, it takes a long time (5 - 10 sec) to display the desktop. Switching from X/Wayland to tty and vice versa also takes the same amount of time. After the switch is complete everything works fine.

Now I was programming some animations using the framebuffer device (/dev/fb0) and I was using `ioctl(fd, KDSETMODE, KD_GRAPHICS)` to enable graphics mode instead of text mode. This also takes 5 - 10 seconds. This might be a good starting point?

KMS is enabled and also reported as such by X on startup. No special configurations are in use, everything is vanilla.

System information:
 - ATI Mobility Radeon HD5470m (512mb)
 - Driver version: xf86-video-ati 1:7.5.0-2, but goes back a long time before this version
 - Kernel: Linux arch 4.2.5-1-ARCH #1 SMP PREEMPT Tue Oct 27 08:13:28 CET 2015 x86_64 GNU/Linux
Comment 1 royvandervegt 2015-11-18 13:20:56 UTC
I should add that this problem does not occur when booting with `nomodeset`. It then uses the vesa framebuffer instead of radeondrmfb.
Comment 2 Michel Dänzer 2015-11-19 02:47:34 UTC
Does it hog the CPU while it's hanging? If so, can you get a CPU profile with sysprof or perf or oprofile?

Otherwise, can you try narrowing down where the time is spent in the ioctl, e.g. by adding debugging output?
Comment 3 royvandervegt 2015-11-19 09:17:46 UTC
Created attachment 119928 [details]
perf stat
Comment 4 royvandervegt 2015-11-19 09:18:07 UTC
Created attachment 119929 [details]
perf report
Comment 5 royvandervegt 2015-11-19 09:20:45 UTC
I wrote the following small program:

#include <stropts.h>
#include <linux/kd.h>

void main() {
	ioctl(0, KDSETMODE, KD_GRAPHICS);
	ioctl(0, KDSETMODE, KD_TEXT);
}

and benchmarked this using perf stat and perf report (see attachments). Is this what you were looking for?
Comment 6 Michel Dänzer 2015-11-19 09:26:27 UTC
That doesn't look like it's CPU bound to me, so you need another approach to isolate where the time is spent.
Comment 7 royvandervegt 2015-11-19 10:07:48 UTC
Wouldn't that be cfb_imageblit as reported by perf report?

`45.27%  test     [kernel.vmlinux]  [k] cfb_imageblit`

If not, can you explain how I can narrow down where the time is spent in the ioctl by adding debugging output? Do I have to compile my own kernel with added printfs?
Comment 8 royvandervegt 2015-11-24 21:15:17 UTC
I did some logging using drm.debug=14. I switched back and forth between X and the tty, the output is in the attachment. Can you see if something is odd in the output? (maybe the dmesg timestamps are useful?)
Comment 9 royvandervegt 2015-11-24 21:15:46 UTC
Created attachment 120094 [details]
Dmesg output drm.debug=14
Comment 10 Michel Dänzer 2015-11-25 09:59:34 UTC
(In reply to royvandervegt from comment #7)
> Do I have to compile my own kernel with added printfs?

I'm afraid so.
Comment 11 royvandervegt 2015-12-02 21:21:34 UTC
It turns out the problems are caused by DPM. Without DPM (using radeon.dpm=0) everything works as it should.

I have tried tweaking the DPM parameters using https://wiki.archlinux.org/index.php/ATI#Dynamic_power_management, but changing dpm_state to `performance` and power_dpm_force_performance_level to `high` doesn't solve the issues (in fact, changing these parameters seems to have no effect at all?).

Obviously disabling DPM isn't ideal, so it would be nice if there was a workaround/fix.
Comment 12 royvandervegt 2015-12-11 15:40:25 UTC
Interestingly enough, it seems to have little to do with the clock speeds. 

With dpm turned on and radeon_dpm_force_performance_level set to high (doesn't switch properly):

uvd    vclk: 0 dclk: 0
power level 2    sclk: 75000 mclk: 80000 vddc: 1120 vddci: 0

With radeon.dpm=0 (WORKS, switches quickly):
default engine clock: 750000 kHz
current engine clock: 749980 kHz
default memory clock: 800000 kHz
current memory clock: 799870 kHz
voltage: 1120 mV
PCIE lanes: 16
Comment 13 Martin Peres 2019-11-19 09:09:44 UTC
-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/drm/amd/issues/661.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.