Bug 99457

(In reply to Eugenij Shkrigunov from comment #0)
> Packages versions before updating:
> xorg-server-1.17.4
> xf86-video-ati-7.5.0

Can you attach a Xorg log from that combo?


> Packages versions after updating:
> xorg-server-1.18.4
> xf86-video-ati-7.7.0

Can you try if the problem also occurs with xf86-video-ati-7.7.0 and xorg-server-1.17.4? If yes, can you bisect which change between xf86-video-ati-7.5.0 and xf86-video-ati-7.7.0 introduced the problem?

Otherwise, can you try if the problem also occurs with the modesetting driver instead of radeon?


P.S. Please attach files individually instead of packed into an archive.

Created attachment 129043 [details]
Xorg.log: xorg-server-1.17.4 + xf86-video-ati-7.5.0 + DVI

Created attachment 129044 [details]
Xorg.log: xorg-server-1.17.4 + xf86-video-ati-7.5.0 + VGA

> Can you try if the problem also occurs with xf86-video-ati-7.7.0 and
> xorg-server-1.17.4? If yes, can you bisect which change between
> xf86-video-ati-7.5.0 and xf86-video-ati-7.7.0 introduced the problem?
Unfortunately it is not so easy to do.
Distribution - Gentoo: versions of xorg-server and xf86-video-ati tied together.
For xorg-server-1.18.4 version <xf86-video-ati-7.6.1 is unsuitable.
For bisect: I do not have a computer for such long-term experiments.

> Otherwise, can you try if the problem also occurs with the modesetting
> driver instead of radeon?
I will try.

The older combo failed to initialize glamor, so it was using shadowfb software rendering. You can try either

 Option "ShadowPrimary"

or

 Option "Accel" "off"

in /etc/X11/xorg.conf Section "Device" to see if one of them works better. The former also uses software rendering for 2D but allows 3D and video hardware acceleration.

It would be interesting to see a CPU profile from when the problem occurs, taken with something like sysprof or perf.

>  Option "Accel" "off"
The problem remains. (xorg-server-1.18.4 + xf86-video-ati-7.7.0)

> It would be interesting to see a CPU profile from when the problem occurs,
> taken with something like sysprof or perf.
I have no experience with these tools.

I have not been able to compile xf86-video-ati-7.5.0 for xorg-server-1.18.4:
/var/tmp/portage/x11-drivers/xf86-video-ati-7.5.0/work/xf86-video-ati-7.5.0/src/radeon_kms.c: In function 'redisplay_dirty':
/var/tmp/portage/x11-drivers/xf86-video-ati-7.5.0/work/xf86-video-ati-7.5.0/src/radeon_kms.c:272:2: error: too many arguments to function 'PixmapSyncDirtyHelper'
  PixmapSyncDirtyHelper(dirty, &pixregion);
  ^
In file included from /usr/include/xorg/gc.h:54:0,
                 from /usr/include/xorg/dix.h:51,
                 from /usr/include/xorg/privates.h:151,
                 from /usr/include/xorg/cursor.h:53,
                 from /usr/include/xorg/scrnintstr.h:53,
                 from /usr/include/xorg/xf86str.h:39,
                 from /var/tmp/portage/x11-drivers/xf86-video-ati-7.5.0/work/xf86-video-ati-7.5.0/src/radeon.h:46,
                 from /var/tmp/portage/x11-drivers/xf86-video-ati-7.5.0/work/xf86-video-ati-7.5.0/src/radeon_kms.c:34:
/usr/include/xorg/pixmap.h:131:1: note: declared here
 PixmapSyncDirtyHelper(PixmapDirtyUpdatePtr dirty);

Ebuild xorg-server-1.18.4 explicitly prohibits the installation of xf86-video-modesetting.

Created attachment 129045 [details]
xorg.strace: Xorg-server tracing during problems - a few seconds of the KDM login screen.

Driver modesetting appeared embedded in xorg-server. With nodesetting everything works without problems.

(In reply to Eugenij Shkrigunov from comment #6)
> >  Option "Accel" "off"
> The problem remains. (xorg-server-1.18.4 + xf86-video-ati-7.7.0)

How about Option "ShadowPrimary"? If neither helps, please attach the corresponding Xorg log file.


> > It would be interesting to see a CPU profile from when the problem occurs,
> > taken with something like sysprof or perf.
> I have no experience with these tools.

sysprof is very easy to use.


> I have not been able to compile xf86-video-ati-7.5.0 for xorg-server-1.18.4:

Yes, older driver versions generally can't compile against newer xserver versions (at least not until the time machine is invented ;). Newer driver versions still work with older xserver versions though, which is why I suggested trying xf86-video-ati-7.7.0 and xorg-server-1.17.4.

> How about Option "ShadowPrimary"? If neither helps, please attach the
> corresponding Xorg log file.
No ShadowPrimary no Accel did not help.

> sysprof is very easy to use.
strace output does not help?

> Yes, older driver versions generally can't compile against newer xserver
> versions (at least not until the time machine is invented ;). Newer driver
> versions still work with older xserver versions though, which is why I
> suggested trying xf86-video-ati-7.7.0 and xorg-server-1.17.4.
Now all computers are busy and I can not compile there older versions of xorg-server: it is rebuilding a large number of packages.

Created attachment 129058 [details]
Xorg.log: xorg-server-1.18.4 + xf86-video-ati-7.7.0 + ShadowPrimary_On

Created attachment 129059 [details]
xorg.strace: xorg-server-1.18.4 + xf86-video-ati-7.7.0 + ShadowPrimary_On

Created attachment 129060 [details]
Xorg.log: xorg-server-1.18.4 + xf86-video-ati-7.7.0 + Accel_No

Created attachment 129061 [details]
xorg.strace: xorg-server-1.18.4 + xf86-video-ati-7.7.0 + Accel_No

(In reply to Eugenij Shkrigunov from comment #11)
> strace output does not help?

Not really, I'm afraid.

Could you try to replicate the problem on your computer?

(In reply to Eugenij Shkrigunov from comment #17)
> Could you try to replicate the problem on your computer?

I've never seen anything like what you're describing, and I don't know how I could trigger it. I'm not sure how to make progress without a CPU profile from your system.

I compiled with debugging xorg-server-1.18.4, xf86-video-ati-7.7.0, mesa-12.0.1, tigervnc-1.7.1 and run oprofile.

Here are the data for the 5 minutes of inactivity of the KDM login screen:

opreport --long-filenames /usr/bin/Xorg

   909697 100.000 /usr/bin/Xorg
        CPU_CLK_UNHALT...|
          samples|      %|
        ------------------
           905321 99.5190 /proc/kallsyms
             1379  0.1516 /usr/lib64/mesa/radeonsi_dri.so
              904  0.0994 /usr/lib64/xorg/modules/extensions/libvnc.so
              654  0.0719 /usr/bin/Xorg
              476  0.0523 /lib64/libc-2.23.so
              249  0.0274 /usr/lib64/xorg/modules/drivers/radeon_drv.so
              176  0.0193 /lib64/libpthread-2.23.so
              122  0.0134 /usr/lib64/xorg/modules/libglamoregl.so
              107  0.0118 /usr/lib64/libpixman-1.so.0.34.0
               78  0.0086 /usr/lib64/libdrm.so.2.4.0
               53  0.0058 /usr/lib64/libdrm_radeon.so.1.0.1
               51  0.0056 [vdso] (tgid:5004 range:0x7ffd70577000-0x7ffd70578fff)
               25  0.0027 /lib64/libm-2.23.so
               25  0.0027 /usr/lib64/gcc/x86_64-pc-linux-gnu/4.9.4/libstdc++.so.6.0.20
               24  0.0026 /usr/lib64/libGL.so.1.2.0
               21  0.0023 /usr/lib64/xorg/modules/input/evdev_drv.so
               13  0.0014 /usr/lib64/xorg/modules/libfb.so
               11  0.0012 /lib64/libudev.so.1.6.4
                7 7.7e-04 /usr/lib64/libglapi.so.0.0.0
                1 1.1e-04 /lib64/ld-2.23.so


opreport --long-filenames --symbols /proc/kallsyms

samples  %        image name               symbol name
747823   82.6031  /proc/kallsyms           delay_tsc
85053     9.3948  /proc/kallsyms           cail_reg_read
21208     2.3426  /proc/kallsyms           atom_get_src_int
9510      1.0505  /proc/kallsyms           atom_put_dst
8068      0.8912  /proc/kallsyms           atom_execute_table_locked
5636      0.6225  /proc/kallsyms           atom_op_move
3921      0.4331  /proc/kallsyms           atom_op_jump
3008      0.3323  /proc/kallsyms           atom_op_compare
2492      0.2753  /proc/kallsyms           atom_op_clear
1824      0.2015  /proc/kallsyms           atom_op_calltable
1260      0.1392  /proc/kallsyms           atom_op_add
1109      0.1225  /proc/kallsyms           atom_op_sub
1080      0.1193  /proc/kallsyms           atom_op_test
891       0.0984  /proc/kallsyms           atom_op_setport
676       0.0747  /proc/kallsyms           atom_op_or
675       0.0746  /proc/kallsyms           atom_op_shift_left
670       0.0740  /proc/kallsyms           atom_op_setfbbase
543       0.0600  /proc/kallsyms           atom_op_and
525       0.0580  /proc/kallsyms           atom_op_mask
426       0.0471  /proc/kallsyms           atom_op_delay
354       0.0391  /proc/kallsyms           __udelay
344       0.0380  /proc/kallsyms           apic_timer_interrupt
334       0.0369  /proc/kallsyms           atom_get_src_direct
311       0.0344  /proc/kallsyms           read_tsc
244       0.0270  /proc/kallsyms           _raw_spin_lock
224       0.0247  /proc/kallsyms           atom_op_setdatablock
177       0.0196  /proc/kallsyms           __ww_mutex_lock
173       0.0191  /proc/kallsyms           cail_reg_write
163       0.0180  /proc/kallsyms           _raw_spin_lock_irqsave
163       0.0180  /proc/kallsyms           update_blocked_averages
159       0.0176  /proc/kallsyms           ww_mutex_unlock
155       0.0171  /proc/kallsyms           task_tick_fair
148       0.0163  /proc/kallsyms           radeon_crtc_load_lut
106       0.0117  /proc/kallsyms           radeon_get_external_encoder


opreport --long-filenames --symbols /usr/lib64/mesa/radeonsi_dri.so

samples  %        image name               symbol name
81        5.8781  /usr/lib64/mesa/radeonsi_dri.so radeon_cs_context_cleanup
73        5.2975  /usr/lib64/mesa/radeonsi_dri.so radeon_drm_cs_add_buffer
40        2.9028  /usr/lib64/mesa/radeonsi_dri.so si_buffer_resources_begin_new_cs
39        2.8302  /usr/lib64/mesa/radeonsi_dri.so radeon_drm_cs_emit_ioctl_oneshot
33        2.3948  /usr/lib64/mesa/radeonsi_dri.so si_draw_vbo
32        2.3222  /usr/lib64/mesa/radeonsi_dri.so surf_drm_to_winsys
31        2.2496  /usr/lib64/mesa/radeonsi_dri.so surf_winsys_to_drm
30        2.1771  /usr/lib64/mesa/radeonsi_dri.so _mesa_Flush
27        1.9594  /usr/lib64/mesa/radeonsi_dri.so radeon_drm_cs_emit_ioctl
26        1.8868  /usr/lib64/mesa/radeonsi_dri.so si_blitter_begin
25        1.8142  /usr/lib64/mesa/radeonsi_dri.so radeon_drm_cs_flush
24        1.7417  /usr/lib64/mesa/radeonsi_dri.so si_all_descriptors_begin_new_cs
23        1.6691  /usr/lib64/mesa/radeonsi_dri.so si_upload_descriptors
22        1.5965  /usr/lib64/mesa/radeonsi_dri.so _mesa_BindTexture
22        1.5965  /usr/lib64/mesa/radeonsi_dri.so si_shader_select
21        1.5239  /usr/lib64/mesa/radeonsi_dri.so radeon_lookup_buffer
19        1.3788  /usr/lib64/mesa/radeonsi_dri.so r600_flush_from_st
19        1.3788  /usr/lib64/mesa/radeonsi_dri.so st_glFlush
17        1.2337  /usr/lib64/mesa/radeonsi_dri.so _mesa_error_check_format_and_type
17        1.2337  /usr/lib64/mesa/radeonsi_dri.so r600_texture_create_object
17        1.2337  /usr/lib64/mesa/radeonsi_dri.so si_make_texture_descriptor
17        1.2337  /usr/lib64/mesa/radeonsi_dri.so si_update_shaders
16        1.1611  /usr/lib64/mesa/radeonsi_dri.so u_upload_alloc
16        1.1611  /usr/lib64/mesa/radeonsi_dri.so util_copy_framebuffer_state
15        1.0885  /usr/lib64/mesa/radeonsi_dri.so _mesa_TexSubImage2D
15        1.0885  /usr/lib64/mesa/radeonsi_dri.so si_set_framebuffer_state
14        1.0160  /usr/lib64/mesa/radeonsi_dri.so _mesa_get_current_tex_object
14        1.0160  /usr/lib64/mesa/radeonsi_dri.so radeon_drm_cs_sync_flush
14        1.0160  /usr/lib64/mesa/radeonsi_dri.so si_emit_framebuffer_state


opreport --long-filenames --symbols /usr/lib64/xorg/modules/extensions/libvnc.so

samples  %        image name               symbol name
43        4.8206  /usr/lib64/xorg/modules/extensions/libvnc.so vncWriteBlockHandler
32        3.5874  /usr/lib64/xorg/modules/extensions/libvnc.so vncGetScreenCount
31        3.4753  /usr/lib64/xorg/modules/extensions/libvnc.so vncCallWriteBlockHandlers
27        3.0269  /usr/lib64/xorg/modules/extensions/libvnc.so rfb::Timer::checkTimeouts()
25        2.8027  /usr/lib64/xorg/modules/extensions/libvnc.so rfb::IntParameter::operator int() const
24        2.6906  /usr/lib64/xorg/modules/extensions/libvnc.so std::_List_base<network::Socket*, std::allocator<network::Socket*> >::_List_
21        2.3543  /usr/lib64/xorg/modules/extensions/libvnc.so XserverDesktop::writeBlockHandler(fd_set*, timeval**)
20        2.2422  /usr/lib64/xorg/modules/extensions/libvnc.so XserverDesktop::readWakeupHandler(fd_set*, int)
20        2.2422  /usr/lib64/xorg/modules/extensions/libvnc.so std::_List_base<network::Socket*, std::allocator<network::Socket*> >::_List_
20        2.2422  /usr/lib64/xorg/modules/extensions/libvnc.so std::list<network::Socket*, std::allocator<network::Socket*> >::list()
20        2.2422  /usr/lib64/xorg/modules/extensions/libvnc.so std::list<network::TcpListener*, std::allocator<network::TcpListener*> >::en
20        2.2422  /usr/lib64/xorg/modules/extensions/libvnc.so std::list<rfb::Timer*, std::allocator<rfb::Timer*> >::empty() const
19        2.1300  /usr/lib64/xorg/modules/extensions/libvnc.so vncXUnionRegion
18        2.0179  /usr/lib64/xorg/modules/extensions/libvnc.so network::SocketListener::getFd()
18        2.0179  /usr/lib64/xorg/modules/extensions/libvnc.so rfb::VNCServerST::add_changed(rfb::Region const&)
17        1.9058  /usr/lib64/xorg/modules/extensions/libvnc.so std::list<network::TcpListener*, std::allocator<network::TcpListener*> >::be
16        1.7937  /usr/lib64/xorg/modules/extensions/libvnc.so std::allocator<std::_List_node<network::Socket*> >::allocator()
15        1.6816  /usr/lib64/xorg/modules/extensions/libvnc.so std::_List_iterator<network::TcpListener*>::operator!=(std::_List_iterator<n
15        1.6816  /usr/lib64/xorg/modules/extensions/libvnc.so vncHooksBlockHandler
14        1.5695  /usr/lib64/xorg/modules/extensions/libvnc.so std::_List_iterator<rfb::Timer*>::_List_iterator(std::__detail::_List_node_b
13        1.4574  /usr/lib64/xorg/modules/extensions/libvnc.so std::_List_base<rfb::Timer*, std::allocator<rfb::Timer*> >::_M_get_Tp_alloca
13        1.4574  /usr/lib64/xorg/modules/extensions/libvnc.so std::_List_iterator<network::Socket*>::_List_iterator()
13        1.4574  /usr/lib64/xorg/modules/extensions/libvnc.so std::list<network::Socket*, std::allocator<network::Socket*> >::clear()
13        1.4574  /usr/lib64/xorg/modules/extensions/libvnc.so vncCallReadWakeupHandlers
12        1.3453  /usr/lib64/xorg/modules/extensions/libvnc.so XserverDesktop::readBlockHandler(fd_set*, timeval**)
12        1.3453  /usr/lib64/xorg/modules/extensions/libvnc.so std::list<rfb::VNCSConnectionST*, std::allocator<rfb::VNCSConnectionST*> >::
12        1.3453  /usr/lib64/xorg/modules/extensions/libvnc.so vncAddChanged
11        1.2332  /usr/lib64/xorg/modules/extensions/libvnc.so __gnu_cxx::new_allocator<std::_List_node<network::Socket*> >::new_allocator(
11        1.2332  /usr/lib64/xorg/modules/extensions/libvnc.so rfb::VNCServerST::checkTimeouts()
11        1.2332  /usr/lib64/xorg/modules/extensions/libvnc.so std::list<rfb::Timer*, std::allocator<rfb::Timer*> >::begin()
10        1.1211  /usr/lib64/xorg/modules/extensions/libvnc.so rfb::Timer** std::__addressof<rfb::Timer*>(rfb::Timer*&)
10        1.1211  /usr/lib64/xorg/modules/extensions/libvnc.so rfb::Timer::insertTimer(rfb::Timer*)
10        1.1211  /usr/lib64/xorg/modules/extensions/libvnc.so rfb::Timer::start(int)
10        1.1211  /usr/lib64/xorg/modules/extensions/libvnc.so rfb::VNCServerST::getSockets(std::list<network::Socket*, std::allocator<netw
10        1.1211  /usr/lib64/xorg/modules/extensions/libvnc.so std::_List_iterator<rfb::VNCSConnectionST*>::_List_iterator()
10        1.1211  /usr/lib64/xorg/modules/extensions/libvnc.so std::list<network::Socket*, std::allocator<network::Socket*> >::begin()


opreport --long-filenames --symbols /usr/lib64/xorg/modules/drivers/radeon_drv.so

samples  %        image name               symbol name
73       29.4355  /usr/lib64/xorg/modules/drivers/radeon_drv.so drmmode_set_desired_modes
59       23.7903  /usr/lib64/xorg/modules/drivers/radeon_drv.so drmmode_set_mode_major
33       13.3065  /usr/lib64/xorg/modules/drivers/radeon_drv.so RADEONBlockHandler_KMS
20        8.0645  /usr/lib64/xorg/modules/drivers/radeon_drv.so drmmode_do_crtc_dpms
13        5.2419  /usr/lib64/xorg/modules/drivers/radeon_drv.so drmmode_crtc_gamma_set
12        4.8387  /usr/lib64/xorg/modules/drivers/radeon_drv.so radeon_flush_callback
9         3.6290  /usr/lib64/xorg/modules/drivers/radeon_drv.so drm_wakeup_handler
9         3.6290  /usr/lib64/xorg/modules/drivers/radeon_drv.so radeon_cs_flush_indirect
8         3.2258  /usr/lib64/xorg/modules/drivers/radeon_drv.so RADEONBlockHandler_oneshot
5         2.0161  /usr/lib64/xorg/modules/drivers/radeon_drv.so drmmode_can_use_hw_cursor
5         2.0161  /usr/lib64/xorg/modules/drivers/radeon_drv.so drmmode_output_dpms
2         0.8065  /usr/lib64/xorg/modules/drivers/radeon_drv.so drmmode_handle_transform

(In reply to Eugenij Shkrigunov from comment #19)
> I compiled with debugging xorg-server-1.18.4, xf86-video-ati-7.7.0,
> mesa-12.0.1, tigervnc-1.7.1 and run oprofile.

Thanks. Any particular reason for not using sysprof? It would allow saving the full profile data and attaching it here, so myself and others could analyze it any way we want.


> Here are the data for the 5 minutes of inactivity of the KDM login screen:

Does the problem occur at the KDM login screen? The profile data looks like there was almost no CPU activity at all. The profile needs to be taken while the problem is occurring, just ~10s or so should be enough.

(In reply to Michel Dänzer from comment #20)
> Thanks. Any particular reason for not using sysprof? It would allow saving
> the full profile data and attaching it here, so myself and others could
> analyze it any way we want.

I have experience with OProfile, but do not have to sysprof. Oprofile's data in the next attachment.


> > Here are the data for the 5 minutes of inactivity of the KDM login screen:
> 
> Does the problem occur at the KDM login screen? The profile data looks like
> there was almost no CPU activity at all. The profile needs to be taken while
> the problem is occurring, just ~10s or so should be enough.

The problem manifests itself all the time while running the Xorg. Even when the system is idle (KDM) - Xorg process consumes 12-13% CPU. After logging in, CPU consumption of Xorg increases to 60-80% and is accompanied by a hard lag.

Created attachment 129469 [details]
OProfile's data

(In reply to Eugenij Shkrigunov from comment #21)
> I have experience with OProfile, but do not have to sysprof.

sysprof is very easy to use, the easiest of all profiling tools I know.


> Oprofile's data in the next attachment.

Thanks, but I suspect that isn't useful outside of your machine. Even if it was, I would have to go out of my way to handle it, since oprofile is no longer available in Debian.

Also, I'm afraid the data in comment #19 isn't enough. Without callgraphs, it's not clear where the CPU usage is coming from.

(In reply to Michel Dänzer from comment #23)
> sysprof is very easy to use, the easiest of all profiling tools I know.
Apparently, so is.

Data for sysprof in the next attachment.

Created attachment 129548 [details]
Data for sysprof

Thanks, this helps a little. Unfortunately though, it's still not clear where drmmode_set_mode_major is getting called from. There are two possibilities for getting better information about that:

1. Make sure /usr/bin/Xorg and /usr/lib64/xorg/modules/drivers/radeon_drv.so are compiled with -fno-omit-frame-pointer (after any -O2/-O3 etc. flags), and get another profile with sysprof.

2. Attach gdb to the Xorg process, and enter the following at the gdb prompt:

b drmmode_set_mode_major
commands 1
bt full
c
end
continue

After that, gdb should start spewing backtraces of where drmmode_set_mode_major gets called from. You can interrupt it with Ctrl-C after a few seconds, then attach the backtraces here.

(In reply to Michel Dänzer from comment #26)
> 1. Make sure /usr/bin/Xorg and /usr/lib64/xorg/modules/drivers/radeon_drv.so
> are compiled with -fno-omit-frame-pointer (after any -O2/-O3 etc. flags),
> and get another profile with sysprof.

I compiled xorg-server, xf86-video-ati with CFLAGS="-ggdb2 -O1 -fno-omit-frame-pointer -pipe"

Data for sysprof and gdb output in the next attachments.

Created attachment 129550 [details]
Data for sysprof

Created attachment 129551 [details]
gdb output

Thanks, now I understand what's happening:

It's a bug in the tigervnc vncHooksBlockHandler function, it doesn't handle the function wrapping correctly: It keeps calling RADEONBlockHandler_oneshot, although that function sets pScreen->BlockHandler = RADEONBlockHandler_KMS. vncHooksBlockHandler needs to re-retrieve the current pScreen->BlockHandler pointer after calling it.

Though if it turns out difficult to get this fixed in tigervnc, we can consider a workaround.

P.S. This would also happen with the modesetting driver as of xserver 1.19.

Thank you. I wrote to bug report for tigervnc: https://github.com/TigerVNC/tigervnc/issues/401 about comment #30

FWIW, https://cgit.freedesktop.org/xorg/driver/xf86-video-ati/commit/?id=0a12bf1085505017068dfdfd31d23133e51b45b9 should avoid this problem even with broken tigervnc.