Gentoo Forums
Gentoo Forums
Gentoo Forums
Quick Search: in
Delay in radeon driver when starting Xorg
View unanswered posts
View posts from last 24 hours

 
Reply to topic    Gentoo Forums Forum Index Kernel & Hardware
View previous topic :: View next topic  
Author Message
zipdisquette
n00b
n00b


Joined: 22 Dec 2018
Posts: 4

PostPosted: Sat Dec 22, 2018 4:38 pm    Post subject: Delay in radeon driver when starting Xorg Reply with quote

Hi all!

Lately I've been digging into my Xorg setup to find out why it takes so long to start. I'm talking around 15 seconds from the moment I type startx to the moment the wm loads.
By looking at the timestamps of every log line in my Xorg.0.log, I found out that the program hangs for 4-5 seconds exactly three times during the boot phase. The logs themselves weren't very helpful, so I tried to run Xorg under strace to find out more. Below are the three interested portions of both the log and strace output.

As you can see, the delays are caused by apparently harmless IOCTLs on the /dev/dri/card0 device (my integrated ATI graphic card). The device is run by the radeon driver. I don't know what those IOCTL requests are supposed to do since the documentation is nonexistent, but for sure a 4 second delay is unjustified.
I also checked out Xorg's code and I made sure that besides those system calls the program isn't doing anything suspicius.

Now, I'm aware that mine is a very very specific problem, I already searched everywhere and I didn't find anything remotely related so I'm not really expecting an easy fix, but do you have any clues on where I could look to find out more? Do you think this is a plain bug in the radeon driver?

First delay:
Xorg log:
Code:

[  3545.769] (II) xfree86: Adding drm device (/dev/dri/card0)
[  3550.333] (--) PCI:*(1@0:0:0) 1002:68e4:1025:0487 rev 0, Mem @ 0xa0000000/268435456, 0xb4000000/131072, I/O @ 0x00003000/256, BIOS @ 0x????????/131072
[  3550.333] (II) LoadModule: "glx"
[  3550.335] (II) Loading /usr/lib64/xorg/modules/extensions/libglx.so

Strace (the elapsed time for every call is reported at the end, between the < >)
Code:

19:29:41.634300 openat(AT_FDCWD, "/dev/dri/card0", O_RDWR|O_CLOEXEC) = 8 <0.000019>
19:29:41.634351 ioctl(8, DRM_IOCTL_SET_VERSION, 0x7ffe8cc38180) = 0 <0.000012>
19:29:41.634390 ioctl(8, DRM_IOCTL_GET_UNIQUE, 0x7ffe8cc38170) = 0 <0.000006>
19:29:41.634422 ioctl(8, DRM_IOCTL_GET_UNIQUE, 0x7ffe8cc38170) = 0 <0.000006>
19:29:41.634455 ioctl(8, DRM_IOCTL_VERSION, 0x55c65cb31670) = 0 <0.000007>
19:29:41.634486 ioctl(8, DRM_IOCTL_VERSION, 0x55c65cb31670) = 0 <0.000006>
19:29:41.634518 close(8)                = 0 <4.534293>


Second:
Xorg log:
Code:

[  3550.342] (II) modesetting: Driver for Modesetting Kernel Drivers: kms
[  3550.342] (--) using VT number 4
[  3554.888] (II) modeset(0): using drv /dev/dri/card0
[  3554.889] (II) modeset(0): Creating default Display subsection in Screen section
        "screen0" for depth/fbbpp 24/32
[  3554.889] (==) modeset(0): Depth 24, (==) framebuffer bpp 32

Strace:
Code:

19:29:46.211332 openat(AT_FDCWD, "/dev/dri/card0", O_RDWR|O_CLOEXEC) = 11 <0.000016>
19:29:46.211380 ioctl(11, DRM_IOCTL_MODE_GETRESOURCES, 0x7ffe8cc380b0) = 0 <0.000009>
19:29:46.211414 ioctl(11, DRM_IOCTL_MODE_GETRESOURCES, 0x7ffe8cc380b0) = 0 <0.000007>
19:29:46.211451 close(11)               = 0 <4.541438>


Third:
This time the log didn't mention anything related. Also I stripped out a lot of lines between the open and the guilty IOCTLs. Strace:
Code:

19:29:50.753634 openat(AT_FDCWD, "/dev/dri/card0", O_RDWR|O_CLOEXEC) = 12 <0.000025>
...
19:29:51.306475 ioctl(12, DRM_IOCTL_MODE_DIRTYFB, 0x7ffe8cc38220) = -1 ENOENT <0.000008>
19:29:51.306525 ioctl(12, DRM_IOCTL_MODE_SETGAMMA, 0x7ffe8cc38180) = 0 <0.000045>
19:29:51.306606 ioctl(12, DRM_IOCTL_MODE_ADDFB, 0x7ffe8cc37fe0) = 0 <0.000011>
19:29:51.306644 ioctl(12, DRM_IOCTL_MODE_SETCRTC, 0x7ffe8cc38070) = 0 <0.000047>
19:29:51.306723 ioctl(12, DRM_IOCTL_MODE_SETPROPERTY, 0x7ffe8cc38160) = 0 <0.000008>
19:29:51.306755 ioctl(12, DRM_IOCTL_MODE_SETCRTC, 0x7ffe8cc38220) = 0 <1.510123>
19:29:52.816994 ioctl(12, DRM_IOCTL_MODE_SETCRTC, 0x7ffe8cc38220) = 0 <1.511856>
19:29:54.329049 ioctl(12, DRM_IOCTL_MODE_SETCRTC, 0x7ffe8cc38220) = 0 <1.511807>


The kernel is the latest, 4.19.11, but I had this problem since ages with many different kernels. I tried to compile radeon both directly in the kernel (with proper firmware blobs) and as a module, so it could lookup for firmware by itself, but I had no results.
This is the device in question:
Code:

01:00.0 VGA compatible controller: Advanced Micro Devices, Inc. [AMD/ATI] Robson CE [Radeon HD 6370M/7370M] (prog-if 00 [VGA controller])
   Subsystem: Acer Incorporated [ALI] Robson CE [Radeon HD 6370M/7370M]
   Flags: bus master, fast devsel, latency 0, IRQ 27
   Memory at a0000000 (64-bit, prefetchable) [size=256M]
   Memory at b4000000 (64-bit, non-prefetchable) [size=128K]
   I/O ports at 3000 [size=256]
   Expansion ROM at 000c0000 [disabled] [size=128K]
   Capabilities: [50] Power Management version 3
   Capabilities: [58] Express Legacy Endpoint, MSI 00
   Capabilities: [a0] MSI: Enable+ Count=1/1 Maskable- 64bit+
   Capabilities: [100] Vendor Specific Information: ID=0001 Rev=1 Len=010 <?>
   Kernel driver in use: radeon
   Kernel modules: radeon
Back to top
View user's profile Send private message
NeddySeagoon
Administrator
Administrator


Joined: 05 Jul 2003
Posts: 43184
Location: 56N 3W

PostPosted: Sat Dec 22, 2018 4:46 pm    Post subject: Reply with quote

zipdisquette,

Pastebin the entire Xorg.0.log please.
Code:
modeset(0)
looks wrong.

I suspect that something is waiting for firmware and timing out.
dmesg will tell more. Please pastebin dmesg too.
_________________
Regards,

NeddySeagoon

Computer users fall into two groups:-
those that do backups
those that have never had a hard drive fail.
Back to top
View user's profile Send private message
zipdisquette
n00b
n00b


Joined: 22 Dec 2018
Posts: 4

PostPosted: Sat Dec 22, 2018 5:25 pm    Post subject: Reply with quote

Xorg log: https://pastebin.com/y3bvr7ec
dmesg: https://pastebin.com/3XPcxK8H

It looks like the kernel modesetting is enabled, but when I switch between X and TTYs the screen flickers and hangs there for 5 seconds, but I can't tell if the problems are related.
I also tried to hardcode my graphic device in the Xorg config and forced it to use both the xorg radeon driver and the modesetting driver, but the result is the same.
Code:

Section "Device"
   Identifier  "card0"
   Driver      "radeon" # if I set it to "modesetting" everything works, but the delay is the same
EndSection
Back to top
View user's profile Send private message
zipdisquette
n00b
n00b


Joined: 22 Dec 2018
Posts: 4

PostPosted: Sat Dec 22, 2018 5:35 pm    Post subject: Reply with quote

This is another Xorg.0.log taken without the additional config, Xorg automatically picks the radeon module.
https://pastebin.com/gH6aPwcP
Back to top
View user's profile Send private message
NeddySeagoon
Administrator
Administrator


Joined: 05 Jul 2003
Posts: 43184
Location: 56N 3W

PostPosted: Sat Dec 22, 2018 7:04 pm    Post subject: Reply with quote

zipdisquette,

Other than that 4 sec delay, it all looks normal.
The radeondrmfb in dmesg looks normal.

In your normal user in the video group?

Are the permissions on /dev/dri/card0 correct?
ls /dev/dri/card0 -l
crw-rw---- 1 root video 226, 0 Feb 16 2014 /dev/dri/card0

I suspect all is well as the Xorg log says nothing about falling back to software rendering.
_________________
Regards,

NeddySeagoon

Computer users fall into two groups:-
those that do backups
those that have never had a hard drive fail.
Back to top
View user's profile Send private message
Marlo
Veteran
Veteran


Joined: 26 Jul 2003
Posts: 1414

PostPosted: Sat Dec 22, 2018 7:30 pm    Post subject: Reply with quote

I can see two time delays here:
Code:

[   11.583358] EXT4-fs (dm-4): mounted filesystem with ordered data mode. Opts: (null)
[   18.932149] udevd[3147]: starting version 3.2.5
[   19.591683] usb 2-1.2: USB disconnect, device number 4
[   19.960097] udevd[3149]: starting eudev-3.2.5
[   23.952593] [drm] radeon kernel modesetting enabled.


You can control this with "dmesg --notime --show-delta"
man dmesg:
Code:

-d, --show-delta
              Display the timestamp and the time delta spent between
              messages.  If used together with --notime then only the time
              delta without the timestamp is printed.

_________________
Thank you for your attention, interest and support.
------------------------------------------------------------------
http://radio.garden/
Back to top
View user's profile Send private message
zipdisquette
n00b
n00b


Joined: 22 Dec 2018
Posts: 4

PostPosted: Sun Dec 23, 2018 8:36 am    Post subject: Reply with quote

NeddySeagoon wrote:

In your normal user in the video group?
Are the permissions on /dev/dri/card0 correct?


Yes, permissions and ownership are ok, and my user is in the video group. The same behavior happens when I run X as root so permissions are not the problem.

Marlo wrote:

I can see two time delays here:
Code:

[   11.583358] EXT4-fs (dm-4): mounted filesystem with ordered data mode. Opts: (null)
[   18.932149] udevd[3147]: starting version 3.2.5
[   19.591683] usb 2-1.2: USB disconnect, device number 4
[   19.960097] udevd[3149]: starting eudev-3.2.5
[   23.952593] [drm] radeon kernel modesetting enabled.


I'm quite sure these delays are not related to my problem as they happen way before I'm able to login and start X.

Anyway, thanks you both for your help! I'll post here if I happen to find a solution.
Back to top
View user's profile Send private message
Display posts from previous:   
Reply to topic    Gentoo Forums Forum Index Kernel & Hardware All times are GMT
Page 1 of 1

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum