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

shard-lnl-3

IGT-Version: 2.1-g4f8c7886a (x86_64) (Linux: 6.17.0-rc7-lgci-xe-xe-3823-53ee7e373ce454dc8+ x86_64)

Using IGT_SRANDOM=1758705915 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:1884 run_test()
  #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (4.533s)
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:1884 run_test()
  #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (5.922s)
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:1884 run_test()
  #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-eDP1: FAIL (8.475s)
Subtest flip-vs-expired-vblank-interruptible: FAIL (18.947s)
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2247 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:7231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:7231) CRITICAL: Failed assertion: end - start < 500
(kms_flip:7231) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.590668
last_received_ts = 471.589905
last_seq = 3347
current_ts = 471.607330
current_received_ts = 471.606567
current_seq = 3348
count = 78
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 40us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.607330
last_received_ts = 471.606567
last_seq = 3348
current_ts = 471.623993
current_received_ts = 471.623199
current_seq = 3349
count = 79
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 46us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.623993
last_received_ts = 471.623199
last_seq = 3349
current_ts = 471.640686
current_received_ts = 471.639923
current_seq = 3350
count = 80
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 114us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.640686
last_received_ts = 471.639923
last_seq = 3350
current_ts = 471.657349
current_received_ts = 471.656555
current_seq = 3351
count = 81
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.657349
last_received_ts = 471.656555
last_seq = 3351
current_ts = 471.674011
current_received_ts = 471.673309
current_seq = 3352
count = 82
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.674011
last_received_ts = 471.673309
last_seq = 3352
current_ts = 471.690674
current_received_ts = 471.690002
current_seq = 3353
count = 83
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 125us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.690674
last_received_ts = 471.690002
last_seq = 3353
current_ts = 471.707336
current_received_ts = 471.706604
current_seq = 3354
count = 84
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 112us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.707336
last_received_ts = 471.706604
last_seq = 3354
current_ts = 471.724030
current_received_ts = 471.723206
current_seq = 3355
count = 85
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.724030
last_received_ts = 471.723206
last_seq = 3355
current_ts = 471.740692
current_received_ts = 471.740021
current_seq = 3356
count = 86
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 40us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.740692
last_received_ts = 471.740021
last_seq = 3356
current_ts = 471.757355
current_received_ts = 471.756683
current_seq = 3357
count = 87
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 52us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.757355
last_received_ts = 471.756683
last_seq = 3357
current_ts = 471.774017
current_received_ts = 471.773315
current_seq = 3358
count = 88
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.774017
last_received_ts = 471.773315
last_seq = 3358
current_ts = 471.790710
current_received_ts = 471.790009
current_seq = 3359
count = 89
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 46us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.790710
last_received_ts = 471.790009
last_seq = 3359
current_ts = 471.807373
current_received_ts = 471.806671
current_seq = 3360
count = 90
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 52us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.807373
last_received_ts = 471.806671
last_seq = 3360
current_ts = 471.824036
current_received_ts = 471.823242
current_seq = 3361
count = 91
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 41us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.824036
last_received_ts = 471.823242
last_seq = 3361
current_ts = 471.840698
current_received_ts = 471.839996
current_seq = 3362
count = 92
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 35us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.840698
last_received_ts = 471.839996
last_seq = 3362
current_ts = 471.857361
current_received_ts = 471.856659
current_seq = 3363
count = 93
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.857361
last_received_ts = 471.856659
last_seq = 3363
current_ts = 471.874054
current_received_ts = 471.873352
current_seq = 3364
count = 94
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 55us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.874054
last_received_ts = 471.873352
last_seq = 3364
current_ts = 471.890717
current_received_ts = 471.890045
current_seq = 3365
count = 95
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 35us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.890717
last_received_ts = 471.890045
last_seq = 3365
current_ts = 471.907379
current_received_ts = 471.906708
current_seq = 3366
count = 96
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 136us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.907379
last_received_ts = 471.906708
last_seq = 3366
current_ts = 471.924042
current_received_ts = 471.923248
current_seq = 3367
count = 97
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.924042
last_received_ts = 471.923248
last_seq = 3367
current_ts = 471.940735
current_received_ts = 471.940002
current_seq = 3368
count = 98
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.940735
last_received_ts = 471.940002
last_seq = 3368
current_ts = 471.957397
current_received_ts = 471.956604
current_seq = 3369
count = 99
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 34us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.957397
last_received_ts = 471.956604
last_seq = 3369
current_ts = 471.974060
current_received_ts = 471.973358
current_seq = 3370
count = 100
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 46us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.974060
last_received_ts = 471.973358
last_seq = 3370
current_ts = 471.990723
current_received_ts = 471.990051
current_seq = 3371
count = 101
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 471.990723
last_received_ts = 471.990051
last_seq = 3371
current_ts = 472.007385
current_received_ts = 472.006622
current_seq = 3372
count = 102
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.007385
last_received_ts = 472.006622
last_seq = 3372
current_ts = 472.024048
current_received_ts = 472.023376
current_seq = 3373
count = 103
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 131us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.024048
last_received_ts = 472.023376
last_seq = 3373
current_ts = 472.040741
current_received_ts = 472.040039
current_seq = 3374
count = 104
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 40us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.040741
last_received_ts = 472.040039
last_seq = 3374
current_ts = 472.057404
current_received_ts = 472.056610
current_seq = 3375
count = 105
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 37us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.057404
last_received_ts = 472.056610
last_seq = 3375
current_ts = 472.074066
current_received_ts = 472.073364
current_seq = 3376
count = 106
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 34us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.074066
last_received_ts = 472.073364
last_seq = 3376
current_ts = 472.090729
current_received_ts = 472.089966
current_seq = 3377
count = 107
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 69us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.090729
last_received_ts = 472.089966
last_seq = 3377
current_ts = 472.107391
current_received_ts = 472.106628
current_seq = 3378
count = 108
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 47us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.107391
last_received_ts = 472.106628
last_seq = 3378
current_ts = 472.124084
current_received_ts = 472.123291
current_seq = 3379
count = 109
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 46us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.124084
last_received_ts = 472.123291
last_seq = 3379
current_ts = 472.140747
current_received_ts = 472.140045
current_seq = 3380
count = 110
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 41us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.140747
last_received_ts = 472.140045
last_seq = 3380
current_ts = 472.157410
current_received_ts = 472.156708
current_seq = 3381
count = 111
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 47us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.157410
last_received_ts = 472.156708
last_seq = 3381
current_ts = 472.174072
current_received_ts = 472.173279
current_seq = 3382
count = 112
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 39us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.174072
last_received_ts = 472.173279
last_seq = 3382
current_ts = 472.190765
current_received_ts = 472.190033
current_seq = 3383
count = 113
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.190765
last_received_ts = 472.190033
last_seq = 3383
current_ts = 472.207428
current_received_ts = 472.206726
current_seq = 3384
count = 114
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 35us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.207428
last_received_ts = 472.206726
last_seq = 3384
current_ts = 472.224091
current_received_ts = 472.223297
current_seq = 3385
count = 115
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 54us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.224091
last_received_ts = 472.223297
last_seq = 3385
current_ts = 472.240753
current_received_ts = 472.239990
current_seq = 3386
count = 116
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 60us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.240753
last_received_ts = 472.239990
last_seq = 3386
current_ts = 472.257416
current_received_ts = 472.256653
current_seq = 3387
count = 117
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 122us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.257416
last_received_ts = 472.256653
last_seq = 3387
current_ts = 472.274109
current_received_ts = 472.273315
current_seq = 3388
count = 118
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 41us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.274109
last_received_ts = 472.273315
last_seq = 3388
current_ts = 472.290771
current_received_ts = 472.290009
current_seq = 3389
count = 119
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 47us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.290771
last_received_ts = 472.290009
last_seq = 3389
current_ts = 472.307434
current_received_ts = 472.306641
current_seq = 3390
count = 120
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 43us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.307434
last_received_ts = 472.306641
last_seq = 3390
current_ts = 472.324097
current_received_ts = 472.323303
current_seq = 3391
count = 121
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 44us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.324097
last_received_ts = 472.323303
last_seq = 3391
current_ts = 472.340759
current_received_ts = 472.340088
current_seq = 3392
count = 122
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 39us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.340759
last_received_ts = 472.340088
last_seq = 3392
current_ts = 472.357452
current_received_ts = 472.356781
current_seq = 3393
count = 123
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 51us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.357452
last_received_ts = 472.356781
last_seq = 3393
current_ts = 472.374115
current_received_ts = 472.373444
current_seq = 3394
count = 124
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 39us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.374115
last_received_ts = 472.373444
last_seq = 3394
current_ts = 472.390778
current_received_ts = 472.390076
current_seq = 3395
count = 125
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.390778
last_received_ts = 472.390076
last_seq = 3395
current_ts = 472.407440
current_received_ts = 472.406677
current_seq = 3396
count = 126
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 44us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.407440
last_received_ts = 472.406677
last_seq = 3396
current_ts = 472.424103
current_received_ts = 472.423431
current_seq = 3397
count = 127
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 55us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.424103
last_received_ts = 472.423431
last_seq = 3397
current_ts = 472.440796
current_received_ts = 472.440002
current_seq = 3398
count = 128
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.440796
last_received_ts = 472.440002
last_seq = 3398
current_ts = 472.457458
current_received_ts = 472.456696
current_seq = 3399
count = 129
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.457458
last_received_ts = 472.456696
last_seq = 3399
current_ts = 472.474121
current_received_ts = 472.473419
current_seq = 3400
count = 130
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.474121
last_received_ts = 472.473419
last_seq = 3400
current_ts = 472.490784
current_received_ts = 472.490051
current_seq = 3401
count = 131
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.490784
last_received_ts = 472.490051
last_seq = 3401
current_ts = 472.507446
current_received_ts = 472.506683
current_seq = 3402
count = 132
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 43us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.507446
last_received_ts = 472.506683
last_seq = 3402
current_ts = 472.524139
current_received_ts = 472.523438
current_seq = 3403
count = 133
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 37us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.524139
last_received_ts = 472.523438
last_seq = 3403
current_ts = 472.540802
current_received_ts = 472.540039
current_seq = 3404
count = 134
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 35us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.540802
last_received_ts = 472.540039
last_seq = 3404
current_ts = 472.557465
current_received_ts = 472.556671
current_seq = 3405
count = 135
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 44us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.557465
last_received_ts = 472.556671
last_seq = 3405
current_ts = 472.574127
current_received_ts = 472.573364
current_seq = 3406
count = 136
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 38us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.574127
last_received_ts = 472.573364
last_seq = 3406
current_ts = 472.590790
current_received_ts = 472.590057
current_seq = 3407
count = 137
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 119us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.590790
last_received_ts = 472.590057
last_seq = 3407
current_ts = 472.607483
current_received_ts = 472.606689
current_seq = 3408
count = 138
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 41us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.607483
last_received_ts = 472.606689
last_seq = 3408
current_ts = 472.624146
current_received_ts = 472.623352
current_seq = 3409
count = 139
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 43us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.624146
last_received_ts = 472.623352
last_seq = 3409
current_ts = 472.640808
current_received_ts = 472.640106
current_seq = 3410
count = 140
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.640808
last_received_ts = 472.640106
last_seq = 3410
current_ts = 472.657501
current_received_ts = 472.656738
current_seq = 3411
count = 141
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 43us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.657501
last_received_ts = 472.656738
last_seq = 3411
current_ts = 472.674164
current_received_ts = 472.673401
current_seq = 3412
count = 142
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 105us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.674164
last_received_ts = 472.673401
last_seq = 3412
current_ts = 472.690826
current_received_ts = 472.690125
current_seq = 3413
count = 143
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 31us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.690826
last_received_ts = 472.690125
last_seq = 3413
current_ts = 472.707489
current_received_ts = 472.706726
current_seq = 3414
count = 144
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 112us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.707489
last_received_ts = 472.706726
last_seq = 3414
current_ts = 472.724152
current_received_ts = 472.723389
current_seq = 3415
count = 145
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 44us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.724152
last_received_ts = 472.723389
last_seq = 3415
current_ts = 472.740814
current_received_ts = 472.740112
current_seq = 3416
count = 146
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 41us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.740814
last_received_ts = 472.740112
last_seq = 3416
current_ts = 472.757507
current_received_ts = 472.756775
current_seq = 3417
count = 147
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 39us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.757507
last_received_ts = 472.756775
last_seq = 3417
current_ts = 472.774170
current_received_ts = 472.773438
current_seq = 3418
count = 148
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 30us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.774170
last_received_ts = 472.773438
last_seq = 3418
current_ts = 472.790833
current_received_ts = 472.790161
current_seq = 3419
count = 149
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 37us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.790833
last_received_ts = 472.790161
last_seq = 3419
current_ts = 472.807495
current_received_ts = 472.806793
current_seq = 3420
count = 150
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 54us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.807495
last_received_ts = 472.806793
last_seq = 3420
current_ts = 472.824158
current_received_ts = 472.823456
current_seq = 3421
count = 151
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 34us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.824158
last_received_ts = 472.823456
last_seq = 3421
current_ts = 472.840851
current_received_ts = 472.840210
current_seq = 3422
count = 152
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 43us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.840851
last_received_ts = 472.840210
last_seq = 3422
current_ts = 472.857513
current_received_ts = 472.856781
current_seq = 3423
count = 153
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 41us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.857513
last_received_ts = 472.856781
last_seq = 3423
current_ts = 472.874176
current_received_ts = 472.873413
current_seq = 3424
count = 154
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 54us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.874176
last_received_ts = 472.873413
last_seq = 3424
current_ts = 472.890839
current_received_ts = 472.890076
current_seq = 3425
count = 155
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 39us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.890839
last_received_ts = 472.890076
last_seq = 3425
current_ts = 472.907532
current_received_ts = 472.906738
current_seq = 3426
count = 156
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.907532
last_received_ts = 472.906738
last_seq = 3426
current_ts = 472.924194
current_received_ts = 472.923492
current_seq = 3427
count = 157
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 52us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.924194
last_received_ts = 472.923492
last_seq = 3427
current_ts = 472.940857
current_received_ts = 472.940186
current_seq = 3428
count = 158
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 35us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.940857
last_received_ts = 472.940186
last_seq = 3428
current_ts = 472.957520
current_received_ts = 472.956848
current_seq = 3429
count = 159
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.957520
last_received_ts = 472.956848
last_seq = 3429
current_ts = 472.974182
current_received_ts = 472.973511
current_seq = 3430
count = 160
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 34us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.974182
last_received_ts = 472.973511
last_seq = 3430
current_ts = 472.990875
current_received_ts = 472.990173
current_seq = 3431
count = 161
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 39us
(kms_flip:7231) DEBUG: name = flip
last_ts = 472.990875
last_received_ts = 472.990173
last_seq = 3431
current_ts = 473.007538
current_received_ts = 473.006744
current_seq = 3432
count = 162
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.007538
last_received_ts = 473.006744
last_seq = 3432
current_ts = 473.024200
current_received_ts = 473.023529
current_seq = 3433
count = 163
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 52us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.024200
last_received_ts = 473.023529
last_seq = 3433
current_ts = 473.040863
current_received_ts = 473.040161
current_seq = 3434
count = 164
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 39us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.040863
last_received_ts = 473.040161
last_seq = 3434
current_ts = 473.057556
current_received_ts = 473.056854
current_seq = 3435
count = 165
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.057556
last_received_ts = 473.056854
last_seq = 3435
current_ts = 473.074219
current_received_ts = 473.073517
current_seq = 3436
count = 166
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 51us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.074219
last_received_ts = 473.073517
last_seq = 3436
current_ts = 473.090881
current_received_ts = 473.090179
current_seq = 3437
count = 167
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 41us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.090881
last_received_ts = 473.090179
last_seq = 3437
current_ts = 473.107544
current_received_ts = 473.106873
current_seq = 3438
count = 168
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 61us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.107544
last_received_ts = 473.106873
last_seq = 3438
current_ts = 473.124207
current_received_ts = 473.123535
current_seq = 3439
count = 169
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 61us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.124207
last_received_ts = 473.123535
last_seq = 3439
current_ts = 473.140869
current_received_ts = 473.140167
current_seq = 3440
count = 170
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 62us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.140869
last_received_ts = 473.140167
last_seq = 3440
current_ts = 473.157562
current_received_ts = 473.156830
current_seq = 3441
count = 171
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 43us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.157562
last_received_ts = 473.156830
last_seq = 3441
current_ts = 473.174225
current_received_ts = 473.173523
current_seq = 3442
count = 172
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.174225
last_received_ts = 473.173523
last_seq = 3442
current_ts = 473.190887
current_received_ts = 473.190338
current_seq = 3443
count = 173
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 72us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.190887
last_received_ts = 473.190338
last_seq = 3443
current_ts = 473.207550
current_received_ts = 473.206818
current_seq = 3444
count = 174
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 130us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.207550
last_received_ts = 473.206818
last_seq = 3444
current_ts = 473.224243
current_received_ts = 473.223450
current_seq = 3445
count = 175
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 67us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.224243
last_received_ts = 473.223450
last_seq = 3445
current_ts = 473.240906
current_received_ts = 473.240143
current_seq = 3446
count = 176
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 66us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.240906
last_received_ts = 473.240143
last_seq = 3446
current_ts = 473.257568
current_received_ts = 473.256805
current_seq = 3447
count = 177
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.257568
last_received_ts = 473.256805
last_seq = 3447
current_ts = 473.274231
current_received_ts = 473.273468
current_seq = 3448
count = 178
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 41us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.274231
last_received_ts = 473.273468
last_seq = 3448
current_ts = 473.290894
current_received_ts = 473.290100
current_seq = 3449
count = 179
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 41us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.290894
last_received_ts = 473.290100
last_seq = 3449
current_ts = 473.307587
current_received_ts = 473.306824
current_seq = 3450
count = 180
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 40us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.307587
last_received_ts = 473.306824
last_seq = 3450
current_ts = 473.324249
current_received_ts = 473.323456
current_seq = 3451
count = 181
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 55us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.324249
last_received_ts = 473.323456
last_seq = 3451
current_ts = 473.340912
current_received_ts = 473.340149
current_seq = 3452
count = 182
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.340912
last_received_ts = 473.340149
last_seq = 3452
current_ts = 473.357574
current_received_ts = 473.356812
current_seq = 3453
count = 183
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 46us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.357574
last_received_ts = 473.356812
last_seq = 3453
current_ts = 473.374268
current_received_ts = 473.373474
current_seq = 3454
count = 184
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 44us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.374268
last_received_ts = 473.373474
last_seq = 3454
current_ts = 473.390930
current_received_ts = 473.390137
current_seq = 3455
count = 185
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 41us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.390930
last_received_ts = 473.390137
last_seq = 3455
current_ts = 473.407593
current_received_ts = 473.406830
current_seq = 3456
count = 186
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 124us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.407593
last_received_ts = 473.406830
last_seq = 3456
current_ts = 473.424255
current_received_ts = 473.423615
current_seq = 3457
count = 187
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 170us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.424255
last_received_ts = 473.423615
last_seq = 3457
current_ts = 473.440918
current_received_ts = 473.440277
current_seq = 3458
count = 188
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 36us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.440918
last_received_ts = 473.440277
last_seq = 3458
current_ts = 473.457611
current_received_ts = 473.456940
current_seq = 3459
count = 189
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 120us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.457611
last_received_ts = 473.456940
last_seq = 3459
current_ts = 473.474274
current_received_ts = 473.473602
current_seq = 3460
count = 190
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.474274
last_received_ts = 473.473602
last_seq = 3460
current_ts = 473.490936
current_received_ts = 473.490173
current_seq = 3461
count = 191
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 55us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.490936
last_received_ts = 473.490173
last_seq = 3461
current_ts = 473.507599
current_received_ts = 473.506836
current_seq = 3462
count = 192
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 128us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.507599
last_received_ts = 473.506836
last_seq = 3462
current_ts = 473.524261
current_received_ts = 473.523499
current_seq = 3463
count = 193
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 52us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.524261
last_received_ts = 473.523499
last_seq = 3463
current_ts = 473.540955
current_received_ts = 473.540161
current_seq = 3464
count = 194
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 62us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.540955
last_received_ts = 473.540161
last_seq = 3464
current_ts = 473.557617
current_received_ts = 473.556946
current_seq = 3465
count = 195
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 44us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.557617
last_received_ts = 473.556946
last_seq = 3465
current_ts = 473.574280
current_received_ts = 473.573608
current_seq = 3466
count = 196
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 52us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.574280
last_received_ts = 473.573608
last_seq = 3466
current_ts = 473.590942
current_received_ts = 473.590240
current_seq = 3467
count = 197
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 39us
(kms_flip:7231) DEBUG: name = flip
last_ts = 473.590942
last_received_ts = 473.590240
last_seq = 3467
current_ts = 473.607605
current_received_ts = 473.606964
current_seq = 3468
count = 198
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 516us
(kms_flip:7231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:7231) CRITICAL: Failed assertion: end - start < 500
(kms_flip:7231) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:7231) igt_core-INFO: Stack trace:
(kms_flip:7231) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:7231) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:7231) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:7231) igt_core-INFO:   #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
(kms_flip:7231) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:7231) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7231) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7231) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (4.533s)
Starting dynamic subtest: B-eDP1
(kms_flip:7231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:7231) CRITICAL: Failed assertion: end - start < 500
(kms_flip:7231) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.517731
last_received_ts = 477.516907
last_seq = 300
current_ts = 477.534393
current_received_ts = 477.533600
current_seq = 301
count = 160
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 60us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.534393
last_received_ts = 477.533600
last_seq = 301
current_ts = 477.551056
current_received_ts = 477.550262
current_seq = 302
count = 161
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.551056
last_received_ts = 477.550262
last_seq = 302
current_ts = 477.567719
current_received_ts = 477.566956
current_seq = 303
count = 162
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.567719
last_received_ts = 477.566956
last_seq = 303
current_ts = 477.584381
current_received_ts = 477.583618
current_seq = 304
count = 163
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 58us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.584381
last_received_ts = 477.583618
last_seq = 304
current_ts = 477.601074
current_received_ts = 477.600250
current_seq = 305
count = 164
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 53us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.601074
last_received_ts = 477.600250
last_seq = 305
current_ts = 477.617737
current_received_ts = 477.616943
current_seq = 306
count = 165
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 74us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.617737
last_received_ts = 477.616943
last_seq = 306
current_ts = 477.634399
current_received_ts = 477.633606
current_seq = 307
count = 166
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 51us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.634399
last_received_ts = 477.633606
last_seq = 307
current_ts = 477.651062
current_received_ts = 477.650269
current_seq = 308
count = 167
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 55us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.651062
last_received_ts = 477.650269
last_seq = 308
current_ts = 477.667755
current_received_ts = 477.666962
current_seq = 309
count = 168
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 72us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.667755
last_received_ts = 477.666962
last_seq = 309
current_ts = 477.684418
current_received_ts = 477.683624
current_seq = 310
count = 169
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 60us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.684418
last_received_ts = 477.683624
last_seq = 310
current_ts = 477.701080
current_received_ts = 477.700287
current_seq = 311
count = 170
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 58us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.701080
last_received_ts = 477.700287
last_seq = 311
current_ts = 477.717743
current_received_ts = 477.716980
current_seq = 312
count = 171
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 62us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.717743
last_received_ts = 477.716980
last_seq = 312
current_ts = 477.734436
current_received_ts = 477.733643
current_seq = 313
count = 172
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.734436
last_received_ts = 477.733643
last_seq = 313
current_ts = 477.751099
current_received_ts = 477.750275
current_seq = 314
count = 173
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 55us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.751099
last_received_ts = 477.750275
last_seq = 314
current_ts = 477.767761
current_received_ts = 477.766968
current_seq = 315
count = 174
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 87us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.767761
last_received_ts = 477.766968
last_seq = 315
current_ts = 477.784424
current_received_ts = 477.783661
current_seq = 316
count = 175
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 73us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.784424
last_received_ts = 477.783661
last_seq = 316
current_ts = 477.801086
current_received_ts = 477.800323
current_seq = 317
count = 176
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 61us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.801086
last_received_ts = 477.800323
last_seq = 317
current_ts = 477.817780
current_received_ts = 477.816986
current_seq = 318
count = 177
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 54us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.817780
last_received_ts = 477.816986
last_seq = 318
current_ts = 477.834442
current_received_ts = 477.833649
current_seq = 319
count = 178
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 46us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.834442
last_received_ts = 477.833649
last_seq = 319
current_ts = 477.851105
current_received_ts = 477.850342
current_seq = 320
count = 179
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.851105
last_received_ts = 477.850342
last_seq = 320
current_ts = 477.867767
current_received_ts = 477.867035
current_seq = 321
count = 180
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.867767
last_received_ts = 477.867035
last_seq = 321
current_ts = 477.884460
current_received_ts = 477.883667
current_seq = 322
count = 181
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.884460
last_received_ts = 477.883667
last_seq = 322
current_ts = 477.901123
current_received_ts = 477.900330
current_seq = 323
count = 182
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.901123
last_received_ts = 477.900330
last_seq = 323
current_ts = 477.917786
current_received_ts = 477.917023
current_seq = 324
count = 183
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.917786
last_received_ts = 477.917023
last_seq = 324
current_ts = 477.934448
current_received_ts = 477.933655
current_seq = 325
count = 184
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 63us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.934448
last_received_ts = 477.933655
last_seq = 325
current_ts = 477.951141
current_received_ts = 477.950317
current_seq = 326
count = 185
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 63us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.951141
last_received_ts = 477.950317
last_seq = 326
current_ts = 477.967804
current_received_ts = 477.967041
current_seq = 327
count = 186
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.967804
last_received_ts = 477.967041
last_seq = 327
current_ts = 477.984467
current_received_ts = 477.983704
current_seq = 328
count = 187
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 477.984467
last_received_ts = 477.983704
last_seq = 328
current_ts = 478.001129
current_received_ts = 478.000336
current_seq = 329
count = 188
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 59us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.001129
last_received_ts = 478.000336
last_seq = 329
current_ts = 478.017792
current_received_ts = 478.017029
current_seq = 330
count = 189
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.017792
last_received_ts = 478.017029
last_seq = 330
current_ts = 478.034485
current_received_ts = 478.033691
current_seq = 331
count = 190
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 47us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.034485
last_received_ts = 478.033691
last_seq = 331
current_ts = 478.051147
current_received_ts = 478.050354
current_seq = 332
count = 191
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 55us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.051147
last_received_ts = 478.050354
last_seq = 332
current_ts = 478.067810
current_received_ts = 478.067047
current_seq = 333
count = 192
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 64us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.067810
last_received_ts = 478.067047
last_seq = 333
current_ts = 478.084473
current_received_ts = 478.083710
current_seq = 334
count = 193
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.084473
last_received_ts = 478.083710
last_seq = 334
current_ts = 478.101166
current_received_ts = 478.100372
current_seq = 335
count = 194
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.101166
last_received_ts = 478.100372
last_seq = 335
current_ts = 478.117828
current_received_ts = 478.117065
current_seq = 336
count = 195
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 67us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.117828
last_received_ts = 478.117065
last_seq = 336
current_ts = 478.134491
current_received_ts = 478.133728
current_seq = 337
count = 196
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 64us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.134491
last_received_ts = 478.133728
last_seq = 337
current_ts = 478.151154
current_received_ts = 478.150391
current_seq = 338
count = 197
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 54us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.151154
last_received_ts = 478.150391
last_seq = 338
current_ts = 478.167847
current_received_ts = 478.167053
current_seq = 339
count = 198
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 58us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.167847
last_received_ts = 478.167053
last_seq = 339
current_ts = 478.184509
current_received_ts = 478.183716
current_seq = 340
count = 199
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 75us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.184509
last_received_ts = 478.183716
last_seq = 340
current_ts = 478.201172
current_received_ts = 478.200378
current_seq = 341
count = 200
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.201172
last_received_ts = 478.200378
last_seq = 341
current_ts = 478.217834
current_received_ts = 478.217041
current_seq = 342
count = 201
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 53us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.217834
last_received_ts = 478.217041
last_seq = 342
current_ts = 478.234528
current_received_ts = 478.233734
current_seq = 343
count = 202
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 58us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.234528
last_received_ts = 478.233734
last_seq = 343
current_ts = 478.251190
current_received_ts = 478.250397
current_seq = 344
count = 203
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 54us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.251190
last_received_ts = 478.250397
last_seq = 344
current_ts = 478.267853
current_received_ts = 478.267059
current_seq = 345
count = 204
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 60us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.267853
last_received_ts = 478.267059
last_seq = 345
current_ts = 478.284515
current_received_ts = 478.283752
current_seq = 346
count = 205
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 60us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.284515
last_received_ts = 478.283752
last_seq = 346
current_ts = 478.301208
current_received_ts = 478.300385
current_seq = 347
count = 206
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.301208
last_received_ts = 478.300385
last_seq = 347
current_ts = 478.317871
current_received_ts = 478.317078
current_seq = 348
count = 207
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 58us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.317871
last_received_ts = 478.317078
last_seq = 348
current_ts = 478.334534
current_received_ts = 478.333740
current_seq = 349
count = 208
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 53us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.334534
last_received_ts = 478.333740
last_seq = 349
current_ts = 478.351196
current_received_ts = 478.350403
current_seq = 350
count = 209
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.351196
last_received_ts = 478.350403
last_seq = 350
current_ts = 478.367859
current_received_ts = 478.367096
current_seq = 351
count = 210
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.367859
last_received_ts = 478.367096
last_seq = 351
current_ts = 478.384552
current_received_ts = 478.383759
current_seq = 352
count = 211
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 58us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.384552
last_received_ts = 478.383759
last_seq = 352
current_ts = 478.401215
current_received_ts = 478.400421
current_seq = 353
count = 212
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.401215
last_received_ts = 478.400421
last_seq = 353
current_ts = 478.417877
current_received_ts = 478.417084
current_seq = 354
count = 213
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.417877
last_received_ts = 478.417084
last_seq = 354
current_ts = 478.434540
current_received_ts = 478.433746
current_seq = 355
count = 214
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 55us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.434540
last_received_ts = 478.433746
last_seq = 355
current_ts = 478.451233
current_received_ts = 478.450439
current_seq = 356
count = 215
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 59us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.451233
last_received_ts = 478.450439
last_seq = 356
current_ts = 478.467896
current_received_ts = 478.467102
current_seq = 357
count = 216
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 59us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.467896
last_received_ts = 478.467102
last_seq = 357
current_ts = 478.484558
current_received_ts = 478.483765
current_seq = 358
count = 217
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 54us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.484558
last_received_ts = 478.483765
last_seq = 358
current_ts = 478.501221
current_received_ts = 478.500427
current_seq = 359
count = 218
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 47us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.501221
last_received_ts = 478.500427
last_seq = 359
current_ts = 478.517914
current_received_ts = 478.517090
current_seq = 360
count = 219
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 60us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.517914
last_received_ts = 478.517090
last_seq = 360
current_ts = 478.534576
current_received_ts = 478.533783
current_seq = 361
count = 220
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 55us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.534576
last_received_ts = 478.533783
last_seq = 361
current_ts = 478.551239
current_received_ts = 478.550446
current_seq = 362
count = 221
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 66us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.551239
last_received_ts = 478.550446
last_seq = 362
current_ts = 478.567902
current_received_ts = 478.567108
current_seq = 363
count = 222
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 76us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.567902
last_received_ts = 478.567108
last_seq = 363
current_ts = 478.584564
current_received_ts = 478.583801
current_seq = 364
count = 223
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 54us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.584564
last_received_ts = 478.583801
last_seq = 364
current_ts = 478.601257
current_received_ts = 478.600464
current_seq = 365
count = 224
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.601257
last_received_ts = 478.600464
last_seq = 365
current_ts = 478.617920
current_received_ts = 478.617279
current_seq = 366
count = 225
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.617920
last_received_ts = 478.617279
last_seq = 366
current_ts = 478.634583
current_received_ts = 478.633820
current_seq = 367
count = 226
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 64us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.634583
last_received_ts = 478.633820
last_seq = 367
current_ts = 478.651245
current_received_ts = 478.650482
current_seq = 368
count = 227
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 53us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.651245
last_received_ts = 478.650482
last_seq = 368
current_ts = 478.667938
current_received_ts = 478.667145
current_seq = 369
count = 228
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.667938
last_received_ts = 478.667145
last_seq = 369
current_ts = 478.684601
current_received_ts = 478.683807
current_seq = 370
count = 229
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 78us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.684601
last_received_ts = 478.683807
last_seq = 370
current_ts = 478.701263
current_received_ts = 478.700500
current_seq = 371
count = 230
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 51us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.701263
last_received_ts = 478.700500
last_seq = 371
current_ts = 478.717926
current_received_ts = 478.717133
current_seq = 372
count = 231
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.717926
last_received_ts = 478.717133
last_seq = 372
current_ts = 478.734619
current_received_ts = 478.733826
current_seq = 373
count = 232
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.734619
last_received_ts = 478.733826
last_seq = 373
current_ts = 478.751282
current_received_ts = 478.750488
current_seq = 374
count = 233
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 59us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.751282
last_received_ts = 478.750488
last_seq = 374
current_ts = 478.767944
current_received_ts = 478.767151
current_seq = 375
count = 234
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.767944
last_received_ts = 478.767151
last_seq = 375
current_ts = 478.784607
current_received_ts = 478.783813
current_seq = 376
count = 235
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 60us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.784607
last_received_ts = 478.783813
last_seq = 376
current_ts = 478.801270
current_received_ts = 478.800476
current_seq = 377
count = 236
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.801270
last_received_ts = 478.800476
last_seq = 377
current_ts = 478.817963
current_received_ts = 478.817169
current_seq = 378
count = 237
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 51us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.817963
last_received_ts = 478.817169
last_seq = 378
current_ts = 478.834625
current_received_ts = 478.833832
current_seq = 379
count = 238
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 59us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.834625
last_received_ts = 478.833832
last_seq = 379
current_ts = 478.851288
current_received_ts = 478.850525
current_seq = 380
count = 239
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 65us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.851288
last_received_ts = 478.850525
last_seq = 380
current_ts = 478.867981
current_received_ts = 478.867157
current_seq = 381
count = 240
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.867981
last_received_ts = 478.867157
last_seq = 381
current_ts = 478.884644
current_received_ts = 478.883850
current_seq = 382
count = 241
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 65us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.884644
last_received_ts = 478.883850
last_seq = 382
current_ts = 478.901306
current_received_ts = 478.900513
current_seq = 383
count = 242
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 58us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.901306
last_received_ts = 478.900513
last_seq = 383
current_ts = 478.917969
current_received_ts = 478.917175
current_seq = 384
count = 243
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.917969
last_received_ts = 478.917175
last_seq = 384
current_ts = 478.934631
current_received_ts = 478.933868
current_seq = 385
count = 244
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 58us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.934631
last_received_ts = 478.933868
last_seq = 385
current_ts = 478.951324
current_received_ts = 478.950531
current_seq = 386
count = 245
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 58us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.951324
last_received_ts = 478.950531
last_seq = 386
current_ts = 478.967987
current_received_ts = 478.967194
current_seq = 387
count = 246
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.967987
last_received_ts = 478.967194
last_seq = 387
current_ts = 478.984650
current_received_ts = 478.983856
current_seq = 388
count = 247
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 478.984650
last_received_ts = 478.983856
last_seq = 388
current_ts = 479.001312
current_received_ts = 479.000549
current_seq = 389
count = 248
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.001312
last_received_ts = 479.000549
last_seq = 389
current_ts = 479.018005
current_received_ts = 479.017212
current_seq = 390
count = 249
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.018005
last_received_ts = 479.017212
last_seq = 390
current_ts = 479.034668
current_received_ts = 479.033875
current_seq = 391
count = 250
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.034668
last_received_ts = 479.033875
last_seq = 391
current_ts = 479.051331
current_received_ts = 479.050537
current_seq = 392
count = 251
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 64us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.051331
last_received_ts = 479.050537
last_seq = 392
current_ts = 479.067993
current_received_ts = 479.067200
current_seq = 393
count = 252
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.067993
last_received_ts = 479.067200
last_seq = 393
current_ts = 479.084686
current_received_ts = 479.083893
current_seq = 394
count = 253
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 58us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.084686
last_received_ts = 479.083893
last_seq = 394
current_ts = 479.101349
current_received_ts = 479.100555
current_seq = 395
count = 254
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 53us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.101349
last_received_ts = 479.100555
last_seq = 395
current_ts = 479.118011
current_received_ts = 479.117218
current_seq = 396
count = 255
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.118011
last_received_ts = 479.117218
last_seq = 396
current_ts = 479.134674
current_received_ts = 479.133911
current_seq = 397
count = 256
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 59us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.134674
last_received_ts = 479.133911
last_seq = 397
current_ts = 479.151337
current_received_ts = 479.150574
current_seq = 398
count = 257
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 53us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.151337
last_received_ts = 479.150574
last_seq = 398
current_ts = 479.168030
current_received_ts = 479.167206
current_seq = 399
count = 258
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 59us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.168030
last_received_ts = 479.167206
last_seq = 399
current_ts = 479.184692
current_received_ts = 479.183899
current_seq = 400
count = 259
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 46us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.184692
last_received_ts = 479.183899
last_seq = 400
current_ts = 479.201355
current_received_ts = 479.200562
current_seq = 401
count = 260
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 58us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.201355
last_received_ts = 479.200562
last_seq = 401
current_ts = 479.218048
current_received_ts = 479.217224
current_seq = 402
count = 261
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.218048
last_received_ts = 479.217224
last_seq = 402
current_ts = 479.234711
current_received_ts = 479.233917
current_seq = 403
count = 262
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 44us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.234711
last_received_ts = 479.233917
last_seq = 403
current_ts = 479.251373
current_received_ts = 479.250580
current_seq = 404
count = 263
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 53us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.251373
last_received_ts = 479.250580
last_seq = 404
current_ts = 479.268036
current_received_ts = 479.267242
current_seq = 405
count = 264
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 59us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.268036
last_received_ts = 479.267242
last_seq = 405
current_ts = 479.284698
current_received_ts = 479.283936
current_seq = 406
count = 265
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 58us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.284698
last_received_ts = 479.283936
last_seq = 406
current_ts = 479.301392
current_received_ts = 479.300598
current_seq = 407
count = 266
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 53us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.301392
last_received_ts = 479.300598
last_seq = 407
current_ts = 479.318054
current_received_ts = 479.317230
current_seq = 408
count = 267
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.318054
last_received_ts = 479.317230
last_seq = 408
current_ts = 479.334717
current_received_ts = 479.333923
current_seq = 409
count = 268
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 91us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.334717
last_received_ts = 479.333923
last_seq = 409
current_ts = 479.351379
current_received_ts = 479.350616
current_seq = 410
count = 269
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 60us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.351379
last_received_ts = 479.350616
last_seq = 410
current_ts = 479.368073
current_received_ts = 479.367279
current_seq = 411
count = 270
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 63us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.368073
last_received_ts = 479.367279
last_seq = 411
current_ts = 479.384735
current_received_ts = 479.383942
current_seq = 412
count = 271
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 97us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.384735
last_received_ts = 479.383942
last_seq = 412
current_ts = 479.401398
current_received_ts = 479.400604
current_seq = 413
count = 272
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.401398
last_received_ts = 479.400604
last_seq = 413
current_ts = 479.418060
current_received_ts = 479.417267
current_seq = 414
count = 273
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.418060
last_received_ts = 479.417267
last_seq = 414
current_ts = 479.434753
current_received_ts = 479.433960
current_seq = 415
count = 274
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.434753
last_received_ts = 479.433960
last_seq = 415
current_ts = 479.451416
current_received_ts = 479.450592
current_seq = 416
count = 275
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.451416
last_received_ts = 479.450592
last_seq = 416
current_ts = 479.468079
current_received_ts = 479.467255
current_seq = 417
count = 276
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.468079
last_received_ts = 479.467255
last_seq = 417
current_ts = 479.484741
current_received_ts = 479.483978
current_seq = 418
count = 277
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 67us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.484741
last_received_ts = 479.483978
last_seq = 418
current_ts = 479.501404
current_received_ts = 479.500641
current_seq = 419
count = 278
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 58us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.501404
last_received_ts = 479.500641
last_seq = 419
current_ts = 479.518097
current_received_ts = 479.517273
current_seq = 420
count = 279
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 479.518097
last_received_ts = 479.517273
last_seq = 420
current_ts = 479.534760
current_received_ts = 479.533966
current_seq = 421
count = 280
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 719us
(kms_flip:7231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:7231) CRITICAL: Failed assertion: end - start < 500
(kms_flip:7231) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:7231) igt_core-INFO: Stack trace:
(kms_flip:7231) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:7231) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:7231) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:7231) igt_core-INFO:   #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
(kms_flip:7231) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:7231) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7231) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7231) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (5.922s)
Starting dynamic subtest: C-eDP1
(kms_flip:7231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:7231) CRITICAL: Failed assertion: end - start < 500
(kms_flip:7231) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest C-eDP1 failed.
**** DEBUG ****
(kms_flip:7231) DEBUG: Vblank took 109us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.001434
last_received_ts = 486.000732
last_seq = 484
current_ts = 486.018097
current_received_ts = 486.017395
current_seq = 485
count = 315
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.018097
last_received_ts = 486.017395
last_seq = 485
current_ts = 486.034760
current_received_ts = 486.033966
current_seq = 486
count = 316
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.034760
last_received_ts = 486.033966
last_seq = 486
current_ts = 486.051422
current_received_ts = 486.050751
current_seq = 487
count = 317
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 119us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.051422
last_received_ts = 486.050751
last_seq = 487
current_ts = 486.068115
current_received_ts = 486.067322
current_seq = 488
count = 318
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.068115
last_received_ts = 486.067322
last_seq = 488
current_ts = 486.084778
current_received_ts = 486.084076
current_seq = 489
count = 319
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 34us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.084778
last_received_ts = 486.084076
last_seq = 489
current_ts = 486.101440
current_received_ts = 486.100800
current_seq = 490
count = 320
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 108us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.101440
last_received_ts = 486.100800
last_seq = 490
current_ts = 486.118103
current_received_ts = 486.117401
current_seq = 491
count = 321
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 39us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.118103
last_received_ts = 486.117401
last_seq = 491
current_ts = 486.134796
current_received_ts = 486.134033
current_seq = 492
count = 322
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 64us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.134796
last_received_ts = 486.134033
last_seq = 492
current_ts = 486.151459
current_received_ts = 486.150787
current_seq = 493
count = 323
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 109us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.151459
last_received_ts = 486.150787
last_seq = 493
current_ts = 486.168121
current_received_ts = 486.167358
current_seq = 494
count = 324
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 161us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.168121
last_received_ts = 486.167358
last_seq = 494
current_ts = 486.184784
current_received_ts = 486.184082
current_seq = 495
count = 325
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 34us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.184784
last_received_ts = 486.184082
last_seq = 495
current_ts = 486.201477
current_received_ts = 486.200775
current_seq = 496
count = 326
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 36us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.201477
last_received_ts = 486.200775
last_seq = 496
current_ts = 486.218140
current_received_ts = 486.217377
current_seq = 497
count = 327
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 107us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.218140
last_received_ts = 486.217377
last_seq = 497
current_ts = 486.234802
current_received_ts = 486.234039
current_seq = 498
count = 328
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 136us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.234802
last_received_ts = 486.234039
last_seq = 498
current_ts = 486.251465
current_received_ts = 486.250793
current_seq = 499
count = 329
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 55us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.251465
last_received_ts = 486.250793
last_seq = 499
current_ts = 486.268158
current_received_ts = 486.267395
current_seq = 500
count = 330
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.268158
last_received_ts = 486.267395
last_seq = 500
current_ts = 486.284821
current_received_ts = 486.284119
current_seq = 501
count = 331
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 36us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.284821
last_received_ts = 486.284119
last_seq = 501
current_ts = 486.301483
current_received_ts = 486.300720
current_seq = 502
count = 332
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 123us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.301483
last_received_ts = 486.300720
last_seq = 502
current_ts = 486.318176
current_received_ts = 486.317383
current_seq = 503
count = 333
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.318176
last_received_ts = 486.317383
last_seq = 503
current_ts = 486.334839
current_received_ts = 486.334045
current_seq = 504
count = 334
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.334839
last_received_ts = 486.334045
last_seq = 504
current_ts = 486.351501
current_received_ts = 486.350739
current_seq = 505
count = 335
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 117us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.351501
last_received_ts = 486.350739
last_seq = 505
current_ts = 486.368164
current_received_ts = 486.367401
current_seq = 506
count = 336
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 131us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.368164
last_received_ts = 486.367401
last_seq = 506
current_ts = 486.384827
current_received_ts = 486.384064
current_seq = 507
count = 337
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 53us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.384827
last_received_ts = 486.384064
last_seq = 507
current_ts = 486.401520
current_received_ts = 486.400726
current_seq = 508
count = 338
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 132us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.401520
last_received_ts = 486.400726
last_seq = 508
current_ts = 486.418182
current_received_ts = 486.417511
current_seq = 509
count = 339
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 116us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.418182
last_received_ts = 486.417511
last_seq = 509
current_ts = 486.434845
current_received_ts = 486.434052
current_seq = 510
count = 340
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 133us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.434845
last_received_ts = 486.434052
last_seq = 510
current_ts = 486.451508
current_received_ts = 486.450745
current_seq = 511
count = 341
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 114us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.451508
last_received_ts = 486.450745
last_seq = 511
current_ts = 486.468201
current_received_ts = 486.467499
current_seq = 512
count = 342
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 127us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.468201
last_received_ts = 486.467499
last_seq = 512
current_ts = 486.484863
current_received_ts = 486.484070
current_seq = 513
count = 343
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.484863
last_received_ts = 486.484070
last_seq = 513
current_ts = 486.501526
current_received_ts = 486.500763
current_seq = 514
count = 344
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.501526
last_received_ts = 486.500763
last_seq = 514
current_ts = 486.518219
current_received_ts = 486.517517
current_seq = 515
count = 345
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 43us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.518219
last_received_ts = 486.517517
last_seq = 515
current_ts = 486.534882
current_received_ts = 486.534088
current_seq = 516
count = 346
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.534882
last_received_ts = 486.534088
last_seq = 516
current_ts = 486.551544
current_received_ts = 486.550873
current_seq = 517
count = 347
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 51us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.551544
last_received_ts = 486.550873
last_seq = 517
current_ts = 486.568207
current_received_ts = 486.567535
current_seq = 518
count = 348
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 44us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.568207
last_received_ts = 486.567535
last_seq = 518
current_ts = 486.584900
current_received_ts = 486.584106
current_seq = 519
count = 349
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.584900
last_received_ts = 486.584106
last_seq = 519
current_ts = 486.601562
current_received_ts = 486.600861
current_seq = 520
count = 350
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.601562
last_received_ts = 486.600861
last_seq = 520
current_ts = 486.618225
current_received_ts = 486.617554
current_seq = 521
count = 351
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.618225
last_received_ts = 486.617554
last_seq = 521
current_ts = 486.634918
current_received_ts = 486.634125
current_seq = 522
count = 352
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 54us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.634918
last_received_ts = 486.634125
last_seq = 522
current_ts = 486.651550
current_received_ts = 486.650879
current_seq = 523
count = 353
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 63us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.651550
last_received_ts = 486.650879
last_seq = 523
current_ts = 486.668243
current_received_ts = 486.667572
current_seq = 524
count = 354
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 59us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.668243
last_received_ts = 486.667572
last_seq = 524
current_ts = 486.684906
current_received_ts = 486.684143
current_seq = 525
count = 355
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.684906
last_received_ts = 486.684143
last_seq = 525
current_ts = 486.701569
current_received_ts = 486.700928
current_seq = 526
count = 356
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.701569
last_received_ts = 486.700928
last_seq = 526
current_ts = 486.718262
current_received_ts = 486.717468
current_seq = 527
count = 357
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.718262
last_received_ts = 486.717468
last_seq = 527
current_ts = 486.734924
current_received_ts = 486.734131
current_seq = 528
count = 358
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.734924
last_received_ts = 486.734131
last_seq = 528
current_ts = 486.751587
current_received_ts = 486.750916
current_seq = 529
count = 359
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 139us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.751587
last_received_ts = 486.750916
last_seq = 529
current_ts = 486.768250
current_received_ts = 486.767578
current_seq = 530
count = 360
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 125us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.768250
last_received_ts = 486.767578
last_seq = 530
current_ts = 486.784943
current_received_ts = 486.784180
current_seq = 531
count = 361
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 44us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.784943
last_received_ts = 486.784180
last_seq = 531
current_ts = 486.801605
current_received_ts = 486.800964
current_seq = 532
count = 362
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.801605
last_received_ts = 486.800964
last_seq = 532
current_ts = 486.818268
current_received_ts = 486.817505
current_seq = 533
count = 363
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.818268
last_received_ts = 486.817505
last_seq = 533
current_ts = 486.834930
current_received_ts = 486.834137
current_seq = 534
count = 364
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 46us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.834930
last_received_ts = 486.834137
last_seq = 534
current_ts = 486.851624
current_received_ts = 486.850952
current_seq = 535
count = 365
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 127us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.851624
last_received_ts = 486.850952
last_seq = 535
current_ts = 486.868286
current_received_ts = 486.867615
current_seq = 536
count = 366
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.868286
last_received_ts = 486.867615
last_seq = 536
current_ts = 486.884949
current_received_ts = 486.884155
current_seq = 537
count = 367
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.884949
last_received_ts = 486.884155
last_seq = 537
current_ts = 486.901611
current_received_ts = 486.900940
current_seq = 538
count = 368
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 74us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.901611
last_received_ts = 486.900940
last_seq = 538
current_ts = 486.918304
current_received_ts = 486.917633
current_seq = 539
count = 369
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.918304
last_received_ts = 486.917633
last_seq = 539
current_ts = 486.934967
current_received_ts = 486.934174
current_seq = 540
count = 370
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.934967
last_received_ts = 486.934174
last_seq = 540
current_ts = 486.951630
current_received_ts = 486.950958
current_seq = 541
count = 371
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 54us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.951630
last_received_ts = 486.950958
last_seq = 541
current_ts = 486.968323
current_received_ts = 486.967529
current_seq = 542
count = 372
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.968323
last_received_ts = 486.967529
last_seq = 542
current_ts = 486.984985
current_received_ts = 486.984497
current_seq = 543
count = 373
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 108us
(kms_flip:7231) DEBUG: name = flip
last_ts = 486.984985
last_received_ts = 486.984497
last_seq = 543
current_ts = 487.001648
current_received_ts = 487.000885
current_seq = 544
count = 374
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.001648
last_received_ts = 487.000885
last_seq = 544
current_ts = 487.018311
current_received_ts = 487.017883
current_seq = 545
count = 375
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 33us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.018311
last_received_ts = 487.017883
last_seq = 545
current_ts = 487.035004
current_received_ts = 487.034546
current_seq = 546
count = 376
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 33us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.035004
last_received_ts = 487.034546
last_seq = 546
current_ts = 487.051666
current_received_ts = 487.050903
current_seq = 547
count = 377
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 46us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.051666
last_received_ts = 487.050903
last_seq = 547
current_ts = 487.068329
current_received_ts = 487.067871
current_seq = 548
count = 378
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 35us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.068329
last_received_ts = 487.067871
last_seq = 548
current_ts = 487.084991
current_received_ts = 487.084412
current_seq = 549
count = 379
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 35us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.084991
last_received_ts = 487.084412
last_seq = 549
current_ts = 487.101685
current_received_ts = 487.100922
current_seq = 550
count = 380
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.101685
last_received_ts = 487.100922
last_seq = 550
current_ts = 487.118347
current_received_ts = 487.117737
current_seq = 551
count = 381
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 43us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.118347
last_received_ts = 487.117737
last_seq = 551
current_ts = 487.135010
current_received_ts = 487.134247
current_seq = 552
count = 382
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 57us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.135010
last_received_ts = 487.134247
last_seq = 552
current_ts = 487.151672
current_received_ts = 487.151031
current_seq = 553
count = 383
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 39us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.151672
last_received_ts = 487.151031
last_seq = 553
current_ts = 487.168335
current_received_ts = 487.167725
current_seq = 554
count = 384
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 39us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.168335
last_received_ts = 487.167725
last_seq = 554
current_ts = 487.185028
current_received_ts = 487.184265
current_seq = 555
count = 385
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 35us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.185028
last_received_ts = 487.184265
last_seq = 555
current_ts = 487.201691
current_received_ts = 487.201263
current_seq = 556
count = 386
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 109us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.201691
last_received_ts = 487.201263
last_seq = 556
current_ts = 487.218353
current_received_ts = 487.217651
current_seq = 557
count = 387
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 36us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.218353
last_received_ts = 487.217651
last_seq = 557
current_ts = 487.235046
current_received_ts = 487.234253
current_seq = 558
count = 388
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.235046
last_received_ts = 487.234253
last_seq = 558
current_ts = 487.251709
current_received_ts = 487.250916
current_seq = 559
count = 389
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 56us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.251709
last_received_ts = 487.250916
last_seq = 559
current_ts = 487.268372
current_received_ts = 487.267609
current_seq = 560
count = 390
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 152us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.268372
last_received_ts = 487.267609
last_seq = 560
current_ts = 487.285034
current_received_ts = 487.284424
current_seq = 561
count = 391
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 37us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.285034
last_received_ts = 487.284424
last_seq = 561
current_ts = 487.301727
current_received_ts = 487.300964
current_seq = 562
count = 392
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 35us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.301727
last_received_ts = 487.300964
last_seq = 562
current_ts = 487.318390
current_received_ts = 487.317627
current_seq = 563
count = 393
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 121us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.318390
last_received_ts = 487.317627
last_seq = 563
current_ts = 487.335052
current_received_ts = 487.334259
current_seq = 564
count = 394
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 44us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.335052
last_received_ts = 487.334259
last_seq = 564
current_ts = 487.351715
current_received_ts = 487.350952
current_seq = 565
count = 395
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 40us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.351715
last_received_ts = 487.350952
last_seq = 565
current_ts = 487.368408
current_received_ts = 487.367737
current_seq = 566
count = 396
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 125us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.368408
last_received_ts = 487.367737
last_seq = 566
current_ts = 487.385071
current_received_ts = 487.384277
current_seq = 567
count = 397
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 45us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.385071
last_received_ts = 487.384277
last_seq = 567
current_ts = 487.401733
current_received_ts = 487.400970
current_seq = 568
count = 398
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.401733
last_received_ts = 487.400970
last_seq = 568
current_ts = 487.418396
current_received_ts = 487.417633
current_seq = 569
count = 399
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.418396
last_received_ts = 487.417633
last_seq = 569
current_ts = 487.435089
current_received_ts = 487.434479
current_seq = 570
count = 400
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 37us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.435089
last_received_ts = 487.434479
last_seq = 570
current_ts = 487.451752
current_received_ts = 487.451019
current_seq = 571
count = 401
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 130us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.451752
last_received_ts = 487.451019
last_seq = 571
current_ts = 487.468414
current_received_ts = 487.467773
current_seq = 572
count = 402
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 39us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.468414
last_received_ts = 487.467773
last_seq = 572
current_ts = 487.485077
current_received_ts = 487.484283
current_seq = 573
count = 403
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 39us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.485077
last_received_ts = 487.484283
last_seq = 573
current_ts = 487.501770
current_received_ts = 487.500977
current_seq = 574
count = 404
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 52us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.501770
last_received_ts = 487.500977
last_seq = 574
current_ts = 487.518433
current_received_ts = 487.517639
current_seq = 575
count = 405
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 55us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.518433
last_received_ts = 487.517639
last_seq = 575
current_ts = 487.535095
current_received_ts = 487.534332
current_seq = 576
count = 406
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 59us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.535095
last_received_ts = 487.534332
last_seq = 576
current_ts = 487.551758
current_received_ts = 487.550995
current_seq = 577
count = 407
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 72us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.551758
last_received_ts = 487.550995
last_seq = 577
current_ts = 487.568451
current_received_ts = 487.567780
current_seq = 578
count = 408
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 46us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.568451
last_received_ts = 487.567780
last_seq = 578
current_ts = 487.585114
current_received_ts = 487.584351
current_seq = 579
count = 409
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.585114
last_received_ts = 487.584351
last_seq = 579
current_ts = 487.601776
current_received_ts = 487.601013
current_seq = 580
count = 410
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.601776
last_received_ts = 487.601013
last_seq = 580
current_ts = 487.618469
current_received_ts = 487.617767
current_seq = 581
count = 411
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 54us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.618469
last_received_ts = 487.617767
last_seq = 581
current_ts = 487.635132
current_received_ts = 487.634430
current_seq = 582
count = 412
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 53us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.635132
last_received_ts = 487.634430
last_seq = 582
current_ts = 487.651794
current_received_ts = 487.651001
current_seq = 583
count = 413
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 44us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.651794
last_received_ts = 487.651001
last_seq = 583
current_ts = 487.668457
current_received_ts = 487.667664
current_seq = 584
count = 414
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 44us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.668457
last_received_ts = 487.667664
last_seq = 584
current_ts = 487.685150
current_received_ts = 487.684448
current_seq = 585
count = 415
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 38us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.685150
last_received_ts = 487.684448
last_seq = 585
current_ts = 487.701813
current_received_ts = 487.701050
current_seq = 586
count = 416
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 64us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.701813
last_received_ts = 487.701050
last_seq = 586
current_ts = 487.718475
current_received_ts = 487.717804
current_seq = 587
count = 417
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 119us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.718475
last_received_ts = 487.717804
last_seq = 587
current_ts = 487.735138
current_received_ts = 487.734375
current_seq = 588
count = 418
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 125us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.735138
last_received_ts = 487.734375
last_seq = 588
current_ts = 487.751831
current_received_ts = 487.751068
current_seq = 589
count = 419
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 50us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.751831
last_received_ts = 487.751068
last_seq = 589
current_ts = 487.768494
current_received_ts = 487.767822
current_seq = 590
count = 420
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.768494
last_received_ts = 487.767822
last_seq = 590
current_ts = 487.785156
current_received_ts = 487.784485
current_seq = 591
count = 421
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 117us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.785156
last_received_ts = 487.784485
last_seq = 591
current_ts = 487.801819
current_received_ts = 487.801056
current_seq = 592
count = 422
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 44us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.801819
last_received_ts = 487.801056
last_seq = 592
current_ts = 487.818512
current_received_ts = 487.817810
current_seq = 593
count = 423
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 102us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.818512
last_received_ts = 487.817810
last_seq = 593
current_ts = 487.835175
current_received_ts = 487.834412
current_seq = 594
count = 424
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.835175
last_received_ts = 487.834412
last_seq = 594
current_ts = 487.851837
current_received_ts = 487.851044
current_seq = 595
count = 425
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 49us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.851837
last_received_ts = 487.851044
last_seq = 595
current_ts = 487.868500
current_received_ts = 487.867737
current_seq = 596
count = 426
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 51us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.868500
last_received_ts = 487.867737
last_seq = 596
current_ts = 487.885193
current_received_ts = 487.884521
current_seq = 597
count = 427
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 51us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.885193
last_received_ts = 487.884521
last_seq = 597
current_ts = 487.901855
current_received_ts = 487.901062
current_seq = 598
count = 428
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 48us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.901855
last_received_ts = 487.901062
last_seq = 598
current_ts = 487.918518
current_received_ts = 487.917755
current_seq = 599
count = 429
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 42us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.918518
last_received_ts = 487.917755
last_seq = 599
current_ts = 487.935181
current_received_ts = 487.934418
current_seq = 600
count = 430
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 43us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.935181
last_received_ts = 487.934418
last_seq = 600
current_ts = 487.951874
current_received_ts = 487.951172
current_seq = 601
count = 431
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 54us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.951874
last_received_ts = 487.951172
last_seq = 601
current_ts = 487.968536
current_received_ts = 487.967773
current_seq = 602
count = 432
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 131us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.968536
last_received_ts = 487.967773
last_seq = 602
current_ts = 487.985199
current_received_ts = 487.984436
current_seq = 603
count = 433
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 121us
(kms_flip:7231) DEBUG: name = flip
last_ts = 487.985199
last_received_ts = 487.984436
last_seq = 603
current_ts = 488.001892
current_received_ts = 488.001068
current_seq = 604
count = 434
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 53us
(kms_flip:7231) DEBUG: name = flip
last_ts = 488.001892
last_received_ts = 488.001068
last_seq = 604
current_ts = 488.018555
current_received_ts = 488.018097
current_seq = 605
count = 435
seq_step = 1
(kms_flip:7231) DEBUG: Vblank took 2001us
(kms_flip:7231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:928:
(kms_flip:7231) CRITICAL: Failed assertion: end - start < 500
(kms_flip:7231) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:7231) igt_core-INFO: Stack trace:
(kms_flip:7231) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:7231) igt_core-INFO:   #1 ../tests/kms_flip.c:923 run_test_on_crtc_set.constprop.0()
(kms_flip:7231) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:7231) igt_core-INFO:   #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
(kms_flip:7231) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:7231) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:7231) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:7231) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-eDP1: FAIL (8.475s)
Subtest flip-vs-expired-vblank-interruptible: FAIL (18.947s)
(kms_flip:7231) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2247:
(kms_flip:7231) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:7231) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:7231) igt_kms-CRITICAL: DPMS property not found on 205