[ 14380.506] sna_block_handler (tv=117.70000)
[ 14380.506] sna_scanout_do_flush: flush timer active: delta=7
[ 14380.506] sna_accel_do_throttle -- no pending activity
[ 14380.506] sna_accel_block: evaluating timers, active=5
[ 14380.506] sna_accel_block: flush timer expires in 7 [14380513]
[ 14380.507] sna_wakeup_handler
[ 14380.507] sna_block_handler (tv=117.69000)
[ 14380.507] sna_scanout_do_flush: flush timer active: delta=6
[ 14380.508] sna_accel_do_throttle -- no pending activity
[ 14380.508] sna_accel_block: evaluating timers, active=5
[ 14380.508] sna_accel_block: flush timer expires in 6 [14380513]
[ 14380.508] sna_wakeup_handler
[ 14380.509] sna_block_handler (tv=117.67000)
[ 14380.509] sna_scanout_do_flush: flush timer active: delta=4
[ 14380.509] sna_accel_do_throttle -- no pending activity
[ 14380.509] sna_accel_block: evaluating timers, active=5
[ 14380.509] sna_accel_block: flush timer expires in 4 [14380513]
[ 14380.509] sna_wakeup_handler
[ 14380.510] sna_block_handler (tv=117.66000)
[ 14380.510] sna_scanout_do_flush: flush timer active: delta=3
[ 14380.510] sna_scanout_do_flush (time=14380510), triggered
[ 14380.510] sna_scanout_flush (time=14380510), cpu damage? 1, exec? 0 nbatch=0, busy? 1
[ 14380.510] has_shadow: has pending damage? 1, outstanding flips: 0
[ 14380.510] stop_flush: scanout=9 shadow?=1, slaves?=0, (cpu?=1 || gpu?=0))
[ 14380.510] has_shadow: has pending damage? 1, outstanding flips: 0
[ 14380.510] sna_mode_redisplay: posting shadow damage? 1 (flips pending? 0, mode reconfiguration pending? 0)
[ 14380.510] sna_mode_redisplay: damage: 1x(507, 460), (655, 588)
[ 14380.510] move_crtc_to_gpu: CRTC 20 [pipe=0] requires frontbuffer
[ 14380.510] sna_pixmap_move_to_gpu(pixmap=344, usage=16), flags=10a
[ 14380.510] sna_pixmap_move_to_gpu: CPU damage? 1
[ 14380.510] _sna_damage_get_boxes([[(507, 460), (655, 588)]: [(507, 460), (655, 588)] ] )...
[ 14380.510]   = 1
[ 14380.510] sna_pixmap_move_to_gpu: uploading 1 damage boxes
[ 14380.510] sna_write_boxes x 1, src stride=5120,  src dx=(0, 0)
[ 14380.510] kgem_bo_can_map: handle=9, map=0x0:0x0:0x0, tiling=1, domain=0, offset=10747904
[ 14380.510] __kgem_bo_is_busy: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.510] write_boxes_inplace x 1, handle=9, tiling=1
[ 14380.510] upload_inplace__tiled: tiling=1
[ 14380.510] kgem_bo_can_map: handle=9, map=0x0:0x0:0x0, tiling=1, domain=0, offset=10747904
[ 14380.510] kgem_bo_map: handle=9, offset=10747904, tiling=1, map=0x0:0x0, domain=0
[ 14380.510] __kgem_bo_map__gtt_or_wc: handle=9
[ 14380.510] kgem_trim_vma_cache: type=0, count=-508 (bucket: 10)
[ 14380.510] __kgem_bo_map__gtt(handle=9, size=5242880)
[ 14380.510] __kgem_busy: handle=9, busy=0, wedged=0
[ 14380.510] kgem_bo_map: sync: needs_flush? 0, domain? 0, busy? 0
[ 14380.510] __kgem_busy: handle=9, busy=0, wedged=0
[ 14380.510] kgem_bo_retire: retiring bo handle=9 (needed flush? 0), rq? 0 [busy?=0]
[ 14380.510] assert_bo_retired: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.510] kgem_create_buffer: size=75776, flags=3 [write?=1, inplace?=1, last?=0]
[ 14380.510] kgem_create_buffer: searching for an inactive GTT map for upload
[ 14380.510] search_linear_cache: num_pages=64, flags=b, use_active? 0, use_large=0 [max=65536]
[ 14380.510] search_linear_cache: searching for inactive gtt map
[ 14380.510] kgem_bo_remove_from_inactive: removing handle=77 from inactive
[ 14380.510]   search_linear_cache: found handle=77 (num_pages=64) in linear vma cache
[ 14380.510] kgem_create_buffer: reusing handle=77 for buffer
[ 14380.510] kgem_bo_can_map: handle=77, map=0x0:0x7fa3a653c000:0x7fa3a657c000, tiling=0, domain=0, offset=44691456
[ 14380.510] init_buffer_from_bo: reusing handle=77 for buffer
[ 14380.510] kgem_bo_map: handle=77, offset=44691456, tiling=0, map=0x0:0x7fa3a657c000, domain=0
[ 14380.510] __kgem_bo_map__gtt_or_wc: handle=77
[ 14380.510] kgem_trim_vma_cache: type=0, count=-509 (bucket: 6)
[ 14380.510] __kgem_busy: handle=77, busy=0, wedged=0
[ 14380.510] kgem_bo_map: sync: needs_flush? 0, domain? 0, busy? 0
[ 14380.510] __kgem_busy: handle=77, busy=0, wedged=0
[ 14380.510] kgem_bo_retire: retiring bo handle=77 (needed flush? 0), rq? 0 [busy?=0]
[ 14380.510] assert_bo_retired: handle=77, domain: 0 exec? 0, rq? 0
[ 14380.510] kgem_create_buffer(pages=64 [64]) new handle=77, used=75776, write=3
[ 14380.510] kgem_create_proxy: target handle=77 [proxy? -1], offset=0, length=75776, io=1
[ 14380.510] __kgem_bo_init(handle=77, num_pages=75776)
[ 14380.510]   sna_write_boxes: box src=(507, 460), dst=(507, 460) size=(148, 128), dst offset=0, dst pitch=592
[ 14380.510] memcpy_blt: src=(507, 460), dst=(0, 0), size=148x128, pitch=5120/592
[ 14380.510] kgem_add_reloc: handle=9, pos=4, delta=0, domains=28002
[ 14380.510] kgem_add_handle: handle=9, index=0
[ 14380.510] __kgem_bo_mark_dirty: handle=9 (proxy? 0)
[ 14380.510] kgem_add_reloc: handle=77, pos=7, delta=0, domains=28000
[ 14380.510] kgem_add_reloc: adding proxy [delta=0] for handle=77
[ 14380.510] kgem_add_handle: handle=77, index=1
[ 14380.510] _kgem_bo_destroy: handle=77, proxy? 1
[ 14380.510] sna_damage_reduce_all(width=1280, height=1024)
[ 14380.510] _sna_damage_reduce
[ 14380.510]     reduce: before region.n=4
[ 14380.510]    nboxes=8, residual=7
[ 14380.510]     reduce: after region.n=4
[ 14380.510] sna_pixmap_mark_active: pixmap=344, handle=9
[ 14380.510] sna_mode_redisplay: crtc[0] transformed? 1
[ 14380.510] sna_mode_redisplay: crtc[0] damage? 1[1]: 1x[(507, 460), (655, 588)]
[ 14380.510] crtc_source: using Screen pixmap=344
[ 14380.510] sna_crtc_redisplay: crtc 20 [pipe=0], damage (507, 460), (655, 588) x 1
[ 14380.510] sna_crtc_redisplay: copy damage boxes
[ 14380.510] gen4_render_copy_boxes x 1
[ 14380.510] sna_blt_copy_boxes src=(0, 0) -> (0, 0) x 1, tiling=(1, 0), pitch=(5120, 5120)
[ 14380.511] kgem_set_mode: flushing before new bo
[ 14380.511] batch[3/0, flags=1800]: 10 10 65528 65528, nreloc=2, nexec=2, nfence=0, aperture=1344 [fenced=0]
[ 14380.511] kgem_finish_buffers: buffer handle=77, used=75776, exec?=1, write=3, mmapped=gtt, refcnt=1
[ 14380.511] kgem_finish_buffers: retaining upload buffer (75776/262144): used=77824, refcnt=1
[ 14380.511] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.511] kgem_commit: release handle=1 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=f40000
[ 14380.511] kgem_commit: release handle=9 (proxy? 0), dirty? 1 flush? 1, snoop? 0 -> offset=a40000
[ 14380.511] kgem_commit: release handle=77 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=2a9f000
[ 14380.511] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.511] sna_blt_copy_boxes: emitting 1 boxes out of 1 (batch space 65520)
[ 14380.511]   sna_blt_copy_boxes: box=(507, 460)x(148, 128)
[ 14380.511] kgem_add_reloc: handle=11, pos=4, delta=0, domains=28002
[ 14380.511] kgem_add_handle: handle=11, index=0
[ 14380.511] __kgem_bo_mark_dirty: handle=11 (proxy? 0)
[ 14380.511] kgem_add_reloc: handle=9, pos=7, delta=0, domains=28000
[ 14380.511] kgem_add_handle: handle=9, index=1
[ 14380.511] batch[3/0, flags=1800]: 10 10 65528 65528, nreloc=2, nexec=2, nfence=0, aperture=2560 [fenced=0]
[ 14380.511] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.511] __kgem_retire_rq: request 1 complete
[ 14380.511] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.511] kgem_commit: release handle=1 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=f40000
[ 14380.511] kgem_commit: release handle=11 (proxy? 0), dirty? 1 flush? 1, snoop? 0 -> offset=1460000
[ 14380.511] kgem_commit: release handle=9 (proxy? 0), dirty? 0 flush? 1, snoop? 0 -> offset=a40000
[ 14380.511] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.511] __kgem_busy: handle=11, busy=0, wedged=0
[ 14380.511] __kgem_bo_clear_busy: handle=11
[ 14380.511] __kgem_flush: handle=11, busy?=0
[ 14380.511] sna_mode_redisplay: crtc[1] transformed? 0
[ 14380.511] timer_enable (time=14380510), starting timer 1
[ 14380.511] sna_accel_block: evaluating timers, active=7
[ 14380.511] sna_accel_block: flush timer expires in 16 [14380526]
[ 14380.516] sna_wakeup_handler
[ 14380.516] sna_block_handler (tv=117.60000)
[ 14380.516] kgem_retire, need_retire?=1
[ 14380.516] kgem_retire__flushing: 0 bo on flushing list
[ 14380.516] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.516] __kgem_retire_rq: request 1 complete
[ 14380.516] __kgem_bo_flush: handle=9, busy=0, wedged=0
[ 14380.516] kgem_retire__requests_ring: ring=0, 0 outstanding requests, oldest=0
[ 14380.516] kgem_retire__requests_ring: ring=1, 0 outstanding requests, oldest=0
[ 14380.516] kgem_retire -- retired=0, need_retire=0
[ 14380.516] kgem_retire__buffers: handle=77, busy? 0 [0]
[ 14380.516] kgem_retire__buffers: releasing upload cache for handle=77? 0
[ 14380.516] __kgem_bo_destroy: handle=77, size=262144
[ 14380.516] kgem_bo_replace_io: transferring io handle=77 to bo
[ 14380.516] kgem_bo_move_to_inactive: moving handle=77 to inactive
[ 14380.516] sna_scanout_do_flush: flush timer active: delta=10
[ 14380.516] sna_accel_block: evaluating timers, active=7
[ 14380.516] sna_accel_block: flush timer expires in 10 [14380526]
[ 14380.517] sna_wakeup_handler
[ 14380.517] sna_copy_area: src=(507, 460)x(148, 128)+(0, 0) -> dst=(507, 460)+(0, 0); alu=3, pm=ffffffffffffffff, depth=24
[ 14380.517] sna_do_copy: src=(507, 460), dst=(507, 460), size=(148x128)
[ 14380.517] sna_do_copy: after drawable: src=(507, 460), dst=(507, 460), size=(148x128)
[ 14380.517] sna_do_copy: dst extents (507, 460), (655, 588), dst clip extents (0, 0), (1280, 1024), dst size=1280x1024
[ 14380.517] sna_do_copy: clipped dst extents (507, 460), (655, 588)
[ 14380.517] sna_do_copy: unclipped src extents (507, 460), (655, 588)
[ 14380.517] sna_do_copy: clipped src extents (507, 460), (655, 588)
[ 14380.517] sna_do_copy: pixmap -- no source clipping
[ 14380.517] sna_do_copy: src extents (507, 460), (655, 588) x 1
[ 14380.517] sna_do_copy: copy region (507, 460), (655, 588) x 1 + (0, 0)
[ 14380.517] sna_copy_boxes (boxes=1x[(507, 460), (655, 588)...], src pixmap=370+(0, 0), dst pixmap=344+(0, 0), alu=3, src.size=1280x1024, dst.size=1280x1024)
[ 14380.517] sna_copy_boxes: dst=(priv=0x7fa3ae546a80, gpu_bo=9, cpu_bo=0), src=(priv=0x0, gpu_bo=0, cpu_bo=0), replaces=0
[ 14380.517] copy_prefer_gpu: source unattached, use cpu
[ 14380.517] sna_drawable_use_bo pixmap=344, box=((507, 460), (655, 588)), flags=8...
[ 14380.517] sna_drawable_use_bo: flush=0, shm=0, cpu=1 => flags=8
[ 14380.517] sna_drawable_use_bo: try cpu as GPU bo is idle
[ 14380.517] sna_drawable_use_bo: no CPU bo, and GPU not forced
[ 14380.517] sna_copy_boxes__inplace - no, bad dst tiling [X]
[ 14380.517] sna_copy_boxes: fallback -- src=(0, 0), dst=(0, 0)
[ 14380.517] sna_drawable_move_region_to_cpu(pixmap=344 (1280x1024), [(507, 460), (655, 588)], flags=5)
[ 14380.517] kgem_bo_is_busy: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.517] kgem_bo_is_busy: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.517] region_inplace: (148x128), inplace? 0
[ 14380.517] _sna_damage_subtract([[(0, 0), (1280, 1024)]: [(0, 0), (1280, 1024) x 4: ((0, 0), (1280, 460)), ((0, 460), (435, 588)), ((655, 460), (1280, 588)), ((0, 588), (1280, 1024))] ]  - [(507, 460), (655, 588)])...
[ 14380.517]     _sna_damage_create_elt: prev=(remain 8), count=1
[ 14380.517]   = [[(0, 0), (1280, 1024)]: [(0, 0), (1280, 1024) x 4: ((0, 0), (1280, 460)), ((0, 460), (435, 588)), ((655, 460), (1280, 588)), ((0, 588), (1280, 1024))] -[ ...]]*
[ 14380.517] sna_drawable_move_region_to_cpu: applying cpu damage
[ 14380.517] _sna_damage_add(None + [(507, 460), (655, 588)])
[ 14380.517] damage_union: extending damage (32767, 32767), (-32768, -32768) by (507, 460), (655, 588)
[ 14380.517]   = [[(507, 460), (655, 588)]: [(507, 460), (655, 588)] ] 
[ 14380.517] sna_damage_reduce_all(width=1280, height=1024)
[ 14380.517] sna_copy_boxes: memcpy_blt(box=(507, 460), (148, 128), src=(0, 0), pitches=(5120, 5120))
[ 14380.517] memcpy_blt: src=(507, 460), dst=(507, 460), size=148x128, pitch=5120/5120
[ 14380.517] sna_block_handler (tv=117.59000)
[ 14380.517] sna_scanout_do_flush: flush timer active: delta=9
[ 14380.517] sna_accel_block: evaluating timers, active=7
[ 14380.517] sna_accel_block: flush timer expires in 9 [14380526]
[ 14380.526] sna_wakeup_handler
[ 14380.526] sna_block_handler (tv=117.50000)
[ 14380.526] sna_scanout_do_flush: flush timer active: delta=0
[ 14380.526] sna_scanout_do_flush (time=14380526), triggered
[ 14380.526] sna_scanout_flush (time=14380526), cpu damage? 1, exec? 0 nbatch=0, busy? 1
[ 14380.526] has_shadow: has pending damage? 1, outstanding flips: 0
[ 14380.526] stop_flush: scanout=9 shadow?=1, slaves?=0, (cpu?=1 || gpu?=0))
[ 14380.526] has_shadow: has pending damage? 1, outstanding flips: 0
[ 14380.526] sna_mode_redisplay: posting shadow damage? 1 (flips pending? 0, mode reconfiguration pending? 0)
[ 14380.526] sna_mode_redisplay: damage: 1x(507, 460), (655, 588)
[ 14380.526] move_crtc_to_gpu: CRTC 20 [pipe=0] requires frontbuffer
[ 14380.526] sna_pixmap_move_to_gpu(pixmap=344, usage=16), flags=10a
[ 14380.526] sna_pixmap_move_to_gpu: CPU damage? 1
[ 14380.526] _sna_damage_get_boxes([[(507, 460), (655, 588)]: [(507, 460), (655, 588)] ] )...
[ 14380.526]   = 1
[ 14380.526] sna_pixmap_move_to_gpu: uploading 1 damage boxes
[ 14380.526] sna_write_boxes x 1, src stride=5120,  src dx=(0, 0)
[ 14380.527] kgem_bo_can_map: handle=9, map=0x0:0x0:0x0, tiling=1, domain=0, offset=10747904
[ 14380.527] __kgem_bo_is_busy: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.527] write_boxes_inplace x 1, handle=9, tiling=1
[ 14380.527] upload_inplace__tiled: tiling=1
[ 14380.527] kgem_bo_can_map: handle=9, map=0x0:0x0:0x0, tiling=1, domain=0, offset=10747904
[ 14380.527] kgem_bo_map: handle=9, offset=10747904, tiling=1, map=0x0:0x0, domain=0
[ 14380.527] __kgem_bo_map__gtt_or_wc: handle=9
[ 14380.527] kgem_trim_vma_cache: type=0, count=-508 (bucket: 10)
[ 14380.527] __kgem_bo_map__gtt(handle=9, size=5242880)
[ 14380.527] __kgem_busy: handle=9, busy=0, wedged=0
[ 14380.527] kgem_bo_map: sync: needs_flush? 0, domain? 0, busy? 0
[ 14380.527] __kgem_busy: handle=9, busy=0, wedged=0
[ 14380.527] kgem_bo_retire: retiring bo handle=9 (needed flush? 0), rq? 0 [busy?=0]
[ 14380.527] assert_bo_retired: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.527] kgem_create_buffer: size=75776, flags=3 [write?=1, inplace?=1, last?=0]
[ 14380.527] kgem_create_buffer: searching for an inactive GTT map for upload
[ 14380.527] search_linear_cache: num_pages=64, flags=b, use_active? 0, use_large=0 [max=65536]
[ 14380.527] search_linear_cache: searching for inactive gtt map
[ 14380.527] kgem_bo_remove_from_inactive: removing handle=77 from inactive
[ 14380.527]   search_linear_cache: found handle=77 (num_pages=64) in linear vma cache
[ 14380.527] kgem_create_buffer: reusing handle=77 for buffer
[ 14380.527] kgem_bo_can_map: handle=77, map=0x0:0x7fa3a653c000:0x7fa3a657c000, tiling=0, domain=0, offset=44691456
[ 14380.527] init_buffer_from_bo: reusing handle=77 for buffer
[ 14380.527] kgem_bo_map: handle=77, offset=44691456, tiling=0, map=0x0:0x7fa3a657c000, domain=0
[ 14380.527] __kgem_bo_map__gtt_or_wc: handle=77
[ 14380.527] kgem_trim_vma_cache: type=0, count=-509 (bucket: 6)
[ 14380.527] __kgem_busy: handle=77, busy=0, wedged=0
[ 14380.527] kgem_bo_map: sync: needs_flush? 0, domain? 0, busy? 0
[ 14380.527] __kgem_busy: handle=77, busy=0, wedged=0
[ 14380.527] kgem_bo_retire: retiring bo handle=77 (needed flush? 0), rq? 0 [busy?=0]
[ 14380.527] assert_bo_retired: handle=77, domain: 0 exec? 0, rq? 0
[ 14380.527] kgem_create_buffer(pages=64 [64]) new handle=77, used=75776, write=3
[ 14380.527] kgem_create_proxy: target handle=77 [proxy? -1], offset=0, length=75776, io=1
[ 14380.527] __kgem_bo_init(handle=77, num_pages=75776)
[ 14380.527]   sna_write_boxes: box src=(507, 460), dst=(507, 460) size=(148, 128), dst offset=0, dst pitch=592
[ 14380.527] memcpy_blt: src=(507, 460), dst=(0, 0), size=148x128, pitch=5120/592
[ 14380.527] kgem_add_reloc: handle=9, pos=4, delta=0, domains=28002
[ 14380.527] kgem_add_handle: handle=9, index=0
[ 14380.527] __kgem_bo_mark_dirty: handle=9 (proxy? 0)
[ 14380.527] kgem_add_reloc: handle=77, pos=7, delta=0, domains=28000
[ 14380.527] kgem_add_reloc: adding proxy [delta=0] for handle=77
[ 14380.527] kgem_add_handle: handle=77, index=1
[ 14380.527] _kgem_bo_destroy: handle=77, proxy? 1
[ 14380.527] sna_damage_reduce_all(width=1280, height=1024)
[ 14380.527] _sna_damage_reduce
[ 14380.527]     reduce: before region.n=4
[ 14380.527]    nboxes=8, residual=7
[ 14380.527]     reduce: after region.n=4
[ 14380.527] sna_pixmap_mark_active: pixmap=344, handle=9
[ 14380.527] sna_mode_redisplay: crtc[0] transformed? 1
[ 14380.527] sna_mode_redisplay: crtc[0] damage? 1[1]: 1x[(507, 460), (655, 588)]
[ 14380.527] crtc_source: using Screen pixmap=344
[ 14380.527] sna_crtc_redisplay: crtc 20 [pipe=0], damage (507, 460), (655, 588) x 1
[ 14380.527] sna_crtc_redisplay: copy damage boxes
[ 14380.527] gen4_render_copy_boxes x 1
[ 14380.527] sna_blt_copy_boxes src=(0, 0) -> (0, 0) x 1, tiling=(1, 0), pitch=(5120, 5120)
[ 14380.527] kgem_set_mode: flushing before new bo
[ 14380.527] batch[3/0, flags=1800]: 10 10 65528 65528, nreloc=2, nexec=2, nfence=0, aperture=1344 [fenced=0]
[ 14380.527] kgem_finish_buffers: buffer handle=77, used=75776, exec?=1, write=3, mmapped=gtt, refcnt=1
[ 14380.527] kgem_finish_buffers: retaining upload buffer (75776/262144): used=77824, refcnt=1
[ 14380.527] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.527] kgem_commit: release handle=1 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=f40000
[ 14380.527] kgem_commit: release handle=9 (proxy? 0), dirty? 1 flush? 1, snoop? 0 -> offset=a40000
[ 14380.527] kgem_commit: release handle=77 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=2a9f000
[ 14380.527] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.527] sna_blt_copy_boxes: emitting 1 boxes out of 1 (batch space 65520)
[ 14380.527]   sna_blt_copy_boxes: box=(507, 460)x(148, 128)
[ 14380.527] kgem_add_reloc: handle=11, pos=4, delta=0, domains=28002
[ 14380.527] kgem_add_handle: handle=11, index=0
[ 14380.527] __kgem_bo_mark_dirty: handle=11 (proxy? 0)
[ 14380.527] kgem_add_reloc: handle=9, pos=7, delta=0, domains=28000
[ 14380.527] kgem_add_handle: handle=9, index=1
[ 14380.527] batch[3/0, flags=1800]: 10 10 65528 65528, nreloc=2, nexec=2, nfence=0, aperture=2560 [fenced=0]
[ 14380.527] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.527] __kgem_retire_rq: request 1 complete
[ 14380.527] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.527] kgem_commit: release handle=1 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=f40000
[ 14380.527] kgem_commit: release handle=11 (proxy? 0), dirty? 1 flush? 1, snoop? 0 -> offset=1460000
[ 14380.528] kgem_commit: release handle=9 (proxy? 0), dirty? 0 flush? 1, snoop? 0 -> offset=a40000
[ 14380.528] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.528] __kgem_busy: handle=11, busy=0, wedged=0
[ 14380.528] __kgem_bo_clear_busy: handle=11
[ 14380.528] __kgem_flush: handle=11, busy?=0
[ 14380.528] sna_mode_redisplay: crtc[1] transformed? 0
[ 14380.528] sna_accel_block: evaluating timers, active=7
[ 14380.528] sna_accel_block: flush timer expires in 16 [14380542]
[ 14380.532] sna_wakeup_handler
[ 14380.532] sna_block_handler (tv=117.44000)
[ 14380.532] kgem_retire, need_retire?=1
[ 14380.532] kgem_retire__flushing: 0 bo on flushing list
[ 14380.532] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.532] __kgem_retire_rq: request 1 complete
[ 14380.532] __kgem_bo_flush: handle=9, busy=0, wedged=0
[ 14380.532] kgem_retire__requests_ring: ring=0, 0 outstanding requests, oldest=0
[ 14380.532] kgem_retire__requests_ring: ring=1, 0 outstanding requests, oldest=0
[ 14380.532] kgem_retire -- retired=0, need_retire=0
[ 14380.532] kgem_retire__buffers: handle=77, busy? 0 [0]
[ 14380.532] kgem_retire__buffers: releasing upload cache for handle=77? 0
[ 14380.532] __kgem_bo_destroy: handle=77, size=262144
[ 14380.532] kgem_bo_replace_io: transferring io handle=77 to bo
[ 14380.532] kgem_bo_move_to_inactive: moving handle=77 to inactive
[ 14380.532] sna_scanout_do_flush: flush timer active: delta=10
[ 14380.532] sna_accel_do_throttle (time=14380532), triggered
[ 14380.532] sna_accel_throttle (time=14380532)
[ 14380.532] sna_accel_disarm_timer[1] (time=14380532)
[ 14380.532] sna_accel_block: evaluating timers, active=5
[ 14380.532] sna_accel_block: flush timer expires in 10 [14380542]
[ 14380.533] sna_wakeup_handler
[ 14380.533] sna_copy_area: src=(507, 460)x(148, 128)+(0, 0) -> dst=(507, 460)+(0, 0); alu=3, pm=ffffffffffffffff, depth=24
[ 14380.533] sna_do_copy: src=(507, 460), dst=(507, 460), size=(148x128)
[ 14380.533] sna_do_copy: after drawable: src=(507, 460), dst=(507, 460), size=(148x128)
[ 14380.533] sna_do_copy: dst extents (507, 460), (655, 588), dst clip extents (0, 0), (1280, 1024), dst size=1280x1024
[ 14380.533] sna_do_copy: clipped dst extents (507, 460), (655, 588)
[ 14380.533] sna_do_copy: unclipped src extents (507, 460), (655, 588)
[ 14380.533] sna_do_copy: clipped src extents (507, 460), (655, 588)
[ 14380.533] sna_do_copy: pixmap -- no source clipping
[ 14380.533] sna_do_copy: src extents (507, 460), (655, 588) x 1
[ 14380.533] sna_do_copy: copy region (507, 460), (655, 588) x 1 + (0, 0)
[ 14380.533] sna_copy_boxes (boxes=1x[(507, 460), (655, 588)...], src pixmap=370+(0, 0), dst pixmap=344+(0, 0), alu=3, src.size=1280x1024, dst.size=1280x1024)
[ 14380.533] sna_copy_boxes: dst=(priv=0x7fa3ae546a80, gpu_bo=9, cpu_bo=0), src=(priv=0x0, gpu_bo=0, cpu_bo=0), replaces=0
[ 14380.533] copy_prefer_gpu: source unattached, use cpu
[ 14380.533] sna_drawable_use_bo pixmap=344, box=((507, 460), (655, 588)), flags=8...
[ 14380.533] sna_drawable_use_bo: flush=0, shm=0, cpu=1 => flags=8
[ 14380.533] sna_drawable_use_bo: try cpu as GPU bo is idle
[ 14380.533] sna_drawable_use_bo: no CPU bo, and GPU not forced
[ 14380.533] sna_copy_boxes__inplace - no, bad dst tiling [X]
[ 14380.533] sna_copy_boxes: fallback -- src=(0, 0), dst=(0, 0)
[ 14380.533] sna_drawable_move_region_to_cpu(pixmap=344 (1280x1024), [(507, 460), (655, 588)], flags=5)
[ 14380.533] kgem_bo_is_busy: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.533] kgem_bo_is_busy: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.533] region_inplace: (148x128), inplace? 0
[ 14380.533] _sna_damage_subtract([[(0, 0), (1280, 1024)]: [(0, 0), (1280, 1024) x 4: ((0, 0), (1280, 460)), ((0, 460), (435, 588)), ((655, 460), (1280, 588)), ((0, 588), (1280, 1024))] ]  - [(507, 460), (655, 588)])...
[ 14380.533]     _sna_damage_create_elt: prev=(remain 8), count=1
[ 14380.533]   = [[(0, 0), (1280, 1024)]: [(0, 0), (1280, 1024) x 4: ((0, 0), (1280, 460)), ((0, 460), (435, 588)), ((655, 460), (1280, 588)), ((0, 588), (1280, 1024))] -[ ...]]*
[ 14380.533] sna_drawable_move_region_to_cpu: applying cpu damage
[ 14380.533] _sna_damage_add(None + [(507, 460), (655, 588)])
[ 14380.533] damage_union: extending damage (32767, 32767), (-32768, -32768) by (507, 460), (655, 588)
[ 14380.533]   = [[(507, 460), (655, 588)]: [(507, 460), (655, 588)] ] 
[ 14380.533] sna_damage_reduce_all(width=1280, height=1024)
[ 14380.533] sna_copy_boxes: memcpy_blt(box=(507, 460), (148, 128), src=(0, 0), pitches=(5120, 5120))
[ 14380.533] memcpy_blt: src=(507, 460), dst=(507, 460), size=148x128, pitch=5120/5120
[ 14380.533] sna_block_handler (tv=117.43000)
[ 14380.533] sna_scanout_do_flush: flush timer active: delta=9
[ 14380.533] sna_accel_do_throttle -- no pending activity
[ 14380.533] sna_accel_block: evaluating timers, active=5
[ 14380.533] sna_accel_block: flush timer expires in 9 [14380542]
[ 14380.539] sna_wakeup_handler
[ 14380.539] sna_change_window_attributes
[ 14380.539] sna_set_window_pixmap: window=27263065, old pixmap=0 new pixmap=344
[ 14380.539] sna_set_window_pixmap: window=27263065, old pixmap=344 new pixmap=344
[ 14380.539] sna_change_window_attributes
[ 14380.539] sna_set_window_pixmap: window=27263066, old pixmap=0 new pixmap=344
[ 14380.539] sna_set_window_pixmap: window=27263066, old pixmap=344 new pixmap=344
[ 14380.539] sna_change_window_attributes
[ 14380.539] sna_block_handler (tv=117.37000)
[ 14380.539] sna_scanout_do_flush: flush timer active: delta=3
[ 14380.539] sna_scanout_do_flush (time=14380539), triggered
[ 14380.539] sna_scanout_flush (time=14380539), cpu damage? 1, exec? 0 nbatch=0, busy? 1
[ 14380.539] has_shadow: has pending damage? 1, outstanding flips: 0
[ 14380.539] stop_flush: scanout=9 shadow?=1, slaves?=0, (cpu?=1 || gpu?=0))
[ 14380.539] has_shadow: has pending damage? 1, outstanding flips: 0
[ 14380.539] sna_mode_redisplay: posting shadow damage? 1 (flips pending? 0, mode reconfiguration pending? 0)
[ 14380.539] sna_mode_redisplay: damage: 1x(507, 460), (655, 588)
[ 14380.539] move_crtc_to_gpu: CRTC 20 [pipe=0] requires frontbuffer
[ 14380.539] sna_pixmap_move_to_gpu(pixmap=344, usage=16), flags=10a
[ 14380.539] sna_pixmap_move_to_gpu: CPU damage? 1
[ 14380.539] _sna_damage_get_boxes([[(507, 460), (655, 588)]: [(507, 460), (655, 588)] ] )...
[ 14380.539]   = 1
[ 14380.539] sna_pixmap_move_to_gpu: uploading 1 damage boxes
[ 14380.539] sna_write_boxes x 1, src stride=5120,  src dx=(0, 0)
[ 14380.539] kgem_bo_can_map: handle=9, map=0x0:0x0:0x0, tiling=1, domain=0, offset=10747904
[ 14380.539] __kgem_bo_is_busy: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.539] write_boxes_inplace x 1, handle=9, tiling=1
[ 14380.539] upload_inplace__tiled: tiling=1
[ 14380.539] kgem_bo_can_map: handle=9, map=0x0:0x0:0x0, tiling=1, domain=0, offset=10747904
[ 14380.539] kgem_bo_map: handle=9, offset=10747904, tiling=1, map=0x0:0x0, domain=0
[ 14380.539] __kgem_bo_map__gtt_or_wc: handle=9
[ 14380.539] kgem_trim_vma_cache: type=0, count=-508 (bucket: 10)
[ 14380.539] __kgem_bo_map__gtt(handle=9, size=5242880)
[ 14380.539] __kgem_busy: handle=9, busy=0, wedged=0
[ 14380.539] kgem_bo_map: sync: needs_flush? 0, domain? 0, busy? 0
[ 14380.539] __kgem_busy: handle=9, busy=0, wedged=0
[ 14380.539] kgem_bo_retire: retiring bo handle=9 (needed flush? 0), rq? 0 [busy?=0]
[ 14380.539] assert_bo_retired: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.539] kgem_create_buffer: size=75776, flags=3 [write?=1, inplace?=1, last?=0]
[ 14380.539] kgem_create_buffer: searching for an inactive GTT map for upload
[ 14380.539] search_linear_cache: num_pages=64, flags=b, use_active? 0, use_large=0 [max=65536]
[ 14380.539] search_linear_cache: searching for inactive gtt map
[ 14380.539] kgem_bo_remove_from_inactive: removing handle=77 from inactive
[ 14380.539]   search_linear_cache: found handle=77 (num_pages=64) in linear vma cache
[ 14380.539] kgem_create_buffer: reusing handle=77 for buffer
[ 14380.539] kgem_bo_can_map: handle=77, map=0x0:0x7fa3a653c000:0x7fa3a657c000, tiling=0, domain=0, offset=44691456
[ 14380.539] init_buffer_from_bo: reusing handle=77 for buffer
[ 14380.539] kgem_bo_map: handle=77, offset=44691456, tiling=0, map=0x0:0x7fa3a657c000, domain=0
[ 14380.539] __kgem_bo_map__gtt_or_wc: handle=77
[ 14380.539] kgem_trim_vma_cache: type=0, count=-509 (bucket: 6)
[ 14380.539] __kgem_busy: handle=77, busy=0, wedged=0
[ 14380.539] kgem_bo_map: sync: needs_flush? 0, domain? 0, busy? 0
[ 14380.539] __kgem_busy: handle=77, busy=0, wedged=0
[ 14380.540] kgem_bo_retire: retiring bo handle=77 (needed flush? 0), rq? 0 [busy?=0]
[ 14380.540] assert_bo_retired: handle=77, domain: 0 exec? 0, rq? 0
[ 14380.540] kgem_create_buffer(pages=64 [64]) new handle=77, used=75776, write=3
[ 14380.540] kgem_create_proxy: target handle=77 [proxy? -1], offset=0, length=75776, io=1
[ 14380.540] __kgem_bo_init(handle=77, num_pages=75776)
[ 14380.540]   sna_write_boxes: box src=(507, 460), dst=(507, 460) size=(148, 128), dst offset=0, dst pitch=592
[ 14380.540] memcpy_blt: src=(507, 460), dst=(0, 0), size=148x128, pitch=5120/592
[ 14380.540] kgem_add_reloc: handle=9, pos=4, delta=0, domains=28002
[ 14380.540] kgem_add_handle: handle=9, index=0
[ 14380.540] __kgem_bo_mark_dirty: handle=9 (proxy? 0)
[ 14380.540] kgem_add_reloc: handle=77, pos=7, delta=0, domains=28000
[ 14380.540] kgem_add_reloc: adding proxy [delta=0] for handle=77
[ 14380.540] kgem_add_handle: handle=77, index=1
[ 14380.540] _kgem_bo_destroy: handle=77, proxy? 1
[ 14380.540] sna_damage_reduce_all(width=1280, height=1024)
[ 14380.540] _sna_damage_reduce
[ 14380.540]     reduce: before region.n=4
[ 14380.540]    nboxes=8, residual=7
[ 14380.540]     reduce: after region.n=4
[ 14380.540] sna_pixmap_mark_active: pixmap=344, handle=9
[ 14380.540] sna_mode_redisplay: crtc[0] transformed? 1
[ 14380.540] sna_mode_redisplay: crtc[0] damage? 1[1]: 1x[(507, 460), (655, 588)]
[ 14380.540] crtc_source: using Screen pixmap=344
[ 14380.540] sna_crtc_redisplay: crtc 20 [pipe=0], damage (507, 460), (655, 588) x 1
[ 14380.540] sna_crtc_redisplay: copy damage boxes
[ 14380.540] gen4_render_copy_boxes x 1
[ 14380.540] sna_blt_copy_boxes src=(0, 0) -> (0, 0) x 1, tiling=(1, 0), pitch=(5120, 5120)
[ 14380.540] kgem_set_mode: flushing before new bo
[ 14380.540] batch[3/0, flags=1800]: 10 10 65528 65528, nreloc=2, nexec=2, nfence=0, aperture=1344 [fenced=0]
[ 14380.540] kgem_finish_buffers: buffer handle=77, used=75776, exec?=1, write=3, mmapped=gtt, refcnt=1
[ 14380.540] kgem_finish_buffers: retaining upload buffer (75776/262144): used=77824, refcnt=1
[ 14380.540] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.540] kgem_commit: release handle=1 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=f40000
[ 14380.540] kgem_commit: release handle=9 (proxy? 0), dirty? 1 flush? 1, snoop? 0 -> offset=a40000
[ 14380.540] kgem_commit: release handle=77 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=2a9f000
[ 14380.540] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.540] sna_blt_copy_boxes: emitting 1 boxes out of 1 (batch space 65520)
[ 14380.540]   sna_blt_copy_boxes: box=(507, 460)x(148, 128)
[ 14380.540] kgem_add_reloc: handle=11, pos=4, delta=0, domains=28002
[ 14380.540] kgem_add_handle: handle=11, index=0
[ 14380.540] __kgem_bo_mark_dirty: handle=11 (proxy? 0)
[ 14380.540] kgem_add_reloc: handle=9, pos=7, delta=0, domains=28000
[ 14380.540] kgem_add_handle: handle=9, index=1
[ 14380.540] batch[3/0, flags=1800]: 10 10 65528 65528, nreloc=2, nexec=2, nfence=0, aperture=2560 [fenced=0]
[ 14380.540] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.540] __kgem_retire_rq: request 1 complete
[ 14380.540] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.540] kgem_commit: release handle=1 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=f40000
[ 14380.540] kgem_commit: release handle=11 (proxy? 0), dirty? 1 flush? 1, snoop? 0 -> offset=1460000
[ 14380.540] kgem_commit: release handle=9 (proxy? 0), dirty? 0 flush? 1, snoop? 0 -> offset=a40000
[ 14380.540] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.540] __kgem_busy: handle=11, busy=65537, wedged=0
[ 14380.540] __kgem_flush: handle=11, busy?=1
[ 14380.540] sna_mode_redisplay: crtc[1] transformed? 0
[ 14380.540] timer_enable (time=14380539), starting timer 1
[ 14380.540] sna_accel_block: evaluating timers, active=7
[ 14380.540] sna_accel_block: flush timer expires in 16 [14380555]
[ 14380.540] sna_wakeup_handler
[ 14380.540] sna_block_handler (tv=117.36000)
[ 14380.541] kgem_retire, need_retire?=1
[ 14380.541] kgem_retire__flushing: 0 bo on flushing list
[ 14380.541] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.541] __kgem_retire_rq: request 1 complete
[ 14380.541] __kgem_bo_flush: handle=9, busy=0, wedged=0
[ 14380.541] kgem_retire__requests_ring: ring=0, 0 outstanding requests, oldest=0
[ 14380.541] kgem_retire__requests_ring: ring=1, 0 outstanding requests, oldest=0
[ 14380.541] kgem_retire -- retired=0, need_retire=0
[ 14380.541] kgem_retire__buffers: handle=77, busy? 0 [0]
[ 14380.541] kgem_retire__buffers: releasing upload cache for handle=77? 0
[ 14380.541] __kgem_bo_destroy: handle=77, size=262144
[ 14380.541] kgem_bo_replace_io: transferring io handle=77 to bo
[ 14380.541] kgem_bo_move_to_inactive: moving handle=77 to inactive
[ 14380.541] sna_scanout_do_flush: flush timer active: delta=14
[ 14380.541] sna_accel_block: evaluating timers, active=7
[ 14380.541] sna_accel_block: flush timer expires in 14 [14380555]
[ 14380.541] sna_wakeup_handler
[ 14380.541] sna_block_handler (tv=117.35000)
[ 14380.541] sna_scanout_do_flush: flush timer active: delta=14
[ 14380.541] sna_accel_block: evaluating timers, active=7
[ 14380.541] sna_accel_block: flush timer expires in 14 [14380555]
[ 14380.541] sna_wakeup_handler
[ 14380.541] sna_block_handler (tv=117.35000)
[ 14380.541] sna_scanout_do_flush: flush timer active: delta=14
[ 14380.541] sna_accel_block: evaluating timers, active=7
[ 14380.541] sna_accel_block: flush timer expires in 14 [14380555]
[ 14380.541] sna_wakeup_handler
[ 14380.541] sna_block_handler (tv=117.35000)
[ 14380.541] sna_scanout_do_flush: flush timer active: delta=14
[ 14380.541] sna_accel_block: evaluating timers, active=7
[ 14380.541] sna_accel_block: flush timer expires in 14 [14380555]
[ 14380.541] sna_wakeup_handler
[ 14380.541] sna_block_handler (tv=117.35000)
[ 14380.541] sna_scanout_do_flush: flush timer active: delta=14
[ 14380.541] sna_accel_block: evaluating timers, active=7
[ 14380.541] sna_accel_block: flush timer expires in 14 [14380555]
[ 14380.541] sna_wakeup_handler
[ 14380.541] sna_block_handler (tv=117.35000)
[ 14380.541] sna_scanout_do_flush: flush timer active: delta=14
[ 14380.541] sna_accel_block: evaluating timers, active=7
[ 14380.541] sna_accel_block: flush timer expires in 14 [14380555]
[ 14380.541] sna_wakeup_handler
[ 14380.541] sna_block_handler (tv=117.35000)
[ 14380.541] sna_scanout_do_flush: flush timer active: delta=14
[ 14380.541] sna_accel_block: evaluating timers, active=7
[ 14380.541] sna_accel_block: flush timer expires in 14 [14380555]
[ 14380.541] sna_wakeup_handler
[ 14380.541] sna_block_handler (tv=117.35000)
[ 14380.541] sna_scanout_do_flush: flush timer active: delta=14
[ 14380.541] sna_accel_block: evaluating timers, active=7
[ 14380.541] sna_accel_block: flush timer expires in 14 [14380555]
[ 14380.541] sna_wakeup_handler
[ 14380.541] sna_block_handler (tv=117.35000)
[ 14380.541] sna_scanout_do_flush: flush timer active: delta=14
[ 14380.541] sna_accel_block: evaluating timers, active=7
[ 14380.541] sna_accel_block: flush timer expires in 14 [14380555]
[ 14380.542] sna_wakeup_handler
[ 14380.542] sna_block_handler (tv=117.34000)
[ 14380.542] sna_scanout_do_flush: flush timer active: delta=13
[ 14380.542] sna_accel_block: evaluating timers, active=7
[ 14380.542] sna_accel_block: flush timer expires in 13 [14380555]
[ 14380.542] sna_wakeup_handler
[ 14380.542] sna_block_handler (tv=117.34000)
[ 14380.542] sna_scanout_do_flush: flush timer active: delta=13
[ 14380.542] sna_accel_block: evaluating timers, active=7
[ 14380.542] sna_accel_block: flush timer expires in 13 [14380555]
[ 14380.542] sna_wakeup_handler
[ 14380.542] sna_block_handler (tv=117.34000)
[ 14380.542] sna_scanout_do_flush: flush timer active: delta=13
[ 14380.542] sna_accel_block: evaluating timers, active=7
[ 14380.542] sna_accel_block: flush timer expires in 13 [14380555]
[ 14380.542] sna_wakeup_handler
[ 14380.542] sna_block_handler (tv=117.34000)
[ 14380.542] sna_scanout_do_flush: flush timer active: delta=13
[ 14380.542] sna_accel_block: evaluating timers, active=7
[ 14380.542] sna_accel_block: flush timer expires in 13 [14380555]
[ 14380.542] sna_wakeup_handler
[ 14380.542] sna_block_handler (tv=117.34000)
[ 14380.542] sna_scanout_do_flush: flush timer active: delta=13
[ 14380.542] sna_accel_block: evaluating timers, active=7
[ 14380.542] sna_accel_block: flush timer expires in 13 [14380555]
[ 14380.542] sna_wakeup_handler
[ 14380.543] sna_block_handler (tv=117.33000)
[ 14380.543] sna_scanout_do_flush: flush timer active: delta=12
[ 14380.543] sna_accel_block: evaluating timers, active=7
[ 14380.543] sna_accel_block: flush timer expires in 12 [14380555]
[ 14380.543] sna_wakeup_handler
[ 14380.543] sna_block_handler (tv=117.33000)
[ 14380.543] sna_scanout_do_flush: flush timer active: delta=12
[ 14380.543] sna_accel_block: evaluating timers, active=7
[ 14380.543] sna_accel_block: flush timer expires in 12 [14380555]
[ 14380.543] sna_wakeup_handler
[ 14380.543] sna_block_handler (tv=117.33000)
[ 14380.543] sna_scanout_do_flush: flush timer active: delta=12
[ 14380.543] sna_accel_block: evaluating timers, active=7
[ 14380.543] sna_accel_block: flush timer expires in 12 [14380555]
[ 14380.543] sna_wakeup_handler
[ 14380.543] sna_block_handler (tv=117.33000)
[ 14380.543] sna_scanout_do_flush: flush timer active: delta=12
[ 14380.543] sna_accel_block: evaluating timers, active=7
[ 14380.543] sna_accel_block: flush timer expires in 12 [14380555]
[ 14380.543] sna_wakeup_handler
[ 14380.543] sna_block_handler (tv=117.33000)
[ 14380.543] sna_scanout_do_flush: flush timer active: delta=12
[ 14380.543] sna_accel_block: evaluating timers, active=7
[ 14380.543] sna_accel_block: flush timer expires in 12 [14380555]
[ 14380.543] sna_wakeup_handler
[ 14380.543] sna_block_handler (tv=117.33000)
[ 14380.544] sna_scanout_do_flush: flush timer active: delta=11
[ 14380.544] sna_accel_block: evaluating timers, active=7
[ 14380.544] sna_accel_block: flush timer expires in 11 [14380555]
[ 14380.544] sna_wakeup_handler
[ 14380.544] sna_block_handler (tv=117.32000)
[ 14380.544] sna_scanout_do_flush: flush timer active: delta=11
[ 14380.544] sna_accel_block: evaluating timers, active=7
[ 14380.544] sna_accel_block: flush timer expires in 11 [14380555]
[ 14380.544] sna_wakeup_handler
[ 14380.544] sna_block_handler (tv=117.32000)
[ 14380.544] sna_scanout_do_flush: flush timer active: delta=11
[ 14380.544] sna_accel_block: evaluating timers, active=7
[ 14380.544] sna_accel_block: flush timer expires in 11 [14380555]
[ 14380.544] sna_wakeup_handler
[ 14380.544] sna_block_handler (tv=117.32000)
[ 14380.544] sna_scanout_do_flush: flush timer active: delta=11
[ 14380.544] sna_accel_block: evaluating timers, active=7
[ 14380.544] sna_accel_block: flush timer expires in 11 [14380555]
[ 14380.544] sna_wakeup_handler
[ 14380.545] sna_block_handler (tv=117.31000)
[ 14380.545] sna_scanout_do_flush: flush timer active: delta=10
[ 14380.545] sna_accel_block: evaluating timers, active=7
[ 14380.545] sna_accel_block: flush timer expires in 10 [14380555]
[ 14380.546] sna_wakeup_handler
[ 14380.546] sna_block_handler (tv=117.30000)
[ 14380.546] sna_scanout_do_flush: flush timer active: delta=9
[ 14380.546] sna_accel_block: evaluating timers, active=7
[ 14380.546] sna_accel_block: flush timer expires in 9 [14380555]
[ 14380.546] sna_wakeup_handler
[ 14380.546] sna_block_handler (tv=117.30000)
[ 14380.546] sna_scanout_do_flush: flush timer active: delta=9
[ 14380.546] sna_accel_block: evaluating timers, active=7
[ 14380.546] sna_accel_block: flush timer expires in 9 [14380555]
[ 14380.546] sna_wakeup_handler
[ 14380.546] sna_block_handler (tv=117.30000)
[ 14380.546] sna_scanout_do_flush: flush timer active: delta=9
[ 14380.546] sna_accel_block: evaluating timers, active=7
[ 14380.546] sna_accel_block: flush timer expires in 9 [14380555]
[ 14380.546] sna_wakeup_handler
[ 14380.546] sna_block_handler (tv=117.30000)
[ 14380.546] sna_scanout_do_flush: flush timer active: delta=9
[ 14380.546] sna_accel_block: evaluating timers, active=7
[ 14380.546] sna_accel_block: flush timer expires in 9 [14380555]
[ 14380.546] sna_wakeup_handler
[ 14380.547] sna_change_window_attributes
[ 14380.547] sna_block_handler (tv=117.29000)
[ 14380.547] sna_scanout_do_flush: flush timer active: delta=8
[ 14380.547] sna_accel_block: evaluating timers, active=7
[ 14380.547] sna_accel_block: flush timer expires in 8 [14380555]
[ 14380.547] sna_wakeup_handler
[ 14380.547] sna_block_handler (tv=117.29000)
[ 14380.547] sna_scanout_do_flush: flush timer active: delta=8
[ 14380.547] sna_accel_block: evaluating timers, active=7
[ 14380.547] sna_accel_block: flush timer expires in 8 [14380555]
[ 14380.547] sna_wakeup_handler
[ 14380.547] sna_block_handler (tv=117.29000)
[ 14380.547] sna_scanout_do_flush: flush timer active: delta=8
[ 14380.547] sna_accel_block: evaluating timers, active=7
[ 14380.547] sna_accel_block: flush timer expires in 8 [14380555]
[ 14380.547] sna_wakeup_handler
[ 14380.547] sna_block_handler (tv=117.29000)
[ 14380.547] sna_scanout_do_flush: flush timer active: delta=8
[ 14380.547] sna_accel_block: evaluating timers, active=7
[ 14380.547] sna_accel_block: flush timer expires in 8 [14380555]
[ 14380.547] sna_wakeup_handler
[ 14380.547] sna_block_handler (tv=117.29000)
[ 14380.547] sna_scanout_do_flush: flush timer active: delta=8
[ 14380.547] sna_accel_block: evaluating timers, active=7
[ 14380.547] sna_accel_block: flush timer expires in 8 [14380555]
[ 14380.547] sna_wakeup_handler
[ 14380.547] sna_block_handler (tv=117.29000)
[ 14380.547] sna_scanout_do_flush: flush timer active: delta=8
[ 14380.547] sna_accel_block: evaluating timers, active=7
[ 14380.547] sna_accel_block: flush timer expires in 8 [14380555]
[ 14380.547] sna_wakeup_handler
[ 14380.547] sna_block_handler (tv=117.29000)
[ 14380.547] sna_scanout_do_flush: flush timer active: delta=8
[ 14380.547] sna_accel_block: evaluating timers, active=7
[ 14380.547] sna_accel_block: flush timer expires in 8 [14380555]
[ 14380.547] sna_wakeup_handler
[ 14380.547] sna_block_handler (tv=117.29000)
[ 14380.547] sna_scanout_do_flush: flush timer active: delta=8
[ 14380.547] sna_accel_block: evaluating timers, active=7
[ 14380.547] sna_accel_block: flush timer expires in 8 [14380555]
[ 14380.547] sna_wakeup_handler
[ 14380.547] sna_block_handler (tv=117.29000)
[ 14380.547] sna_scanout_do_flush: flush timer active: delta=8
[ 14380.547] sna_accel_block: evaluating timers, active=7
[ 14380.547] sna_accel_block: flush timer expires in 8 [14380555]
[ 14380.547] sna_wakeup_handler
[ 14380.547] sna_block_handler (tv=117.29000)
[ 14380.547] sna_scanout_do_flush: flush timer active: delta=8
[ 14380.547] sna_accel_block: evaluating timers, active=7
[ 14380.547] sna_accel_block: flush timer expires in 8 [14380555]
[ 14380.547] sna_wakeup_handler
[ 14380.547] sna_block_handler (tv=117.29000)
[ 14380.547] sna_scanout_do_flush: flush timer active: delta=8
[ 14380.547] sna_accel_block: evaluating timers, active=7
[ 14380.547] sna_accel_block: flush timer expires in 8 [14380555]
[ 14380.548] sna_wakeup_handler
[ 14380.548] sna_block_handler (tv=117.28000)
[ 14380.548] sna_scanout_do_flush: flush timer active: delta=7
[ 14380.548] sna_accel_block: evaluating timers, active=7
[ 14380.548] sna_accel_block: flush timer expires in 7 [14380555]
[ 14380.548] sna_wakeup_handler
[ 14380.549] sna_block_handler (tv=117.27000)
[ 14380.549] sna_scanout_do_flush: flush timer active: delta=6
[ 14380.549] sna_accel_block: evaluating timers, active=7
[ 14380.549] sna_accel_block: flush timer expires in 6 [14380555]
[ 14380.549] sna_wakeup_handler
[ 14380.549] sna_block_handler (tv=117.27000)
[ 14380.549] sna_scanout_do_flush: flush timer active: delta=6
[ 14380.549] sna_accel_block: evaluating timers, active=7
[ 14380.549] sna_accel_block: flush timer expires in 6 [14380555]
[ 14380.549] sna_wakeup_handler
[ 14380.549] sna_block_handler (tv=117.27000)
[ 14380.549] sna_scanout_do_flush: flush timer active: delta=6
[ 14380.549] sna_accel_block: evaluating timers, active=7
[ 14380.549] sna_accel_block: flush timer expires in 6 [14380555]
[ 14380.549] sna_wakeup_handler
[ 14380.549] sna_copy_area: src=(579, 460)x(76, 128)+(0, 0) -> dst=(579, 460)+(0, 0); alu=3, pm=ffffffffffffffff, depth=24
[ 14380.549] sna_do_copy: src=(579, 460), dst=(579, 460), size=(76x128)
[ 14380.549] sna_do_copy: after drawable: src=(579, 460), dst=(579, 460), size=(76x128)
[ 14380.549] sna_do_copy: dst extents (579, 460), (655, 588), dst clip extents (0, 0), (1280, 1024), dst size=1280x1024
[ 14380.549] sna_do_copy: clipped dst extents (579, 460), (655, 588)
[ 14380.549] sna_do_copy: unclipped src extents (579, 460), (655, 588)
[ 14380.549] sna_do_copy: clipped src extents (579, 460), (655, 588)
[ 14380.549] sna_do_copy: pixmap -- no source clipping
[ 14380.549] sna_do_copy: src extents (579, 460), (655, 588) x 1
[ 14380.549] sna_do_copy: copy region (579, 460), (655, 588) x 1 + (0, 0)
[ 14380.549] sna_copy_boxes (boxes=1x[(579, 460), (655, 588)...], src pixmap=370+(0, 0), dst pixmap=344+(0, 0), alu=3, src.size=1280x1024, dst.size=1280x1024)
[ 14380.549] sna_copy_boxes: dst=(priv=0x7fa3ae546a80, gpu_bo=9, cpu_bo=0), src=(priv=0x0, gpu_bo=0, cpu_bo=0), replaces=0
[ 14380.549] copy_prefer_gpu: source unattached, use cpu
[ 14380.549] sna_drawable_use_bo pixmap=344, box=((579, 460), (655, 588)), flags=8...
[ 14380.549] sna_drawable_use_bo: flush=0, shm=0, cpu=1 => flags=8
[ 14380.549] sna_drawable_use_bo: try cpu as GPU bo is idle
[ 14380.549] sna_drawable_use_bo: no CPU bo, and GPU not forced
[ 14380.549] sna_copy_boxes__inplace - no, bad dst tiling [X]
[ 14380.549] sna_copy_boxes: fallback -- src=(0, 0), dst=(0, 0)
[ 14380.549] sna_drawable_move_region_to_cpu(pixmap=344 (1280x1024), [(579, 460), (655, 588)], flags=5)
[ 14380.549] kgem_bo_is_busy: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.549] kgem_bo_is_busy: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.549] region_inplace: (76x128), inplace? 0
[ 14380.549] _sna_damage_subtract([[(0, 0), (1280, 1024)]: [(0, 0), (1280, 1024) x 4: ((0, 0), (1280, 460)), ((0, 460), (435, 588)), ((655, 460), (1280, 588)), ((0, 588), (1280, 1024))] ]  - [(579, 460), (655, 588)])...
[ 14380.549]     _sna_damage_create_elt: prev=(remain 8), count=1
[ 14380.549]   = [[(0, 0), (1280, 1024)]: [(0, 0), (1280, 1024) x 4: ((0, 0), (1280, 460)), ((0, 460), (435, 588)), ((655, 460), (1280, 588)), ((0, 588), (1280, 1024))] -[ ...]]*
[ 14380.549] sna_drawable_move_region_to_cpu: applying cpu damage
[ 14380.549] _sna_damage_add(None + [(579, 460), (655, 588)])
[ 14380.549] damage_union: extending damage (32767, 32767), (-32768, -32768) by (579, 460), (655, 588)
[ 14380.549]   = [[(579, 460), (655, 588)]: [(579, 460), (655, 588)] ] 
[ 14380.549] sna_damage_reduce_all(width=1280, height=1024)
[ 14380.549] sna_copy_boxes: memcpy_blt(box=(579, 460), (76, 128), src=(0, 0), pitches=(5120, 5120))
[ 14380.549] memcpy_blt: src=(579, 460), dst=(579, 460), size=76x128, pitch=5120/5120
[ 14380.549] sna_block_handler (tv=117.27000)
[ 14380.549] sna_scanout_do_flush: flush timer active: delta=6
[ 14380.550] sna_accel_block: evaluating timers, active=7
[ 14380.550] sna_accel_block: flush timer expires in 6 [14380555]
[ 14380.555] sna_wakeup_handler
[ 14380.555] sna_block_handler (tv=117.21000)
[ 14380.555] sna_scanout_do_flush: flush timer active: delta=0
[ 14380.555] sna_scanout_do_flush (time=14380555), triggered
[ 14380.555] sna_scanout_flush (time=14380555), cpu damage? 1, exec? 0 nbatch=0, busy? 1
[ 14380.555] has_shadow: has pending damage? 1, outstanding flips: 0
[ 14380.555] stop_flush: scanout=9 shadow?=1, slaves?=0, (cpu?=1 || gpu?=0))
[ 14380.555] has_shadow: has pending damage? 1, outstanding flips: 0
[ 14380.555] sna_mode_redisplay: posting shadow damage? 1 (flips pending? 0, mode reconfiguration pending? 0)
[ 14380.556] sna_mode_redisplay: damage: 1x(579, 460), (655, 588)
[ 14380.556] move_crtc_to_gpu: CRTC 20 [pipe=0] requires frontbuffer
[ 14380.556] sna_pixmap_move_to_gpu(pixmap=344, usage=16), flags=10a
[ 14380.556] sna_pixmap_move_to_gpu: CPU damage? 1
[ 14380.556] _sna_damage_get_boxes([[(579, 460), (655, 588)]: [(579, 460), (655, 588)] ] )...
[ 14380.556]   = 1
[ 14380.556] sna_pixmap_move_to_gpu: uploading 1 damage boxes
[ 14380.556] sna_write_boxes x 1, src stride=5120,  src dx=(0, 0)
[ 14380.556] kgem_bo_can_map: handle=9, map=0x0:0x0:0x0, tiling=1, domain=0, offset=10747904
[ 14380.556] __kgem_bo_is_busy: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.556] write_boxes_inplace x 1, handle=9, tiling=1
[ 14380.556] upload_inplace__tiled: tiling=1
[ 14380.556] kgem_bo_can_map: handle=9, map=0x0:0x0:0x0, tiling=1, domain=0, offset=10747904
[ 14380.556] kgem_bo_map: handle=9, offset=10747904, tiling=1, map=0x0:0x0, domain=0
[ 14380.556] __kgem_bo_map__gtt_or_wc: handle=9
[ 14380.556] kgem_trim_vma_cache: type=0, count=-508 (bucket: 10)
[ 14380.556] __kgem_bo_map__gtt(handle=9, size=5242880)
[ 14380.556] __kgem_busy: handle=9, busy=0, wedged=0
[ 14380.556] kgem_bo_map: sync: needs_flush? 0, domain? 0, busy? 0
[ 14380.556] __kgem_busy: handle=9, busy=0, wedged=0
[ 14380.556] kgem_bo_retire: retiring bo handle=9 (needed flush? 0), rq? 0 [busy?=0]
[ 14380.556] assert_bo_retired: handle=9, domain: 0 exec? 0, rq? 0
[ 14380.556] kgem_create_buffer: size=38912, flags=3 [write?=1, inplace?=1, last?=0]
[ 14380.556] kgem_create_buffer: searching for an inactive GTT map for upload
[ 14380.556] search_linear_cache: num_pages=64, flags=b, use_active? 0, use_large=0 [max=65536]
[ 14380.556] search_linear_cache: searching for inactive gtt map
[ 14380.556] kgem_bo_remove_from_inactive: removing handle=77 from inactive
[ 14380.556]   search_linear_cache: found handle=77 (num_pages=64) in linear vma cache
[ 14380.556] kgem_create_buffer: reusing handle=77 for buffer
[ 14380.556] kgem_bo_can_map: handle=77, map=0x0:0x7fa3a653c000:0x7fa3a657c000, tiling=0, domain=0, offset=44691456
[ 14380.556] init_buffer_from_bo: reusing handle=77 for buffer
[ 14380.556] kgem_bo_map: handle=77, offset=44691456, tiling=0, map=0x0:0x7fa3a657c000, domain=0
[ 14380.556] __kgem_bo_map__gtt_or_wc: handle=77
[ 14380.556] kgem_trim_vma_cache: type=0, count=-509 (bucket: 6)
[ 14380.556] __kgem_busy: handle=77, busy=0, wedged=0
[ 14380.556] kgem_bo_map: sync: needs_flush? 0, domain? 0, busy? 0
[ 14380.556] __kgem_busy: handle=77, busy=0, wedged=0
[ 14380.556] kgem_bo_retire: retiring bo handle=77 (needed flush? 0), rq? 0 [busy?=0]
[ 14380.556] assert_bo_retired: handle=77, domain: 0 exec? 0, rq? 0
[ 14380.556] kgem_create_buffer(pages=64 [64]) new handle=77, used=38912, write=3
[ 14380.556] kgem_create_proxy: target handle=77 [proxy? -1], offset=0, length=38912, io=1
[ 14380.556] __kgem_bo_init(handle=77, num_pages=38912)
[ 14380.556]   sna_write_boxes: box src=(579, 460), dst=(579, 460) size=(76, 128), dst offset=0, dst pitch=304
[ 14380.556] memcpy_blt: src=(579, 460), dst=(0, 0), size=76x128, pitch=5120/304
[ 14380.556] kgem_add_reloc: handle=9, pos=4, delta=0, domains=28002
[ 14380.556] kgem_add_handle: handle=9, index=0
[ 14380.556] __kgem_bo_mark_dirty: handle=9 (proxy? 0)
[ 14380.556] kgem_add_reloc: handle=77, pos=7, delta=0, domains=28000
[ 14380.556] kgem_add_reloc: adding proxy [delta=0] for handle=77
[ 14380.556] kgem_add_handle: handle=77, index=1
[ 14380.556] _kgem_bo_destroy: handle=77, proxy? 1
[ 14380.556] sna_damage_reduce_all(width=1280, height=1024)
[ 14380.556] _sna_damage_reduce
[ 14380.556]     reduce: before region.n=4
[ 14380.556]    nboxes=8, residual=7
[ 14380.556]     reduce: after region.n=4
[ 14380.556] sna_pixmap_mark_active: pixmap=344, handle=9
[ 14380.556] sna_mode_redisplay: crtc[0] transformed? 1
[ 14380.556] sna_mode_redisplay: crtc[0] damage? 1[1]: 1x[(579, 460), (655, 588)]
[ 14380.556] crtc_source: using Screen pixmap=344
[ 14380.556] sna_crtc_redisplay: crtc 20 [pipe=0], damage (579, 460), (655, 588) x 1
[ 14380.556] sna_crtc_redisplay: copy damage boxes
[ 14380.556] gen4_render_copy_boxes x 1
[ 14380.556] sna_blt_copy_boxes src=(0, 0) -> (0, 0) x 1, tiling=(1, 0), pitch=(5120, 5120)
[ 14380.556] kgem_set_mode: flushing before new bo
[ 14380.556] batch[3/0, flags=1800]: 10 10 65528 65528, nreloc=2, nexec=2, nfence=0, aperture=1344 [fenced=0]
[ 14380.556] kgem_finish_buffers: buffer handle=77, used=38912, exec?=1, write=3, mmapped=gtt, refcnt=1
[ 14380.556] kgem_finish_buffers: retaining upload buffer (38912/262144): used=40960, refcnt=1
[ 14380.556] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.556] kgem_commit: release handle=1 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=f40000
[ 14380.556] kgem_commit: release handle=9 (proxy? 0), dirty? 1 flush? 1, snoop? 0 -> offset=a40000
[ 14380.556] kgem_commit: release handle=77 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=2a9f000
[ 14380.556] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.557] sna_blt_copy_boxes: emitting 1 boxes out of 1 (batch space 65520)
[ 14380.557]   sna_blt_copy_boxes: box=(579, 460)x(76, 128)
[ 14380.557] kgem_add_reloc: handle=11, pos=4, delta=0, domains=28002
[ 14380.557] kgem_add_handle: handle=11, index=0
[ 14380.557] __kgem_bo_mark_dirty: handle=11 (proxy? 0)
[ 14380.557] kgem_add_reloc: handle=9, pos=7, delta=0, domains=28000
[ 14380.557] kgem_add_handle: handle=9, index=1
[ 14380.557] batch[3/0, flags=1800]: 10 10 65528 65528, nreloc=2, nexec=2, nfence=0, aperture=2560 [fenced=0]
[ 14380.557] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.557] __kgem_retire_rq: request 1 complete
[ 14380.557] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.557] kgem_commit: release handle=1 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=f40000
[ 14380.557] kgem_commit: release handle=11 (proxy? 0), dirty? 1 flush? 1, snoop? 0 -> offset=1460000
[ 14380.557] kgem_commit: release handle=9 (proxy? 0), dirty? 0 flush? 1, snoop? 0 -> offset=a40000
[ 14380.557] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.557] __kgem_busy: handle=11, busy=0, wedged=0
[ 14380.557] __kgem_bo_clear_busy: handle=11
[ 14380.557] __kgem_flush: handle=11, busy?=0
[ 14380.557] sna_mode_redisplay: crtc[1] transformed? 0
[ 14380.557] sna_accel_block: evaluating timers, active=7
[ 14380.557] sna_accel_block: flush timer expires in 16 [14380571]
[ 14380.559] sna_wakeup_handler
[ 14380.559] sna_block_handler (tv=117.17000)
[ 14380.559] kgem_retire, need_retire?=1
[ 14380.559] kgem_retire__flushing: 0 bo on flushing list
[ 14380.559] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.559] __kgem_retire_rq: request 1 complete
[ 14380.559] __kgem_bo_flush: handle=9, busy=0, wedged=0
[ 14380.559] kgem_retire__requests_ring: ring=0, 0 outstanding requests, oldest=0
[ 14380.559] kgem_retire__requests_ring: ring=1, 0 outstanding requests, oldest=0
[ 14380.559] kgem_retire -- retired=0, need_retire=0
[ 14380.559] kgem_retire__buffers: handle=77, busy? 0 [0]
[ 14380.559] kgem_retire__buffers: releasing upload cache for handle=77? 0
[ 14380.559] __kgem_bo_destroy: handle=77, size=262144
[ 14380.559] kgem_bo_replace_io: transferring io handle=77 to bo
[ 14380.559] kgem_bo_move_to_inactive: moving handle=77 to inactive
[ 14380.559] sna_scanout_do_flush: flush timer active: delta=12
[ 14380.559] sna_accel_do_throttle (time=14380559), triggered
[ 14380.559] sna_accel_throttle (time=14380559)
[ 14380.559] sna_accel_disarm_timer[1] (time=14380559)
[ 14380.559] sna_accel_block: evaluating timers, active=5
[ 14380.559] sna_accel_block: flush timer expires in 12 [14380571]
[ 14380.559] sna_wakeup_handler
[ 14380.559] sna_block_handler (tv=117.17000)
[ 14380.559] sna_scanout_do_flush: flush timer active: delta=12
[ 14380.559] sna_accel_do_throttle -- no pending activity
[ 14380.560] sna_accel_block: evaluating timers, active=5
[ 14380.560] sna_accel_block: flush timer expires in 12 [14380571]
[ 14380.560] sna_wakeup_handler
[ 14380.560] sna_block_handler (tv=117.16000)
[ 14380.560] sna_scanout_do_flush: flush timer active: delta=11
[ 14380.560] sna_accel_do_throttle -- no pending activity
[ 14380.560] sna_accel_block: evaluating timers, active=5
[ 14380.560] sna_accel_block: flush timer expires in 11 [14380571]
[ 14380.560] sna_wakeup_handler
[ 14380.560] sna_block_handler (tv=117.16000)
[ 14380.560] sna_scanout_do_flush: flush timer active: delta=11
[ 14380.560] sna_accel_do_throttle -- no pending activity
[ 14380.560] sna_accel_block: evaluating timers, active=5
[ 14380.560] sna_accel_block: flush timer expires in 11 [14380571]
[ 14380.560] sna_wakeup_handler
[ 14380.560] sna_set_window_pixmap: window=27263064, old pixmap=0 new pixmap=344
[ 14380.560] sna_set_window_pixmap: window=27263064, old pixmap=344 new pixmap=344
[ 14380.560] sna_change_window_attributes
[ 14380.560] sna_change_window_attributes
[ 14380.560] sna_block_handler (tv=117.16000)
[ 14380.560] sna_scanout_do_flush: flush timer active: delta=11
[ 14380.560] sna_accel_do_throttle -- no pending activity
[ 14380.560] sna_accel_block: evaluating timers, active=5
[ 14380.560] sna_accel_block: flush timer expires in 11 [14380571]
[ 14380.560] sna_wakeup_handler
[ 14380.560] sna_change_window_attributes
[ 14380.560] sna_block_handler (tv=117.16000)
[ 14380.560] sna_scanout_do_flush: flush timer active: delta=11
[ 14380.560] sna_accel_do_throttle -- no pending activity
[ 14380.560] sna_accel_block: evaluating timers, active=5
[ 14380.560] sna_accel_block: flush timer expires in 11 [14380571]
[ 14380.560] sna_wakeup_handler
[ 14380.560] sna_block_handler (tv=117.16000)
[ 14380.560] sna_scanout_do_flush: flush timer active: delta=11
[ 14380.560] sna_accel_do_throttle -- no pending activity
[ 14380.560] sna_accel_block: evaluating timers, active=5
[ 14380.560] sna_accel_block: flush timer expires in 11 [14380571]
[ 14380.560] sna_wakeup_handler
[ 14380.560] sna_set_window_pixmap: window=89, old pixmap=0 new pixmap=344
[ 14380.560] sna_set_window_pixmap: window=89, old pixmap=344 new pixmap=344
[ 14380.560] sna_change_window_attributes
[ 14380.560] sna_use_hw_cursor (24x24)?
[ 14380.560] sna_use_hw_cursor(24x24): ARGB?=1, serial->17, size->64
[ 14380.560] memcpy_blt: src=(0, 0), dst=(0, 0), size=24x24, pitch=96/256
[ 14380.566] sna_show_cursors: cursor?=1
[ 14380.566] sna_show_cursors: skipping cursor already show on CRTC (pipe=0)
[ 14380.566] sna_block_handler (tv=117.10000)
[ 14380.566] sna_scanout_do_flush: flush timer active: delta=5
[ 14380.566] sna_accel_do_throttle -- no pending activity
[ 14380.566] sna_accel_block: evaluating timers, active=5
[ 14380.566] sna_accel_block: flush timer expires in 5 [14380571]
[ 14380.566] sna_wakeup_handler
[ 14380.566] sna_hide_cursors
[ 14380.566] sna_crtc_disable_cursor: CRTC:20, handle=12
[ 14380.583] sna_block_handler (tv=0.0)
[ 14380.583] sna_wakeup_handler
[ 14380.583] sna_block_handler (tv=0.0)
[ 14380.583] sna_wakeup_handler
[ 14380.583] sna_change_window_attributes
[ 14380.583] sna_change_window_attributes
[ 14380.583] sna_block_handler (tv=116.993000)
[ 14380.583] sna_scanout_do_flush: flush timer active: delta=-12
[ 14380.583] sna_scanout_do_flush (time=14380583), triggered
[ 14380.583] sna_scanout_flush (time=14380583), cpu damage? 0, exec? 0 nbatch=0, busy? 1
[ 14380.583] has_shadow: has pending damage? 0, outstanding flips: 0
[ 14380.583] stop_flush: scanout=9 shadow?=0, slaves?=0, (cpu?=0 || gpu?=0))
[ 14380.583] has_shadow: has pending damage? 0, outstanding flips: 0
[ 14380.583] sna_mode_redisplay: posting shadow damage? 0 (flips pending? 0, mode reconfiguration pending? 0)
[ 14380.583] sna_accel_do_throttle -- no pending activity
[ 14380.583] sna_accel_block: evaluating timers, active=5
[ 14380.583] sna_accel_block: flush timer expires in 16 [14380599]
[ 14380.583] sna_wakeup_handler
[ 14380.583] sna_block_handler (tv=116.993000)
[ 14380.583] sna_scanout_do_flush: flush timer active: delta=16
[ 14380.583] sna_accel_do_throttle -- no pending activity
[ 14380.583] sna_accel_block: evaluating timers, active=5
[ 14380.583] sna_accel_block: flush timer expires in 16 [14380599]
[ 14380.583] sna_wakeup_handler
[ 14380.583] sna_block_handler (tv=116.993000)
[ 14380.583] sna_scanout_do_flush: flush timer active: delta=16
[ 14380.583] sna_accel_do_throttle -- no pending activity
[ 14380.583] sna_accel_block: evaluating timers, active=5
[ 14380.583] sna_accel_block: flush timer expires in 16 [14380599]
[ 14380.583] sna_wakeup_handler
[ 14380.583] sna_block_handler (tv=116.993000)
[ 14380.583] sna_scanout_do_flush: flush timer active: delta=16
[ 14380.583] sna_accel_do_throttle -- no pending activity
[ 14380.583] sna_accel_block: evaluating timers, active=5
[ 14380.583] sna_accel_block: flush timer expires in 16 [14380599]
[ 14380.583] sna_wakeup_handler
[ 14380.583] sna_block_handler (tv=116.993000)
[ 14380.583] sna_scanout_do_flush: flush timer active: delta=16
[ 14380.583] sna_accel_do_throttle -- no pending activity
[ 14380.583] sna_accel_block: evaluating timers, active=5
[ 14380.583] sna_accel_block: flush timer expires in 16 [14380599]
[ 14380.583] sna_wakeup_handler
[ 14380.583] sna_block_handler (tv=116.993000)
[ 14380.583] sna_scanout_do_flush: flush timer active: delta=16
[ 14380.583] sna_accel_do_throttle -- no pending activity
[ 14380.583] sna_accel_block: evaluating timers, active=5
[ 14380.583] sna_accel_block: flush timer expires in 16 [14380599]
[ 14380.583] sna_wakeup_handler
[ 14380.583] sna_create_pixmap(1280, 1024, 24, usage=0)
[ 14380.583] kgem_can_create_2d: 1280x1024 @ 24
[ 14380.583] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=5120, height=1024
[ 14380.583] kgem_can_create_2d: untiled size=5242880
[ 14380.583] kgem_choose_tiling: TLB miss between lines 1280x1024 (pitch=5120), forcing tiling 1
[ 14380.583] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=5120, height=1024
[ 14380.583] kgem_can_create_2d: tiled[-1] size=5242880
[ 14380.583] sna_create_pixmap: usage=0, flags=19
[ 14380.583] sna_create_pixmap: creating GPU pixmap 1280x1024, stride=5120, flags=19
[ 14380.583] create_pixmap: allocating pixmap 0x0, depth=24/32, size=0
[ 14380.583] create_pixmap: serial=657, usage=0, 0x0
[ 14380.583] create_pixmap_hdr: pixmap=657, width=1280, height=1024, usage=0
[ 14380.583] sna_create_pixmap: serial=657, 1280x1024, usage=0
[ 14380.583] sna_output_detect(VGA1:24)
[ 14380.584] sna_output_detect(VGA1) reporting cached status (since 5049ms): 0
[ 14380.584] sna_output_get_modes(VGA1:24)
[ 14380.584] sna_output_attach_edid: attaching EDID id=26, current=26
[ 14380.584] sna_output_attach_edid: retrieving blob id=26, length=128
[ 14380.584] sna_output_get_modes: CRTC:20, pipe=0: has mode?=1
[ 14380.584] kmode: 1280x1024, clock=108000, 1280 1328 1440 1688 0, 1024 1025 1028 1066 0, flags=5, type=48
[ 14380.584] sna_output_get_modes: adding 16 probed modes
[ 14380.584] kmode: 1280x1024, clock=108000, 1280 1328 1440 1688 0, 1024 1025 1028 1066 0, flags=5, type=48
[ 14380.584] kmode: 1280x1024, clock=135000, 1280 1296 1440 1688 0, 1024 1025 1028 1066 0, flags=5, type=40
[ 14380.584] kmode: 1152x864, clock=108000, 1152 1216 1344 1600 0, 864 865 868 900 0, flags=5, type=40
[ 14380.584] kmode: 1024x768, clock=78800, 1024 1040 1136 1312 0, 768 769 772 800 0, flags=5, type=40
[ 14380.584] kmode: 1024x768, clock=75000, 1024 1048 1184 1328 0, 768 771 777 806 0, flags=a, type=40
[ 14380.584] kmode: 1024x768, clock=65000, 1024 1048 1184 1344 0, 768 771 777 806 0, flags=a, type=40
[ 14380.584] kmode: 832x624, clock=57284, 832 864 928 1152 0, 624 625 628 667 0, flags=a, type=40
[ 14380.584] kmode: 800x600, clock=49500, 800 816 896 1056 0, 600 601 604 625 0, flags=5, type=40
[ 14380.584] kmode: 800x600, clock=50000, 800 856 976 1040 0, 600 637 643 666 0, flags=5, type=40
[ 14380.584] kmode: 800x600, clock=40000, 800 840 968 1056 0, 600 601 605 628 0, flags=5, type=40
[ 14380.584] kmode: 800x600, clock=36000, 800 824 896 1024 0, 600 601 603 625 0, flags=5, type=40
[ 14380.584] kmode: 640x480, clock=31500, 640 656 720 840 0, 480 481 484 500 0, flags=a, type=40
[ 14380.584] kmode: 640x480, clock=31500, 640 664 704 832 0, 480 489 491 520 0, flags=a, type=40
[ 14380.584] kmode: 640x480, clock=30240, 640 704 768 864 0, 480 483 486 525 0, flags=a, type=40
[ 14380.584] kmode: 640x480, clock=25200, 640 656 752 800 0, 480 490 492 525 0, flags=a, type=40
[ 14380.584] kmode: 720x400, clock=28320, 720 738 846 900 0, 400 412 414 449 0, flags=6, type=40
[ 14380.584] kgem_can_create_2d: 1280x1024 @ 32
[ 14380.584] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=5120, height=1024
[ 14380.584] kgem_can_create_2d: untiled size=5242880
[ 14380.584] kgem_choose_tiling: TLB miss between lines 1280x1024 (pitch=5120), forcing tiling 1
[ 14380.584] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=5120, height=1024
[ 14380.584] kgem_can_create_2d: tiled[-1] size=5242880
[ 14380.584] kgem_can_create_2d: 1152x864 @ 32
[ 14380.584] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=4608, height=864
[ 14380.584] kgem_can_create_2d: untiled size=3981312
[ 14380.584] kgem_choose_tiling: TLB miss between lines 1152x864 (pitch=4608), forcing tiling 1
[ 14380.584] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=4608, height=864
[ 14380.584] kgem_can_create_2d: tiled[-1] size=3981312
[ 14380.584] kgem_can_create_2d: 1024x768 @ 32
[ 14380.584] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=4096, height=768
[ 14380.584] kgem_can_create_2d: untiled size=3145728
[ 14380.584] kgem_choose_tiling: TLB miss between lines 1024x768 (pitch=4096), forcing tiling 1
[ 14380.584] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=4096, height=768
[ 14380.584] kgem_can_create_2d: tiled[-1] size=3145728
[ 14380.585] kgem_can_create_2d: 1024x768 @ 32
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=4096, height=768
[ 14380.585] kgem_can_create_2d: untiled size=3145728
[ 14380.585] kgem_choose_tiling: TLB miss between lines 1024x768 (pitch=4096), forcing tiling 1
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=4096, height=768
[ 14380.585] kgem_can_create_2d: tiled[-1] size=3145728
[ 14380.585] kgem_can_create_2d: 832x624 @ 32
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=3328, height=624
[ 14380.585] kgem_can_create_2d: untiled size=2076672
[ 14380.585] kgem_choose_tiling: TLB near-miss between lines 832x624 (pitch=3328), forcing tiling 1
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=3328, height=624
[ 14380.585] kgem_can_create_2d: tiled[-1] size=2076672
[ 14380.585] kgem_can_create_2d: 800x600 @ 32
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=3200, height=600
[ 14380.585] kgem_can_create_2d: untiled size=1921024
[ 14380.585] kgem_choose_tiling: TLB near-miss between lines 800x600 (pitch=3200), forcing tiling 1
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=3200, height=600
[ 14380.585] kgem_can_create_2d: tiled[-1] size=1921024
[ 14380.585] kgem_can_create_2d: 800x600 @ 32
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=3200, height=600
[ 14380.585] kgem_can_create_2d: untiled size=1921024
[ 14380.585] kgem_choose_tiling: TLB near-miss between lines 800x600 (pitch=3200), forcing tiling 1
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=3200, height=600
[ 14380.585] kgem_can_create_2d: tiled[-1] size=1921024
[ 14380.585] kgem_can_create_2d: 640x480 @ 32
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=2560, height=480
[ 14380.585] kgem_can_create_2d: untiled size=1228800
[ 14380.585] kgem_choose_tiling: TLB near-miss between lines 640x480 (pitch=2560), forcing tiling 1
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=2560, height=480
[ 14380.585] kgem_can_create_2d: tiled[-1] size=1228800
[ 14380.585] kgem_can_create_2d: 640x480 @ 32
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=2560, height=480
[ 14380.585] kgem_can_create_2d: untiled size=1228800
[ 14380.585] kgem_choose_tiling: TLB near-miss between lines 640x480 (pitch=2560), forcing tiling 1
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=2560, height=480
[ 14380.585] kgem_can_create_2d: tiled[-1] size=1228800
[ 14380.585] kgem_can_create_2d: 720x400 @ 32
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=2880, height=400
[ 14380.585] kgem_can_create_2d: untiled size=1155072
[ 14380.585] kgem_choose_tiling: TLB near-miss between lines 720x400 (pitch=2880), forcing tiling 1
[ 14380.585] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=2880, height=400
[ 14380.585] kgem_can_create_2d: tiled[-1] size=1155072
[ 14380.585] sna_output_detect(VIRTUAL1) has user modes? 0
[ 14380.585] sna_block_handler (tv=116.991000)
[ 14380.585] sna_scanout_do_flush: flush timer active: delta=14
[ 14380.585] sna_accel_do_throttle -- no pending activity
[ 14380.585] sna_accel_block: evaluating timers, active=5
[ 14380.585] sna_accel_block: flush timer expires in 14 [14380599]
[ 14380.585] sna_wakeup_handler
[ 14380.585] sna_validate_gc(0x7fa3ae86e590) changes=0, previous serial=168, drawable=28f
[ 14380.585] sna_validate_gc: recomputing clip
[ 14380.585] sna_validate_gc: composite clip=0x[(0, 0), (0, 0)] [0x7fa3ae887ed0]
[ 14380.585] sna_copy_area: src=(579, 460)x(148, 128)+(0, 0) -> dst=(579, 460)+(0, 0); alu=3, pm=ffffffffffffffff, depth=24
[ 14380.585] sna_do_copy: src=(579, 460), dst=(579, 460), size=(148x128)
[ 14380.585] sna_do_copy: after drawable: src=(579, 460), dst=(579, 460), size=(148x128)
[ 14380.585] sna_do_copy: dst extents (579, 460), (727, 588), dst clip extents (0, 0), (0, 0), dst size=1280x1024
[ 14380.586] sna_do_copy: dst clipped out
[ 14380.586] sna_block_handler (tv=116.990000)
[ 14380.586] sna_scanout_do_flush: flush timer active: delta=13
[ 14380.586] sna_accel_do_throttle -- no pending activity
[ 14380.586] sna_accel_block: evaluating timers, active=5
[ 14380.586] sna_accel_block: flush timer expires in 13 [14380599]
[ 14380.589] sna_wakeup_handler
[ 14380.589] sna_create_pixmap(1280, 1024, 24, usage=2)
[ 14380.589] kgem_can_create_2d: 1280x1024 @ 24
[ 14380.589] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=5120, height=1024
[ 14380.589] kgem_can_create_2d: untiled size=5242880
[ 14380.589] kgem_choose_tiling: TLB miss between lines 1280x1024 (pitch=5120), forcing tiling 1
[ 14380.589] kgem_surface_size: tile_width=8, tile_height=1 => aligned pitch=5120, height=1024
[ 14380.589] kgem_can_create_2d: tiled[-1] size=5242880
[ 14380.589] sna_create_pixmap: usage=2, flags=19
[ 14380.589] sna_create_pixmap: creating GPU pixmap 1280x1024, stride=5120, flags=19
[ 14380.589] create_pixmap: allocating pixmap 0x0, depth=24/32, size=0
[ 14380.589] create_pixmap: serial=659, usage=0, 0x0
[ 14380.589] create_pixmap_hdr: pixmap=659, width=1280, height=1024, usage=0
[ 14380.589] sna_create_pixmap: serial=659, 1280x1024, usage=0
[ 14380.589] sna_validate_gc(0x7fa3ae546dd0) changes=7fffff, previous serial=80000000, drawable=293
[ 14380.589] sna_validate_gc: recomputing clip
[ 14380.589] sna_validate_gc: composite clip=1x[(0, 0), (1280, 1024)] [0x7fa3ae85d780]
[ 14380.589] sna_copy_area: src=(0, 0)x(1280, 1024)+(0, 0) -> dst=(0, 0)+(0, 0); alu=3, pm=ffffffffffffffff, depth=24
[ 14380.589] sna_do_copy: src=(0, 0), dst=(0, 0), size=(1280x1024)
[ 14380.589] sna_do_copy: after drawable: src=(0, 0), dst=(0, 0), size=(1280x1024)
[ 14380.589] sna_do_copy: dst extents (0, 0), (1280, 1024), dst clip extents (0, 0), (1280, 1024), dst size=1280x1024
[ 14380.589] sna_do_copy: clipped dst extents (0, 0), (1280, 1024)
[ 14380.589] sna_do_copy: unclipped src extents (0, 0), (1280, 1024)
[ 14380.589] sna_do_copy: clipped src extents (0, 0), (1280, 1024)
[ 14380.589] sna_do_copy: window -- include inferiors
[ 14380.589] sna_do_copy: src extents (0, 0), (1280, 1024) x 1
[ 14380.589] sna_do_copy: copy region (0, 0), (1280, 1024) x 1 + (0, 0)
[ 14380.589] sna_copy_boxes (boxes=1x[(0, 0), (1280, 1024)...], src pixmap=344+(0, 0), dst pixmap=659+(0, 0), alu=3, src.size=1280x1024, dst.size=1280x1024)
[ 14380.589] sna_copy_boxes: dst=(priv=0x7fa3ae8ffcb0, gpu_bo=0, cpu_bo=0), src=(priv=0x7fa3ae546a80, gpu_bo=9, cpu_bo=0), replaces=1
[ 14380.589] copy_prefer_gpu: source has gpu damage, force gpu? 1
[ 14380.589] sna_drawable_use_bo pixmap=659, box=((0, 0), (1280, 1024)), flags=1b...
[ 14380.589] sna_drawable_use_bo: flush=0, shm=0, cpu=0 => flags=1b
[ 14380.589] sna_drawable_use_bo: gpu? 0, damaged? 0; cpu? 0, damaged? 0
[ 14380.589] sna_pixmap_move_to_gpu(pixmap=659, usage=0), flags=4b
[ 14380.589] sna_pixmap_move_to_gpu: CPU damage? 0
[ 14380.589] sna_pixmap_move_to_gpu: creating GPU bo (1280x1024@32), create=9
[ 14380.589] kgem_choose_tiling: TLB miss between lines 1280x1024 (pitch=5120), forcing tiling 1
[ 14380.589] kgem_choose_tiling: TLB miss between lines 1280x1024 (pitch=5120), forcing tiling 1
[ 14380.589] sna_pixmap_alloc_gpu: pixmap=659
[ 14380.589] kgem_create_2d(1280x1024, bpp=32, tiling=1, exact=1, inactive=0, cpu-mapping=0, gtt-mapping=0, scanout?=0, prime?=0, temp?=0)
[ 14380.589] kgem_surface_size: tile_width=512, tile_height=8 => aligned pitch=5120, height=1024
[ 14380.589] kgem_bo_remove_from_inactive: removing handle=14 from inactive
[ 14380.589]   from inactive: pitch=5120, tiling=1: handle=14, id=543
[ 14380.589] __sna_damage_all(1280, 1024)
[ 14380.589] sna_pixmap_move_to_gpu: marking as all-damaged for GPU
[ 14380.589] sna_pixmap_mark_active: pixmap=659, handle=14
[ 14380.589] sna_drawable_use_bo: allocated GPU bo for operation
[ 14380.589] sna_drawable_use_bo: using GPU bo with damage? 0
[ 14380.589] move_to_gpu: has gpu bo (cpu damage?=0, cpu=1, gpu tiling=1)
[ 14380.589] sna_pixmap_move_to_gpu(pixmap=344, usage=16), flags=a
[ 14380.589] _sna_damage_is_all(1280, 1024)?
[ 14380.589] _sna_damage_is_all: (0, 0), (1280, 1024)
[ 14380.589] _sna_damage_is_all: no, not singular
[ 14380.589] sna_pixmap_move_to_gpu: CPU damage? 0
[ 14380.590] sna_damage_reduce_all(width=1280, height=1024)
[ 14380.590] sna_pixmap_mark_active: pixmap=344, handle=9
[ 14380.590] sna_copy_boxes: move whole src_pixmap to GPU and copy
[ 14380.590] sna_pixmap_make_cow: make cow src=344, dst=659, handle=9 (already cow? src=0, dst=0)
[ 14380.590] sna_pixmap_make_cow: moo! attaching source cow to pixmap=344, handle=9
[ 14380.590] _kgem_bo_destroy: handle=14, proxy? 0
[ 14380.590] __kgem_bo_destroy: handle=14, size=10485760
[ 14380.590] kgem_bo_move_to_inactive: moving handle=14 to inactive
[ 14380.590] sna_pixmap_make_cow: moo! attaching clone to pixmap=659 (source=344, handle=9)
[ 14380.590] sna_set_window_pixmap: window=8388611, old pixmap=344 new pixmap=659
[ 14380.590] sna_block_handler (tv=116.986000)
[ 14380.590] sna_scanout_do_flush: flush timer active: delta=9
[ 14380.590] sna_accel_do_throttle -- no pending activity
[ 14380.590] sna_accel_block: evaluating timers, active=5
[ 14380.590] sna_accel_block: flush timer expires in 9 [14380599]
[ 14380.590] sna_wakeup_handler
[ 14380.590] sna_block_handler (tv=116.986000)
[ 14380.590] sna_scanout_do_flush: flush timer active: delta=9
[ 14380.590] sna_accel_do_throttle -- no pending activity
[ 14380.590] sna_accel_block: evaluating timers, active=5
[ 14380.590] sna_accel_block: flush timer expires in 9 [14380599]
[ 14380.590] sna_wakeup_handler
[ 14380.590] sna_validate_gc(0x7fa3ae86e590) changes=0, previous serial=28f, drawable=296
[ 14380.590] sna_validate_gc: recomputing clip
[ 14380.590] sna_validate_gc: composite clip=1x[(0, 0), (1280, 1024)] [0x7fa3ae887ed0]
[ 14380.590] sna_copy_area: src=(0, 0)x(1280, 1024)+(0, 0) -> dst=(0, 0)+(0, 0); alu=3, pm=ffffffffffffffff, depth=24
[ 14380.590] sna_do_copy: src=(0, 0), dst=(0, 0), size=(1280x1024)
[ 14380.590] sna_do_copy: after drawable: src=(0, 0), dst=(0, 0), size=(1280x1024)
[ 14380.590] sna_do_copy: dst extents (0, 0), (1280, 1024), dst clip extents (0, 0), (1280, 1024), dst size=1280x1024
[ 14380.590] sna_do_copy: clipped dst extents (0, 0), (1280, 1024)
[ 14380.590] sna_do_copy: unclipped src extents (0, 0), (1280, 1024)
[ 14380.590] sna_do_copy: clipped src extents (0, 0), (1280, 1024)
[ 14380.590] sna_do_copy: pixmap -- no source clipping
[ 14380.590] sna_do_copy: src extents (0, 0), (1280, 1024) x 1
[ 14380.590] sna_do_copy: copy region (0, 0), (1280, 1024) x 1 + (0, 0)
[ 14380.590] sna_copy_boxes (boxes=1x[(0, 0), (1280, 1024)...], src pixmap=370+(0, 0), dst pixmap=659+(0, 0), alu=3, src.size=1280x1024, dst.size=1280x1024)
[ 14380.590] sna_copy_boxes: dst=(priv=0x7fa3ae8ffcb0, gpu_bo=9, cpu_bo=0), src=(priv=0x0, gpu_bo=0, cpu_bo=0), replaces=1
[ 14380.590] copy_prefer_gpu: source unattached, use cpu
[ 14380.590] sna_drawable_use_bo pixmap=659, box=((0, 0), (1280, 1024)), flags=18...
[ 14380.590] region_subsumes_damage?
[ 14380.590] region_subsumes_damage: region (0, 0), (1280, 1024), damage (0, 0), (1280, 1024)
[ 14380.590] region_subsumes_damage: singular region contains damage
[ 14380.590] sna_pixmap_undo_cow: pixmap=659, handle=9 [refcnt=2], cow refcnt=2, flags=41
[ 14380.590] sna_drawable_use_bo: flush=0, shm=0, cpu=0 => flags=18
[ 14380.591] sna_drawable_use_bo: try cpu as GPU bo is idle
[ 14380.591] sna_drawable_use_bo: no CPU bo, and GPU not forced
[ 14380.591] sna_copy_boxes__inplace - no, no src or dst GPU bo
[ 14380.591] sna_copy_boxes: fallback -- src=(0, 0), dst=(0, 0)
[ 14380.591] sna_drawable_move_region_to_cpu(pixmap=659 (1280x1024), [(0, 0), (1280, 1024)], flags=5)
[ 14380.591] sna_drawable_move_region_to_cpu: marking for inplace hint (0, 1)
[ 14380.591] sna_drawable_move_region_to_cpu: region (0, 0), (1280, 1024) + (0, 0) subsumes pixmap (1280x1024)
[ 14380.591] _sna_pixmap_move_to_cpu(pixmap=659, 1280x1024, flags=5)
[ 14380.591] _sna_pixmap_move_to_cpu: gpu_bo=0, gpu_damage=0x0, cpu_damage=0x0, is-clear?=0
[ 14380.591] _sna_pixmap_move_to_cpu: no readback, discarding gpu damage [0], pending clear[0]
[ 14380.591] kgem_choose_tiling: TLB miss between lines 1280x1024 (pitch=5120), forcing tiling 1
[ 14380.591] sna_pixmap_alloc_gpu: pixmap=659
[ 14380.591] kgem_create_2d(1280x1024, bpp=32, tiling=1, exact=1, inactive=1, cpu-mapping=0, gtt-mapping=1, scanout?=0, prime?=0, temp?=0)
[ 14380.591] kgem_surface_size: tile_width=512, tile_height=8 => aligned pitch=5120, height=1024
[ 14380.591] kgem_bo_remove_from_inactive: removing handle=14 from inactive
[ 14380.591]   from inactive: pitch=5120, tiling=1: handle=14, id=544
[ 14380.591] kgem_bo_can_map: handle=14, map=0x0:0x7fa3a2974000:0x7fa3a3874000, tiling=1, domain=0, offset=31866880
[ 14380.591] kgem_bo_is_busy: handle=14, domain: 0 exec? 0, rq? 0
[ 14380.591] _sna_pixmap_move_to_cpu: write inplace
[ 14380.591] kgem_bo_map: handle=14, offset=31866880, tiling=1, map=0x0:0x7fa3a3874000, domain=0
[ 14380.591] __kgem_bo_map__gtt_or_wc: handle=14
[ 14380.591] kgem_trim_vma_cache: type=0, count=-510 (bucket: 11)
[ 14380.591] __kgem_bo_map__gtt(handle=14, size=10485760)
[ 14380.591] __kgem_busy: handle=14, busy=0, wedged=0
[ 14380.591] kgem_bo_map: sync: needs_flush? 0, domain? 0, busy? 0
[ 14380.591] __kgem_busy: handle=14, busy=0, wedged=0
[ 14380.591] kgem_bo_retire: retiring bo handle=14 (needed flush? 0), rq? 0 [busy?=0]
[ 14380.591] assert_bo_retired: handle=14, domain: 0 exec? 0, rq? 0
[ 14380.591] kgem_bo_is_busy: handle=14, domain: 2 exec? 0, rq? 0
[ 14380.591] kgem_bo_is_busy: handle=14, domain: 2 exec? 0, rq? 0
[ 14380.591] kgem_bo_can_map: handle=14, map=0x0:0x7fa3a2974000:0x7fa3a3874000, tiling=1, domain=2, offset=31866880
[ 14380.591] __kgem_bo_is_busy: handle=14, domain: 2 exec? 0, rq? 0
[ 14380.591] kgem_bo_can_map: handle=14, map=0x0:0x7fa3a2974000:0x7fa3a3874000, tiling=1, domain=2, offset=31866880
[ 14380.591] kgem_bo_is_busy: handle=14, domain: 2 exec? 0, rq? 0
[ 14380.591] _sna_pixmap_move_to_cpu: try to operate inplace (GTT)
[ 14380.591] kgem_bo_map: handle=14, offset=31866880, tiling=1, map=0x0:0x7fa3a3874000, domain=2
[ 14380.591] __kgem_bo_map__gtt_or_wc: handle=14
[ 14380.591] kgem_trim_vma_cache: type=0, count=-510 (bucket: 11)
[ 14380.591] __kgem_bo_map__gtt(handle=14, size=10485760)
[ 14380.591] sna_pixmap_alloc_cpu: pixmap=659
[ 14380.591] sna_pixmap_alloc_cpu: allocating ordinary memory for shadow pixels [5242880 bytes]
[ 14380.591] _sna_pixmap_move_to_cpu: marking as damaged
[ 14380.591] __sna_damage_all(1280, 1024)
[ 14380.591] sna_pixmap_free_gpu: handle=14 (pinned? 0)
[ 14380.591] _kgem_bo_destroy: handle=14, proxy? 0
[ 14380.591] __kgem_bo_destroy: handle=14, size=10485760
[ 14380.591] kgem_bo_move_to_inactive: moving handle=14 to inactive
[ 14380.591] sna_copy_boxes: memcpy_blt(box=(0, 0), (1280, 1024), src=(0, 0), pitches=(5120, 5120))
[ 14380.591] memcpy_blt: src=(0, 0), dst=(0, 0), size=1280x1024, pitch=5120/5120
[ 14380.600] sna_block_handler (tv=116.976000)
[ 14380.600] sna_scanout_do_flush: flush timer active: delta=-1
[ 14380.600] sna_scanout_do_flush (time=14380600), triggered
[ 14380.600] sna_scanout_flush (time=14380600), cpu damage? 0, exec? 0 nbatch=0, busy? 0
[ 14380.600] has_shadow: has pending damage? 0, outstanding flips: 0
[ 14380.600] stop_flush: scanout=9 shadow?=0, slaves?=0, (cpu?=0 || gpu?=0))
[ 14380.600] has_shadow: has pending damage? 0, outstanding flips: 0
[ 14380.600] sna_accel_disarm_timer[0] (time=14380600)
[ 14380.600] sna_mode_redisplay: posting shadow damage? 0 (flips pending? 0, mode reconfiguration pending? 0)
[ 14380.600] sna_accel_do_throttle -- no pending activity
[ 14380.600] sna_wakeup_handler
[ 14380.600] sna_block_handler (tv=116.976000)
[ 14380.600] has_shadow: has pending damage? 0, outstanding flips: 0
[ 14380.600] sna_accel_do_throttle -- no pending activity
[ 14380.601] sna_wakeup_handler
[ 14380.601] sna_copy_area: src=(579, 460)x(148, 128)+(0, 0) -> dst=(579, 460)+(0, 0); alu=3, pm=ffffffffffffffff, depth=24
[ 14380.601] sna_do_copy: src=(579, 460), dst=(579, 460), size=(148x128)
[ 14380.601] sna_do_copy: after drawable: src=(579, 460), dst=(579, 460), size=(148x128)
[ 14380.601] sna_do_copy: dst extents (579, 460), (727, 588), dst clip extents (0, 0), (1280, 1024), dst size=1280x1024
[ 14380.601] sna_do_copy: clipped dst extents (579, 460), (727, 588)
[ 14380.601] sna_do_copy: unclipped src extents (579, 460), (727, 588)
[ 14380.601] sna_do_copy: clipped src extents (579, 460), (727, 588)
[ 14380.601] sna_do_copy: pixmap -- no source clipping
[ 14380.601] sna_do_copy: src extents (579, 460), (727, 588) x 1
[ 14380.601] sna_do_copy: copy region (579, 460), (727, 588) x 1 + (0, 0)
[ 14380.601] sna_copy_boxes (boxes=1x[(579, 460), (727, 588)...], src pixmap=370+(0, 0), dst pixmap=659+(0, 0), alu=3, src.size=1280x1024, dst.size=1280x1024)
[ 14380.601] sna_copy_boxes: dst=(priv=0x7fa3ae8ffcb0, gpu_bo=0, cpu_bo=0), src=(priv=0x0, gpu_bo=0, cpu_bo=0), replaces=0
[ 14380.601] copy_prefer_gpu: source unattached, use cpu
[ 14380.601] region_subsumes_damage?
[ 14380.601] region_subsumes_damage: region (579, 460), (727, 588), damage (0, 0), (1280, 1024)
[ 14380.601] region_subsumes_damage: not contained
[ 14380.601] sna_drawable_use_bo pixmap=659, box=((579, 460), (727, 588)), flags=8...
[ 14380.601] sna_drawable_use_bo: flush=0, shm=0, cpu=1 => flags=8
[ 14380.601] sna_drawable_use_bo: try cpu as GPU bo is idle
[ 14380.601] sna_drawable_use_bo: no CPU bo, and GPU not forced
[ 14380.601] sna_copy_boxes__inplace - no, no src or dst GPU bo
[ 14380.601] sna_copy_boxes: fallback -- src=(0, 0), dst=(0, 0)
[ 14380.602] sna_drawable_move_region_to_cpu(pixmap=659 (1280x1024), [(579, 460), (727, 588)], flags=5)
[ 14380.602] sna_drawable_move_region_to_cpu: pixmap=659 all damaged on CPU
[ 14380.602] sna_pixmap_free_gpu: handle=0 (pinned? 0)
[ 14380.602] sna_copy_boxes: memcpy_blt(box=(579, 460), (148, 128), src=(0, 0), pitches=(5120, 5120))
[ 14380.602] memcpy_blt: src=(579, 460), dst=(579, 460), size=148x128, pitch=5120/5120
[ 14380.602] sna_block_handler (tv=116.974000)
[ 14380.602] has_shadow: has pending damage? 0, outstanding flips: 0
[ 14380.602] sna_accel_do_throttle -- no pending activity
[ 14380.612] sna_wakeup_handler
[ 14380.613] sna_block_handler (tv=116.963000)
[ 14380.613] has_shadow: has pending damage? 0, outstanding flips: 0
[ 14380.613] sna_accel_do_throttle -- no pending activity
[ 14380.613] sna_wakeup_handler
[ 14380.613] sna_composite_rectangles(pixmap=658, op=1, ff000000 x 1 [(0, 0)x(1280, 1024) ...])
[ 14380.613] sna_composite_rectangles: converted to op 1
[ 14380.613] sna_composite_rectangles[0] (0, 0)x(1280, 1024) -> (0, 0), (1280, 1024)
[ 14380.613] sna_composite_rectangles: nrects=1, region=(0, 0), (1280, 1024) x 1
[ 14380.613] sna_composite_rectangles: clipped extents (0, 0),(1280, 1024) x 1
[ 14380.613] sna_composite_rectangles: pixmap +(0, 0) extents (0, 0),(1280, 1024)
[ 14380.613] sna_composite_rectangles: dropping last-cpu hint
[ 14380.613] sna_drawable_use_bo pixmap=658, box=((0, 0), (1280, 1024)), flags=19...
[ 14380.613] sna_drawable_use_bo: flush=0, shm=0, cpu=0 => flags=19
[ 14380.613] sna_drawable_use_bo: gpu? 0, damaged? 0; cpu? 0, damaged? 0
[ 14380.613] sna_pixmap_move_to_gpu(pixmap=658, usage=0), flags=b
[ 14380.613] sna_pixmap_move_to_gpu: CPU damage? 0
[ 14380.613] sna_pixmap_move_to_gpu: creating GPU bo (1280x1024@32), create=9
[ 14380.613] kgem_choose_tiling: TLB miss between lines 1280x1024 (pitch=5120), forcing tiling 1
[ 14380.613] kgem_choose_tiling: TLB miss between lines 1280x1024 (pitch=5120), forcing tiling 1
[ 14380.613] sna_pixmap_alloc_gpu: pixmap=658
[ 14380.613] kgem_create_2d(1280x1024, bpp=32, tiling=1, exact=1, inactive=0, cpu-mapping=0, gtt-mapping=0, scanout?=0, prime?=0, temp?=0)
[ 14380.613] kgem_surface_size: tile_width=512, tile_height=8 => aligned pitch=5120, height=1024
[ 14380.613] kgem_bo_remove_from_inactive: removing handle=14 from inactive
[ 14380.613]   from inactive: pitch=5120, tiling=1: handle=14, id=545
[ 14380.613] __sna_damage_all(1280, 1024)
[ 14380.613] sna_pixmap_move_to_gpu: marking as all-damaged for GPU
[ 14380.613] sna_pixmap_mark_active: pixmap=658, handle=14
[ 14380.613] sna_drawable_use_bo: allocated GPU bo for operation
[ 14380.613] sna_drawable_use_bo: using GPU bo with damage? 0
[ 14380.613] sna_blt_fill_boxes (32, ff000000, 3) x 1
[ 14380.613] sna_blt_fill_box: box=((0, 0), (1280, 1024))
[ 14380.613] kgem_add_reloc: handle=14, pos=4, delta=0, domains=28002
[ 14380.613] kgem_add_handle: handle=14, index=0
[ 14380.613] __kgem_bo_mark_dirty: handle=14 (proxy? 0)
[ 14380.613] sna_composite_rectangles: pixmap=658 marking clear [ff000000]? 1
[ 14380.613] sna_composite(pixmap=344, op=1, src=658+(0, 0), mask=0+(0, 0), dst=344+(0, 0)+(0, 0), size=(1280, 1024)
[ 14380.613] sna_compute_composite_region: dst=(0, 0)x(1280, 1024)
[ 14380.613] sna_compute_composite_region: initial clip against dst->pDrawable: (0, 0), (1280, 1024)
[ 14380.613] clip_to_dst: region: 1x[(0, 0), (1280, 1024)], clip: 1x[(0, 0), (1280, 1024)]
[ 14380.613] sna_compute_composite_region: clip against dst->pCompositeClip: (0, 0), (1280, 1024)
[ 14380.613] sna_compute_composite_region: clip against src (1280x1024 clip=0): (0, 0), (1280, 1024)
[ 14380.614] sna_composite: composite region extents:+(0, 0) -> (0, 0), (1280, 1024) + (0, 0)
[ 14380.614] gen4_render_composite: 1280x1024, current mode=3
[ 14380.614] sna_blt_composite (0, 0), (0, 0), 1280x1024
[ 14380.614] sna_transform_is_imprecise_integer_translation: no transform
[ 14380.614] sna_blt_composite: converting transform to integer translation? (0, 0)
[ 14380.614] color_convert: src=ff000000 [20020888]
[ 14380.614] color_convert: dst=ff000000 [20020888]
[ 14380.614] sna_drawable_use_bo pixmap=344, box=((0, 0), (1280, 1024)), flags=19...
[ 14380.614] region_subsumes_damage?
[ 14380.614] region_subsumes_damage: region (0, 0), (1280, 1024), damage (0, 0), (1280, 1024)
[ 14380.614] region_subsumes_damage: singular region contains damage
[ 14380.614] sna_pixmap_undo_cow: pixmap=344, handle=9 [refcnt=1], cow refcnt=1, flags=41
[ 14380.614] sna_pixmap_undo_cow: freeing cow
[ 14380.614] sna_drawable_use_bo: flush=0, shm=0, cpu=1 => flags=19
[ 14380.614] sna_drawable_use_bo: gpu? 9, damaged? 1; cpu? 0, damaged? 0
[ 14380.614] sna_drawable_use_bo extents (0, 0), (1280, 1024)
[ 14380.614] sna_pixmap_move_to_gpu(pixmap=344, usage=16), flags=1
[ 14380.614] _sna_damage_is_all(1280, 1024)?
[ 14380.614] _sna_damage_is_all: (0, 0), (1280, 1024)
[ 14380.614] _sna_damage_is_all: no, not singular
[ 14380.614] sna_pixmap_move_to_gpu: CPU damage? 0
[ 14380.614] sna_damage_reduce_all(width=1280, height=1024)
[ 14380.614] sna_pixmap_mark_active: pixmap=344, handle=9
[ 14380.614] sna_drawable_use_bo: using whole GPU bo
[ 14380.614] prepare_blt_fill
[ 14380.614] kgem_set_mode: flushing before new bo
[ 14380.614] batch[3/0, flags=1800]: 8 8 65528 65528, nreloc=1, nexec=1, nfence=0, aperture=2560 [fenced=0]
[ 14380.614] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.614] kgem_commit: release handle=1 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=f40000
[ 14380.614] kgem_commit: release handle=14 (proxy? 0), dirty? 1 flush? 1, snoop? 0 -> offset=1e64000
[ 14380.614] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.614] kgem_add_reloc: handle=9, pos=4, delta=0, domains=28002
[ 14380.614] kgem_add_handle: handle=9, index=0
[ 14380.614] __kgem_bo_mark_dirty: handle=9 (proxy? 0)
[ 14380.614] _sna_blt_fill_box: (0, 0), (1280, 1024): ff000000
[ 14380.614] _sna_blt_maybe_clear: pixmap=344 marking clear [ff000000]
[ 14380.614] apply_damage: damage=0x0, region=1 [(0, 0), (1280, 1024) + (0, 0)]
[ 14380.614] sna_block_handler (tv=116.962000)
[ 14380.614] kgem_retire, need_retire?=1
[ 14380.614] kgem_retire__flushing: 0 bo on flushing list
[ 14380.614] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.614] kgem_retire__requests_ring: ring=0, 1 outstanding requests, oldest=1
[ 14380.614] kgem_retire__requests_ring: ring=1, 0 outstanding requests, oldest=0
[ 14380.614] kgem_retire -- retired=0, need_retire=1
[ 14380.614] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.614] __kgem_ring_is_idle: last fence handle=1 still busy
[ 14380.614] has_shadow: has pending damage? 1, outstanding flips: 0
[ 14380.614] start_flush: has dirty shadow
[ 14380.614] timer_enable (time=14380614), starting timer 0
[ 14380.614] timer_enable (time=14380614), starting timer 1
[ 14380.614] sna_accel_block: evaluating timers, active=7
[ 14380.614] sna_accel_block: flush timer expires in 8 [14380622]
[ 14380.614] sna_wakeup_handler
[ 14380.614] sna_block_handler (tv=116.962000)
[ 14380.615] kgem_retire, need_retire?=1
[ 14380.615] kgem_retire__flushing: 0 bo on flushing list
[ 14380.615] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.615] kgem_retire__requests_ring: ring=0, 1 outstanding requests, oldest=1
[ 14380.615] kgem_retire__requests_ring: ring=1, 0 outstanding requests, oldest=0
[ 14380.615] kgem_retire -- retired=0, need_retire=1
[ 14380.615] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.615] __kgem_ring_is_idle: last fence handle=1 still busy
[ 14380.615] sna_scanout_do_flush: flush timer active: delta=7
[ 14380.615] sna_accel_block: evaluating timers, active=7
[ 14380.615] sna_accel_block: flush timer expires in 7 [14380622]
[ 14380.615] sna_wakeup_handler
[ 14380.615] sna_block_handler (tv=116.961000)
[ 14380.615] kgem_retire, need_retire?=1
[ 14380.615] kgem_retire__flushing: 0 bo on flushing list
[ 14380.615] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.615] kgem_retire__requests_ring: ring=0, 1 outstanding requests, oldest=1
[ 14380.615] kgem_retire__requests_ring: ring=1, 0 outstanding requests, oldest=0
[ 14380.615] kgem_retire -- retired=0, need_retire=1
[ 14380.615] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.615] __kgem_ring_is_idle: last fence handle=1 still busy
[ 14380.615] sna_scanout_do_flush: flush timer active: delta=7
[ 14380.615] sna_accel_block: evaluating timers, active=7
[ 14380.615] sna_accel_block: flush timer expires in 7 [14380622]
[ 14380.615] sna_wakeup_handler
[ 14380.615] sna_block_handler (tv=116.961000)
[ 14380.615] kgem_retire, need_retire?=1
[ 14380.615] kgem_retire__flushing: 0 bo on flushing list
[ 14380.615] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.615] kgem_retire__requests_ring: ring=0, 1 outstanding requests, oldest=1
[ 14380.615] kgem_retire__requests_ring: ring=1, 0 outstanding requests, oldest=0
[ 14380.615] kgem_retire -- retired=0, need_retire=1
[ 14380.615] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.615] __kgem_ring_is_idle: last fence handle=1 still busy
[ 14380.615] sna_scanout_do_flush: flush timer active: delta=7
[ 14380.615] sna_accel_block: evaluating timers, active=7
[ 14380.615] sna_accel_block: flush timer expires in 7 [14380622]
[ 14380.616] sna_wakeup_handler
[ 14380.616] sna_copy_area: src=(579, 460)x(148, 128)+(0, 0) -> dst=(579, 460)+(0, 0); alu=3, pm=ffffffffffffffff, depth=24
[ 14380.616] sna_do_copy: src=(579, 460), dst=(579, 460), size=(148x128)
[ 14380.616] sna_do_copy: after drawable: src=(579, 460), dst=(579, 460), size=(148x128)
[ 14380.616] sna_do_copy: dst extents (579, 460), (727, 588), dst clip extents (0, 0), (1280, 1024), dst size=1280x1024
[ 14380.616] sna_do_copy: clipped dst extents (579, 460), (727, 588)
[ 14380.616] sna_do_copy: unclipped src extents (579, 460), (727, 588)
[ 14380.616] sna_do_copy: clipped src extents (579, 460), (727, 588)
[ 14380.616] sna_do_copy: pixmap -- no source clipping
[ 14380.616] sna_do_copy: src extents (579, 460), (727, 588) x 1
[ 14380.616] sna_do_copy: copy region (579, 460), (727, 588) x 1 + (0, 0)
[ 14380.616] sna_copy_boxes (boxes=1x[(579, 460), (727, 588)...], src pixmap=370+(0, 0), dst pixmap=659+(0, 0), alu=3, src.size=1280x1024, dst.size=1280x1024)
[ 14380.616] sna_copy_boxes: dst=(priv=0x7fa3ae8ffcb0, gpu_bo=0, cpu_bo=0), src=(priv=0x0, gpu_bo=0, cpu_bo=0), replaces=0
[ 14380.616] copy_prefer_gpu: source unattached, use cpu
[ 14380.616] region_subsumes_damage?
[ 14380.616] region_subsumes_damage: region (579, 460), (727, 588), damage (0, 0), (1280, 1024)
[ 14380.616] region_subsumes_damage: not contained
[ 14380.616] sna_drawable_use_bo pixmap=659, box=((579, 460), (727, 588)), flags=8...
[ 14380.616] sna_drawable_use_bo: flush=0, shm=0, cpu=1 => flags=8
[ 14380.616] sna_drawable_use_bo: try cpu as GPU bo is idle
[ 14380.616] sna_drawable_use_bo: no CPU bo, and GPU not forced
[ 14380.616] sna_copy_boxes__inplace - no, no src or dst GPU bo
[ 14380.616] sna_copy_boxes: fallback -- src=(0, 0), dst=(0, 0)
[ 14380.616] sna_drawable_move_region_to_cpu(pixmap=659 (1280x1024), [(579, 460), (727, 588)], flags=5)
[ 14380.616] sna_drawable_move_region_to_cpu: pixmap=659 all damaged on CPU
[ 14380.616] sna_pixmap_free_gpu: handle=0 (pinned? 0)
[ 14380.616] sna_copy_boxes: memcpy_blt(box=(579, 460), (148, 128), src=(0, 0), pitches=(5120, 5120))
[ 14380.616] memcpy_blt: src=(579, 460), dst=(579, 460), size=148x128, pitch=5120/5120
[ 14380.617] sna_block_handler (tv=116.959000)
[ 14380.617] kgem_retire, need_retire?=1
[ 14380.617] kgem_retire__flushing: 0 bo on flushing list
[ 14380.617] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.617] __kgem_retire_rq: request 1 complete
[ 14380.617] __kgem_bo_flush: handle=14, busy=0, wedged=0
[ 14380.617] kgem_retire__requests_ring: ring=0, 0 outstanding requests, oldest=0
[ 14380.617] kgem_retire__requests_ring: ring=1, 0 outstanding requests, oldest=0
[ 14380.617] kgem_retire -- retired=0, need_retire=0
[ 14380.617] sna_accel_block: GPU idle, flushing
[ 14380.617] batch[3/0, flags=1800]: 14 14 65528 65528, nreloc=1, nexec=1, nfence=0, aperture=1280 [fenced=0]
[ 14380.617] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.617] kgem_commit: release handle=1 (proxy? 0), dirty? 0 flush? 0, snoop? 0 -> offset=f40000
[ 14380.617] kgem_commit: release handle=9 (proxy? 0), dirty? 1 flush? 1, snoop? 0 -> offset=a40000
[ 14380.617] __kgem_busy: handle=1, busy=65537, wedged=0
[ 14380.617] sna_scanout_do_flush: flush timer active: delta=5
[ 14380.617] sna_accel_block: evaluating timers, active=7
[ 14380.617] sna_accel_block: flush timer expires in 5 [14380622]
[ 14380.618] sna_wakeup_handler
[ 14380.618] sna_block_handler (tv=116.958000)
[ 14380.618] kgem_retire, need_retire?=1
[ 14380.618] kgem_retire__flushing: 0 bo on flushing list
[ 14380.618] __kgem_busy: handle=1, busy=0, wedged=0
[ 14380.618] __kgem_retire_rq: request 1 complete
[ 14380.618] __kgem_bo_flush: handle=9, busy=0, wedged=0
[ 14380.618] kgem_retire__requests_ring: ring=0, 0 outstanding requests, oldest=0
[ 14380.618] kgem_retire__requests_ring: ring=1, 0 outstanding requests, oldest=0
[ 14380.618] kgem_retire -- retired=0, need_retire=0
[ 14380.618] sna_scanout_do_flush: flush timer active: delta=4
[ 14380.619] sna_accel_block: evaluating timers, active=7
[ 14380.619] sna_accel_block: flush timer expires in 4 [14380622]
[ 14380.619] sna_wakeup_handler
[ 14380.619] sna_block_handler (tv=116.957000)
[ 14380.619] sna_scanout_do_flush: flush timer active: delta=3
[ 14380.619] sna_scanout_do_flush (time=14380619), triggered
[ 14380.619] sna_scanout_flush (time=14380619), cpu damage? 0, exec? 0 nbatch=0, busy? 0
[ 14380.619] has_shadow: has pending damage? 1, outstanding flips: 0
[ 14380.619] stop_flush: scanout=9 shadow?=1, slaves?=0, (cpu?=0 || gpu?=0))
[ 14380.619] has_shadow: has pending damage? 1, outstanding flips: 0
[ 14380.619] sna_mode_redisplay: posting shadow damage? 1 (flips pending? 0, mode reconfiguration pending? 0)
[ 14380.619] sna_mode_redisplay: damage: 1x(0, 0), (1280, 1024)
[ 14380.619] move_crtc_to_gpu: CRTC 20 [pipe=0] requires frontbuffer
[ 14380.619] sna_pixmap_move_to_gpu(pixmap=344, usage=16), flags=10a
[ 14380.619] (EE) 
[ 14380.619] (EE) Backtrace:
[ 14380.619] (EE) 0: /usr/bin/X (xorg_backtrace+0x56) [0x7fa3acf4ed46]
[ 14380.619] (EE) 1: /usr/lib/xorg/modules/drivers/intel_drv.so (0x7fa3a6d32000+0x4b8a5) [0x7fa3a6d7d8a5]
[ 14380.619] (EE) 2: /usr/lib/xorg/modules/drivers/intel_drv.so (0x7fa3a6d32000+0x5a611) [0x7fa3a6d8c611]
[ 14380.619] (EE) 3: /usr/lib/xorg/modules/drivers/intel_drv.so (0x7fa3a6d32000+0xca234) [0x7fa3a6dfc234]
[ 14380.619] (EE) 4: /usr/lib/xorg/modules/drivers/intel_drv.so (0x7fa3a6d32000+0xca566) [0x7fa3a6dfc566]
[ 14380.619] (EE) 5: /usr/lib/xorg/modules/drivers/intel_drv.so (0x7fa3a6d32000+0x912a0) [0x7fa3a6dc32a0]
[ 14380.620] (EE) 6: /usr/lib/xorg/modules/drivers/intel_drv.so (0x7fa3a6d32000+0x92a37) [0x7fa3a6dc4a37]
[ 14380.620] (EE) 7: /usr/lib/xorg/modules/drivers/intel_drv.so (0x7fa3a6d32000+0xcff4f) [0x7fa3a6e01f4f]
[ 14380.620] (EE) 8: /usr/bin/X (BlockHandler+0x4a) [0x7fa3acdf3f2a]
[ 14380.620] (EE) 9: /usr/bin/X (WaitForSomething+0x132) [0x7fa3acf4bf62]
[ 14380.620] (EE) 10: /usr/bin/X (0x7fa3acd98000+0x57211) [0x7fa3acdef211]
[ 14380.620] (EE) 11: /usr/bin/X (0x7fa3acd98000+0x5b596) [0x7fa3acdf3596]
[ 14380.620] (EE) 12: /lib/x86_64-linux-gnu/libc.so.6 (__libc_start_main+0xf5) [0x7fa3aaaadb45]
[ 14380.620] (EE) 13: /usr/bin/X (0x7fa3acd98000+0x4590e) [0x7fa3acddd90e]
[ 14380.620] (EE) 
[ 14380.620] (EE) 
Fatal server error:
[ 14380.620] (EE) assert_pixmap_damage:382 assertion 'DAMAGE_IS_ALL(priv->gpu_damage)' failed
[ 14380.620] (EE) 
[ 14380.620] (EE) 
Please consult the The X.Org Foundation support 
	 at http://wiki.x.org
 for help. 
[ 14380.620] (EE) Please also check the log file at "/var/log/Xorg.0.log" for additional information.
[ 14380.620] (EE) 
[ 14380.621] (II) AIGLX: Suspending AIGLX clients for VT switch
[ 14380.621] sna_leave_vt
[ 14380.621] sna_accel_leave
[ 14380.621] sna_mode_reset
[ 14380.621] sna_disable_cursors
[ 14380.633] sna_crtc_disable_shadow: disabling for crtc 20
[ 14380.633] sna_mode_disable_shadow
[ 14380.633] __sna_crtc_disable: releasing handle=11 from scanout, active=0
[ 14380.633] _kgem_bo_destroy: handle=11, proxy? 0
[ 14380.633] __kgem_bo_destroy: handle=11, size=5242880
[ 14380.633] kgem_bo_move_to_scanout: moving 11 [fb 44] to scanout cache, active? 0
[ 14380.633] rotation_set: obj=21, type=eeeeeeee prop=18 set-rotation=1
[ 14380.664] (EE) Server terminated with error (1). Closing log file.