[3.5 regression] DRM: Massive (EDID-probing?) X startup delay on ATI Radeon RV770 (HD4870)

From: Nix
Date: Sat Aug 04 2012 - 12:25:17 EST

Possibly-relevant info:

- Two DVI monitors, identical specs, one dual-head graphics card
(so no VGA switcheroo or awesome-yet-terrifying PRIME madness needed)

- KMS, Xserver 1.12.3, driver 6.14.6-28 (trunk current as of today),
Mesa 8.0.4, libdrm 2.4.37

As of kernel 3.5 EDID probing of the older of my two monitors appears to
have subtly broken. The log shows that it appears to work -- KMS comes
up OK and I get a working console -- but then X stops during startup for
nearly a minute (with both monitors black) before coming back to life
again and EDID-probing the monitor a further six times for no obvious
reason. (Full log attached, and xorg.conf, for what little use it is.)

Something appears to be wrong, but I have no idea what. I've not changed
anything other than the kernel since my last non-huge-delayed startup
earlier this week, and both the monitors still work, including the one
suffering a huge startup delay.

At this point X is idle, no window manager or anything except for
XScreenSaver and a single xterm. No kernel log messages.

Here's a few representative log snippets from Xorg.0.0.log, with only
info regarding what appears to be the problematic monitor displayed:

[ 402.101] (II) [KMS] Kernel modesetting enabled.
[ 402.101] (II) RADEON(0): Creating default Display subsection in Screen section
"Default Screen Section" for depth/fbbpp 24/32
[ 402.101] (++) RADEON(0): Depth 24, (--) framebuffer bpp 32
[ 402.101] (II) RADEON(0): Pixel depth = 24 bits stored in 4 bytes (32 bpp pixmaps)
[ 402.101] (==) RADEON(0): Default visual is TrueColor
[ 402.101] (==) RADEON(0): RGB weight 888
[ 402.101] (II) RADEON(0): Using 8 bits per RGB (8 bit DAC)
[ 402.101] (--) RADEON(0): Chipset: "ATI Radeon 4800 Series" (ChipID = 0x9440)
[ 402.101] drmOpenDevice: node name is /dev/dri/card0
[ 402.101] drmOpenDevice: open result is 11, (OK)
[ 402.101] drmOpenByBusid: Searching for BusID pci:0000:02:00.0
[ 402.101] drmOpenDevice: node name is /dev/dri/card0
[ 402.101] drmOpenDevice: open result is 11, (OK)
[ 402.101] drmOpenByBusid: drmOpenMinor returns 11
[ 402.101] drmOpenByBusid: drmGetBusid reports pci:0000:02:00.0
[ 402.101] (II) Loading sub module "exa"
[ 402.101] (II) LoadModule: "exa"
[ 402.101] (II) Loading /usr/lib/xorg/modules/libexa.so
[ 402.138] (II) Module exa: vendor="X.Org Foundation"
[ 402.138] compiled for 1.12.3, module version = 2.5.0
[ 402.138] ABI class: X.Org Video Driver, version 12.0
[ 402.138] (II) RADEON(0): KMS Color Tiling: enabled
[ 402.138] (II) RADEON(0): KMS Pageflipping: enabled
[ 402.138] (II) RADEON(0): SwapBuffers wait for vsync: enabled
[ 402.197] (II) RADEON(0): Output DVI-0 has no monitor section
[ 402.209] (II) RADEON(0): Output DIN has no monitor section
[ 402.240] (II) RADEON(0): Output DVI-1 has no monitor section
[...]
[ 402.343] (II) RADEON(0): EDID for output DVI-1
[ 402.343] (II) RADEON(0): Manufacturer: SAM Model: 30d Serial#: 1296380466
[ 402.343] (II) RADEON(0): Year: 2008 Week: 8
[ 402.343] (II) RADEON(0): EDID Version: 1.3
[ 402.343] (II) RADEON(0): Digital Display Input
[ 402.343] (II) RADEON(0): Max Image Size [cm]: horiz.: 47 vert.: 30
[ 402.343] (II) RADEON(0): Gamma: 2.20
[ 402.343] (II) RADEON(0): DPMS capabilities: Off
[ 402.343] (II) RADEON(0): Supported color encodings: RGB 4:4:4 YCrCb 4:4:4
[ 402.343] (II) RADEON(0): First detailed timing is preferred mode
[ 402.343] (II) RADEON(0): redX: 0.644 redY: 0.333 greenX: 0.286 greenY: 0.603
[ 402.343] (II) RADEON(0): blueX: 0.152 blueY: 0.079 whiteX: 0.313 whiteY: 0.329
[ 402.343] (II) RADEON(0): Supported established timings:
[ 402.343] (II) RADEON(0): 720x400@70Hz
[ 402.343] (II) RADEON(0): 640x480@60Hz
[ 402.343] (II) RADEON(0): 640x480@67Hz
[ 402.343] (II) RADEON(0): 640x480@72Hz
[ 402.343] (II) RADEON(0): 640x480@75Hz
[ 402.343] (II) RADEON(0): 800x600@56Hz
[ 402.343] (II) RADEON(0): 800x600@60Hz
[ 402.343] (II) RADEON(0): 800x600@72Hz
[ 402.343] (II) RADEON(0): 800x600@75Hz
[ 402.343] (II) RADEON(0): 832x624@75Hz
[ 402.343] (II) RADEON(0): 1024x768@60Hz
[ 402.343] (II) RADEON(0): 1024x768@70Hz
[ 402.343] (II) RADEON(0): 1024x768@75Hz
[ 402.343] (II) RADEON(0): 1280x1024@75Hz
[ 402.343] (II) RADEON(0): 1152x864@75Hz
[ 402.343] (II) RADEON(0): Manufacturer's mask: 0
[ 402.343] (II) RADEON(0): Supported standard timings:
[ 402.343] (II) RADEON(0): #0: hsize: 1680 vsize 1050 refresh: 60 vid: 179
[ 402.343] (II) RADEON(0): #1: hsize: 1280 vsize 1024 refresh: 60 vid: 32897
[ 402.343] (II) RADEON(0): #2: hsize: 1280 vsize 960 refresh: 60 vid: 16513
[ 402.343] (II) RADEON(0): #3: hsize: 1152 vsize 864 refresh: 75 vid: 20337
[ 402.343] (II) RADEON(0): Supported detailed timing:
[ 402.343] (II) RADEON(0): clock: 119.0 MHz Image Size: 474 x 296 mm
[ 402.343] (II) RADEON(0): h_active: 1680 h_sync: 1728 h_sync_end 1760 h_blank_end 1840 h_border: 0
[ 402.343] (II) RADEON(0): v_active: 1050 v_sync: 1053 v_sync_end 1059 v_blanking: 1080 v_border: 0
[ 402.343] (II) RADEON(0): Ranges: V min: 56 V max: 75 Hz, H min: 30 H max: 81 kHz, PixClock max 145 MHz
[ 402.343] (II) RADEON(0): Monitor name: SyncMaster
[ 402.343] (II) RADEON(0): Serial No: HS3Q214739
[ 402.343] (II) RADEON(0): EDID (in hex):
[ 402.343] (II) RADEON(0): 00ffffffffffff004c2d0d033232454d
[ 402.343] (II) RADEON(0): 08120103802f1e782ad515a455499a27
[ 402.343] (II) RADEON(0): 145054bfef80b30081808140714f0101
[ 402.343] (II) RADEON(0): 0101010101017c2e90a0601a1e403020
[ 402.343] (II) RADEON(0): 3600da281100001a000000fd00384b1e
[ 402.343] (II) RADEON(0): 510e000a202020202020000000fc0053
[ 402.343] (II) RADEON(0): 796e634d61737465720a2020000000ff
[ 402.343] (II) RADEON(0): 00485333513231343733390a202000cd
[ 402.343] (II) RADEON(0): Printing probed modes for output DVI-1
[ 402.343] (II) RADEON(0): Modeline "1680x1050"x59.9 119.00 1680 1728 1760 1840 1050 1053 1059 1080 +hsync -vsync (64.7 kHz eP)
[ 402.343] (II) RADEON(0): Modeline "1680x945"x60.0 131.48 1680 1784 1960 2240 945 946 949 978 -hsync +vsync (58.7 kHz)
[ 402.343] (II) RADEON(0): Modeline "1400x1050"x59.9 101.00 1400 1448 1480 1560 1050 1053 1057 1080 +hsync -vsync (64.7 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1600x900"x60.0 118.96 1600 1696 1864 2128 900 901 904 932 -hsync +vsync (55.9 kHz)
[ 402.343] (II) RADEON(0): Modeline "1280x1024"x75.0 135.00 1280 1296 1440 1688 1024 1025 1028 1066 +hsync +vsync (80.0 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1280x1024"x60.0 108.00 1280 1328 1440 1688 1024 1025 1028 1066 +hsync +vsync (64.0 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1440x900"x75.0 136.75 1440 1536 1688 1936 900 903 909 942 -hsync +vsync (70.6 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1440x900"x59.9 88.75 1440 1488 1520 1600 900 903 909 926 +hsync -vsync (55.5 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1280x960"x60.0 108.00 1280 1376 1488 1800 960 961 964 1000 +hsync +vsync (60.0 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1366x768"x60.0 85.89 1366 1439 1583 1800 768 769 772 795 -hsync +vsync (47.7 kHz)
[ 402.343] (II) RADEON(0): Modeline "1360x768"x60.0 85.50 1360 1424 1536 1792 768 771 777 795 +hsync +vsync (47.7 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1280x800"x74.9 106.50 1280 1360 1488 1696 800 803 809 838 -hsync +vsync (62.8 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1280x800"x59.9 71.00 1280 1328 1360 1440 800 803 809 823 +hsync -vsync (49.3 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1152x864"x75.0 108.00 1152 1216 1344 1600 864 865 868 900 +hsync +vsync (67.5 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1280x768"x74.9 102.25 1280 1360 1488 1696 768 771 778 805 +hsync -vsync (60.3 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1280x768"x60.0 68.25 1280 1328 1360 1440 768 771 778 790 +hsync -vsync (47.4 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1024x768"x75.1 78.80 1024 1040 1136 1312 768 769 772 800 +hsync +vsync (60.1 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1024x768"x70.1 75.00 1024 1048 1184 1328 768 771 777 806 -hsync -vsync (56.5 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1024x768"x60.0 65.00 1024 1048 1184 1344 768 771 777 806 -hsync -vsync (48.4 kHz e)
[ 402.343] (II) RADEON(0): Modeline "1024x576"x60.0 46.97 1024 1064 1168 1312 576 577 580 597 -hsync +vsync (35.8 kHz)
[ 402.343] (II) RADEON(0): Modeline "832x624"x74.6 57.28 832 864 928 1152 624 625 628 667 -hsync -vsync (49.7 kHz e)
[ 402.343] (II) RADEON(0): Modeline "800x600"x72.2 50.00 800 856 976 1040 600 637 643 666 +hsync +vsync (48.1 kHz e)
[ 402.343] (II) RADEON(0): Modeline "800x600"x75.0 49.50 800 816 896 1056 600 601 604 625 +hsync +vsync (46.9 kHz e)
[ 402.343] (II) RADEON(0): Modeline "800x600"x60.3 40.00 800 840 968 1056 600 601 605 628 +hsync +vsync (37.9 kHz e)
[ 402.343] (II) RADEON(0): Modeline "800x600"x56.2 36.00 800 824 896 1024 600 601 603 625 +hsync +vsync (35.2 kHz e)
[ 402.343] (II) RADEON(0): Modeline "848x480"x60.0 33.75 848 864 976 1088 480 486 494 517 +hsync +vsync (31.0 kHz e)
[ 402.343] (II) RADEON(0): Modeline "640x480"x72.8 31.50 640 664 704 832 480 489 491 520 -hsync -vsync (37.9 kHz e)
[ 402.343] (II) RADEON(0): Modeline "640x480"x75.0 31.50 640 656 720 840 480 481 484 500 -hsync -vsync (37.5 kHz e)
[ 402.343] (II) RADEON(0): Modeline "640x480"x66.7 30.24 640 704 768 864 480 483 486 525 -hsync -vsync (35.0 kHz e)
[ 402.343] (II) RADEON(0): Modeline "640x480"x60.0 25.20 640 656 752 800 480 490 492 525 -hsync -vsync (31.5 kHz e)
[ 402.343] (II) RADEON(0): Modeline "720x400"x70.1 28.32 720 738 846 900 400 412 414 449 -hsync +vsync (31.5 kHz e)
[ 402.343] (II) RADEON(0): Output DVI-0 connected
[ 402.343] (II) RADEON(0): Output DIN disconnected
[ 402.343] (II) RADEON(0): Output DVI-1 connected
[ 402.343] (II) RADEON(0): Using exact sizes for initial modes
[ 402.344] (II) RADEON(0): Output DVI-0 using initial mode 1680x1050
[ 402.344] (II) RADEON(0): Output DVI-1 using initial mode 1680x1050
[ 402.344] (II) RADEON(0): Using default gamma of (1.0, 1.0, 1.0) unless otherwise stated.
[ 402.344] (II) RADEON(0): mem size init: gart size :1fdff000 vram size: s:20000000 visible:f8ca000
[ 402.344] (II) RADEON(0): EXA: Driver will allow EXA pixmaps in VRAM
[ 402.344] (**) RADEON(0): Display dimensions: (480, 300) mm
[ 402.344] (**) RADEON(0): DPI set to (88, 88)
[...]
[ 406.441] (EE) evdev: PS/2 Generic Mouse: ioctl EVIOCGID failed: Inappropriate ioctl for device
[ 406.456] (EE) PreInit returned 8 for "PS/2 Generic Mouse"
[ 406.456] (II) UnloadModule: "evdev"
[... dead silence except for client-connection auditing for some time:
black screen, then, abruptly, my older monitor gets EDID-probed again]
[ 474.155] (II) RADEON(0): EDID vendor "SAM", prod id 781
[ 474.155] (II) RADEON(0): Using hsync ranges from config file
[ 474.155] (II) RADEON(0): Using vrefresh ranges from config file
[ 474.155] (II) RADEON(0): Printing DDC gathered Modelines:
[ 474.155] (II) RADEON(0): Modeline "1680x1050"x0.0 119.00 1680 1728 1760 1840 1050 1053 1059 1080 +hsync -vsync (64.7 kHz eP)
[ 474.155] (II) RADEON(0): Modeline "800x600"x0.0 40.00 800 840 968 1056 600 601 605 628 +hsync +vsync (37.9 kHz e)
[ 474.155] (II) RADEON(0): Modeline "800x600"x0.0 36.00 800 824 896 1024 600 601 603 625 +hsync +vsync (35.2 kHz e)
[ 474.155] (II) RADEON(0): Modeline "640x480"x0.0 31.50 640 656 720 840 480 481 484 500 -hsync -vsync (37.5 kHz e)
[ 474.155] (II) RADEON(0): Modeline "640x480"x0.0 31.50 640 664 704 832 480 489 492 520 -hsync -vsync (37.9 kHz e)
[ 474.155] (II) RADEON(0): Modeline "640x480"x0.0 30.24 640 704 768 864 480 483 486 525 -hsync -vsync (35.0 kHz e)
[ 474.155] (II) RADEON(0): Modeline "640x480"x0.0 25.18 640 656 752 800 480 490 492 525 -hsync -vsync (31.5 kHz e)
[ 474.155] (II) RADEON(0): Modeline "720x400"x0.0 28.32 720 738 846 900 400 412 414 449 -hsync +vsync (31.5 kHz e)
[ 474.155] (II) RADEON(0): Modeline "1280x1024"x0.0 135.00 1280 1296 1440 1688 1024 1025 1028 1066 +hsync +vsync (80.0 kHz e)
[ 474.155] (II) RADEON(0): Modeline "1024x768"x0.0 78.75 1024 1040 1136 1312 768 769 772 800 +hsync +vsync (60.0 kHz e)
[ 474.155] (II) RADEON(0): Modeline "1024x768"x0.0 75.00 1024 1048 1184 1328 768 771 777 806 -hsync -vsync (56.5 kHz e)
[ 474.155] (II) RADEON(0): Modeline "1024x768"x0.0 65.00 1024 1048 1184 1344 768 771 777 806 -hsync -vsync (48.4 kHz e)
[ 474.155] (II) RADEON(0): Modeline "832x624"x0.0 57.28 832 864 928 1152 624 625 628 667 -hsync -vsync (49.7 kHz e)
[ 474.155] (II) RADEON(0): Modeline "800x600"x0.0 49.50 800 816 896 1056 600 601 604 625 +hsync +vsync (46.9 kHz e)
[ 474.155] (II) RADEON(0): Modeline "800x600"x0.0 50.00 800 856 976 1040 600 637 643 666 +hsync +vsync (48.1 kHz e)
[ 474.155] (II) RADEON(0): Modeline "1152x864"x0.0 108.00 1152 1216 1344 1600 864 865 868 900 +hsync +vsync (67.5 kHz e)
[ 474.155] (II) RADEON(0): Modeline "1280x1024"x0.0 108.00 1280 1328 1440 1688 1024 1025 1028 1066 +hsync +vsync (64.0 kHz e)
[ 474.155] (II) RADEON(0): Modeline "1280x960"x0.0 108.00 1280 1376 1488 1800 960 961 964 1000 +hsync +vsync (60.0 kHz e)

[... repeated twice, then ...]

[ 474.371] (II) RADEON(0): Allocate new frame buffer 3360x1056 stride 3360
[ 474.371] (II) RADEON(0): VRAM usage limit set to 216810K

[and then another *five* repetitions of the same EDID-and-modeline info
from a probe of the old monitor]

Something is clearly wrong, but I have no idea what it might be.

Attachment: Xorg.0.0.log.gz
Description: Xorg.0.0.log.gz

Section "ServerLayout"
Identifier "Workstation"
# Screen 0 "Primary Screen" 0 0
# InputClass "Mouse" "CorePointer"
# InputClass "Keyboard" "CoreKeyboard"
EndSection

Section "Files"
FontPath "/usr/local/share/fonts"
FontPath "/usr/share/fonts"
FontPath "/usr/lib/X11/fonts"
FontPath "/usr/share/fonts/override"
FontPath "/usr/lib/X11/fonts/100dpi"
FontPath "/usr/lib/X11/fonts/75dpi"
FontPath "/usr/lib/X11/fonts/freefont"
FontPath "/usr/lib/X11/fonts/jmk"
FontPath "/usr/lib/X11/fonts/local"
FontPath "/usr/lib/X11/fonts/mathematica"
FontPath "/usr/lib/X11/fonts/misc"
FontPath "/usr/lib/X11/fonts/mozilla"
FontPath "/usr/lib/X11/fonts/SillyNamesForAdobeFonts"
FontPath "/usr/lib/X11/fonts/TeX"
FontPath "/usr/lib/X11/fonts/TTF"
FontPath "/usr/lib/X11/fonts/Type1"
FontPath "/usr/lib/X11/fonts/cyrillic"
FontPath "/usr/lib/X11/fonts/OTF"
FontPath "/usr/lib/X11/fonts/STIX"
FontPath "/usr/share/ghostscript/fonts"
EndSection

Section "ServerFlags"
Option "DontZap" "true"
EndSection

Section "Module"
Load "GLcore"
Load "bitmap"
EndSection

Section "InputClass"
Identifier "Keyboard"
MatchIsKeyboard "true"
Driver "evdev"
Option "XkbRules" "evdev"
Option "XkbModel" "pc105"
Option "XkbLayout" "gb"
# Option "XkbVariant" "intl-unicode"
Option "XkbOptions" "altwin:left_meta_win,altwin:super_rwin,altwin:hyper_prtsc,keypad:pointerkeys,grab:break_actions,lv3:enter_switch,compose:paus"
# Option "XkbGeometry" "maltron"
Option "Floating" "false"
EndSection

Section "InputClass"
Identifier "Mouse"
MatchIsPointer "true"
Driver "evdev"
Option "Floating" "false"
EndSection

Section "Device"
Identifier "Radeon HD 4850"
Driver "radeon"
VendorName "ATI"
BoardName "RV770"
EndSection

Section "DRI"
Mode 0666
EndSection