Attachment 131460 Details for Bug 100215 – ftrace, weird vblank timings

ftrace, weird vblank timings

file_100215.txt (text/plain), 11.40 KB, created by Maarten Lankhorst on 2017-05-24 07:17:37 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Maarten Lankhorst

Created: 2017-05-24 07:17:37 UTC

Size: 11.40 KB

patch

obsolete

># tracer: function
>#
># entries-in-buffer/entries-written: 25125/25125   #P:8
>#
>#                              _-----=> irqs-off
>#                             / _----=> need-resched
>#                            | / _---=> hardirq/softirq
>#                            || / _--=> preempt-depth
>#                            ||| /     delay
>#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
>#              | |       |   ||||       |         |
> # Gem_busy..
> kms_cursor_lega-2274  [005] ....  2437.012262: drm_ioctl <-do_vfs_ioctl
> kms_cursor_lega-2274  [005] ....  2437.012262: drm_printk <-drm_ioctl
> kms_cursor_lega-2274  [005] ....  2437.012262: drm_ioctl_permit <-drm_ioctl
>
> kms_cursor_lega-2274  [005] ....  2437.012262: drm_ioctl <-do_vfs_ioctl
> kms_cursor_lega-2274  [005] ....  2437.012263: drm_wait_vblank <-drm_ioctl
> kms_cursor_lega-2274  [005] ....  2437.012263: drm_vblank_get <-drm_wait_vblank
> kms_cursor_lega-2274  [005] d..1  2437.012263: drm_vblank_enable <-drm_vblank_get
> kms_cursor_lega-2274  [005] ....  2437.012263: drm_printk <-drm_wait_vblank
>          <idle>-0     [004] d.h1  2437.037527: drm_handle_vblank <-intel_pipe_handle_vblank
>          <idle>-0     [004] d.h3  2437.037528: drm_update_vblank_count <-drm_handle_vblank
>          <idle>-0     [004] d.h3  2437.037528: __get_vblank_counter <-drm_update_vblank_count
>          <idle>-0     [004] d.h3  2437.037528: drm_crtc_from_index <-__get_vblank_counter
>          <idle>-0     [004] d.h3  2437.037529: drm_get_last_vbltimestamp <-drm_update_vblank_count
>          <idle>-0     [004] d.h3  2437.037529: drm_calc_vbltimestamp_from_scanoutpos <-drm_get_last_vbltimestamp
>          <idle>-0     [004] d.h3  2437.037529: drm_crtc_from_index <-drm_calc_vbltimestamp_from_scanoutpos
>          <idle>-0     [004] d.h3  2437.037529: drm_printk <-drm_calc_vbltimestamp_from_scanoutpos
>          <idle>-0     [004] d.h3  2437.037529: __get_vblank_counter <-drm_update_vblank_count
>          <idle>-0     [004] d.h3  2437.037530: drm_crtc_from_index <-__get_vblank_counter
>          <idle>-0     [004] d.h3  2437.037530: drm_printk <-drm_update_vblank_count
>          <idle>-0     [004] d.h3  2437.037530: store_vblank <-drm_update_vblank_count
>          <idle>-0     [004] d.h2  2437.037530: drm_vblank_count_and_time <-drm_handle_vblank
> kms_cursor_lega-2274  [006] ....  2437.077701: drm_vblank_count_and_time <-drm_wait_vblank
> kms_cursor_lega-2274  [006] ....  2437.077702: drm_printk <-drm_wait_vblank
> kms_cursor_lega-2274  [006] ....  2437.077702: drm_vblank_put <-drm_wait_vblank
>
>#Begin evasion
> kms_cursor_lega-2274  [006] ....  2437.077703: drm_ioctl <-do_vfs_ioctl
> kms_cursor_lega-2274  [006] ....  2437.077704: drm_mode_page_flip_ioctl <-drm_ioctl
> kms_cursor_lega-2274  [006] ....  2437.077719: drm_modeset_acquire_fini <-drm_mode_page_flip_ioctl
>
> kms_cursor_lega-2274  [006] ....  2437.077719: drm_ioctl <-do_vfs_ioctl
> kms_cursor_lega-2274  [006] ....  2437.077720: drm_vblank_put <-drm_wait_vblank
>
> kms_cursor_lega-2274  [006] ....  2437.077720: drm_ioctl <-do_vfs_ioctl
> kms_cursor_lega-2274  [006] ....  2437.077721: drm_mode_cursor_ioctl <-drm_ioctl
> kms_cursor_lega-2274  [006] ....  2437.077726: drm_modeset_acquire_fini <-drm_mode_cursor_common
>
> kms_cursor_lega-2274  [006] ....  2437.077726: drm_ioctl <-do_vfs_ioctl
> kms_cursor_lega-2274  [006] ....  2437.077727: drm_vblank_put <-drm_wait_vblank
> 
> kms_cursor_lega-2274  [006] ....  2437.077727: drm_poll <-do_sys_poll
>
> kms_cursor_lega-2274  [006] ....  2437.077732: drm_read <-__vfs_read
>          <idle>-0     [004] dNh1  2437.077780: drm_handle_vblank <-intel_pipe_handle_vblank
>          <idle>-0     [004] dNh3  2437.077780: drm_update_vblank_count <-drm_handle_vblank
>          <idle>-0     [004] dNh3  2437.077780: __get_vblank_counter <-drm_update_vblank_count
>          <idle>-0     [004] dNh3  2437.077780: drm_crtc_from_index <-__get_vblank_counter
>          <idle>-0     [004] dNh3  2437.077781: drm_get_last_vbltimestamp <-drm_update_vblank_count
>          <idle>-0     [004] dNh3  2437.077781: drm_calc_vbltimestamp_from_scanoutpos <-drm_get_last_vbltimestamp
>          <idle>-0     [004] dNh3  2437.077781: drm_crtc_from_index <-drm_calc_vbltimestamp_from_scanoutpos
>          <idle>-0     [004] dNh3  2437.077782: drm_printk <-drm_calc_vbltimestamp_from_scanoutpos
>          <idle>-0     [004] dNh3  2437.077782: __get_vblank_counter <-drm_update_vblank_count
>          <idle>-0     [004] dNh3  2437.077782: drm_crtc_from_index <-__get_vblank_counter
>          <idle>-0     [004] dNh3  2437.077782: drm_printk <-drm_update_vblank_count
>          <idle>-0     [004] dNh3  2437.077782: store_vblank <-drm_update_vblank_count
>          <idle>-0     [004] dNh2  2437.077782: drm_vblank_count_and_time <-drm_handle_vblank
>     kworker/5:2-216   [005] ....  2437.077785: drm_mm_remove_node <-i915_vma_remove
>     kworker/5:2-216   [005] ....  2437.077786: add_hole <-drm_mm_remove_node
>     kworker/5:2-216   [005] ....  2437.077787: drm_gem_object_release <-__i915_gem_free_objects
>     kworker/5:2-216   [005] ....  2437.077788: drm_vma_offset_remove <-drm_gem_object_release
>          <idle>-0     [004] dNh1  2437.077788: drm_handle_vblank <-intel_pipe_handle_vblank
>          <idle>-0     [004] dNh3  2437.077788: drm_update_vblank_count <-drm_handle_vblank
>          <idle>-0     [004] dNh3  2437.077788: __get_vblank_counter <-drm_update_vblank_count
>          <idle>-0     [004] dNh3  2437.077789: drm_crtc_from_index <-__get_vblank_counter
>          <idle>-0     [004] dNh3  2437.077789: drm_get_last_vbltimestamp <-drm_update_vblank_count
>          <idle>-0     [004] dNh3  2437.077789: drm_calc_vbltimestamp_from_scanoutpos <-drm_get_last_vbltimestamp
>          <idle>-0     [004] dNh3  2437.077789: drm_crtc_from_index <-drm_calc_vbltimestamp_from_scanoutpos
>          <idle>-0     [004] dNh3  2437.077789: drm_printk <-drm_calc_vbltimestamp_from_scanoutpos
>          <idle>-0     [004] dNh3  2437.077789: __get_vblank_counter <-drm_update_vblank_count
>          <idle>-0     [004] dNh3  2437.077789: drm_crtc_from_index <-__get_vblank_counter
>          <idle>-0     [004] dNh3  2437.077790: drm_printk <-drm_update_vblank_count
>          <idle>-0     [004] dNh2  2437.077790: drm_vblank_count_and_time <-drm_handle_vblank
>   kworker/u16:6-145   [004] ....  2437.077795: drm_atomic_helper_wait_for_dependencies <-intel_atomic_commit_tail
>   kworker/u16:6-145   [004] ....  2437.077797: drm_atomic_helper_commit_planes_on_crtc <-intel_update_crtc
>   kworker/u16:6-145   [004] d...  2437.077797: drm_crtc_vblank_get <-intel_pipe_update_start
>   kworker/u16:6-145   [004] d...  2437.077798: drm_vblank_get <-drm_crtc_vblank_get
>   kworker/u16:6-145   [004] d..1  2437.077798: drm_vblank_enable <-drm_vblank_get
>   kworker/u16:6-145   [004] d...  2437.077798: drm_crtc_vblank_put <-intel_pipe_update_start
>   kworker/u16:6-145   [004] d...  2437.077798: drm_vblank_put <-drm_crtc_vblank_put
>   kworker/u16:6-145   [004] d...  2437.077800: drm_crtc_vblank_get <-intel_pipe_update_end
>   kworker/u16:6-145   [004] d...  2437.077800: drm_vblank_get <-drm_crtc_vblank_get
>   kworker/u16:6-145   [004] d..1  2437.077800: drm_vblank_enable <-drm_vblank_get
>   kworker/u16:6-145   [004] d..1  2437.077800: drm_crtc_arm_vblank_event <-intel_pipe_update_end
>   kworker/u16:6-145   [004] ....  2437.077801: drm_atomic_helper_commit_hw_done <-intel_atomic_commit_tail
>   kworker/u16:6-145   [004] ....  2437.077801: drm_atomic_helper_cleanup_planes <-intel_atomic_commit_tail
>   kworker/u16:6-145   [004] ....  2437.077801: drm_atomic_helper_commit_cleanup_done <-intel_atomic_commit_tail
>          <idle>-0     [004] d.h1  2437.078855: drm_handle_vblank <-intel_pipe_handle_vblank
>          <idle>-0     [004] d.h3  2437.078856: drm_update_vblank_count <-drm_handle_vblank
>          <idle>-0     [004] d.h3  2437.078856: __get_vblank_counter <-drm_update_vblank_count
>          <idle>-0     [004] d.h3  2437.078856: drm_crtc_from_index <-__get_vblank_counter
>          <idle>-0     [004] d.h3  2437.078857: drm_get_last_vbltimestamp <-drm_update_vblank_count
>          <idle>-0     [004] d.h3  2437.078857: drm_calc_vbltimestamp_from_scanoutpos <-drm_get_last_vbltimestamp
>          <idle>-0     [004] d.h3  2437.078857: drm_crtc_from_index <-drm_calc_vbltimestamp_from_scanoutpos
>          <idle>-0     [004] d.h3  2437.078857: drm_printk <-drm_calc_vbltimestamp_from_scanoutpos
>          <idle>-0     [004] d.h3  2437.078857: __get_vblank_counter <-drm_update_vblank_count
>          <idle>-0     [004] d.h3  2437.078857: drm_crtc_from_index <-__get_vblank_counter
>          <idle>-0     [004] d.h3  2437.078858: drm_printk <-drm_update_vblank_count
>          <idle>-0     [004] d.h3  2437.078858: store_vblank <-drm_update_vblank_count
>          <idle>-0     [004] d.h2  2437.078858: drm_vblank_count_and_time <-drm_handle_vblank
>          <idle>-0     [004] d.h2  2437.078858: drm_printk <-drm_handle_vblank
>          <idle>-0     [004] d.h2  2437.078858: drm_vblank_put <-drm_handle_vblank
>          <idle>-0     [004] d.h2  2437.078858: send_vblank_event <-drm_handle_vblank
>          <idle>-0     [004] d.h2  2437.078859: drm_send_event_locked <-send_vblank_event
>          <idle>-0     [004] dNh2  2437.078860: release_crtc_commit <-drm_send_event_locked
>   kworker/u16:6-145   [004] ....  2437.078868: __drm_atomic_state_free <-intel_atomic_commit_tail
>   kworker/u16:6-145   [004] ....  2437.078868: drm_atomic_state_clear <-__drm_atomic_state_free
>   kworker/u16:6-145   [004] ....  2437.078868: drm_atomic_state_default_clear <-intel_atomic_state_clear
>   kworker/u16:6-145   [004] ....  2437.078868: drm_printk <-drm_atomic_state_default_clear
>   kworker/u16:6-145   [004] ....  2437.078868: drm_atomic_helper_crtc_destroy_state <-intel_crtc_destroy_state
>   kworker/u16:6-145   [004] ....  2437.078868: __drm_atomic_helper_crtc_destroy_state <-drm_atomic_helper_crtc_destroy_state
>   kworker/u16:6-145   [004] ....  2437.078869: drm_property_blob_put <-__drm_atomic_helper_crtc_destroy_state
>   kworker/u16:6-145   [004] ....  2437.078869: drm_mode_object_put <-drm_property_blob_put
>   kworker/u16:6-145   [004] ....  2437.078869: drm_printk <-drm_mode_object_put
>   kworker/u16:6-145   [004] ....  2437.078869: drm_property_blob_put <-__drm_atomic_helper_crtc_destroy_state
>   kworker/u16:6-145   [004] ....  2437.078869: drm_property_blob_put <-__drm_atomic_helper_crtc_destroy_state
>   kworker/u16:6-145   [004] ....  2437.078869: drm_property_blob_put <-__drm_atomic_helper_crtc_destroy_state
>   kworker/u16:6-145   [004] ....  2437.078869: drm_mode_object_put <-drm_property_blob_put
>   kworker/u16:6-145   [004] ....  2437.078869: drm_printk <-drm_mode_object_put
>   kworker/u16:6-145   [004] ....  2437.078870: drm_atomic_helper_plane_destroy_state <-intel_plane_destroy_state
>   kworker/u16:6-145   [004] ....  2437.078870: __drm_atomic_helper_plane_destroy_state <-drm_atomic_helper_plane_destroy_state
>   kworker/u16:6-145   [004] ....  2437.078870: drm_mode_object_put <-__drm_atomic_helper_plane_destroy_state
>   kworker/u16:6-145   [004] ....  2437.078870: drm_printk <-drm_mode_object_put
>   kworker/u16:6-145   [004] ....  2437.078870: drm_printk <-__drm_atomic_state_free
>   kworker/u16:6-145   [004] ....  2437.078870: drm_atomic_state_default_release <-intel_atomic_state_free
>
> kms_cursor_lega-2274  [006] ....  2437.078905: drm_ioctl <-do_vfs_ioctl
> kms_cursor_lega-2274  [006] ....  2437.078906: drm_vblank_put <-drm_wait_vblank

Actions: View

Attachments on bug 100215: 131433 | 131460

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.