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

shard-lnl-8

IGT-Version: 2.3-g1072e4f2e (x86_64) (Linux: 6.19.0-rc1-lgci-xe-xe-4261-c5b056356f247370c+ x86_64)

Using IGT_SRANDOM=1766101034 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: flip-vs-expired-vblank-interruptible
Starting dynamic subtest: A-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1889 run_test()
  #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
  #4 ../tests/kms_flip.c:2045 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (6.157s)
Starting dynamic subtest: B-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1889 run_test()
  #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
  #4 ../tests/kms_flip.c:2045 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (10.015s)
Starting dynamic subtest: C-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1889 run_test()
  #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
  #4 ../tests/kms_flip.c:2045 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-eDP1: FAIL (7.484s)
Subtest flip-vs-expired-vblank-interruptible: FAIL (23.671s)
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2386 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2961 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2416 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: flip-vs-expired-vblank-interruptible
Starting dynamic subtest: A-eDP1
(kms_flip:5486) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:5486) CRITICAL: Failed assertion: end - start < 500
(kms_flip:5486) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 354.978180
last_received_ts = 354.977356
last_seq = 9891
current_ts = 354.994843
current_received_ts = 354.994049
current_seq = 9892
count = 172
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 62us
(kms_flip:5486) DEBUG: name = flip
last_ts = 354.994843
last_received_ts = 354.994049
last_seq = 9892
current_ts = 355.011536
current_received_ts = 355.010712
current_seq = 9893
count = 173
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.011536
last_received_ts = 355.010712
last_seq = 9893
current_ts = 355.028198
current_received_ts = 355.027374
current_seq = 9894
count = 174
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.028198
last_received_ts = 355.027374
last_seq = 9894
current_ts = 355.044891
current_received_ts = 355.044067
current_seq = 9895
count = 175
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.044891
last_received_ts = 355.044067
last_seq = 9895
current_ts = 355.061554
current_received_ts = 355.060730
current_seq = 9896
count = 176
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.061554
last_received_ts = 355.060730
last_seq = 9896
current_ts = 355.078217
current_received_ts = 355.077393
current_seq = 9897
count = 177
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.078217
last_received_ts = 355.077393
last_seq = 9897
current_ts = 355.094910
current_received_ts = 355.094086
current_seq = 9898
count = 178
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 60us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.094910
last_received_ts = 355.094086
last_seq = 9898
current_ts = 355.111572
current_received_ts = 355.110748
current_seq = 9899
count = 179
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.111572
last_received_ts = 355.110748
last_seq = 9899
current_ts = 355.128265
current_received_ts = 355.127441
current_seq = 9900
count = 180
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.128265
last_received_ts = 355.127441
last_seq = 9900
current_ts = 355.144928
current_received_ts = 355.144104
current_seq = 9901
count = 181
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.144928
last_received_ts = 355.144104
last_seq = 9901
current_ts = 355.161591
current_received_ts = 355.160767
current_seq = 9902
count = 182
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.161591
last_received_ts = 355.160767
last_seq = 9902
current_ts = 355.178284
current_received_ts = 355.177460
current_seq = 9903
count = 183
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 59us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.178284
last_received_ts = 355.177460
last_seq = 9903
current_ts = 355.194946
current_received_ts = 355.194122
current_seq = 9904
count = 184
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.194946
last_received_ts = 355.194122
last_seq = 9904
current_ts = 355.211639
current_received_ts = 355.210815
current_seq = 9905
count = 185
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 56us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.211639
last_received_ts = 355.210815
last_seq = 9905
current_ts = 355.228302
current_received_ts = 355.227478
current_seq = 9906
count = 186
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 58us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.228302
last_received_ts = 355.227478
last_seq = 9906
current_ts = 355.244965
current_received_ts = 355.244141
current_seq = 9907
count = 187
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.244965
last_received_ts = 355.244141
last_seq = 9907
current_ts = 355.261658
current_received_ts = 355.260834
current_seq = 9908
count = 188
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.261658
last_received_ts = 355.260834
last_seq = 9908
current_ts = 355.278320
current_received_ts = 355.277496
current_seq = 9909
count = 189
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.278320
last_received_ts = 355.277496
last_seq = 9909
current_ts = 355.295013
current_received_ts = 355.294189
current_seq = 9910
count = 190
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.295013
last_received_ts = 355.294189
last_seq = 9910
current_ts = 355.311676
current_received_ts = 355.310852
current_seq = 9911
count = 191
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.311676
last_received_ts = 355.310852
last_seq = 9911
current_ts = 355.328369
current_received_ts = 355.327545
current_seq = 9912
count = 192
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.328369
last_received_ts = 355.327545
last_seq = 9912
current_ts = 355.345032
current_received_ts = 355.344208
current_seq = 9913
count = 193
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.345032
last_received_ts = 355.344208
last_seq = 9913
current_ts = 355.361694
current_received_ts = 355.360870
current_seq = 9914
count = 194
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.361694
last_received_ts = 355.360870
last_seq = 9914
current_ts = 355.378387
current_received_ts = 355.377563
current_seq = 9915
count = 195
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.378387
last_received_ts = 355.377563
last_seq = 9915
current_ts = 355.395050
current_received_ts = 355.394226
current_seq = 9916
count = 196
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.395050
last_received_ts = 355.394226
last_seq = 9916
current_ts = 355.411713
current_received_ts = 355.410919
current_seq = 9917
count = 197
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 59us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.411713
last_received_ts = 355.410919
last_seq = 9917
current_ts = 355.428406
current_received_ts = 355.427582
current_seq = 9918
count = 198
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.428406
last_received_ts = 355.427582
last_seq = 9918
current_ts = 355.445068
current_received_ts = 355.444244
current_seq = 9919
count = 199
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.445068
last_received_ts = 355.444244
last_seq = 9919
current_ts = 355.461761
current_received_ts = 355.460938
current_seq = 9920
count = 200
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 68us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.461761
last_received_ts = 355.460938
last_seq = 9920
current_ts = 355.478424
current_received_ts = 355.477600
current_seq = 9921
count = 201
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.478424
last_received_ts = 355.477600
last_seq = 9921
current_ts = 355.495117
current_received_ts = 355.494293
current_seq = 9922
count = 202
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 59us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.495117
last_received_ts = 355.494293
last_seq = 9922
current_ts = 355.511780
current_received_ts = 355.510956
current_seq = 9923
count = 203
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 73us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.511780
last_received_ts = 355.510956
last_seq = 9923
current_ts = 355.528442
current_received_ts = 355.527649
current_seq = 9924
count = 204
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 65us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.528442
last_received_ts = 355.527649
last_seq = 9924
current_ts = 355.545135
current_received_ts = 355.544312
current_seq = 9925
count = 205
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 64us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.545135
last_received_ts = 355.544312
last_seq = 9925
current_ts = 355.561798
current_received_ts = 355.561005
current_seq = 9926
count = 206
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 58us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.561798
last_received_ts = 355.561005
last_seq = 9926
current_ts = 355.578491
current_received_ts = 355.577667
current_seq = 9927
count = 207
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 58us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.578491
last_received_ts = 355.577667
last_seq = 9927
current_ts = 355.595154
current_received_ts = 355.594330
current_seq = 9928
count = 208
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 60us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.595154
last_received_ts = 355.594330
last_seq = 9928
current_ts = 355.611816
current_received_ts = 355.611023
current_seq = 9929
count = 209
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.611816
last_received_ts = 355.611023
last_seq = 9929
current_ts = 355.628510
current_received_ts = 355.627686
current_seq = 9930
count = 210
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.628510
last_received_ts = 355.627686
last_seq = 9930
current_ts = 355.645172
current_received_ts = 355.644348
current_seq = 9931
count = 211
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.645172
last_received_ts = 355.644348
last_seq = 9931
current_ts = 355.661865
current_received_ts = 355.661041
current_seq = 9932
count = 212
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 58us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.661865
last_received_ts = 355.661041
last_seq = 9932
current_ts = 355.678528
current_received_ts = 355.677704
current_seq = 9933
count = 213
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.678528
last_received_ts = 355.677704
last_seq = 9933
current_ts = 355.695221
current_received_ts = 355.694366
current_seq = 9934
count = 214
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.695221
last_received_ts = 355.694366
last_seq = 9934
current_ts = 355.711884
current_received_ts = 355.711060
current_seq = 9935
count = 215
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.711884
last_received_ts = 355.711060
last_seq = 9935
current_ts = 355.728546
current_received_ts = 355.727753
current_seq = 9936
count = 216
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 73us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.728546
last_received_ts = 355.727753
last_seq = 9936
current_ts = 355.745239
current_received_ts = 355.744415
current_seq = 9937
count = 217
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.745239
last_received_ts = 355.744415
last_seq = 9937
current_ts = 355.761902
current_received_ts = 355.761108
current_seq = 9938
count = 218
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 59us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.761902
last_received_ts = 355.761108
last_seq = 9938
current_ts = 355.778595
current_received_ts = 355.777771
current_seq = 9939
count = 219
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 59us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.778595
last_received_ts = 355.777771
last_seq = 9939
current_ts = 355.795258
current_received_ts = 355.794464
current_seq = 9940
count = 220
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 62us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.795258
last_received_ts = 355.794464
last_seq = 9940
current_ts = 355.811920
current_received_ts = 355.811127
current_seq = 9941
count = 221
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 58us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.811920
last_received_ts = 355.811127
last_seq = 9941
current_ts = 355.828613
current_received_ts = 355.827789
current_seq = 9942
count = 222
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 59us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.828613
last_received_ts = 355.827789
last_seq = 9942
current_ts = 355.845276
current_received_ts = 355.844452
current_seq = 9943
count = 223
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 58us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.845276
last_received_ts = 355.844452
last_seq = 9943
current_ts = 355.861969
current_received_ts = 355.861145
current_seq = 9944
count = 224
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 71us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.861969
last_received_ts = 355.861145
last_seq = 9944
current_ts = 355.878632
current_received_ts = 355.877808
current_seq = 9945
count = 225
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 61us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.878632
last_received_ts = 355.877808
last_seq = 9945
current_ts = 355.895294
current_received_ts = 355.894501
current_seq = 9946
count = 226
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 60us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.895294
last_received_ts = 355.894501
last_seq = 9946
current_ts = 355.911987
current_received_ts = 355.911224
current_seq = 9947
count = 227
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 98us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.911987
last_received_ts = 355.911224
last_seq = 9947
current_ts = 355.928650
current_received_ts = 355.927917
current_seq = 9948
count = 228
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 163us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.928650
last_received_ts = 355.927917
last_seq = 9948
current_ts = 355.945343
current_received_ts = 355.944580
current_seq = 9949
count = 229
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 71us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.945343
last_received_ts = 355.944580
last_seq = 9949
current_ts = 355.962006
current_received_ts = 355.961212
current_seq = 9950
count = 230
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 67us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.962006
last_received_ts = 355.961212
last_seq = 9950
current_ts = 355.978668
current_received_ts = 355.977905
current_seq = 9951
count = 231
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.978668
last_received_ts = 355.977905
last_seq = 9951
current_ts = 355.995361
current_received_ts = 355.994568
current_seq = 9952
count = 232
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 57us
(kms_flip:5486) DEBUG: name = flip
last_ts = 355.995361
last_received_ts = 355.994568
last_seq = 9952
current_ts = 356.012024
current_received_ts = 356.011230
current_seq = 9953
count = 233
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.012024
last_received_ts = 356.011230
last_seq = 9953
current_ts = 356.028687
current_received_ts = 356.027924
current_seq = 9954
count = 234
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.028687
last_received_ts = 356.027924
last_seq = 9954
current_ts = 356.045380
current_received_ts = 356.044586
current_seq = 9955
count = 235
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 122us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.045380
last_received_ts = 356.044586
last_seq = 9955
current_ts = 356.062042
current_received_ts = 356.061249
current_seq = 9956
count = 236
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 67us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.062042
last_received_ts = 356.061249
last_seq = 9956
current_ts = 356.078735
current_received_ts = 356.077942
current_seq = 9957
count = 237
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 133us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.078735
last_received_ts = 356.077942
last_seq = 9957
current_ts = 356.095398
current_received_ts = 356.094635
current_seq = 9958
count = 238
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.095398
last_received_ts = 356.094635
last_seq = 9958
current_ts = 356.112091
current_received_ts = 356.111267
current_seq = 9959
count = 239
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.112091
last_received_ts = 356.111267
last_seq = 9959
current_ts = 356.128754
current_received_ts = 356.127960
current_seq = 9960
count = 240
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 62us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.128754
last_received_ts = 356.127960
last_seq = 9960
current_ts = 356.145416
current_received_ts = 356.144623
current_seq = 9961
count = 241
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.145416
last_received_ts = 356.144623
last_seq = 9961
current_ts = 356.162109
current_received_ts = 356.161285
current_seq = 9962
count = 242
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 41us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.162109
last_received_ts = 356.161285
last_seq = 9962
current_ts = 356.178772
current_received_ts = 356.177948
current_seq = 9963
count = 243
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 49us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.178772
last_received_ts = 356.177948
last_seq = 9963
current_ts = 356.195435
current_received_ts = 356.194672
current_seq = 9964
count = 244
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 56us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.195435
last_received_ts = 356.194672
last_seq = 9964
current_ts = 356.212128
current_received_ts = 356.211334
current_seq = 9965
count = 245
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 96us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.212128
last_received_ts = 356.211334
last_seq = 9965
current_ts = 356.228790
current_received_ts = 356.228027
current_seq = 9966
count = 246
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 92us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.228790
last_received_ts = 356.228027
last_seq = 9966
current_ts = 356.245453
current_received_ts = 356.244690
current_seq = 9967
count = 247
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 120us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.245453
last_received_ts = 356.244690
last_seq = 9967
current_ts = 356.262146
current_received_ts = 356.261353
current_seq = 9968
count = 248
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 94us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.262146
last_received_ts = 356.261353
last_seq = 9968
current_ts = 356.278809
current_received_ts = 356.278046
current_seq = 9969
count = 249
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 39us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.278809
last_received_ts = 356.278046
last_seq = 9969
current_ts = 356.295502
current_received_ts = 356.294708
current_seq = 9970
count = 250
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 41us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.295502
last_received_ts = 356.294708
last_seq = 9970
current_ts = 356.312164
current_received_ts = 356.311371
current_seq = 9971
count = 251
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.312164
last_received_ts = 356.311371
last_seq = 9971
current_ts = 356.328857
current_received_ts = 356.328033
current_seq = 9972
count = 252
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 41us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.328857
last_received_ts = 356.328033
last_seq = 9972
current_ts = 356.345520
current_received_ts = 356.344696
current_seq = 9973
count = 253
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.345520
last_received_ts = 356.344696
last_seq = 9973
current_ts = 356.362183
current_received_ts = 356.361420
current_seq = 9974
count = 254
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.362183
last_received_ts = 356.361420
last_seq = 9974
current_ts = 356.378876
current_received_ts = 356.378052
current_seq = 9975
count = 255
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 51us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.378876
last_received_ts = 356.378052
last_seq = 9975
current_ts = 356.395538
current_received_ts = 356.394745
current_seq = 9976
count = 256
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.395538
last_received_ts = 356.394745
last_seq = 9976
current_ts = 356.412201
current_received_ts = 356.411438
current_seq = 9977
count = 257
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.412201
last_received_ts = 356.411438
last_seq = 9977
current_ts = 356.428894
current_received_ts = 356.428101
current_seq = 9978
count = 258
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.428894
last_received_ts = 356.428101
last_seq = 9978
current_ts = 356.445557
current_received_ts = 356.444794
current_seq = 9979
count = 259
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.445557
last_received_ts = 356.444794
last_seq = 9979
current_ts = 356.462250
current_received_ts = 356.461456
current_seq = 9980
count = 260
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.462250
last_received_ts = 356.461456
last_seq = 9980
current_ts = 356.478912
current_received_ts = 356.478088
current_seq = 9981
count = 261
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.478912
last_received_ts = 356.478088
last_seq = 9981
current_ts = 356.495575
current_received_ts = 356.494781
current_seq = 9982
count = 262
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 42us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.495575
last_received_ts = 356.494781
last_seq = 9982
current_ts = 356.512268
current_received_ts = 356.511444
current_seq = 9983
count = 263
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 49us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.512268
last_received_ts = 356.511444
last_seq = 9983
current_ts = 356.528931
current_received_ts = 356.528137
current_seq = 9984
count = 264
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.528931
last_received_ts = 356.528137
last_seq = 9984
current_ts = 356.545624
current_received_ts = 356.544830
current_seq = 9985
count = 265
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.545624
last_received_ts = 356.544830
last_seq = 9985
current_ts = 356.562286
current_received_ts = 356.561493
current_seq = 9986
count = 266
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.562286
last_received_ts = 356.561493
last_seq = 9986
current_ts = 356.578949
current_received_ts = 356.578156
current_seq = 9987
count = 267
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.578949
last_received_ts = 356.578156
last_seq = 9987
current_ts = 356.595642
current_received_ts = 356.594849
current_seq = 9988
count = 268
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.595642
last_received_ts = 356.594849
last_seq = 9988
current_ts = 356.612305
current_received_ts = 356.611511
current_seq = 9989
count = 269
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.612305
last_received_ts = 356.611511
last_seq = 9989
current_ts = 356.628998
current_received_ts = 356.628174
current_seq = 9990
count = 270
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.628998
last_received_ts = 356.628174
last_seq = 9990
current_ts = 356.645660
current_received_ts = 356.644867
current_seq = 9991
count = 271
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.645660
last_received_ts = 356.644867
last_seq = 9991
current_ts = 356.662323
current_received_ts = 356.661530
current_seq = 9992
count = 272
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 51us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.662323
last_received_ts = 356.661530
last_seq = 9992
current_ts = 356.679016
current_received_ts = 356.678192
current_seq = 9993
count = 273
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 49us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.679016
last_received_ts = 356.678192
last_seq = 9993
current_ts = 356.695679
current_received_ts = 356.694916
current_seq = 9994
count = 274
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.695679
last_received_ts = 356.694916
last_seq = 9994
current_ts = 356.712341
current_received_ts = 356.711578
current_seq = 9995
count = 275
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 57us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.712341
last_received_ts = 356.711578
last_seq = 9995
current_ts = 356.729034
current_received_ts = 356.728241
current_seq = 9996
count = 276
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 53us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.729034
last_received_ts = 356.728241
last_seq = 9996
current_ts = 356.745697
current_received_ts = 356.744904
current_seq = 9997
count = 277
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 53us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.745697
last_received_ts = 356.744904
last_seq = 9997
current_ts = 356.762390
current_received_ts = 356.761597
current_seq = 9998
count = 278
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 49us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.762390
last_received_ts = 356.761597
last_seq = 9998
current_ts = 356.779053
current_received_ts = 356.778259
current_seq = 9999
count = 279
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 52us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.779053
last_received_ts = 356.778259
last_seq = 9999
current_ts = 356.795715
current_received_ts = 356.794922
current_seq = 10000
count = 280
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 50us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.795715
last_received_ts = 356.794922
last_seq = 10000
current_ts = 356.812408
current_received_ts = 356.811584
current_seq = 10001
count = 281
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 50us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.812408
last_received_ts = 356.811584
last_seq = 10001
current_ts = 356.829071
current_received_ts = 356.828278
current_seq = 10002
count = 282
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 49us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.829071
last_received_ts = 356.828278
last_seq = 10002
current_ts = 356.845734
current_received_ts = 356.844971
current_seq = 10003
count = 283
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 218us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.845734
last_received_ts = 356.844971
last_seq = 10003
current_ts = 356.862427
current_received_ts = 356.861633
current_seq = 10004
count = 284
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 50us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.862427
last_received_ts = 356.861633
last_seq = 10004
current_ts = 356.879089
current_received_ts = 356.878296
current_seq = 10005
count = 285
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 52us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.879089
last_received_ts = 356.878296
last_seq = 10005
current_ts = 356.895782
current_received_ts = 356.894989
current_seq = 10006
count = 286
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 87us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.895782
last_received_ts = 356.894989
last_seq = 10006
current_ts = 356.912445
current_received_ts = 356.911652
current_seq = 10007
count = 287
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 50us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.912445
last_received_ts = 356.911652
last_seq = 10007
current_ts = 356.929108
current_received_ts = 356.928314
current_seq = 10008
count = 288
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.929108
last_received_ts = 356.928314
last_seq = 10008
current_ts = 356.945801
current_received_ts = 356.945038
current_seq = 10009
count = 289
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 109us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.945801
last_received_ts = 356.945038
last_seq = 10009
current_ts = 356.962463
current_received_ts = 356.961670
current_seq = 10010
count = 290
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 77us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.962463
last_received_ts = 356.961670
last_seq = 10010
current_ts = 356.979126
current_received_ts = 356.978333
current_seq = 10011
count = 291
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 80us
(kms_flip:5486) DEBUG: name = flip
last_ts = 356.979126
last_received_ts = 356.978333
last_seq = 10011
current_ts = 356.995819
current_received_ts = 356.995026
current_seq = 10012
count = 292
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 1587us
(kms_flip:5486) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:5486) CRITICAL: Failed assertion: end - start < 500
(kms_flip:5486) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:5486) igt_core-INFO: Stack trace:
(kms_flip:5486) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:5486) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:5486) igt_core-INFO:   #2 ../tests/kms_flip.c:1889 run_test()
(kms_flip:5486) igt_core-INFO:   #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
(kms_flip:5486) igt_core-INFO:   #4 ../tests/kms_flip.c:2045 main()
(kms_flip:5486) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:5486) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:5486) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (6.157s)
Starting dynamic subtest: B-eDP1
(kms_flip:5486) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:5486) CRITICAL: Failed assertion: end - start < 500
(kms_flip:5486) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:5486) DEBUG: Vblank took 35us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.007599
last_received_ts = 365.006989
last_seq = 734
current_ts = 365.024292
current_received_ts = 365.023682
current_seq = 735
count = 402
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 32us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.024292
last_received_ts = 365.023682
last_seq = 735
current_ts = 365.040955
current_received_ts = 365.040344
current_seq = 736
count = 403
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 32us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.040955
last_received_ts = 365.040344
last_seq = 736
current_ts = 365.057617
current_received_ts = 365.056976
current_seq = 737
count = 404
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 69us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.057617
last_received_ts = 365.056976
last_seq = 737
current_ts = 365.074280
current_received_ts = 365.073669
current_seq = 738
count = 405
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 32us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.074280
last_received_ts = 365.073669
last_seq = 738
current_ts = 365.090973
current_received_ts = 365.090515
current_seq = 739
count = 406
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 32us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.090973
last_received_ts = 365.090515
last_seq = 739
current_ts = 365.107635
current_received_ts = 365.107117
current_seq = 740
count = 407
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 33us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.107635
last_received_ts = 365.107117
last_seq = 740
current_ts = 365.124298
current_received_ts = 365.123810
current_seq = 741
count = 408
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 30us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.124298
last_received_ts = 365.123810
last_seq = 741
current_ts = 365.140961
current_received_ts = 365.140503
current_seq = 742
count = 409
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 34us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.140961
last_received_ts = 365.140503
last_seq = 742
current_ts = 365.157654
current_received_ts = 365.157104
current_seq = 743
count = 410
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 33us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.157654
last_received_ts = 365.157104
last_seq = 743
current_ts = 365.174316
current_received_ts = 365.173706
current_seq = 744
count = 411
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 34us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.174316
last_received_ts = 365.173706
last_seq = 744
current_ts = 365.190979
current_received_ts = 365.190369
current_seq = 745
count = 412
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 35us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.190979
last_received_ts = 365.190369
last_seq = 745
current_ts = 365.207672
current_received_ts = 365.207062
current_seq = 746
count = 413
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 91us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.207672
last_received_ts = 365.207062
last_seq = 746
current_ts = 365.224335
current_received_ts = 365.223846
current_seq = 747
count = 414
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 34us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.224335
last_received_ts = 365.223846
last_seq = 747
current_ts = 365.240997
current_received_ts = 365.240509
current_seq = 748
count = 415
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 33us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.240997
last_received_ts = 365.240509
last_seq = 748
current_ts = 365.257660
current_received_ts = 365.257324
current_seq = 749
count = 416
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 74us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.257660
last_received_ts = 365.257324
last_seq = 749
current_ts = 365.274353
current_received_ts = 365.273743
current_seq = 750
count = 417
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 110us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.274353
last_received_ts = 365.273743
last_seq = 750
current_ts = 365.291016
current_received_ts = 365.290466
current_seq = 751
count = 418
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 103us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.291016
last_received_ts = 365.290466
last_seq = 751
current_ts = 365.307678
current_received_ts = 365.307190
current_seq = 752
count = 419
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 86us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.307678
last_received_ts = 365.307190
last_seq = 752
current_ts = 365.324341
current_received_ts = 365.323883
current_seq = 753
count = 420
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 41us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.324341
last_received_ts = 365.323883
last_seq = 753
current_ts = 365.341034
current_received_ts = 365.340515
current_seq = 754
count = 421
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 104us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.341034
last_received_ts = 365.340515
last_seq = 754
current_ts = 365.357697
current_received_ts = 365.357056
current_seq = 755
count = 422
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 35us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.357697
last_received_ts = 365.357056
last_seq = 755
current_ts = 365.374359
current_received_ts = 365.373901
current_seq = 756
count = 423
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 32us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.374359
last_received_ts = 365.373901
last_seq = 756
current_ts = 365.391052
current_received_ts = 365.390564
current_seq = 757
count = 424
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 101us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.391052
last_received_ts = 365.390564
last_seq = 757
current_ts = 365.407715
current_received_ts = 365.407227
current_seq = 758
count = 425
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 31us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.407715
last_received_ts = 365.407227
last_seq = 758
current_ts = 365.424377
current_received_ts = 365.423767
current_seq = 759
count = 426
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 92us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.424377
last_received_ts = 365.423767
last_seq = 759
current_ts = 365.441040
current_received_ts = 365.440369
current_seq = 760
count = 427
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 91us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.441040
last_received_ts = 365.440369
last_seq = 760
current_ts = 365.457733
current_received_ts = 365.457214
current_seq = 761
count = 428
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 32us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.457733
last_received_ts = 365.457214
last_seq = 761
current_ts = 365.474396
current_received_ts = 365.473907
current_seq = 762
count = 429
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 32us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.474396
last_received_ts = 365.473907
last_seq = 762
current_ts = 365.491058
current_received_ts = 365.490448
current_seq = 763
count = 430
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 87us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.491058
last_received_ts = 365.490448
last_seq = 763
current_ts = 365.507721
current_received_ts = 365.507233
current_seq = 764
count = 431
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 30us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.507721
last_received_ts = 365.507233
last_seq = 764
current_ts = 365.524414
current_received_ts = 365.523804
current_seq = 765
count = 432
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 33us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.524414
last_received_ts = 365.523804
last_seq = 765
current_ts = 365.541077
current_received_ts = 365.540619
current_seq = 766
count = 433
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 33us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.541077
last_received_ts = 365.540619
last_seq = 766
current_ts = 365.557739
current_received_ts = 365.557251
current_seq = 767
count = 434
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 30us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.557739
last_received_ts = 365.557251
last_seq = 767
current_ts = 365.574402
current_received_ts = 365.573822
current_seq = 768
count = 435
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 36us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.574402
last_received_ts = 365.573822
last_seq = 768
current_ts = 365.591095
current_received_ts = 365.590637
current_seq = 769
count = 436
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 32us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.591095
last_received_ts = 365.590637
last_seq = 769
current_ts = 365.607758
current_received_ts = 365.607269
current_seq = 770
count = 437
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 31us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.607758
last_received_ts = 365.607269
last_seq = 770
current_ts = 365.624420
current_received_ts = 365.623810
current_seq = 771
count = 438
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 31us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.624420
last_received_ts = 365.623810
last_seq = 771
current_ts = 365.641083
current_received_ts = 365.640472
current_seq = 772
count = 439
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 40us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.641083
last_received_ts = 365.640472
last_seq = 772
current_ts = 365.657776
current_received_ts = 365.657135
current_seq = 773
count = 440
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 32us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.657776
last_received_ts = 365.657135
last_seq = 773
current_ts = 365.674438
current_received_ts = 365.673645
current_seq = 774
count = 441
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 57us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.674438
last_received_ts = 365.673645
last_seq = 774
current_ts = 365.691101
current_received_ts = 365.690308
current_seq = 775
count = 442
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 64us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.691101
last_received_ts = 365.690308
last_seq = 775
current_ts = 365.707764
current_received_ts = 365.707001
current_seq = 776
count = 443
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 53us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.707764
last_received_ts = 365.707001
last_seq = 776
current_ts = 365.724457
current_received_ts = 365.723663
current_seq = 777
count = 444
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.724457
last_received_ts = 365.723663
last_seq = 777
current_ts = 365.741119
current_received_ts = 365.740295
current_seq = 778
count = 445
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.741119
last_received_ts = 365.740295
last_seq = 778
current_ts = 365.757782
current_received_ts = 365.756989
current_seq = 779
count = 446
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 71us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.757782
last_received_ts = 365.756989
last_seq = 779
current_ts = 365.774445
current_received_ts = 365.773682
current_seq = 780
count = 447
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 58us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.774445
last_received_ts = 365.773682
last_seq = 780
current_ts = 365.791138
current_received_ts = 365.790314
current_seq = 781
count = 448
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 42us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.791138
last_received_ts = 365.790314
last_seq = 781
current_ts = 365.807800
current_received_ts = 365.807037
current_seq = 782
count = 449
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.807800
last_received_ts = 365.807037
last_seq = 782
current_ts = 365.824463
current_received_ts = 365.823700
current_seq = 783
count = 450
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 53us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.824463
last_received_ts = 365.823700
last_seq = 783
current_ts = 365.841156
current_received_ts = 365.840363
current_seq = 784
count = 451
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 57us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.841156
last_received_ts = 365.840363
last_seq = 784
current_ts = 365.857819
current_received_ts = 365.857025
current_seq = 785
count = 452
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.857819
last_received_ts = 365.857025
last_seq = 785
current_ts = 365.874481
current_received_ts = 365.873688
current_seq = 786
count = 453
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.874481
last_received_ts = 365.873688
last_seq = 786
current_ts = 365.891144
current_received_ts = 365.890381
current_seq = 787
count = 454
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 108us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.891144
last_received_ts = 365.890381
last_seq = 787
current_ts = 365.907837
current_received_ts = 365.907043
current_seq = 788
count = 455
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 59us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.907837
last_received_ts = 365.907043
last_seq = 788
current_ts = 365.924500
current_received_ts = 365.923676
current_seq = 789
count = 456
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 52us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.924500
last_received_ts = 365.923676
last_seq = 789
current_ts = 365.941162
current_received_ts = 365.940369
current_seq = 790
count = 457
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 120us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.941162
last_received_ts = 365.940369
last_seq = 790
current_ts = 365.957825
current_received_ts = 365.957062
current_seq = 791
count = 458
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 53us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.957825
last_received_ts = 365.957062
last_seq = 791
current_ts = 365.974487
current_received_ts = 365.973724
current_seq = 792
count = 459
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.974487
last_received_ts = 365.973724
last_seq = 792
current_ts = 365.991180
current_received_ts = 365.990387
current_seq = 793
count = 460
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 365.991180
last_received_ts = 365.990387
last_seq = 793
current_ts = 366.007843
current_received_ts = 366.007050
current_seq = 794
count = 461
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.007843
last_received_ts = 366.007050
last_seq = 794
current_ts = 366.024506
current_received_ts = 366.023743
current_seq = 795
count = 462
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.024506
last_received_ts = 366.023743
last_seq = 795
current_ts = 366.041199
current_received_ts = 366.040405
current_seq = 796
count = 463
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.041199
last_received_ts = 366.040405
last_seq = 796
current_ts = 366.057861
current_received_ts = 366.057068
current_seq = 797
count = 464
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.057861
last_received_ts = 366.057068
last_seq = 797
current_ts = 366.074524
current_received_ts = 366.073761
current_seq = 798
count = 465
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.074524
last_received_ts = 366.073761
last_seq = 798
current_ts = 366.091187
current_received_ts = 366.090424
current_seq = 799
count = 466
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.091187
last_received_ts = 366.090424
last_seq = 799
current_ts = 366.107880
current_received_ts = 366.107056
current_seq = 800
count = 467
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 50us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.107880
last_received_ts = 366.107056
last_seq = 800
current_ts = 366.124542
current_received_ts = 366.123749
current_seq = 801
count = 468
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.124542
last_received_ts = 366.123749
last_seq = 801
current_ts = 366.141205
current_received_ts = 366.140411
current_seq = 802
count = 469
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.141205
last_received_ts = 366.140411
last_seq = 802
current_ts = 366.157867
current_received_ts = 366.157074
current_seq = 803
count = 470
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.157867
last_received_ts = 366.157074
last_seq = 803
current_ts = 366.174561
current_received_ts = 366.173767
current_seq = 804
count = 471
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.174561
last_received_ts = 366.173767
last_seq = 804
current_ts = 366.191223
current_received_ts = 366.190430
current_seq = 805
count = 472
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.191223
last_received_ts = 366.190430
last_seq = 805
current_ts = 366.207886
current_received_ts = 366.207092
current_seq = 806
count = 473
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.207886
last_received_ts = 366.207092
last_seq = 806
current_ts = 366.224548
current_received_ts = 366.223785
current_seq = 807
count = 474
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.224548
last_received_ts = 366.223785
last_seq = 807
current_ts = 366.241241
current_received_ts = 366.240448
current_seq = 808
count = 475
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.241241
last_received_ts = 366.240448
last_seq = 808
current_ts = 366.257904
current_received_ts = 366.257080
current_seq = 809
count = 476
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.257904
last_received_ts = 366.257080
last_seq = 809
current_ts = 366.274567
current_received_ts = 366.273773
current_seq = 810
count = 477
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 42us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.274567
last_received_ts = 366.273773
last_seq = 810
current_ts = 366.291229
current_received_ts = 366.290466
current_seq = 811
count = 478
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.291229
last_received_ts = 366.290466
last_seq = 811
current_ts = 366.307922
current_received_ts = 366.307098
current_seq = 812
count = 479
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 39us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.307922
last_received_ts = 366.307098
last_seq = 812
current_ts = 366.324585
current_received_ts = 366.323792
current_seq = 813
count = 480
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 49us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.324585
last_received_ts = 366.323792
last_seq = 813
current_ts = 366.341248
current_received_ts = 366.340485
current_seq = 814
count = 481
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 65us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.341248
last_received_ts = 366.340485
last_seq = 814
current_ts = 366.357910
current_received_ts = 366.357117
current_seq = 815
count = 482
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.357910
last_received_ts = 366.357117
last_seq = 815
current_ts = 366.374603
current_received_ts = 366.373810
current_seq = 816
count = 483
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 50us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.374603
last_received_ts = 366.373810
last_seq = 816
current_ts = 366.391266
current_received_ts = 366.390472
current_seq = 817
count = 484
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.391266
last_received_ts = 366.390472
last_seq = 817
current_ts = 366.407928
current_received_ts = 366.407135
current_seq = 818
count = 485
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.407928
last_received_ts = 366.407135
last_seq = 818
current_ts = 366.424591
current_received_ts = 366.423828
current_seq = 819
count = 486
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 42us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.424591
last_received_ts = 366.423828
last_seq = 819
current_ts = 366.441284
current_received_ts = 366.440491
current_seq = 820
count = 487
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 38us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.441284
last_received_ts = 366.440491
last_seq = 820
current_ts = 366.457947
current_received_ts = 366.457123
current_seq = 821
count = 488
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 40us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.457947
last_received_ts = 366.457123
last_seq = 821
current_ts = 366.474609
current_received_ts = 366.473816
current_seq = 822
count = 489
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.474609
last_received_ts = 366.473816
last_seq = 822
current_ts = 366.491272
current_received_ts = 366.490509
current_seq = 823
count = 490
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.491272
last_received_ts = 366.490509
last_seq = 823
current_ts = 366.507965
current_received_ts = 366.507141
current_seq = 824
count = 491
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.507965
last_received_ts = 366.507141
last_seq = 824
current_ts = 366.524628
current_received_ts = 366.523834
current_seq = 825
count = 492
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.524628
last_received_ts = 366.523834
last_seq = 825
current_ts = 366.541290
current_received_ts = 366.540527
current_seq = 826
count = 493
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 121us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.541290
last_received_ts = 366.540527
last_seq = 826
current_ts = 366.557983
current_received_ts = 366.557159
current_seq = 827
count = 494
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 49us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.557983
last_received_ts = 366.557159
last_seq = 827
current_ts = 366.574646
current_received_ts = 366.573853
current_seq = 828
count = 495
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 53us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.574646
last_received_ts = 366.573853
last_seq = 828
current_ts = 366.591309
current_received_ts = 366.590515
current_seq = 829
count = 496
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 60us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.591309
last_received_ts = 366.590515
last_seq = 829
current_ts = 366.607971
current_received_ts = 366.607147
current_seq = 830
count = 497
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.607971
last_received_ts = 366.607147
last_seq = 830
current_ts = 366.624634
current_received_ts = 366.623871
current_seq = 831
count = 498
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.624634
last_received_ts = 366.623871
last_seq = 831
current_ts = 366.641327
current_received_ts = 366.640533
current_seq = 832
count = 499
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.641327
last_received_ts = 366.640533
last_seq = 832
current_ts = 366.657990
current_received_ts = 366.657196
current_seq = 833
count = 500
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 49us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.657990
last_received_ts = 366.657196
last_seq = 833
current_ts = 366.674652
current_received_ts = 366.673889
current_seq = 834
count = 501
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.674652
last_received_ts = 366.673889
last_seq = 834
current_ts = 366.691345
current_received_ts = 366.690552
current_seq = 835
count = 502
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.691345
last_received_ts = 366.690552
last_seq = 835
current_ts = 366.708008
current_received_ts = 366.707184
current_seq = 836
count = 503
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.708008
last_received_ts = 366.707184
last_seq = 836
current_ts = 366.724670
current_received_ts = 366.723877
current_seq = 837
count = 504
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 49us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.724670
last_received_ts = 366.723877
last_seq = 837
current_ts = 366.741333
current_received_ts = 366.740540
current_seq = 838
count = 505
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.741333
last_received_ts = 366.740540
last_seq = 838
current_ts = 366.758026
current_received_ts = 366.757202
current_seq = 839
count = 506
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 56us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.758026
last_received_ts = 366.757202
last_seq = 839
current_ts = 366.774689
current_received_ts = 366.773895
current_seq = 840
count = 507
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.774689
last_received_ts = 366.773895
last_seq = 840
current_ts = 366.791351
current_received_ts = 366.790588
current_seq = 841
count = 508
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 42us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.791351
last_received_ts = 366.790588
last_seq = 841
current_ts = 366.808014
current_received_ts = 366.807220
current_seq = 842
count = 509
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.808014
last_received_ts = 366.807220
last_seq = 842
current_ts = 366.824707
current_received_ts = 366.823914
current_seq = 843
count = 510
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 53us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.824707
last_received_ts = 366.823914
last_seq = 843
current_ts = 366.841370
current_received_ts = 366.840576
current_seq = 844
count = 511
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 53us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.841370
last_received_ts = 366.840576
last_seq = 844
current_ts = 366.858032
current_received_ts = 366.857239
current_seq = 845
count = 512
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 51us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.858032
last_received_ts = 366.857239
last_seq = 845
current_ts = 366.874695
current_received_ts = 366.873932
current_seq = 846
count = 513
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 57us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.874695
last_received_ts = 366.873932
last_seq = 846
current_ts = 366.891388
current_received_ts = 366.890594
current_seq = 847
count = 514
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.891388
last_received_ts = 366.890594
last_seq = 847
current_ts = 366.908051
current_received_ts = 366.907257
current_seq = 848
count = 515
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.908051
last_received_ts = 366.907257
last_seq = 848
current_ts = 366.924713
current_received_ts = 366.923950
current_seq = 849
count = 516
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 66us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.924713
last_received_ts = 366.923950
last_seq = 849
current_ts = 366.941376
current_received_ts = 366.940613
current_seq = 850
count = 517
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.941376
last_received_ts = 366.940613
last_seq = 850
current_ts = 366.958069
current_received_ts = 366.957245
current_seq = 851
count = 518
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.958069
last_received_ts = 366.957245
last_seq = 851
current_ts = 366.974731
current_received_ts = 366.973938
current_seq = 852
count = 519
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 116us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.974731
last_received_ts = 366.973938
last_seq = 852
current_ts = 366.991394
current_received_ts = 366.990631
current_seq = 853
count = 520
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 366.991394
last_received_ts = 366.990631
last_seq = 853
current_ts = 367.008057
current_received_ts = 367.007263
current_seq = 854
count = 521
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 367.008057
last_received_ts = 367.007263
last_seq = 854
current_ts = 367.024750
current_received_ts = 367.023956
current_seq = 855
count = 522
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 573us
(kms_flip:5486) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:5486) CRITICAL: Failed assertion: end - start < 500
(kms_flip:5486) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:5486) igt_core-INFO: Stack trace:
(kms_flip:5486) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:5486) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:5486) igt_core-INFO:   #2 ../tests/kms_flip.c:1889 run_test()
(kms_flip:5486) igt_core-INFO:   #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
(kms_flip:5486) igt_core-INFO:   #4 ../tests/kms_flip.c:2045 main()
(kms_flip:5486) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:5486) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:5486) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (10.015s)
Starting dynamic subtest: C-eDP1
(kms_flip:5486) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:5486) CRITICAL: Failed assertion: end - start < 500
(kms_flip:5486) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest C-eDP1 failed.
**** DEBUG ****
(kms_flip:5486) DEBUG: Vblank took 41us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.496735
last_received_ts = 372.495941
last_seq = 1035
current_ts = 372.513397
current_received_ts = 372.512634
current_seq = 1036
count = 251
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 37us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.513397
last_received_ts = 372.512634
last_seq = 1036
current_ts = 372.530090
current_received_ts = 372.529266
current_seq = 1037
count = 252
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 40us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.530090
last_received_ts = 372.529266
last_seq = 1037
current_ts = 372.546753
current_received_ts = 372.545959
current_seq = 1038
count = 253
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 53us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.546753
last_received_ts = 372.545959
last_seq = 1038
current_ts = 372.563416
current_received_ts = 372.562653
current_seq = 1039
count = 254
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 96us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.563416
last_received_ts = 372.562653
last_seq = 1039
current_ts = 372.580078
current_received_ts = 372.579285
current_seq = 1040
count = 255
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.580078
last_received_ts = 372.579285
last_seq = 1040
current_ts = 372.596771
current_received_ts = 372.595978
current_seq = 1041
count = 256
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.596771
last_received_ts = 372.595978
last_seq = 1041
current_ts = 372.613434
current_received_ts = 372.612671
current_seq = 1042
count = 257
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 96us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.613434
last_received_ts = 372.612671
last_seq = 1042
current_ts = 372.630096
current_received_ts = 372.629303
current_seq = 1043
count = 258
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.630096
last_received_ts = 372.629303
last_seq = 1043
current_ts = 372.646759
current_received_ts = 372.645996
current_seq = 1044
count = 259
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 68us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.646759
last_received_ts = 372.645996
last_seq = 1044
current_ts = 372.663422
current_received_ts = 372.662659
current_seq = 1045
count = 260
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.663422
last_received_ts = 372.662659
last_seq = 1045
current_ts = 372.680115
current_received_ts = 372.679321
current_seq = 1046
count = 261
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.680115
last_received_ts = 372.679321
last_seq = 1046
current_ts = 372.696777
current_received_ts = 372.695984
current_seq = 1047
count = 262
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 63us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.696777
last_received_ts = 372.695984
last_seq = 1047
current_ts = 372.713440
current_received_ts = 372.712677
current_seq = 1048
count = 263
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 59us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.713440
last_received_ts = 372.712677
last_seq = 1048
current_ts = 372.730103
current_received_ts = 372.729340
current_seq = 1049
count = 264
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 56us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.730103
last_received_ts = 372.729340
last_seq = 1049
current_ts = 372.746796
current_received_ts = 372.746033
current_seq = 1050
count = 265
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.746796
last_received_ts = 372.746033
last_seq = 1050
current_ts = 372.763458
current_received_ts = 372.762665
current_seq = 1051
count = 266
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.763458
last_received_ts = 372.762665
last_seq = 1051
current_ts = 372.780121
current_received_ts = 372.779327
current_seq = 1052
count = 267
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.780121
last_received_ts = 372.779327
last_seq = 1052
current_ts = 372.796783
current_received_ts = 372.795990
current_seq = 1053
count = 268
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 67us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.796783
last_received_ts = 372.795990
last_seq = 1053
current_ts = 372.813446
current_received_ts = 372.812653
current_seq = 1054
count = 269
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 58us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.813446
last_received_ts = 372.812653
last_seq = 1054
current_ts = 372.830139
current_received_ts = 372.829346
current_seq = 1055
count = 270
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.830139
last_received_ts = 372.829346
last_seq = 1055
current_ts = 372.846802
current_received_ts = 372.846039
current_seq = 1056
count = 271
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 56us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.846802
last_received_ts = 372.846039
last_seq = 1056
current_ts = 372.863464
current_received_ts = 372.862701
current_seq = 1057
count = 272
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 58us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.863464
last_received_ts = 372.862701
last_seq = 1057
current_ts = 372.880127
current_received_ts = 372.879364
current_seq = 1058
count = 273
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 50us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.880127
last_received_ts = 372.879364
last_seq = 1058
current_ts = 372.896820
current_received_ts = 372.896027
current_seq = 1059
count = 274
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 51us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.896820
last_received_ts = 372.896027
last_seq = 1059
current_ts = 372.913483
current_received_ts = 372.912689
current_seq = 1060
count = 275
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 53us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.913483
last_received_ts = 372.912689
last_seq = 1060
current_ts = 372.930145
current_received_ts = 372.929352
current_seq = 1061
count = 276
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 50us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.930145
last_received_ts = 372.929352
last_seq = 1061
current_ts = 372.946808
current_received_ts = 372.946045
current_seq = 1062
count = 277
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.946808
last_received_ts = 372.946045
last_seq = 1062
current_ts = 372.963501
current_received_ts = 372.962708
current_seq = 1063
count = 278
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 53us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.963501
last_received_ts = 372.962708
last_seq = 1063
current_ts = 372.980164
current_received_ts = 372.979370
current_seq = 1064
count = 279
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 59us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.980164
last_received_ts = 372.979370
last_seq = 1064
current_ts = 372.996826
current_received_ts = 372.996063
current_seq = 1065
count = 280
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 59us
(kms_flip:5486) DEBUG: name = flip
last_ts = 372.996826
last_received_ts = 372.996063
last_seq = 1065
current_ts = 373.013489
current_received_ts = 373.012726
current_seq = 1066
count = 281
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 39us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.013489
last_received_ts = 373.012726
last_seq = 1066
current_ts = 373.030182
current_received_ts = 373.029388
current_seq = 1067
count = 282
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.030182
last_received_ts = 373.029388
last_seq = 1067
current_ts = 373.046844
current_received_ts = 373.046051
current_seq = 1068
count = 283
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 40us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.046844
last_received_ts = 373.046051
last_seq = 1068
current_ts = 373.063507
current_received_ts = 373.062683
current_seq = 1069
count = 284
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.063507
last_received_ts = 373.062683
last_seq = 1069
current_ts = 373.080170
current_received_ts = 373.079376
current_seq = 1070
count = 285
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 40us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.080170
last_received_ts = 373.079376
last_seq = 1070
current_ts = 373.096832
current_received_ts = 373.096069
current_seq = 1071
count = 286
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 49us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.096832
last_received_ts = 373.096069
last_seq = 1071
current_ts = 373.113525
current_received_ts = 373.112732
current_seq = 1072
count = 287
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 53us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.113525
last_received_ts = 373.112732
last_seq = 1072
current_ts = 373.130188
current_received_ts = 373.129395
current_seq = 1073
count = 288
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.130188
last_received_ts = 373.129395
last_seq = 1073
current_ts = 373.146851
current_received_ts = 373.146057
current_seq = 1074
count = 289
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.146851
last_received_ts = 373.146057
last_seq = 1074
current_ts = 373.163513
current_received_ts = 373.162750
current_seq = 1075
count = 290
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.163513
last_received_ts = 373.162750
last_seq = 1075
current_ts = 373.180176
current_received_ts = 373.179413
current_seq = 1076
count = 291
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.180176
last_received_ts = 373.179413
last_seq = 1076
current_ts = 373.196869
current_received_ts = 373.196075
current_seq = 1077
count = 292
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 41us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.196869
last_received_ts = 373.196075
last_seq = 1077
current_ts = 373.213531
current_received_ts = 373.212769
current_seq = 1078
count = 293
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 50us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.213531
last_received_ts = 373.212769
last_seq = 1078
current_ts = 373.230194
current_received_ts = 373.229401
current_seq = 1079
count = 294
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.230194
last_received_ts = 373.229401
last_seq = 1079
current_ts = 373.246857
current_received_ts = 373.246063
current_seq = 1080
count = 295
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 42us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.246857
last_received_ts = 373.246063
last_seq = 1080
current_ts = 373.263550
current_received_ts = 373.262756
current_seq = 1081
count = 296
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.263550
last_received_ts = 373.262756
last_seq = 1081
current_ts = 373.280212
current_received_ts = 373.279388
current_seq = 1082
count = 297
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.280212
last_received_ts = 373.279388
last_seq = 1082
current_ts = 373.296875
current_received_ts = 373.296082
current_seq = 1083
count = 298
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 41us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.296875
last_received_ts = 373.296082
last_seq = 1083
current_ts = 373.313538
current_received_ts = 373.312775
current_seq = 1084
count = 299
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 92us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.313538
last_received_ts = 373.312775
last_seq = 1084
current_ts = 373.330231
current_received_ts = 373.329437
current_seq = 1085
count = 300
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 42us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.330231
last_received_ts = 373.329437
last_seq = 1085
current_ts = 373.346893
current_received_ts = 373.346069
current_seq = 1086
count = 301
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 41us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.346893
last_received_ts = 373.346069
last_seq = 1086
current_ts = 373.363556
current_received_ts = 373.362793
current_seq = 1087
count = 302
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 42us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.363556
last_received_ts = 373.362793
last_seq = 1087
current_ts = 373.380219
current_received_ts = 373.379425
current_seq = 1088
count = 303
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 42us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.380219
last_received_ts = 373.379425
last_seq = 1088
current_ts = 373.396881
current_received_ts = 373.396088
current_seq = 1089
count = 304
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 51us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.396881
last_received_ts = 373.396088
last_seq = 1089
current_ts = 373.413574
current_received_ts = 373.412781
current_seq = 1090
count = 305
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.413574
last_received_ts = 373.412781
last_seq = 1090
current_ts = 373.430237
current_received_ts = 373.429443
current_seq = 1091
count = 306
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.430237
last_received_ts = 373.429443
last_seq = 1091
current_ts = 373.446899
current_received_ts = 373.446106
current_seq = 1092
count = 307
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.446899
last_received_ts = 373.446106
last_seq = 1092
current_ts = 373.463562
current_received_ts = 373.462799
current_seq = 1093
count = 308
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 42us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.463562
last_received_ts = 373.462799
last_seq = 1093
current_ts = 373.480255
current_received_ts = 373.479431
current_seq = 1094
count = 309
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 51us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.480255
last_received_ts = 373.479431
last_seq = 1094
current_ts = 373.496918
current_received_ts = 373.496124
current_seq = 1095
count = 310
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.496918
last_received_ts = 373.496124
last_seq = 1095
current_ts = 373.513580
current_received_ts = 373.512787
current_seq = 1096
count = 311
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 51us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.513580
last_received_ts = 373.512787
last_seq = 1096
current_ts = 373.530243
current_received_ts = 373.529480
current_seq = 1097
count = 312
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 98us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.530243
last_received_ts = 373.529480
last_seq = 1097
current_ts = 373.546936
current_received_ts = 373.546112
current_seq = 1098
count = 313
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.546936
last_received_ts = 373.546112
last_seq = 1098
current_ts = 373.563599
current_received_ts = 373.562805
current_seq = 1099
count = 314
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.563599
last_received_ts = 373.562805
last_seq = 1099
current_ts = 373.580261
current_received_ts = 373.579498
current_seq = 1100
count = 315
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 52us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.580261
last_received_ts = 373.579498
last_seq = 1100
current_ts = 373.596924
current_received_ts = 373.596130
current_seq = 1101
count = 316
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 52us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.596924
last_received_ts = 373.596130
last_seq = 1101
current_ts = 373.613586
current_received_ts = 373.612823
current_seq = 1102
count = 317
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 52us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.613586
last_received_ts = 373.612823
last_seq = 1102
current_ts = 373.630280
current_received_ts = 373.629486
current_seq = 1103
count = 318
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 43us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.630280
last_received_ts = 373.629486
last_seq = 1103
current_ts = 373.646942
current_received_ts = 373.646149
current_seq = 1104
count = 319
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.646942
last_received_ts = 373.646149
last_seq = 1104
current_ts = 373.663605
current_received_ts = 373.662842
current_seq = 1105
count = 320
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 52us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.663605
last_received_ts = 373.662842
last_seq = 1105
current_ts = 373.680267
current_received_ts = 373.679504
current_seq = 1106
count = 321
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.680267
last_received_ts = 373.679504
last_seq = 1106
current_ts = 373.696960
current_received_ts = 373.696228
current_seq = 1107
count = 322
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 93us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.696960
last_received_ts = 373.696228
last_seq = 1107
current_ts = 373.713623
current_received_ts = 373.713074
current_seq = 1108
count = 323
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 135us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.713623
last_received_ts = 373.713074
last_seq = 1108
current_ts = 373.730286
current_received_ts = 373.729523
current_seq = 1109
count = 324
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 69us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.730286
last_received_ts = 373.729523
last_seq = 1109
current_ts = 373.746948
current_received_ts = 373.746185
current_seq = 1110
count = 325
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 66us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.746948
last_received_ts = 373.746185
last_seq = 1110
current_ts = 373.763611
current_received_ts = 373.762848
current_seq = 1111
count = 326
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 57us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.763611
last_received_ts = 373.762848
last_seq = 1111
current_ts = 373.780304
current_received_ts = 373.779541
current_seq = 1112
count = 327
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 56us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.780304
last_received_ts = 373.779541
last_seq = 1112
current_ts = 373.796967
current_received_ts = 373.796173
current_seq = 1113
count = 328
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 103us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.796967
last_received_ts = 373.796173
last_seq = 1113
current_ts = 373.813629
current_received_ts = 373.812866
current_seq = 1114
count = 329
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.813629
last_received_ts = 373.812866
last_seq = 1114
current_ts = 373.830292
current_received_ts = 373.829529
current_seq = 1115
count = 330
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 63us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.830292
last_received_ts = 373.829529
last_seq = 1115
current_ts = 373.846985
current_received_ts = 373.846191
current_seq = 1116
count = 331
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 62us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.846985
last_received_ts = 373.846191
last_seq = 1116
current_ts = 373.863647
current_received_ts = 373.862854
current_seq = 1117
count = 332
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.863647
last_received_ts = 373.862854
last_seq = 1117
current_ts = 373.880310
current_received_ts = 373.879517
current_seq = 1118
count = 333
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.880310
last_received_ts = 373.879517
last_seq = 1118
current_ts = 373.896973
current_received_ts = 373.896179
current_seq = 1119
count = 334
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.896973
last_received_ts = 373.896179
last_seq = 1119
current_ts = 373.913666
current_received_ts = 373.912842
current_seq = 1120
count = 335
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.913666
last_received_ts = 373.912842
last_seq = 1120
current_ts = 373.930328
current_received_ts = 373.929565
current_seq = 1121
count = 336
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 97us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.930328
last_received_ts = 373.929565
last_seq = 1121
current_ts = 373.946991
current_received_ts = 373.946167
current_seq = 1122
count = 337
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.946991
last_received_ts = 373.946167
last_seq = 1122
current_ts = 373.963654
current_received_ts = 373.962891
current_seq = 1123
count = 338
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.963654
last_received_ts = 373.962891
last_seq = 1123
current_ts = 373.980316
current_received_ts = 373.979553
current_seq = 1124
count = 339
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.980316
last_received_ts = 373.979553
last_seq = 1124
current_ts = 373.997009
current_received_ts = 373.996185
current_seq = 1125
count = 340
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 44us
(kms_flip:5486) DEBUG: name = flip
last_ts = 373.997009
last_received_ts = 373.996185
last_seq = 1125
current_ts = 374.013672
current_received_ts = 374.012878
current_seq = 1126
count = 341
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 51us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.013672
last_received_ts = 374.012878
last_seq = 1126
current_ts = 374.030334
current_received_ts = 374.029541
current_seq = 1127
count = 342
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 59us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.030334
last_received_ts = 374.029541
last_seq = 1127
current_ts = 374.046997
current_received_ts = 374.046204
current_seq = 1128
count = 343
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 47us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.046997
last_received_ts = 374.046204
last_seq = 1128
current_ts = 374.063690
current_received_ts = 374.062897
current_seq = 1129
count = 344
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.063690
last_received_ts = 374.062897
last_seq = 1129
current_ts = 374.080353
current_received_ts = 374.079559
current_seq = 1130
count = 345
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 58us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.080353
last_received_ts = 374.079559
last_seq = 1130
current_ts = 374.097015
current_received_ts = 374.096375
current_seq = 1131
count = 346
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 88us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.097015
last_received_ts = 374.096375
last_seq = 1131
current_ts = 374.113678
current_received_ts = 374.112915
current_seq = 1132
count = 347
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 54us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.113678
last_received_ts = 374.112915
last_seq = 1132
current_ts = 374.130371
current_received_ts = 374.129547
current_seq = 1133
count = 348
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 52us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.130371
last_received_ts = 374.129547
last_seq = 1133
current_ts = 374.147034
current_received_ts = 374.146210
current_seq = 1134
count = 349
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 67us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.147034
last_received_ts = 374.146210
last_seq = 1134
current_ts = 374.163696
current_received_ts = 374.162903
current_seq = 1135
count = 350
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.163696
last_received_ts = 374.162903
last_seq = 1135
current_ts = 374.180359
current_received_ts = 374.179596
current_seq = 1136
count = 351
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.180359
last_received_ts = 374.179596
last_seq = 1136
current_ts = 374.197021
current_received_ts = 374.196228
current_seq = 1137
count = 352
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 50us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.197021
last_received_ts = 374.196228
last_seq = 1137
current_ts = 374.213715
current_received_ts = 374.212952
current_seq = 1138
count = 353
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 112us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.213715
last_received_ts = 374.212952
last_seq = 1138
current_ts = 374.230377
current_received_ts = 374.229584
current_seq = 1139
count = 354
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 67us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.230377
last_received_ts = 374.229584
last_seq = 1139
current_ts = 374.247040
current_received_ts = 374.246246
current_seq = 1140
count = 355
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 56us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.247040
last_received_ts = 374.246246
last_seq = 1140
current_ts = 374.263702
current_received_ts = 374.262909
current_seq = 1141
count = 356
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 64us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.263702
last_received_ts = 374.262909
last_seq = 1141
current_ts = 374.280365
current_received_ts = 374.279602
current_seq = 1142
count = 357
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.280365
last_received_ts = 374.279602
last_seq = 1142
current_ts = 374.297058
current_received_ts = 374.296234
current_seq = 1143
count = 358
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 48us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.297058
last_received_ts = 374.296234
last_seq = 1143
current_ts = 374.313721
current_received_ts = 374.312927
current_seq = 1144
count = 359
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 45us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.313721
last_received_ts = 374.312927
last_seq = 1144
current_ts = 374.330383
current_received_ts = 374.329620
current_seq = 1145
count = 360
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 51us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.330383
last_received_ts = 374.329620
last_seq = 1145
current_ts = 374.347046
current_received_ts = 374.346252
current_seq = 1146
count = 361
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.347046
last_received_ts = 374.346252
last_seq = 1146
current_ts = 374.363739
current_received_ts = 374.362946
current_seq = 1147
count = 362
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 63us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.363739
last_received_ts = 374.362946
last_seq = 1147
current_ts = 374.380402
current_received_ts = 374.379608
current_seq = 1148
count = 363
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 50us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.380402
last_received_ts = 374.379608
last_seq = 1148
current_ts = 374.397064
current_received_ts = 374.396271
current_seq = 1149
count = 364
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 53us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.397064
last_received_ts = 374.396271
last_seq = 1149
current_ts = 374.413727
current_received_ts = 374.412964
current_seq = 1150
count = 365
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 59us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.413727
last_received_ts = 374.412964
last_seq = 1150
current_ts = 374.430389
current_received_ts = 374.429626
current_seq = 1151
count = 366
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 49us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.430389
last_received_ts = 374.429626
last_seq = 1151
current_ts = 374.447083
current_received_ts = 374.446289
current_seq = 1152
count = 367
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 55us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.447083
last_received_ts = 374.446289
last_seq = 1152
current_ts = 374.463745
current_received_ts = 374.462982
current_seq = 1153
count = 368
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 60us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.463745
last_received_ts = 374.462982
last_seq = 1153
current_ts = 374.480408
current_received_ts = 374.479645
current_seq = 1154
count = 369
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 46us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.480408
last_received_ts = 374.479645
last_seq = 1154
current_ts = 374.497101
current_received_ts = 374.496277
current_seq = 1155
count = 370
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 58us
(kms_flip:5486) DEBUG: name = flip
last_ts = 374.497101
last_received_ts = 374.496277
last_seq = 1155
current_ts = 374.513763
current_received_ts = 374.512970
current_seq = 1156
count = 371
seq_step = 1
(kms_flip:5486) DEBUG: Vblank took 751us
(kms_flip:5486) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:5486) CRITICAL: Failed assertion: end - start < 500
(kms_flip:5486) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:5486) igt_core-INFO: Stack trace:
(kms_flip:5486) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:5486) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:5486) igt_core-INFO:   #2 ../tests/kms_flip.c:1889 run_test()
(kms_flip:5486) igt_core-INFO:   #3 ../tests/kms_flip.c:2158 __igt_unique____real_main2045()
(kms_flip:5486) igt_core-INFO:   #4 ../tests/kms_flip.c:2045 main()
(kms_flip:5486) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:5486) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:5486) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-eDP1: FAIL (7.484s)
Subtest flip-vs-expired-vblank-interruptible: FAIL (23.671s)
(kms_flip:5486) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2386:
(kms_flip:5486) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:5486) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:5486) igt_kms-CRITICAL: DPMS property not found on 391