Results for igt@kms_flip@flip-vs-expired-vblank

shard-dg2-436

IGT-Version: 1.30-g1c7089f61 (x86_64) (Linux: 6.14.0-rc5-xe+ x86_64)

Using IGT_SRANDOM=1741098652 for randomisation
Opened device: /dev/dri/card1
Using monotonic timestamps
Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-HDMI-A6
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Dynamic subtest A-HDMI-A6: SUCCESS (4.050s)
Starting dynamic subtest: B-HDMI-A6
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A6: FAIL (3.431s)
Starting dynamic subtest: C-HDMI-A6
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-HDMI-A6: FAIL (0.224s)
Starting dynamic subtest: D-HDMI-A6
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest D-HDMI-A6: FAIL (3.398s)
Starting dynamic subtest: A-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-DP4: FAIL (2.962s)
Starting dynamic subtest: B-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-DP4: FAIL (0.259s)
Starting dynamic subtest: C-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Dynamic subtest C-DP4: SUCCESS (3.969s)
Starting dynamic subtest: D-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest D-DP4: FAIL (2.936s)
Subtest flip-vs-expired-vblank: FAIL (21.265s)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2246 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2934 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2390 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-HDMI-A6
Dynamic subtest A-HDMI-A6: SUCCESS (4.050s)
Starting dynamic subtest: B-HDMI-A6
(kms_flip:3773) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3773) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-HDMI-A6 failed.
**** DEBUG ****
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.522064
last_received_ts = 295.521454
last_seq = 4865
current_ts = 295.538727
current_received_ts = 295.538116
current_seq = 4866
count = 51
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.538727
last_received_ts = 295.538116
last_seq = 4866
current_ts = 295.555389
current_received_ts = 295.554779
current_seq = 4867
count = 52
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.555389
last_received_ts = 295.554779
last_seq = 4867
current_ts = 295.572052
current_received_ts = 295.571442
current_seq = 4868
count = 53
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.572052
last_received_ts = 295.571442
last_seq = 4868
current_ts = 295.588715
current_received_ts = 295.588135
current_seq = 4869
count = 54
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.588715
last_received_ts = 295.588135
last_seq = 4869
current_ts = 295.605408
current_received_ts = 295.604797
current_seq = 4870
count = 55
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.605408
last_received_ts = 295.604797
last_seq = 4870
current_ts = 295.622070
current_received_ts = 295.621460
current_seq = 4871
count = 56
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.622070
last_received_ts = 295.621460
last_seq = 4871
current_ts = 295.638733
current_received_ts = 295.638123
current_seq = 4872
count = 57
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.638733
last_received_ts = 295.638123
last_seq = 4872
current_ts = 295.655396
current_received_ts = 295.654785
current_seq = 4873
count = 58
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.655396
last_received_ts = 295.654785
last_seq = 4873
current_ts = 295.672058
current_received_ts = 295.671478
current_seq = 4874
count = 59
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.672058
last_received_ts = 295.671478
last_seq = 4874
current_ts = 295.688751
current_received_ts = 295.688141
current_seq = 4875
count = 60
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.688751
last_received_ts = 295.688141
last_seq = 4875
current_ts = 295.705414
current_received_ts = 295.704803
current_seq = 4876
count = 61
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.705414
last_received_ts = 295.704803
last_seq = 4876
current_ts = 295.722076
current_received_ts = 295.721466
current_seq = 4877
count = 62
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.722076
last_received_ts = 295.721466
last_seq = 4877
current_ts = 295.738739
current_received_ts = 295.738129
current_seq = 4878
count = 63
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.738739
last_received_ts = 295.738129
last_seq = 4878
current_ts = 295.755402
current_received_ts = 295.754822
current_seq = 4879
count = 64
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.755402
last_received_ts = 295.754822
last_seq = 4879
current_ts = 295.772095
current_received_ts = 295.771484
current_seq = 4880
count = 65
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.772095
last_received_ts = 295.771484
last_seq = 4880
current_ts = 295.788757
current_received_ts = 295.788147
current_seq = 4881
count = 66
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.788757
last_received_ts = 295.788147
last_seq = 4881
current_ts = 295.805420
current_received_ts = 295.804810
current_seq = 4882
count = 67
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.805420
last_received_ts = 295.804810
last_seq = 4882
current_ts = 295.822083
current_received_ts = 295.821472
current_seq = 4883
count = 68
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.822083
last_received_ts = 295.821472
last_seq = 4883
current_ts = 295.838745
current_received_ts = 295.838135
current_seq = 4884
count = 69
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.838745
last_received_ts = 295.838135
last_seq = 4884
current_ts = 295.855438
current_received_ts = 295.854828
current_seq = 4885
count = 70
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.855438
last_received_ts = 295.854828
last_seq = 4885
current_ts = 295.872101
current_received_ts = 295.871490
current_seq = 4886
count = 71
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.872101
last_received_ts = 295.871490
last_seq = 4886
current_ts = 295.888763
current_received_ts = 295.888153
current_seq = 4887
count = 72
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.888763
last_received_ts = 295.888153
last_seq = 4887
current_ts = 295.905426
current_received_ts = 295.904816
current_seq = 4888
count = 73
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.905426
last_received_ts = 295.904816
last_seq = 4888
current_ts = 295.922089
current_received_ts = 295.921509
current_seq = 4889
count = 74
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.922089
last_received_ts = 295.921509
last_seq = 4889
current_ts = 295.938782
current_received_ts = 295.938171
current_seq = 4890
count = 75
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.938782
last_received_ts = 295.938171
last_seq = 4890
current_ts = 295.955444
current_received_ts = 295.954834
current_seq = 4891
count = 76
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.955444
last_received_ts = 295.954834
last_seq = 4891
current_ts = 295.972107
current_received_ts = 295.971497
current_seq = 4892
count = 77
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.972107
last_received_ts = 295.971497
last_seq = 4892
current_ts = 295.988770
current_received_ts = 295.988159
current_seq = 4893
count = 78
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 295.988770
last_received_ts = 295.988159
last_seq = 4893
current_ts = 296.005432
current_received_ts = 296.004822
current_seq = 4894
count = 79
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.005432
last_received_ts = 296.004822
last_seq = 4894
current_ts = 296.022125
current_received_ts = 296.021515
current_seq = 4895
count = 80
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.022125
last_received_ts = 296.021515
last_seq = 4895
current_ts = 296.038788
current_received_ts = 296.038177
current_seq = 4896
count = 81
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.038788
last_received_ts = 296.038177
last_seq = 4896
current_ts = 296.055450
current_received_ts = 296.054840
current_seq = 4897
count = 82
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.055450
last_received_ts = 296.054840
last_seq = 4897
current_ts = 296.072113
current_received_ts = 296.071503
current_seq = 4898
count = 83
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.072113
last_received_ts = 296.071503
last_seq = 4898
current_ts = 296.088776
current_received_ts = 296.088165
current_seq = 4899
count = 84
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.088776
last_received_ts = 296.088165
last_seq = 4899
current_ts = 296.105469
current_received_ts = 296.104858
current_seq = 4900
count = 85
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.105469
last_received_ts = 296.104858
last_seq = 4900
current_ts = 296.122131
current_received_ts = 296.121521
current_seq = 4901
count = 86
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.122131
last_received_ts = 296.121521
last_seq = 4901
current_ts = 296.138794
current_received_ts = 296.138184
current_seq = 4902
count = 87
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.138794
last_received_ts = 296.138184
last_seq = 4902
current_ts = 296.155457
current_received_ts = 296.154846
current_seq = 4903
count = 88
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.155457
last_received_ts = 296.154846
last_seq = 4903
current_ts = 296.172119
current_received_ts = 296.171509
current_seq = 4904
count = 89
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.172119
last_received_ts = 296.171509
last_seq = 4904
current_ts = 296.188812
current_received_ts = 296.188202
current_seq = 4905
count = 90
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.188812
last_received_ts = 296.188202
last_seq = 4905
current_ts = 296.205444
current_received_ts = 296.204865
current_seq = 4906
count = 91
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.205444
last_received_ts = 296.204865
last_seq = 4906
current_ts = 296.222137
current_received_ts = 296.221527
current_seq = 4907
count = 92
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.222137
last_received_ts = 296.221527
last_seq = 4907
current_ts = 296.238800
current_received_ts = 296.238190
current_seq = 4908
count = 93
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.238800
last_received_ts = 296.238190
last_seq = 4908
current_ts = 296.255463
current_received_ts = 296.254852
current_seq = 4909
count = 94
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.255463
last_received_ts = 296.254852
last_seq = 4909
current_ts = 296.272156
current_received_ts = 296.271545
current_seq = 4910
count = 95
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.272156
last_received_ts = 296.271545
last_seq = 4910
current_ts = 296.288818
current_received_ts = 296.288208
current_seq = 4911
count = 96
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 20us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.288818
last_received_ts = 296.288208
last_seq = 4911
current_ts = 296.305481
current_received_ts = 296.304871
current_seq = 4912
count = 97
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 19us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.305481
last_received_ts = 296.304871
last_seq = 4912
current_ts = 296.322144
current_received_ts = 296.321533
current_seq = 4913
count = 98
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.322144
last_received_ts = 296.321533
last_seq = 4913
current_ts = 296.338806
current_received_ts = 296.338196
current_seq = 4914
count = 99
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.338806
last_received_ts = 296.338196
last_seq = 4914
current_ts = 296.355499
current_received_ts = 296.354889
current_seq = 4915
count = 100
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.355499
last_received_ts = 296.354889
last_seq = 4915
current_ts = 296.372162
current_received_ts = 296.371552
current_seq = 4916
count = 101
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.372162
last_received_ts = 296.371552
last_seq = 4916
current_ts = 296.388824
current_received_ts = 296.388214
current_seq = 4917
count = 102
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.388824
last_received_ts = 296.388214
last_seq = 4917
current_ts = 296.405487
current_received_ts = 296.404877
current_seq = 4918
count = 103
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.405487
last_received_ts = 296.404877
last_seq = 4918
current_ts = 296.422150
current_received_ts = 296.421570
current_seq = 4919
count = 104
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.422150
last_received_ts = 296.421570
last_seq = 4919
current_ts = 296.438843
current_received_ts = 296.438232
current_seq = 4920
count = 105
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.438843
last_received_ts = 296.438232
last_seq = 4920
current_ts = 296.455505
current_received_ts = 296.454895
current_seq = 4921
count = 106
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.455505
last_received_ts = 296.454895
last_seq = 4921
current_ts = 296.472168
current_received_ts = 296.471558
current_seq = 4922
count = 107
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.472168
last_received_ts = 296.471558
last_seq = 4922
current_ts = 296.488831
current_received_ts = 296.488220
current_seq = 4923
count = 108
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.488831
last_received_ts = 296.488220
last_seq = 4923
current_ts = 296.505493
current_received_ts = 296.504883
current_seq = 4924
count = 109
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.505493
last_received_ts = 296.504883
last_seq = 4924
current_ts = 296.522186
current_received_ts = 296.521576
current_seq = 4925
count = 110
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.522186
last_received_ts = 296.521576
last_seq = 4925
current_ts = 296.538849
current_received_ts = 296.538239
current_seq = 4926
count = 111
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.538849
last_received_ts = 296.538239
last_seq = 4926
current_ts = 296.555511
current_received_ts = 296.554901
current_seq = 4927
count = 112
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 19us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.555511
last_received_ts = 296.554901
last_seq = 4927
current_ts = 296.572174
current_received_ts = 296.571564
current_seq = 4928
count = 113
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.572174
last_received_ts = 296.571564
last_seq = 4928
current_ts = 296.588837
current_received_ts = 296.588226
current_seq = 4929
count = 114
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.588837
last_received_ts = 296.588226
last_seq = 4929
current_ts = 296.605530
current_received_ts = 296.604919
current_seq = 4930
count = 115
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.605530
last_received_ts = 296.604919
last_seq = 4930
current_ts = 296.622192
current_received_ts = 296.621582
current_seq = 4931
count = 116
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.622192
last_received_ts = 296.621582
last_seq = 4931
current_ts = 296.638855
current_received_ts = 296.638245
current_seq = 4932
count = 117
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.638855
last_received_ts = 296.638245
last_seq = 4932
current_ts = 296.655518
current_received_ts = 296.654907
current_seq = 4933
count = 118
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.655518
last_received_ts = 296.654907
last_seq = 4933
current_ts = 296.672180
current_received_ts = 296.671570
current_seq = 4934
count = 119
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.672180
last_received_ts = 296.671570
last_seq = 4934
current_ts = 296.688843
current_received_ts = 296.688263
current_seq = 4935
count = 120
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.688843
last_received_ts = 296.688263
last_seq = 4935
current_ts = 296.705536
current_received_ts = 296.704926
current_seq = 4936
count = 121
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.705536
last_received_ts = 296.704926
last_seq = 4936
current_ts = 296.722198
current_received_ts = 296.721588
current_seq = 4937
count = 122
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.722198
last_received_ts = 296.721588
last_seq = 4937
current_ts = 296.738861
current_received_ts = 296.738251
current_seq = 4938
count = 123
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.738861
last_received_ts = 296.738251
last_seq = 4938
current_ts = 296.755524
current_received_ts = 296.754913
current_seq = 4939
count = 124
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.755524
last_received_ts = 296.754913
last_seq = 4939
current_ts = 296.772186
current_received_ts = 296.771606
current_seq = 4940
count = 125
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.772186
last_received_ts = 296.771606
last_seq = 4940
current_ts = 296.788879
current_received_ts = 296.788269
current_seq = 4941
count = 126
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.788879
last_received_ts = 296.788269
last_seq = 4941
current_ts = 296.805542
current_received_ts = 296.804932
current_seq = 4942
count = 127
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.805542
last_received_ts = 296.804932
last_seq = 4942
current_ts = 296.822205
current_received_ts = 296.821594
current_seq = 4943
count = 128
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.822205
last_received_ts = 296.821594
last_seq = 4943
current_ts = 296.838867
current_received_ts = 296.838257
current_seq = 4944
count = 129
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.838867
last_received_ts = 296.838257
last_seq = 4944
current_ts = 296.855530
current_received_ts = 296.854950
current_seq = 4945
count = 130
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.855530
last_received_ts = 296.854950
last_seq = 4945
current_ts = 296.872223
current_received_ts = 296.871613
current_seq = 4946
count = 131
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.872223
last_received_ts = 296.871613
last_seq = 4946
current_ts = 296.888885
current_received_ts = 296.888275
current_seq = 4947
count = 132
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.888885
last_received_ts = 296.888275
last_seq = 4947
current_ts = 296.905548
current_received_ts = 296.904938
current_seq = 4948
count = 133
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.905548
last_received_ts = 296.904938
last_seq = 4948
current_ts = 296.922211
current_received_ts = 296.921600
current_seq = 4949
count = 134
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.922211
last_received_ts = 296.921600
last_seq = 4949
current_ts = 296.938873
current_received_ts = 296.938263
current_seq = 4950
count = 135
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.938873
last_received_ts = 296.938263
last_seq = 4950
current_ts = 296.955566
current_received_ts = 296.954956
current_seq = 4951
count = 136
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.955566
last_received_ts = 296.954956
last_seq = 4951
current_ts = 296.972198
current_received_ts = 296.971619
current_seq = 4952
count = 137
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.972198
last_received_ts = 296.971619
last_seq = 4952
current_ts = 296.988892
current_received_ts = 296.988281
current_seq = 4953
count = 138
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 296.988892
last_received_ts = 296.988281
last_seq = 4953
current_ts = 297.005554
current_received_ts = 297.004944
current_seq = 4954
count = 139
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.005554
last_received_ts = 297.004944
last_seq = 4954
current_ts = 297.022217
current_received_ts = 297.021606
current_seq = 4955
count = 140
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.022217
last_received_ts = 297.021606
last_seq = 4955
current_ts = 297.038910
current_received_ts = 297.038300
current_seq = 4956
count = 141
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.038910
last_received_ts = 297.038300
last_seq = 4956
current_ts = 297.055573
current_received_ts = 297.054962
current_seq = 4957
count = 142
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.055573
last_received_ts = 297.054962
last_seq = 4957
current_ts = 297.072235
current_received_ts = 297.071625
current_seq = 4958
count = 143
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.072235
last_received_ts = 297.071625
last_seq = 4958
current_ts = 297.088898
current_received_ts = 297.088287
current_seq = 4959
count = 144
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.088898
last_received_ts = 297.088287
last_seq = 4959
current_ts = 297.105560
current_received_ts = 297.104950
current_seq = 4960
count = 145
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 37us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.105560
last_received_ts = 297.104950
last_seq = 4960
current_ts = 297.122253
current_received_ts = 297.121643
current_seq = 4961
count = 146
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.122253
last_received_ts = 297.121643
last_seq = 4961
current_ts = 297.138916
current_received_ts = 297.138306
current_seq = 4962
count = 147
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.138916
last_received_ts = 297.138306
last_seq = 4962
current_ts = 297.155579
current_received_ts = 297.154968
current_seq = 4963
count = 148
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 32us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.155579
last_received_ts = 297.154968
last_seq = 4963
current_ts = 297.172241
current_received_ts = 297.171631
current_seq = 4964
count = 149
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.172241
last_received_ts = 297.171631
last_seq = 4964
current_ts = 297.188904
current_received_ts = 297.188293
current_seq = 4965
count = 150
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.188904
last_received_ts = 297.188293
last_seq = 4965
current_ts = 297.205597
current_received_ts = 297.204987
current_seq = 4966
count = 151
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 35us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.205597
last_received_ts = 297.204987
last_seq = 4966
current_ts = 297.222260
current_received_ts = 297.221649
current_seq = 4967
count = 152
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.222260
last_received_ts = 297.221649
last_seq = 4967
current_ts = 297.238922
current_received_ts = 297.238312
current_seq = 4968
count = 153
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.238922
last_received_ts = 297.238312
last_seq = 4968
current_ts = 297.255585
current_received_ts = 297.254974
current_seq = 4969
count = 154
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 40us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.255585
last_received_ts = 297.254974
last_seq = 4969
current_ts = 297.272247
current_received_ts = 297.271637
current_seq = 4970
count = 155
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.272247
last_received_ts = 297.271637
last_seq = 4970
current_ts = 297.288940
current_received_ts = 297.288330
current_seq = 4971
count = 156
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.288940
last_received_ts = 297.288330
last_seq = 4971
current_ts = 297.305603
current_received_ts = 297.304993
current_seq = 4972
count = 157
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.305603
last_received_ts = 297.304993
last_seq = 4972
current_ts = 297.322266
current_received_ts = 297.321655
current_seq = 4973
count = 158
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.322266
last_received_ts = 297.321655
last_seq = 4973
current_ts = 297.338928
current_received_ts = 297.338318
current_seq = 4974
count = 159
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.338928
last_received_ts = 297.338318
last_seq = 4974
current_ts = 297.355591
current_received_ts = 297.354980
current_seq = 4975
count = 160
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.355591
last_received_ts = 297.354980
last_seq = 4975
current_ts = 297.372284
current_received_ts = 297.371674
current_seq = 4976
count = 161
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.372284
last_received_ts = 297.371674
last_seq = 4976
current_ts = 297.388947
current_received_ts = 297.388336
current_seq = 4977
count = 162
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.388947
last_received_ts = 297.388336
last_seq = 4977
current_ts = 297.405609
current_received_ts = 297.404999
current_seq = 4978
count = 163
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.405609
last_received_ts = 297.404999
last_seq = 4978
current_ts = 297.422272
current_received_ts = 297.421661
current_seq = 4979
count = 164
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.422272
last_received_ts = 297.421661
last_seq = 4979
current_ts = 297.438934
current_received_ts = 297.438324
current_seq = 4980
count = 165
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.438934
last_received_ts = 297.438324
last_seq = 4980
current_ts = 297.455627
current_received_ts = 297.455017
current_seq = 4981
count = 166
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.455627
last_received_ts = 297.455017
last_seq = 4981
current_ts = 297.472290
current_received_ts = 297.471680
current_seq = 4982
count = 167
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.472290
last_received_ts = 297.471680
last_seq = 4982
current_ts = 297.488953
current_received_ts = 297.488342
current_seq = 4983
count = 168
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.488953
last_received_ts = 297.488342
last_seq = 4983
current_ts = 297.505615
current_received_ts = 297.505035
current_seq = 4984
count = 169
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.505615
last_received_ts = 297.505035
last_seq = 4984
current_ts = 297.522278
current_received_ts = 297.521667
current_seq = 4985
count = 170
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.522278
last_received_ts = 297.521667
last_seq = 4985
current_ts = 297.538971
current_received_ts = 297.538361
current_seq = 4986
count = 171
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 297.538971
last_received_ts = 297.538361
last_seq = 4986
current_ts = 297.555603
current_received_ts = 297.555054
current_seq = 4987
count = 172
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 659us
(kms_flip:3773) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3773) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3773) igt_core-INFO: Stack trace:
(kms_flip:3773) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3773) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:3773) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3773) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3773) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3773) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3773) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3773) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A6: FAIL (3.431s)
Starting dynamic subtest: C-HDMI-A6
(kms_flip:3773) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3773) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest C-HDMI-A6 failed.
**** DEBUG ****
(kms_flip:3773) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3773) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:3773) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3773) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3773) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=7680)
(kms_flip:3773) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3773) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b7406adcd0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b7406adcd0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b7406adcd0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b7406adcd0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b7406adcd0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b7406adcd0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b74074fb70, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b74074fb70, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3773) DEBUG: No stale events found
(kms_flip:3773) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3773) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3773) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 298.118988
current_received_ts = 298.118378
current_seq = 873
count = 0
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 526us
(kms_flip:3773) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3773) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3773) igt_core-INFO: Stack trace:
(kms_flip:3773) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3773) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:3773) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3773) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3773) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3773) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3773) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3773) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A6: FAIL (0.224s)
Starting dynamic subtest: D-HDMI-A6
(kms_flip:3773) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3773) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest D-HDMI-A6 failed.
**** DEBUG ****
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.165314
last_received_ts = 299.164703
last_seq = 858
current_ts = 299.181976
current_received_ts = 299.181366
current_seq = 859
count = 51
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.181976
last_received_ts = 299.181366
last_seq = 859
current_ts = 299.198639
current_received_ts = 299.198059
current_seq = 860
count = 52
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.198639
last_received_ts = 299.198059
last_seq = 860
current_ts = 299.215302
current_received_ts = 299.214691
current_seq = 861
count = 53
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.215302
last_received_ts = 299.214691
last_seq = 861
current_ts = 299.231964
current_received_ts = 299.231384
current_seq = 862
count = 54
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.231964
last_received_ts = 299.231384
last_seq = 862
current_ts = 299.248657
current_received_ts = 299.248047
current_seq = 863
count = 55
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.248657
last_received_ts = 299.248047
last_seq = 863
current_ts = 299.265289
current_received_ts = 299.264740
current_seq = 864
count = 56
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 30us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.265289
last_received_ts = 299.264740
last_seq = 864
current_ts = 299.281982
current_received_ts = 299.281372
current_seq = 865
count = 57
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.281982
last_received_ts = 299.281372
last_seq = 865
current_ts = 299.298645
current_received_ts = 299.298065
current_seq = 866
count = 58
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.298645
last_received_ts = 299.298065
last_seq = 866
current_ts = 299.315308
current_received_ts = 299.314728
current_seq = 867
count = 59
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.315308
last_received_ts = 299.314728
last_seq = 867
current_ts = 299.332001
current_received_ts = 299.331390
current_seq = 868
count = 60
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.332001
last_received_ts = 299.331390
last_seq = 868
current_ts = 299.348663
current_received_ts = 299.348053
current_seq = 869
count = 61
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.348663
last_received_ts = 299.348053
last_seq = 869
current_ts = 299.365326
current_received_ts = 299.364716
current_seq = 870
count = 62
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.365326
last_received_ts = 299.364716
last_seq = 870
current_ts = 299.381989
current_received_ts = 299.381378
current_seq = 871
count = 63
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.381989
last_received_ts = 299.381378
last_seq = 871
current_ts = 299.398651
current_received_ts = 299.398071
current_seq = 872
count = 64
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.398651
last_received_ts = 299.398071
last_seq = 872
current_ts = 299.415344
current_received_ts = 299.414734
current_seq = 873
count = 65
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.415344
last_received_ts = 299.414734
last_seq = 873
current_ts = 299.432007
current_received_ts = 299.431396
current_seq = 874
count = 66
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.432007
last_received_ts = 299.431396
last_seq = 874
current_ts = 299.448669
current_received_ts = 299.448059
current_seq = 875
count = 67
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.448669
last_received_ts = 299.448059
last_seq = 875
current_ts = 299.465332
current_received_ts = 299.464752
current_seq = 876
count = 68
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 30us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.465332
last_received_ts = 299.464752
last_seq = 876
current_ts = 299.481995
current_received_ts = 299.481384
current_seq = 877
count = 69
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.481995
last_received_ts = 299.481384
last_seq = 877
current_ts = 299.498657
current_received_ts = 299.498077
current_seq = 878
count = 70
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.498657
last_received_ts = 299.498077
last_seq = 878
current_ts = 299.515350
current_received_ts = 299.514740
current_seq = 879
count = 71
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.515350
last_received_ts = 299.514740
last_seq = 879
current_ts = 299.532013
current_received_ts = 299.531403
current_seq = 880
count = 72
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.532013
last_received_ts = 299.531403
last_seq = 880
current_ts = 299.548676
current_received_ts = 299.548096
current_seq = 881
count = 73
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.548676
last_received_ts = 299.548096
last_seq = 881
current_ts = 299.565338
current_received_ts = 299.564758
current_seq = 882
count = 74
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.565338
last_received_ts = 299.564758
last_seq = 882
current_ts = 299.582031
current_received_ts = 299.581421
current_seq = 883
count = 75
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.582031
last_received_ts = 299.581421
last_seq = 883
current_ts = 299.598694
current_received_ts = 299.598083
current_seq = 884
count = 76
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.598694
last_received_ts = 299.598083
last_seq = 884
current_ts = 299.615356
current_received_ts = 299.614746
current_seq = 885
count = 77
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.615356
last_received_ts = 299.614746
last_seq = 885
current_ts = 299.632019
current_received_ts = 299.631409
current_seq = 886
count = 78
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.632019
last_received_ts = 299.631409
last_seq = 886
current_ts = 299.648682
current_received_ts = 299.648071
current_seq = 887
count = 79
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.648682
last_received_ts = 299.648071
last_seq = 887
current_ts = 299.665344
current_received_ts = 299.664764
current_seq = 888
count = 80
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 25us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.665344
last_received_ts = 299.664764
last_seq = 888
current_ts = 299.682037
current_received_ts = 299.681427
current_seq = 889
count = 81
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.682037
last_received_ts = 299.681427
last_seq = 889
current_ts = 299.698700
current_received_ts = 299.698090
current_seq = 890
count = 82
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.698700
last_received_ts = 299.698090
last_seq = 890
current_ts = 299.715363
current_received_ts = 299.714752
current_seq = 891
count = 83
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.715363
last_received_ts = 299.714752
last_seq = 891
current_ts = 299.732025
current_received_ts = 299.731415
current_seq = 892
count = 84
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.732025
last_received_ts = 299.731415
last_seq = 892
current_ts = 299.748718
current_received_ts = 299.748077
current_seq = 893
count = 85
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 20us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.748718
last_received_ts = 299.748077
last_seq = 893
current_ts = 299.765381
current_received_ts = 299.764771
current_seq = 894
count = 86
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.765381
last_received_ts = 299.764771
last_seq = 894
current_ts = 299.782043
current_received_ts = 299.781433
current_seq = 895
count = 87
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.782043
last_received_ts = 299.781433
last_seq = 895
current_ts = 299.798706
current_received_ts = 299.798096
current_seq = 896
count = 88
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.798706
last_received_ts = 299.798096
last_seq = 896
current_ts = 299.815369
current_received_ts = 299.814758
current_seq = 897
count = 89
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.815369
last_received_ts = 299.814758
last_seq = 897
current_ts = 299.832031
current_received_ts = 299.831421
current_seq = 898
count = 90
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 25us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.832031
last_received_ts = 299.831421
last_seq = 898
current_ts = 299.848724
current_received_ts = 299.848114
current_seq = 899
count = 91
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.848724
last_received_ts = 299.848114
last_seq = 899
current_ts = 299.865356
current_received_ts = 299.864807
current_seq = 900
count = 92
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 25us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.865356
last_received_ts = 299.864807
last_seq = 900
current_ts = 299.882050
current_received_ts = 299.881439
current_seq = 901
count = 93
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.882050
last_received_ts = 299.881439
last_seq = 901
current_ts = 299.898712
current_received_ts = 299.898102
current_seq = 902
count = 94
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.898712
last_received_ts = 299.898102
last_seq = 902
current_ts = 299.915375
current_received_ts = 299.914795
current_seq = 903
count = 95
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.915375
last_received_ts = 299.914795
last_seq = 903
current_ts = 299.932068
current_received_ts = 299.931458
current_seq = 904
count = 96
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.932068
last_received_ts = 299.931458
last_seq = 904
current_ts = 299.948730
current_received_ts = 299.948120
current_seq = 905
count = 97
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.948730
last_received_ts = 299.948120
last_seq = 905
current_ts = 299.965393
current_received_ts = 299.964783
current_seq = 906
count = 98
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.965393
last_received_ts = 299.964783
last_seq = 906
current_ts = 299.982056
current_received_ts = 299.981445
current_seq = 907
count = 99
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.982056
last_received_ts = 299.981445
last_seq = 907
current_ts = 299.998718
current_received_ts = 299.998108
current_seq = 908
count = 100
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 299.998718
last_received_ts = 299.998108
last_seq = 908
current_ts = 300.015381
current_received_ts = 300.014801
current_seq = 909
count = 101
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.015381
last_received_ts = 300.014801
last_seq = 909
current_ts = 300.032074
current_received_ts = 300.031464
current_seq = 910
count = 102
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.032074
last_received_ts = 300.031464
last_seq = 910
current_ts = 300.048737
current_received_ts = 300.048126
current_seq = 911
count = 103
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.048737
last_received_ts = 300.048126
last_seq = 911
current_ts = 300.065399
current_received_ts = 300.064819
current_seq = 912
count = 104
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 33us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.065399
last_received_ts = 300.064819
last_seq = 912
current_ts = 300.082062
current_received_ts = 300.081482
current_seq = 913
count = 105
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.082062
last_received_ts = 300.081482
last_seq = 913
current_ts = 300.098755
current_received_ts = 300.098145
current_seq = 914
count = 106
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.098755
last_received_ts = 300.098145
last_seq = 914
current_ts = 300.115417
current_received_ts = 300.114807
current_seq = 915
count = 107
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.115417
last_received_ts = 300.114807
last_seq = 915
current_ts = 300.132080
current_received_ts = 300.131470
current_seq = 916
count = 108
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.132080
last_received_ts = 300.131470
last_seq = 916
current_ts = 300.148743
current_received_ts = 300.148132
current_seq = 917
count = 109
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.148743
last_received_ts = 300.148132
last_seq = 917
current_ts = 300.165405
current_received_ts = 300.164795
current_seq = 918
count = 110
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.165405
last_received_ts = 300.164795
last_seq = 918
current_ts = 300.182098
current_received_ts = 300.181488
current_seq = 919
count = 111
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.182098
last_received_ts = 300.181488
last_seq = 919
current_ts = 300.198761
current_received_ts = 300.198151
current_seq = 920
count = 112
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.198761
last_received_ts = 300.198151
last_seq = 920
current_ts = 300.215424
current_received_ts = 300.214813
current_seq = 921
count = 113
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.215424
last_received_ts = 300.214813
last_seq = 921
current_ts = 300.232086
current_received_ts = 300.231476
current_seq = 922
count = 114
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.232086
last_received_ts = 300.231476
last_seq = 922
current_ts = 300.248749
current_received_ts = 300.248138
current_seq = 923
count = 115
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.248749
last_received_ts = 300.248138
last_seq = 923
current_ts = 300.265411
current_received_ts = 300.264832
current_seq = 924
count = 116
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 31us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.265411
last_received_ts = 300.264832
last_seq = 924
current_ts = 300.282104
current_received_ts = 300.281494
current_seq = 925
count = 117
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.282104
last_received_ts = 300.281494
last_seq = 925
current_ts = 300.298767
current_received_ts = 300.298157
current_seq = 926
count = 118
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.298767
last_received_ts = 300.298157
last_seq = 926
current_ts = 300.315430
current_received_ts = 300.314819
current_seq = 927
count = 119
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.315430
last_received_ts = 300.314819
last_seq = 927
current_ts = 300.332092
current_received_ts = 300.331482
current_seq = 928
count = 120
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.332092
last_received_ts = 300.331482
last_seq = 928
current_ts = 300.348785
current_received_ts = 300.348175
current_seq = 929
count = 121
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.348785
last_received_ts = 300.348175
last_seq = 929
current_ts = 300.365448
current_received_ts = 300.364838
current_seq = 930
count = 122
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.365448
last_received_ts = 300.364838
last_seq = 930
current_ts = 300.382111
current_received_ts = 300.381500
current_seq = 931
count = 123
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.382111
last_received_ts = 300.381500
last_seq = 931
current_ts = 300.398773
current_received_ts = 300.398163
current_seq = 932
count = 124
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.398773
last_received_ts = 300.398163
last_seq = 932
current_ts = 300.415436
current_received_ts = 300.414825
current_seq = 933
count = 125
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.415436
last_received_ts = 300.414825
last_seq = 933
current_ts = 300.432129
current_received_ts = 300.431519
current_seq = 934
count = 126
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.432129
last_received_ts = 300.431519
last_seq = 934
current_ts = 300.448792
current_received_ts = 300.448181
current_seq = 935
count = 127
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.448792
last_received_ts = 300.448181
last_seq = 935
current_ts = 300.465454
current_received_ts = 300.464874
current_seq = 936
count = 128
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 27us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.465454
last_received_ts = 300.464874
last_seq = 936
current_ts = 300.482117
current_received_ts = 300.481506
current_seq = 937
count = 129
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.482117
last_received_ts = 300.481506
last_seq = 937
current_ts = 300.498779
current_received_ts = 300.498169
current_seq = 938
count = 130
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.498779
last_received_ts = 300.498169
last_seq = 938
current_ts = 300.515442
current_received_ts = 300.514862
current_seq = 939
count = 131
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.515442
last_received_ts = 300.514862
last_seq = 939
current_ts = 300.532135
current_received_ts = 300.531525
current_seq = 940
count = 132
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.532135
last_received_ts = 300.531525
last_seq = 940
current_ts = 300.548798
current_received_ts = 300.548187
current_seq = 941
count = 133
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.548798
last_received_ts = 300.548187
last_seq = 941
current_ts = 300.565460
current_received_ts = 300.564850
current_seq = 942
count = 134
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.565460
last_received_ts = 300.564850
last_seq = 942
current_ts = 300.582123
current_received_ts = 300.581512
current_seq = 943
count = 135
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.582123
last_received_ts = 300.581512
last_seq = 943
current_ts = 300.598785
current_received_ts = 300.598206
current_seq = 944
count = 136
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.598785
last_received_ts = 300.598206
last_seq = 944
current_ts = 300.615479
current_received_ts = 300.614868
current_seq = 945
count = 137
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.615479
last_received_ts = 300.614868
last_seq = 945
current_ts = 300.632141
current_received_ts = 300.631531
current_seq = 946
count = 138
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.632141
last_received_ts = 300.631531
last_seq = 946
current_ts = 300.648804
current_received_ts = 300.648193
current_seq = 947
count = 139
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.648804
last_received_ts = 300.648193
last_seq = 947
current_ts = 300.665466
current_received_ts = 300.664886
current_seq = 948
count = 140
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.665466
last_received_ts = 300.664886
last_seq = 948
current_ts = 300.682129
current_received_ts = 300.681549
current_seq = 949
count = 141
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.682129
last_received_ts = 300.681549
last_seq = 949
current_ts = 300.698792
current_received_ts = 300.698212
current_seq = 950
count = 142
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 28us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.698792
last_received_ts = 300.698212
last_seq = 950
current_ts = 300.715485
current_received_ts = 300.714935
current_seq = 951
count = 143
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 39us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.715485
last_received_ts = 300.714935
last_seq = 951
current_ts = 300.732147
current_received_ts = 300.731506
current_seq = 952
count = 144
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 13us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.732147
last_received_ts = 300.731506
last_seq = 952
current_ts = 300.748810
current_received_ts = 300.748169
current_seq = 953
count = 145
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 15us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.748810
last_received_ts = 300.748169
last_seq = 953
current_ts = 300.765472
current_received_ts = 300.764862
current_seq = 954
count = 146
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 12us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.765472
last_received_ts = 300.764862
last_seq = 954
current_ts = 300.782135
current_received_ts = 300.781555
current_seq = 955
count = 147
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 13us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.782135
last_received_ts = 300.781555
last_seq = 955
current_ts = 300.798828
current_received_ts = 300.798187
current_seq = 956
count = 148
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 15us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.798828
last_received_ts = 300.798187
last_seq = 956
current_ts = 300.815491
current_received_ts = 300.814880
current_seq = 957
count = 149
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 25us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.815491
last_received_ts = 300.814880
last_seq = 957
current_ts = 300.832153
current_received_ts = 300.831665
current_seq = 958
count = 150
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 361us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.832153
last_received_ts = 300.831665
last_seq = 958
current_ts = 300.848816
current_received_ts = 300.848358
current_seq = 959
count = 151
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 34us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.848816
last_received_ts = 300.848358
last_seq = 959
current_ts = 300.865509
current_received_ts = 300.864960
current_seq = 960
count = 152
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 30us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.865509
last_received_ts = 300.864960
last_seq = 960
current_ts = 300.882141
current_received_ts = 300.881561
current_seq = 961
count = 153
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.882141
last_received_ts = 300.881561
last_seq = 961
current_ts = 300.898834
current_received_ts = 300.898224
current_seq = 962
count = 154
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.898834
last_received_ts = 300.898224
last_seq = 962
current_ts = 300.915497
current_received_ts = 300.914917
current_seq = 963
count = 155
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.915497
last_received_ts = 300.914917
last_seq = 963
current_ts = 300.932159
current_received_ts = 300.931580
current_seq = 964
count = 156
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.932159
last_received_ts = 300.931580
last_seq = 964
current_ts = 300.948853
current_received_ts = 300.948242
current_seq = 965
count = 157
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.948853
last_received_ts = 300.948242
last_seq = 965
current_ts = 300.965515
current_received_ts = 300.964905
current_seq = 966
count = 158
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.965515
last_received_ts = 300.964905
last_seq = 966
current_ts = 300.982178
current_received_ts = 300.981598
current_seq = 967
count = 159
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.982178
last_received_ts = 300.981598
last_seq = 967
current_ts = 300.998840
current_received_ts = 300.998230
current_seq = 968
count = 160
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 300.998840
last_received_ts = 300.998230
last_seq = 968
current_ts = 301.015503
current_received_ts = 301.014923
current_seq = 969
count = 161
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 301.015503
last_received_ts = 301.014923
last_seq = 969
current_ts = 301.032166
current_received_ts = 301.031647
current_seq = 970
count = 162
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 346us
(kms_flip:3773) DEBUG: name = flip
last_ts = 301.032166
last_received_ts = 301.031647
last_seq = 970
current_ts = 301.048828
current_received_ts = 301.048279
current_seq = 971
count = 163
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 26us
(kms_flip:3773) DEBUG: name = flip
last_ts = 301.048828
last_received_ts = 301.048279
last_seq = 971
current_ts = 301.065521
current_received_ts = 301.064941
current_seq = 972
count = 164
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 301.065521
last_received_ts = 301.064941
last_seq = 972
current_ts = 301.082184
current_received_ts = 301.081573
current_seq = 973
count = 165
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 301.082184
last_received_ts = 301.081573
last_seq = 973
current_ts = 301.098846
current_received_ts = 301.098267
current_seq = 974
count = 166
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 301.098846
last_received_ts = 301.098267
last_seq = 974
current_ts = 301.115540
current_received_ts = 301.114929
current_seq = 975
count = 167
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 301.115540
last_received_ts = 301.114929
last_seq = 975
current_ts = 301.132202
current_received_ts = 301.131592
current_seq = 976
count = 168
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 301.132202
last_received_ts = 301.131592
last_seq = 976
current_ts = 301.148865
current_received_ts = 301.148254
current_seq = 977
count = 169
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 301.148865
last_received_ts = 301.148254
last_seq = 977
current_ts = 301.165527
current_received_ts = 301.164917
current_seq = 978
count = 170
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 301.165527
last_received_ts = 301.164917
last_seq = 978
current_ts = 301.182190
current_received_ts = 301.181610
current_seq = 979
count = 171
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 301.182190
last_received_ts = 301.181610
last_seq = 979
current_ts = 301.198853
current_received_ts = 301.198395
current_seq = 980
count = 172
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 631us
(kms_flip:3773) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3773) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3773) igt_core-INFO: Stack trace:
(kms_flip:3773) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3773) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:3773) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3773) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3773) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3773) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3773) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3773) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest D-HDMI-A6: FAIL (3.398s)
Starting dynamic subtest: A-DP4
(kms_flip:3773) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3773) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest A-DP4 failed.
**** DEBUG ****
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.125488
last_received_ts = 302.124878
last_seq = 6139
current_ts = 302.142151
current_received_ts = 302.141571
current_seq = 6140
count = 22
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.142151
last_received_ts = 302.141571
last_seq = 6140
current_ts = 302.158844
current_received_ts = 302.158234
current_seq = 6141
count = 23
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.158844
last_received_ts = 302.158234
last_seq = 6141
current_ts = 302.175507
current_received_ts = 302.174896
current_seq = 6142
count = 24
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.175507
last_received_ts = 302.174896
last_seq = 6142
current_ts = 302.192169
current_received_ts = 302.191559
current_seq = 6143
count = 25
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.192169
last_received_ts = 302.191559
last_seq = 6143
current_ts = 302.208832
current_received_ts = 302.208221
current_seq = 6144
count = 26
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.208832
last_received_ts = 302.208221
last_seq = 6144
current_ts = 302.225494
current_received_ts = 302.224884
current_seq = 6145
count = 27
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.225494
last_received_ts = 302.224884
last_seq = 6145
current_ts = 302.242157
current_received_ts = 302.241577
current_seq = 6146
count = 28
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.242157
last_received_ts = 302.241577
last_seq = 6146
current_ts = 302.258850
current_received_ts = 302.258240
current_seq = 6147
count = 29
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.258850
last_received_ts = 302.258240
last_seq = 6147
current_ts = 302.275513
current_received_ts = 302.274902
current_seq = 6148
count = 30
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.275513
last_received_ts = 302.274902
last_seq = 6148
current_ts = 302.292175
current_received_ts = 302.291565
current_seq = 6149
count = 31
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.292175
last_received_ts = 302.291565
last_seq = 6149
current_ts = 302.308838
current_received_ts = 302.308228
current_seq = 6150
count = 32
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.308838
last_received_ts = 302.308228
last_seq = 6150
current_ts = 302.325531
current_received_ts = 302.324921
current_seq = 6151
count = 33
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.325531
last_received_ts = 302.324921
last_seq = 6151
current_ts = 302.342163
current_received_ts = 302.341583
current_seq = 6152
count = 34
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.342163
last_received_ts = 302.341583
last_seq = 6152
current_ts = 302.358856
current_received_ts = 302.358246
current_seq = 6153
count = 35
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.358856
last_received_ts = 302.358246
last_seq = 6153
current_ts = 302.375519
current_received_ts = 302.374908
current_seq = 6154
count = 36
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.375519
last_received_ts = 302.374908
last_seq = 6154
current_ts = 302.392181
current_received_ts = 302.391571
current_seq = 6155
count = 37
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.392181
last_received_ts = 302.391571
last_seq = 6155
current_ts = 302.408875
current_received_ts = 302.408264
current_seq = 6156
count = 38
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.408875
last_received_ts = 302.408264
last_seq = 6156
current_ts = 302.425537
current_received_ts = 302.424927
current_seq = 6157
count = 39
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.425537
last_received_ts = 302.424927
last_seq = 6157
current_ts = 302.442200
current_received_ts = 302.441589
current_seq = 6158
count = 40
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.442200
last_received_ts = 302.441589
last_seq = 6158
current_ts = 302.458862
current_received_ts = 302.458252
current_seq = 6159
count = 41
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.458862
last_received_ts = 302.458252
last_seq = 6159
current_ts = 302.475525
current_received_ts = 302.474915
current_seq = 6160
count = 42
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.475525
last_received_ts = 302.474915
last_seq = 6160
current_ts = 302.492218
current_received_ts = 302.491608
current_seq = 6161
count = 43
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.492218
last_received_ts = 302.491608
last_seq = 6161
current_ts = 302.508881
current_received_ts = 302.508270
current_seq = 6162
count = 44
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.508881
last_received_ts = 302.508270
last_seq = 6162
current_ts = 302.525543
current_received_ts = 302.524933
current_seq = 6163
count = 45
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.525543
last_received_ts = 302.524933
last_seq = 6163
current_ts = 302.542206
current_received_ts = 302.541595
current_seq = 6164
count = 46
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.542206
last_received_ts = 302.541595
last_seq = 6164
current_ts = 302.558868
current_received_ts = 302.558258
current_seq = 6165
count = 47
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.558868
last_received_ts = 302.558258
last_seq = 6165
current_ts = 302.575531
current_received_ts = 302.574951
current_seq = 6166
count = 48
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.575531
last_received_ts = 302.574951
last_seq = 6166
current_ts = 302.592224
current_received_ts = 302.591614
current_seq = 6167
count = 49
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.592224
last_received_ts = 302.591614
last_seq = 6167
current_ts = 302.608887
current_received_ts = 302.608276
current_seq = 6168
count = 50
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.608887
last_received_ts = 302.608276
last_seq = 6168
current_ts = 302.625549
current_received_ts = 302.624939
current_seq = 6169
count = 51
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.625549
last_received_ts = 302.624939
last_seq = 6169
current_ts = 302.642212
current_received_ts = 302.641602
current_seq = 6170
count = 52
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.642212
last_received_ts = 302.641602
last_seq = 6170
current_ts = 302.658875
current_received_ts = 302.658295
current_seq = 6171
count = 53
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.658875
last_received_ts = 302.658295
last_seq = 6171
current_ts = 302.675568
current_received_ts = 302.674957
current_seq = 6172
count = 54
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.675568
last_received_ts = 302.674957
last_seq = 6172
current_ts = 302.692230
current_received_ts = 302.691620
current_seq = 6173
count = 55
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.692230
last_received_ts = 302.691620
last_seq = 6173
current_ts = 302.708893
current_received_ts = 302.708282
current_seq = 6174
count = 56
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 20us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.708893
last_received_ts = 302.708282
last_seq = 6174
current_ts = 302.725555
current_received_ts = 302.724945
current_seq = 6175
count = 57
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.725555
last_received_ts = 302.724945
last_seq = 6175
current_ts = 302.742218
current_received_ts = 302.741638
current_seq = 6176
count = 58
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.742218
last_received_ts = 302.741638
last_seq = 6176
current_ts = 302.758911
current_received_ts = 302.758301
current_seq = 6177
count = 59
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.758911
last_received_ts = 302.758301
last_seq = 6177
current_ts = 302.775574
current_received_ts = 302.774963
current_seq = 6178
count = 60
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.775574
last_received_ts = 302.774963
last_seq = 6178
current_ts = 302.792236
current_received_ts = 302.791626
current_seq = 6179
count = 61
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 20us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.792236
last_received_ts = 302.791626
last_seq = 6179
current_ts = 302.808899
current_received_ts = 302.808289
current_seq = 6180
count = 62
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.808899
last_received_ts = 302.808289
last_seq = 6180
current_ts = 302.825562
current_received_ts = 302.824982
current_seq = 6181
count = 63
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 38us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.825562
last_received_ts = 302.824982
last_seq = 6181
current_ts = 302.842224
current_received_ts = 302.841644
current_seq = 6182
count = 64
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.842224
last_received_ts = 302.841644
last_seq = 6182
current_ts = 302.858917
current_received_ts = 302.858307
current_seq = 6183
count = 65
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.858917
last_received_ts = 302.858307
last_seq = 6183
current_ts = 302.875580
current_received_ts = 302.874969
current_seq = 6184
count = 66
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 45us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.875580
last_received_ts = 302.874969
last_seq = 6184
current_ts = 302.892242
current_received_ts = 302.891632
current_seq = 6185
count = 67
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.892242
last_received_ts = 302.891632
last_seq = 6185
current_ts = 302.908905
current_received_ts = 302.908325
current_seq = 6186
count = 68
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.908905
last_received_ts = 302.908325
last_seq = 6186
current_ts = 302.925598
current_received_ts = 302.924988
current_seq = 6187
count = 69
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 51us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.925598
last_received_ts = 302.924988
last_seq = 6187
current_ts = 302.942261
current_received_ts = 302.941650
current_seq = 6188
count = 70
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.942261
last_received_ts = 302.941650
last_seq = 6188
current_ts = 302.958923
current_received_ts = 302.958313
current_seq = 6189
count = 71
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.958923
last_received_ts = 302.958313
last_seq = 6189
current_ts = 302.975586
current_received_ts = 302.974976
current_seq = 6190
count = 72
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 44us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.975586
last_received_ts = 302.974976
last_seq = 6190
current_ts = 302.992249
current_received_ts = 302.991638
current_seq = 6191
count = 73
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 302.992249
last_received_ts = 302.991638
last_seq = 6191
current_ts = 303.008942
current_received_ts = 303.008331
current_seq = 6192
count = 74
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.008942
last_received_ts = 303.008331
last_seq = 6192
current_ts = 303.025574
current_received_ts = 303.024994
current_seq = 6193
count = 75
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 20us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.025574
last_received_ts = 303.024994
last_seq = 6193
current_ts = 303.042267
current_received_ts = 303.041656
current_seq = 6194
count = 76
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.042267
last_received_ts = 303.041656
last_seq = 6194
current_ts = 303.058929
current_received_ts = 303.058319
current_seq = 6195
count = 77
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.058929
last_received_ts = 303.058319
last_seq = 6195
current_ts = 303.075592
current_received_ts = 303.075012
current_seq = 6196
count = 78
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 82us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.075592
last_received_ts = 303.075012
last_seq = 6196
current_ts = 303.092285
current_received_ts = 303.091675
current_seq = 6197
count = 79
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.092285
last_received_ts = 303.091675
last_seq = 6197
current_ts = 303.108948
current_received_ts = 303.108337
current_seq = 6198
count = 80
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.108948
last_received_ts = 303.108337
last_seq = 6198
current_ts = 303.125610
current_received_ts = 303.125031
current_seq = 6199
count = 81
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 260us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.125610
last_received_ts = 303.125031
last_seq = 6199
current_ts = 303.142273
current_received_ts = 303.141663
current_seq = 6200
count = 82
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.142273
last_received_ts = 303.141663
last_seq = 6200
current_ts = 303.158936
current_received_ts = 303.158325
current_seq = 6201
count = 83
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.158936
last_received_ts = 303.158325
last_seq = 6201
current_ts = 303.175629
current_received_ts = 303.175049
current_seq = 6202
count = 84
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 81us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.175629
last_received_ts = 303.175049
last_seq = 6202
current_ts = 303.192291
current_received_ts = 303.191681
current_seq = 6203
count = 85
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.192291
last_received_ts = 303.191681
last_seq = 6203
current_ts = 303.208954
current_received_ts = 303.208344
current_seq = 6204
count = 86
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.208954
last_received_ts = 303.208344
last_seq = 6204
current_ts = 303.225616
current_received_ts = 303.225037
current_seq = 6205
count = 87
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.225616
last_received_ts = 303.225037
last_seq = 6205
current_ts = 303.242279
current_received_ts = 303.241699
current_seq = 6206
count = 88
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.242279
last_received_ts = 303.241699
last_seq = 6206
current_ts = 303.258972
current_received_ts = 303.258362
current_seq = 6207
count = 89
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.258972
last_received_ts = 303.258362
last_seq = 6207
current_ts = 303.275635
current_received_ts = 303.275024
current_seq = 6208
count = 90
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.275635
last_received_ts = 303.275024
last_seq = 6208
current_ts = 303.292297
current_received_ts = 303.291687
current_seq = 6209
count = 91
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.292297
last_received_ts = 303.291687
last_seq = 6209
current_ts = 303.308960
current_received_ts = 303.308350
current_seq = 6210
count = 92
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.308960
last_received_ts = 303.308350
last_seq = 6210
current_ts = 303.325623
current_received_ts = 303.325043
current_seq = 6211
count = 93
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.325623
last_received_ts = 303.325043
last_seq = 6211
current_ts = 303.342285
current_received_ts = 303.341705
current_seq = 6212
count = 94
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.342285
last_received_ts = 303.341705
last_seq = 6212
current_ts = 303.358978
current_received_ts = 303.358368
current_seq = 6213
count = 95
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.358978
last_received_ts = 303.358368
last_seq = 6213
current_ts = 303.375641
current_received_ts = 303.375031
current_seq = 6214
count = 96
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.375641
last_received_ts = 303.375031
last_seq = 6214
current_ts = 303.392303
current_received_ts = 303.391693
current_seq = 6215
count = 97
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.392303
last_received_ts = 303.391693
last_seq = 6215
current_ts = 303.408966
current_received_ts = 303.408356
current_seq = 6216
count = 98
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.408966
last_received_ts = 303.408356
last_seq = 6216
current_ts = 303.425659
current_received_ts = 303.425049
current_seq = 6217
count = 99
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.425659
last_received_ts = 303.425049
last_seq = 6217
current_ts = 303.442291
current_received_ts = 303.441772
current_seq = 6218
count = 100
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 35us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.442291
last_received_ts = 303.441772
last_seq = 6218
current_ts = 303.458954
current_received_ts = 303.458405
current_seq = 6219
count = 101
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 30us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.458954
last_received_ts = 303.458405
last_seq = 6219
current_ts = 303.475647
current_received_ts = 303.475037
current_seq = 6220
count = 102
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 20us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.475647
last_received_ts = 303.475037
last_seq = 6220
current_ts = 303.492310
current_received_ts = 303.491730
current_seq = 6221
count = 103
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 15us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.492310
last_received_ts = 303.491730
last_seq = 6221
current_ts = 303.508972
current_received_ts = 303.508423
current_seq = 6222
count = 104
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 27us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.508972
last_received_ts = 303.508423
last_seq = 6222
current_ts = 303.525665
current_received_ts = 303.525513
current_seq = 6223
count = 105
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 131us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.525665
last_received_ts = 303.525513
last_seq = 6223
current_ts = 303.542328
current_received_ts = 303.541748
current_seq = 6224
count = 106
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 31us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.542328
last_received_ts = 303.541748
last_seq = 6224
current_ts = 303.558990
current_received_ts = 303.558411
current_seq = 6225
count = 107
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 26us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.558990
last_received_ts = 303.558411
last_seq = 6225
current_ts = 303.575653
current_received_ts = 303.575073
current_seq = 6226
count = 108
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 25us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.575653
last_received_ts = 303.575073
last_seq = 6226
current_ts = 303.592316
current_received_ts = 303.591736
current_seq = 6227
count = 109
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 25us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.592316
last_received_ts = 303.591736
last_seq = 6227
current_ts = 303.609009
current_received_ts = 303.608429
current_seq = 6228
count = 110
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 32us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.609009
last_received_ts = 303.608429
last_seq = 6228
current_ts = 303.625671
current_received_ts = 303.625092
current_seq = 6229
count = 111
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 25us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.625671
last_received_ts = 303.625092
last_seq = 6229
current_ts = 303.642334
current_received_ts = 303.641754
current_seq = 6230
count = 112
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 29us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.642334
last_received_ts = 303.641754
last_seq = 6230
current_ts = 303.658997
current_received_ts = 303.658447
current_seq = 6231
count = 113
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 32us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.658997
last_received_ts = 303.658447
last_seq = 6231
current_ts = 303.675659
current_received_ts = 303.675110
current_seq = 6232
count = 114
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 25us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.675659
last_received_ts = 303.675110
last_seq = 6232
current_ts = 303.692352
current_received_ts = 303.691711
current_seq = 6233
count = 115
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 16us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.692352
last_received_ts = 303.691711
last_seq = 6233
current_ts = 303.709015
current_received_ts = 303.708405
current_seq = 6234
count = 116
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.709015
last_received_ts = 303.708405
last_seq = 6234
current_ts = 303.725677
current_received_ts = 303.725098
current_seq = 6235
count = 117
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 300us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.725677
last_received_ts = 303.725098
last_seq = 6235
current_ts = 303.742340
current_received_ts = 303.741760
current_seq = 6236
count = 118
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.742340
last_received_ts = 303.741760
last_seq = 6236
current_ts = 303.759003
current_received_ts = 303.758423
current_seq = 6237
count = 119
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.759003
last_received_ts = 303.758423
last_seq = 6237
current_ts = 303.775696
current_received_ts = 303.775085
current_seq = 6238
count = 120
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.775696
last_received_ts = 303.775085
last_seq = 6238
current_ts = 303.792358
current_received_ts = 303.791748
current_seq = 6239
count = 121
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.792358
last_received_ts = 303.791748
last_seq = 6239
current_ts = 303.809021
current_received_ts = 303.808411
current_seq = 6240
count = 122
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.809021
last_received_ts = 303.808411
last_seq = 6240
current_ts = 303.825684
current_received_ts = 303.825073
current_seq = 6241
count = 123
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.825684
last_received_ts = 303.825073
last_seq = 6241
current_ts = 303.842346
current_received_ts = 303.841736
current_seq = 6242
count = 124
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.842346
last_received_ts = 303.841736
last_seq = 6242
current_ts = 303.859039
current_received_ts = 303.858429
current_seq = 6243
count = 125
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.859039
last_received_ts = 303.858429
last_seq = 6243
current_ts = 303.875702
current_received_ts = 303.875092
current_seq = 6244
count = 126
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.875702
last_received_ts = 303.875092
last_seq = 6244
current_ts = 303.892365
current_received_ts = 303.891754
current_seq = 6245
count = 127
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.892365
last_received_ts = 303.891754
last_seq = 6245
current_ts = 303.909027
current_received_ts = 303.908417
current_seq = 6246
count = 128
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.909027
last_received_ts = 303.908417
last_seq = 6246
current_ts = 303.925690
current_received_ts = 303.925079
current_seq = 6247
count = 129
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.925690
last_received_ts = 303.925079
last_seq = 6247
current_ts = 303.942383
current_received_ts = 303.941772
current_seq = 6248
count = 130
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.942383
last_received_ts = 303.941772
last_seq = 6248
current_ts = 303.959045
current_received_ts = 303.958435
current_seq = 6249
count = 131
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.959045
last_received_ts = 303.958435
last_seq = 6249
current_ts = 303.975708
current_received_ts = 303.975098
current_seq = 6250
count = 132
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.975708
last_received_ts = 303.975098
last_seq = 6250
current_ts = 303.992371
current_received_ts = 303.991760
current_seq = 6251
count = 133
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 303.992371
last_received_ts = 303.991760
last_seq = 6251
current_ts = 304.009033
current_received_ts = 304.008423
current_seq = 6252
count = 134
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 304.009033
last_received_ts = 304.008423
last_seq = 6252
current_ts = 304.025726
current_received_ts = 304.025116
current_seq = 6253
count = 135
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 304.025726
last_received_ts = 304.025116
last_seq = 6253
current_ts = 304.042389
current_received_ts = 304.041779
current_seq = 6254
count = 136
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 304.042389
last_received_ts = 304.041779
last_seq = 6254
current_ts = 304.059052
current_received_ts = 304.058441
current_seq = 6255
count = 137
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 304.059052
last_received_ts = 304.058441
last_seq = 6255
current_ts = 304.075714
current_received_ts = 304.075104
current_seq = 6256
count = 138
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 304.075714
last_received_ts = 304.075104
last_seq = 6256
current_ts = 304.092377
current_received_ts = 304.091797
current_seq = 6257
count = 139
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 304.092377
last_received_ts = 304.091797
last_seq = 6257
current_ts = 304.109070
current_received_ts = 304.108459
current_seq = 6258
count = 140
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 304.109070
last_received_ts = 304.108459
last_seq = 6258
current_ts = 304.125732
current_received_ts = 304.125122
current_seq = 6259
count = 141
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 304.125732
last_received_ts = 304.125122
last_seq = 6259
current_ts = 304.142395
current_received_ts = 304.141785
current_seq = 6260
count = 142
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 304.142395
last_received_ts = 304.141785
last_seq = 6260
current_ts = 304.159058
current_received_ts = 304.158447
current_seq = 6261
count = 143
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 546us
(kms_flip:3773) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3773) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3773) igt_core-INFO: Stack trace:
(kms_flip:3773) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3773) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:3773) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3773) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3773) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3773) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3773) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3773) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-DP4: FAIL (2.962s)
Starting dynamic subtest: B-DP4
(kms_flip:3773) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3773) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-DP4 failed.
**** DEBUG ****
(kms_flip:3773) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3773) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=9, pitch=7680)
(kms_flip:3773) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3773) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:3773) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=10, pitch=7680)
(kms_flip:3773) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:3773) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b74074b6f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b74074b6f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b74074b6f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b74074b6f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b74074b6f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b74074b6f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b74074b6f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) intel_allocator_simple-DEBUG: <ial: 0x55b74074b6f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:3773) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:3773) DEBUG: No stale events found
(kms_flip:3773) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:3773) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:3773) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 304.750671
current_received_ts = 304.750122
current_seq = 5019
count = 0
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 648us
(kms_flip:3773) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3773) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3773) igt_core-INFO: Stack trace:
(kms_flip:3773) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3773) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:3773) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3773) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3773) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3773) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3773) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3773) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-DP4: FAIL (0.259s)
Starting dynamic subtest: C-DP4
Dynamic subtest C-DP4: SUCCESS (3.969s)
Starting dynamic subtest: D-DP4
(kms_flip:3773) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3773) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest D-DP4 failed.
**** DEBUG ****
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.295959
last_received_ts = 309.295380
last_seq = 1030
current_ts = 309.312653
current_received_ts = 309.312073
current_seq = 1031
count = 20
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 297us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.312653
last_received_ts = 309.312073
last_seq = 1031
current_ts = 309.329285
current_received_ts = 309.328705
current_seq = 1032
count = 21
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.329285
last_received_ts = 309.328705
last_seq = 1032
current_ts = 309.345978
current_received_ts = 309.345367
current_seq = 1033
count = 22
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.345978
last_received_ts = 309.345367
last_seq = 1033
current_ts = 309.362640
current_received_ts = 309.362061
current_seq = 1034
count = 23
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.362640
last_received_ts = 309.362061
last_seq = 1034
current_ts = 309.379303
current_received_ts = 309.378693
current_seq = 1035
count = 24
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.379303
last_received_ts = 309.378693
last_seq = 1035
current_ts = 309.395996
current_received_ts = 309.395386
current_seq = 1036
count = 25
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.395996
last_received_ts = 309.395386
last_seq = 1036
current_ts = 309.412659
current_received_ts = 309.412048
current_seq = 1037
count = 26
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.412659
last_received_ts = 309.412048
last_seq = 1037
current_ts = 309.429321
current_received_ts = 309.428711
current_seq = 1038
count = 27
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.429321
last_received_ts = 309.428711
last_seq = 1038
current_ts = 309.445984
current_received_ts = 309.445374
current_seq = 1039
count = 28
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.445984
last_received_ts = 309.445374
last_seq = 1039
current_ts = 309.462646
current_received_ts = 309.462067
current_seq = 1040
count = 29
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.462646
last_received_ts = 309.462067
last_seq = 1040
current_ts = 309.479340
current_received_ts = 309.478729
current_seq = 1041
count = 30
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.479340
last_received_ts = 309.478729
last_seq = 1041
current_ts = 309.496002
current_received_ts = 309.495392
current_seq = 1042
count = 31
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.496002
last_received_ts = 309.495392
last_seq = 1042
current_ts = 309.512665
current_received_ts = 309.512054
current_seq = 1043
count = 32
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.512665
last_received_ts = 309.512054
last_seq = 1043
current_ts = 309.529327
current_received_ts = 309.528717
current_seq = 1044
count = 33
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.529327
last_received_ts = 309.528717
last_seq = 1044
current_ts = 309.545990
current_received_ts = 309.545410
current_seq = 1045
count = 34
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.545990
last_received_ts = 309.545410
last_seq = 1045
current_ts = 309.562653
current_received_ts = 309.562073
current_seq = 1046
count = 35
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.562653
last_received_ts = 309.562073
last_seq = 1046
current_ts = 309.579315
current_received_ts = 309.578735
current_seq = 1047
count = 36
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.579315
last_received_ts = 309.578735
last_seq = 1047
current_ts = 309.596008
current_received_ts = 309.595398
current_seq = 1048
count = 37
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.596008
last_received_ts = 309.595398
last_seq = 1048
current_ts = 309.612671
current_received_ts = 309.612091
current_seq = 1049
count = 38
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.612671
last_received_ts = 309.612091
last_seq = 1049
current_ts = 309.629333
current_received_ts = 309.628754
current_seq = 1050
count = 39
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.629333
last_received_ts = 309.628754
last_seq = 1050
current_ts = 309.645996
current_received_ts = 309.645416
current_seq = 1051
count = 40
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.645996
last_received_ts = 309.645416
last_seq = 1051
current_ts = 309.662659
current_received_ts = 309.662079
current_seq = 1052
count = 41
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.662659
last_received_ts = 309.662079
last_seq = 1052
current_ts = 309.679352
current_received_ts = 309.678741
current_seq = 1053
count = 42
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.679352
last_received_ts = 309.678741
last_seq = 1053
current_ts = 309.696014
current_received_ts = 309.695404
current_seq = 1054
count = 43
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.696014
last_received_ts = 309.695404
last_seq = 1054
current_ts = 309.712677
current_received_ts = 309.712097
current_seq = 1055
count = 44
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.712677
last_received_ts = 309.712097
last_seq = 1055
current_ts = 309.729340
current_received_ts = 309.728760
current_seq = 1056
count = 45
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.729340
last_received_ts = 309.728760
last_seq = 1056
current_ts = 309.746033
current_received_ts = 309.745422
current_seq = 1057
count = 46
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.746033
last_received_ts = 309.745422
last_seq = 1057
current_ts = 309.762665
current_received_ts = 309.762085
current_seq = 1058
count = 47
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.762665
last_received_ts = 309.762085
last_seq = 1058
current_ts = 309.779358
current_received_ts = 309.778748
current_seq = 1059
count = 48
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.779358
last_received_ts = 309.778748
last_seq = 1059
current_ts = 309.796021
current_received_ts = 309.795410
current_seq = 1060
count = 49
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.796021
last_received_ts = 309.795410
last_seq = 1060
current_ts = 309.812683
current_received_ts = 309.812103
current_seq = 1061
count = 50
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.812683
last_received_ts = 309.812103
last_seq = 1061
current_ts = 309.829346
current_received_ts = 309.828766
current_seq = 1062
count = 51
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.829346
last_received_ts = 309.828766
last_seq = 1062
current_ts = 309.846039
current_received_ts = 309.845428
current_seq = 1063
count = 52
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.846039
last_received_ts = 309.845428
last_seq = 1063
current_ts = 309.862701
current_received_ts = 309.862091
current_seq = 1064
count = 53
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.862701
last_received_ts = 309.862091
last_seq = 1064
current_ts = 309.879364
current_received_ts = 309.878754
current_seq = 1065
count = 54
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.879364
last_received_ts = 309.878754
last_seq = 1065
current_ts = 309.896027
current_received_ts = 309.895416
current_seq = 1066
count = 55
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.896027
last_received_ts = 309.895416
last_seq = 1066
current_ts = 309.912720
current_received_ts = 309.912109
current_seq = 1067
count = 56
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.912720
last_received_ts = 309.912109
last_seq = 1067
current_ts = 309.929382
current_received_ts = 309.928772
current_seq = 1068
count = 57
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.929382
last_received_ts = 309.928772
last_seq = 1068
current_ts = 309.946045
current_received_ts = 309.945435
current_seq = 1069
count = 58
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.946045
last_received_ts = 309.945435
last_seq = 1069
current_ts = 309.962708
current_received_ts = 309.962097
current_seq = 1070
count = 59
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.962708
last_received_ts = 309.962097
last_seq = 1070
current_ts = 309.979370
current_received_ts = 309.978760
current_seq = 1071
count = 60
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.979370
last_received_ts = 309.978760
last_seq = 1071
current_ts = 309.996063
current_received_ts = 309.995453
current_seq = 1072
count = 61
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 309.996063
last_received_ts = 309.995453
last_seq = 1072
current_ts = 310.012726
current_received_ts = 310.012115
current_seq = 1073
count = 62
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.012726
last_received_ts = 310.012115
last_seq = 1073
current_ts = 310.029388
current_received_ts = 310.028870
current_seq = 1074
count = 63
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 263us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.029388
last_received_ts = 310.028870
last_seq = 1074
current_ts = 310.046051
current_received_ts = 310.045441
current_seq = 1075
count = 64
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 19us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.046051
last_received_ts = 310.045441
last_seq = 1075
current_ts = 310.062714
current_received_ts = 310.062134
current_seq = 1076
count = 65
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 29us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.062714
last_received_ts = 310.062134
last_seq = 1076
current_ts = 310.079376
current_received_ts = 310.078766
current_seq = 1077
count = 66
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 15us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.079376
last_received_ts = 310.078766
last_seq = 1077
current_ts = 310.096069
current_received_ts = 310.095428
current_seq = 1078
count = 67
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 208us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.096069
last_received_ts = 310.095428
last_seq = 1078
current_ts = 310.112732
current_received_ts = 310.112091
current_seq = 1079
count = 68
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 13us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.112732
last_received_ts = 310.112091
last_seq = 1079
current_ts = 310.129395
current_received_ts = 310.128754
current_seq = 1080
count = 69
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 12us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.129395
last_received_ts = 310.128754
last_seq = 1080
current_ts = 310.146057
current_received_ts = 310.145447
current_seq = 1081
count = 70
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 14us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.146057
last_received_ts = 310.145447
last_seq = 1081
current_ts = 310.162720
current_received_ts = 310.162109
current_seq = 1082
count = 71
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 14us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.162720
last_received_ts = 310.162109
last_seq = 1082
current_ts = 310.179413
current_received_ts = 310.178772
current_seq = 1083
count = 72
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 14us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.179413
last_received_ts = 310.178772
last_seq = 1083
current_ts = 310.196045
current_received_ts = 310.195587
current_seq = 1084
count = 73
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 446us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.196045
last_received_ts = 310.195587
last_seq = 1084
current_ts = 310.212738
current_received_ts = 310.212158
current_seq = 1085
count = 74
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 34us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.212738
last_received_ts = 310.212158
last_seq = 1085
current_ts = 310.229401
current_received_ts = 310.228821
current_seq = 1086
count = 75
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 25us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.229401
last_received_ts = 310.228821
last_seq = 1086
current_ts = 310.246063
current_received_ts = 310.245483
current_seq = 1087
count = 76
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.246063
last_received_ts = 310.245483
last_seq = 1087
current_ts = 310.262756
current_received_ts = 310.262146
current_seq = 1088
count = 77
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 25us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.262756
last_received_ts = 310.262146
last_seq = 1088
current_ts = 310.279419
current_received_ts = 310.278809
current_seq = 1089
count = 78
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.279419
last_received_ts = 310.278809
last_seq = 1089
current_ts = 310.296082
current_received_ts = 310.295563
current_seq = 1090
count = 79
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 341us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.296082
last_received_ts = 310.295563
last_seq = 1090
current_ts = 310.312744
current_received_ts = 310.312164
current_seq = 1091
count = 80
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 307us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.312744
last_received_ts = 310.312164
last_seq = 1091
current_ts = 310.329407
current_received_ts = 310.328827
current_seq = 1092
count = 81
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 227us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.329407
last_received_ts = 310.328827
last_seq = 1092
current_ts = 310.346100
current_received_ts = 310.345490
current_seq = 1093
count = 82
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 25us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.346100
last_received_ts = 310.345490
last_seq = 1093
current_ts = 310.362762
current_received_ts = 310.362152
current_seq = 1094
count = 83
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 22us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.362762
last_received_ts = 310.362152
last_seq = 1094
current_ts = 310.379425
current_received_ts = 310.378815
current_seq = 1095
count = 84
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.379425
last_received_ts = 310.378815
last_seq = 1095
current_ts = 310.396088
current_received_ts = 310.395477
current_seq = 1096
count = 85
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.396088
last_received_ts = 310.395477
last_seq = 1096
current_ts = 310.412750
current_received_ts = 310.412170
current_seq = 1097
count = 86
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.412750
last_received_ts = 310.412170
last_seq = 1097
current_ts = 310.429443
current_received_ts = 310.428833
current_seq = 1098
count = 87
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.429443
last_received_ts = 310.428833
last_seq = 1098
current_ts = 310.446106
current_received_ts = 310.445496
current_seq = 1099
count = 88
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 245us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.446106
last_received_ts = 310.445496
last_seq = 1099
current_ts = 310.462769
current_received_ts = 310.462158
current_seq = 1100
count = 89
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 21us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.462769
last_received_ts = 310.462158
last_seq = 1100
current_ts = 310.479431
current_received_ts = 310.478821
current_seq = 1101
count = 90
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 319us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.479431
last_received_ts = 310.478821
last_seq = 1101
current_ts = 310.496094
current_received_ts = 310.495514
current_seq = 1102
count = 91
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 220us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.496094
last_received_ts = 310.495514
last_seq = 1102
current_ts = 310.512787
current_received_ts = 310.512177
current_seq = 1103
count = 92
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.512787
last_received_ts = 310.512177
last_seq = 1103
current_ts = 310.529449
current_received_ts = 310.528839
current_seq = 1104
count = 93
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 236us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.529449
last_received_ts = 310.528839
last_seq = 1104
current_ts = 310.546112
current_received_ts = 310.545502
current_seq = 1105
count = 94
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 250us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.546112
last_received_ts = 310.545502
last_seq = 1105
current_ts = 310.562775
current_received_ts = 310.562164
current_seq = 1106
count = 95
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.562775
last_received_ts = 310.562164
last_seq = 1106
current_ts = 310.579437
current_received_ts = 310.578857
current_seq = 1107
count = 96
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.579437
last_received_ts = 310.578857
last_seq = 1107
current_ts = 310.596100
current_received_ts = 310.595520
current_seq = 1108
count = 97
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.596100
last_received_ts = 310.595520
last_seq = 1108
current_ts = 310.612793
current_received_ts = 310.612183
current_seq = 1109
count = 98
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.612793
last_received_ts = 310.612183
last_seq = 1109
current_ts = 310.629456
current_received_ts = 310.628845
current_seq = 1110
count = 99
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 228us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.629456
last_received_ts = 310.628845
last_seq = 1110
current_ts = 310.646118
current_received_ts = 310.645508
current_seq = 1111
count = 100
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.646118
last_received_ts = 310.645508
last_seq = 1111
current_ts = 310.662781
current_received_ts = 310.662170
current_seq = 1112
count = 101
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.662781
last_received_ts = 310.662170
last_seq = 1112
current_ts = 310.679443
current_received_ts = 310.678864
current_seq = 1113
count = 102
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 299us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.679443
last_received_ts = 310.678864
last_seq = 1113
current_ts = 310.696136
current_received_ts = 310.695526
current_seq = 1114
count = 103
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 212us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.696136
last_received_ts = 310.695526
last_seq = 1114
current_ts = 310.712799
current_received_ts = 310.712189
current_seq = 1115
count = 104
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.712799
last_received_ts = 310.712189
last_seq = 1115
current_ts = 310.729462
current_received_ts = 310.728851
current_seq = 1116
count = 105
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.729462
last_received_ts = 310.728851
last_seq = 1116
current_ts = 310.746124
current_received_ts = 310.745514
current_seq = 1117
count = 106
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.746124
last_received_ts = 310.745514
last_seq = 1117
current_ts = 310.762787
current_received_ts = 310.762207
current_seq = 1118
count = 107
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.762787
last_received_ts = 310.762207
last_seq = 1118
current_ts = 310.779480
current_received_ts = 310.778870
current_seq = 1119
count = 108
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.779480
last_received_ts = 310.778870
last_seq = 1119
current_ts = 310.796143
current_received_ts = 310.795532
current_seq = 1120
count = 109
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.796143
last_received_ts = 310.795532
last_seq = 1120
current_ts = 310.812805
current_received_ts = 310.812195
current_seq = 1121
count = 110
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.812805
last_received_ts = 310.812195
last_seq = 1121
current_ts = 310.829468
current_received_ts = 310.828857
current_seq = 1122
count = 111
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.829468
last_received_ts = 310.828857
last_seq = 1122
current_ts = 310.846130
current_received_ts = 310.845551
current_seq = 1123
count = 112
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.846130
last_received_ts = 310.845551
last_seq = 1123
current_ts = 310.862823
current_received_ts = 310.862213
current_seq = 1124
count = 113
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.862823
last_received_ts = 310.862213
last_seq = 1124
current_ts = 310.879486
current_received_ts = 310.878876
current_seq = 1125
count = 114
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.879486
last_received_ts = 310.878876
last_seq = 1125
current_ts = 310.896149
current_received_ts = 310.895538
current_seq = 1126
count = 115
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.896149
last_received_ts = 310.895538
last_seq = 1126
current_ts = 310.912811
current_received_ts = 310.912201
current_seq = 1127
count = 116
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.912811
last_received_ts = 310.912201
last_seq = 1127
current_ts = 310.929474
current_received_ts = 310.928894
current_seq = 1128
count = 117
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.929474
last_received_ts = 310.928894
last_seq = 1128
current_ts = 310.946167
current_received_ts = 310.945557
current_seq = 1129
count = 118
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 26us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.946167
last_received_ts = 310.945557
last_seq = 1129
current_ts = 310.962830
current_received_ts = 310.962463
current_seq = 1130
count = 119
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 31us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.962830
last_received_ts = 310.962463
last_seq = 1130
current_ts = 310.979492
current_received_ts = 310.978943
current_seq = 1131
count = 120
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 223us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.979492
last_received_ts = 310.978943
last_seq = 1131
current_ts = 310.996155
current_received_ts = 310.995544
current_seq = 1132
count = 121
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 266us
(kms_flip:3773) DEBUG: name = flip
last_ts = 310.996155
last_received_ts = 310.995544
last_seq = 1132
current_ts = 311.012817
current_received_ts = 311.012177
current_seq = 1133
count = 122
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 312us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.012817
last_received_ts = 311.012177
last_seq = 1133
current_ts = 311.029480
current_received_ts = 311.028870
current_seq = 1134
count = 123
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 304us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.029480
last_received_ts = 311.028870
last_seq = 1134
current_ts = 311.046143
current_received_ts = 311.045563
current_seq = 1135
count = 124
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 389us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.046143
last_received_ts = 311.045563
last_seq = 1135
current_ts = 311.062836
current_received_ts = 311.062225
current_seq = 1136
count = 125
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.062836
last_received_ts = 311.062225
last_seq = 1136
current_ts = 311.079498
current_received_ts = 311.078888
current_seq = 1137
count = 126
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.079498
last_received_ts = 311.078888
last_seq = 1137
current_ts = 311.096161
current_received_ts = 311.095642
current_seq = 1138
count = 127
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 256us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.096161
last_received_ts = 311.095642
last_seq = 1138
current_ts = 311.112823
current_received_ts = 311.112305
current_seq = 1139
count = 128
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 26us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.112823
last_received_ts = 311.112305
last_seq = 1139
current_ts = 311.129486
current_received_ts = 311.128967
current_seq = 1140
count = 129
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 62us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.129486
last_received_ts = 311.128967
last_seq = 1140
current_ts = 311.146179
current_received_ts = 311.145660
current_seq = 1141
count = 130
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.146179
last_received_ts = 311.145660
last_seq = 1141
current_ts = 311.162842
current_received_ts = 311.162292
current_seq = 1142
count = 131
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.162842
last_received_ts = 311.162292
last_seq = 1142
current_ts = 311.179504
current_received_ts = 311.178986
current_seq = 1143
count = 132
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 46us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.179504
last_received_ts = 311.178986
last_seq = 1143
current_ts = 311.196167
current_received_ts = 311.195648
current_seq = 1144
count = 133
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.196167
last_received_ts = 311.195648
last_seq = 1144
current_ts = 311.212830
current_received_ts = 311.212311
current_seq = 1145
count = 134
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.212830
last_received_ts = 311.212311
last_seq = 1145
current_ts = 311.229523
current_received_ts = 311.228973
current_seq = 1146
count = 135
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 83us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.229523
last_received_ts = 311.228973
last_seq = 1146
current_ts = 311.246185
current_received_ts = 311.245667
current_seq = 1147
count = 136
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.246185
last_received_ts = 311.245667
last_seq = 1147
current_ts = 311.262848
current_received_ts = 311.262299
current_seq = 1148
count = 137
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 23us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.262848
last_received_ts = 311.262299
last_seq = 1148
current_ts = 311.279510
current_received_ts = 311.278992
current_seq = 1149
count = 138
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 231us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.279510
last_received_ts = 311.278992
last_seq = 1149
current_ts = 311.296173
current_received_ts = 311.295654
current_seq = 1150
count = 139
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.296173
last_received_ts = 311.295654
last_seq = 1150
current_ts = 311.312866
current_received_ts = 311.312317
current_seq = 1151
count = 140
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 24us
(kms_flip:3773) DEBUG: name = flip
last_ts = 311.312866
last_received_ts = 311.312317
last_seq = 1151
current_ts = 311.329529
current_received_ts = 311.328979
current_seq = 1152
count = 141
seq_step = 1
(kms_flip:3773) DEBUG: Vblank took 649us
(kms_flip:3773) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:3773) CRITICAL: Failed assertion: end - start < 500
(kms_flip:3773) igt_core-INFO: Stack trace:
(kms_flip:3773) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3773) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:3773) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3773) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3773) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3773) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3773) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3773) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest D-DP4: FAIL (2.936s)
Subtest flip-vs-expired-vblank: FAIL (21.265s)
(kms_flip:3773) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:3773) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:3773) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:3773) igt_kms-CRITICAL: DPMS property not found on 264