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

shard-lnl-4

IGT-Version: 1.30-g6f71829fe (x86_64) (Linux: 6.14.0-rc6-xe+ x86_64)

Using IGT_SRANDOM=1741789170 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: flip-vs-expired-vblank
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:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (7.740s)
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:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (9.808s)
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:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-eDP1: FAIL (10.351s)
Subtest flip-vs-expired-vblank: FAIL (27.910s)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2246 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2934 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2390 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-eDP1
(kms_flip:2909) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2909) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.098541
last_received_ts = 196.097900
last_seq = 378
current_ts = 196.115204
current_received_ts = 196.114532
current_seq = 379
count = 245
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 49us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.115204
last_received_ts = 196.114532
last_seq = 379
current_ts = 196.131882
current_received_ts = 196.131287
current_seq = 380
count = 246
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 46us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.131882
last_received_ts = 196.131287
last_seq = 380
current_ts = 196.148544
current_received_ts = 196.147903
current_seq = 381
count = 247
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 49us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.148544
last_received_ts = 196.147903
last_seq = 381
current_ts = 196.165207
current_received_ts = 196.164551
current_seq = 382
count = 248
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 50us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.165207
last_received_ts = 196.164551
last_seq = 382
current_ts = 196.181870
current_received_ts = 196.181259
current_seq = 383
count = 249
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 49us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.181870
last_received_ts = 196.181259
last_seq = 383
current_ts = 196.198532
current_received_ts = 196.197906
current_seq = 384
count = 250
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 46us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.198532
last_received_ts = 196.197906
last_seq = 384
current_ts = 196.215195
current_received_ts = 196.214539
current_seq = 385
count = 251
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 51us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.215195
last_received_ts = 196.214539
last_seq = 385
current_ts = 196.231857
current_received_ts = 196.231262
current_seq = 386
count = 252
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 49us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.231857
last_received_ts = 196.231262
last_seq = 386
current_ts = 196.248535
current_received_ts = 196.247879
current_seq = 387
count = 253
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 43us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.248535
last_received_ts = 196.247879
last_seq = 387
current_ts = 196.265198
current_received_ts = 196.264526
current_seq = 388
count = 254
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 51us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.265198
last_received_ts = 196.264526
last_seq = 388
current_ts = 196.281860
current_received_ts = 196.281250
current_seq = 389
count = 255
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 45us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.281860
last_received_ts = 196.281250
last_seq = 389
current_ts = 196.298523
current_received_ts = 196.297882
current_seq = 390
count = 256
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 48us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.298523
last_received_ts = 196.297882
last_seq = 390
current_ts = 196.315186
current_received_ts = 196.314560
current_seq = 391
count = 257
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 50us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.315186
last_received_ts = 196.314560
last_seq = 391
current_ts = 196.331863
current_received_ts = 196.331238
current_seq = 392
count = 258
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 49us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.331863
last_received_ts = 196.331238
last_seq = 392
current_ts = 196.348526
current_received_ts = 196.347900
current_seq = 393
count = 259
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 46us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.348526
last_received_ts = 196.347900
last_seq = 393
current_ts = 196.365189
current_received_ts = 196.364548
current_seq = 394
count = 260
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 49us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.365189
last_received_ts = 196.364548
last_seq = 394
current_ts = 196.381851
current_received_ts = 196.381241
current_seq = 395
count = 261
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 48us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.381851
last_received_ts = 196.381241
last_seq = 395
current_ts = 196.398514
current_received_ts = 196.397903
current_seq = 396
count = 262
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 46us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.398514
last_received_ts = 196.397903
last_seq = 396
current_ts = 196.415176
current_received_ts = 196.414566
current_seq = 397
count = 263
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 46us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.415176
last_received_ts = 196.414566
last_seq = 397
current_ts = 196.431839
current_received_ts = 196.431244
current_seq = 398
count = 264
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 46us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.431839
last_received_ts = 196.431244
last_seq = 398
current_ts = 196.448502
current_received_ts = 196.447876
current_seq = 399
count = 265
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 47us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.448502
last_received_ts = 196.447876
last_seq = 399
current_ts = 196.465179
current_received_ts = 196.464508
current_seq = 400
count = 266
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 50us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.465179
last_received_ts = 196.464508
last_seq = 400
current_ts = 196.481842
current_received_ts = 196.481232
current_seq = 401
count = 267
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 49us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.481842
last_received_ts = 196.481232
last_seq = 401
current_ts = 196.498505
current_received_ts = 196.497879
current_seq = 402
count = 268
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 48us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.498505
last_received_ts = 196.497879
last_seq = 402
current_ts = 196.515182
current_received_ts = 196.514496
current_seq = 403
count = 269
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 47us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.515182
last_received_ts = 196.514496
last_seq = 403
current_ts = 196.531845
current_received_ts = 196.531235
current_seq = 404
count = 270
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 48us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.531845
last_received_ts = 196.531235
last_seq = 404
current_ts = 196.548492
current_received_ts = 196.547867
current_seq = 405
count = 271
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 49us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.548492
last_received_ts = 196.547867
last_seq = 405
current_ts = 196.565170
current_received_ts = 196.564621
current_seq = 406
count = 272
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 412us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.565170
last_received_ts = 196.564621
last_seq = 406
current_ts = 196.581833
current_received_ts = 196.581360
current_seq = 407
count = 273
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 440us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.581833
last_received_ts = 196.581360
last_seq = 407
current_ts = 196.598495
current_received_ts = 196.597992
current_seq = 408
count = 274
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 460us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.598495
last_received_ts = 196.597992
last_seq = 408
current_ts = 196.615158
current_received_ts = 196.614609
current_seq = 409
count = 275
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 423us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.615158
last_received_ts = 196.614609
last_seq = 409
current_ts = 196.631836
current_received_ts = 196.631332
current_seq = 410
count = 276
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 273us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.631836
last_received_ts = 196.631332
last_seq = 410
current_ts = 196.648499
current_received_ts = 196.647980
current_seq = 411
count = 277
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 304us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.648499
last_received_ts = 196.647980
last_seq = 411
current_ts = 196.665161
current_received_ts = 196.664612
current_seq = 412
count = 278
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 399us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.665161
last_received_ts = 196.664612
last_seq = 412
current_ts = 196.681824
current_received_ts = 196.681213
current_seq = 413
count = 279
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.681824
last_received_ts = 196.681213
last_seq = 413
current_ts = 196.698486
current_received_ts = 196.697983
current_seq = 414
count = 280
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 301us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.698486
last_received_ts = 196.697983
last_seq = 414
current_ts = 196.715149
current_received_ts = 196.714600
current_seq = 415
count = 281
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 451us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.715149
last_received_ts = 196.714600
last_seq = 415
current_ts = 196.731827
current_received_ts = 196.731293
current_seq = 416
count = 282
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 416us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.731827
last_received_ts = 196.731293
last_seq = 416
current_ts = 196.748489
current_received_ts = 196.747986
current_seq = 417
count = 283
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 465us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.748489
last_received_ts = 196.747986
last_seq = 417
current_ts = 196.765152
current_received_ts = 196.764572
current_seq = 418
count = 284
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 447us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.765152
last_received_ts = 196.764572
last_seq = 418
current_ts = 196.781815
current_received_ts = 196.781326
current_seq = 419
count = 285
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 400us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.781815
last_received_ts = 196.781326
last_seq = 419
current_ts = 196.798477
current_received_ts = 196.797989
current_seq = 420
count = 286
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 437us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.798477
last_received_ts = 196.797989
last_seq = 420
current_ts = 196.815140
current_received_ts = 196.814606
current_seq = 421
count = 287
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 333us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.815140
last_received_ts = 196.814606
last_seq = 421
current_ts = 196.831818
current_received_ts = 196.831177
current_seq = 422
count = 288
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 405us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.831818
last_received_ts = 196.831177
last_seq = 422
current_ts = 196.848480
current_received_ts = 196.847946
current_seq = 423
count = 289
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 132us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.848480
last_received_ts = 196.847946
last_seq = 423
current_ts = 196.865143
current_received_ts = 196.864594
current_seq = 424
count = 290
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 420us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.865143
last_received_ts = 196.864594
last_seq = 424
current_ts = 196.881805
current_received_ts = 196.881195
current_seq = 425
count = 291
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.881805
last_received_ts = 196.881195
last_seq = 425
current_ts = 196.898468
current_received_ts = 196.897964
current_seq = 426
count = 292
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 377us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.898468
last_received_ts = 196.897964
last_seq = 426
current_ts = 196.915131
current_received_ts = 196.914597
current_seq = 427
count = 293
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 426us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.915131
last_received_ts = 196.914597
last_seq = 427
current_ts = 196.931808
current_received_ts = 196.931213
current_seq = 428
count = 294
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.931808
last_received_ts = 196.931213
last_seq = 428
current_ts = 196.948471
current_received_ts = 196.947952
current_seq = 429
count = 295
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 162us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.948471
last_received_ts = 196.947952
last_seq = 429
current_ts = 196.965134
current_received_ts = 196.964584
current_seq = 430
count = 296
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 446us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.965134
last_received_ts = 196.964584
last_seq = 430
current_ts = 196.981796
current_received_ts = 196.981293
current_seq = 431
count = 297
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 351us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.981796
last_received_ts = 196.981293
last_seq = 431
current_ts = 196.998459
current_received_ts = 196.997955
current_seq = 432
count = 298
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 142us
(kms_flip:2909) DEBUG: name = flip
last_ts = 196.998459
last_received_ts = 196.997955
last_seq = 432
current_ts = 197.015121
current_received_ts = 197.014557
current_seq = 433
count = 299
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 273us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.015121
last_received_ts = 197.014557
last_seq = 433
current_ts = 197.031799
current_received_ts = 197.031235
current_seq = 434
count = 300
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 52us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.031799
last_received_ts = 197.031235
last_seq = 434
current_ts = 197.048462
current_received_ts = 197.047943
current_seq = 435
count = 301
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 118us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.048462
last_received_ts = 197.047943
last_seq = 435
current_ts = 197.065125
current_received_ts = 197.064590
current_seq = 436
count = 302
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 339us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.065125
last_received_ts = 197.064590
last_seq = 436
current_ts = 197.081787
current_received_ts = 197.081192
current_seq = 437
count = 303
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 50us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.081787
last_received_ts = 197.081192
last_seq = 437
current_ts = 197.098450
current_received_ts = 197.097946
current_seq = 438
count = 304
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 149us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.098450
last_received_ts = 197.097946
last_seq = 438
current_ts = 197.115128
current_received_ts = 197.114563
current_seq = 439
count = 305
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 467us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.115128
last_received_ts = 197.114563
last_seq = 439
current_ts = 197.131790
current_received_ts = 197.131195
current_seq = 440
count = 306
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.131790
last_received_ts = 197.131195
last_seq = 440
current_ts = 197.148453
current_received_ts = 197.147934
current_seq = 441
count = 307
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 149us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.148453
last_received_ts = 197.147934
last_seq = 441
current_ts = 197.165115
current_received_ts = 197.164474
current_seq = 442
count = 308
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 232us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.165115
last_received_ts = 197.164474
last_seq = 442
current_ts = 197.181778
current_received_ts = 197.181213
current_seq = 443
count = 309
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 53us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.181778
last_received_ts = 197.181213
last_seq = 443
current_ts = 197.198441
current_received_ts = 197.197952
current_seq = 444
count = 310
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 139us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.198441
last_received_ts = 197.197952
last_seq = 444
current_ts = 197.215103
current_received_ts = 197.214539
current_seq = 445
count = 311
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 269us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.215103
last_received_ts = 197.214539
last_seq = 445
current_ts = 197.231781
current_received_ts = 197.231262
current_seq = 446
count = 312
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 321us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.231781
last_received_ts = 197.231262
last_seq = 446
current_ts = 197.248444
current_received_ts = 197.247955
current_seq = 447
count = 313
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 97us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.248444
last_received_ts = 197.247955
last_seq = 447
current_ts = 197.265106
current_received_ts = 197.264526
current_seq = 448
count = 314
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 344us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.265106
last_received_ts = 197.264526
last_seq = 448
current_ts = 197.281769
current_received_ts = 197.281265
current_seq = 449
count = 315
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 383us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.281769
last_received_ts = 197.281265
last_seq = 449
current_ts = 197.298431
current_received_ts = 197.297928
current_seq = 450
count = 316
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 182us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.298431
last_received_ts = 197.297928
last_seq = 450
current_ts = 197.315094
current_received_ts = 197.314453
current_seq = 451
count = 317
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 292us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.315094
last_received_ts = 197.314453
last_seq = 451
current_ts = 197.331757
current_received_ts = 197.331223
current_seq = 452
count = 318
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.331757
last_received_ts = 197.331223
last_seq = 452
current_ts = 197.348434
current_received_ts = 197.347931
current_seq = 453
count = 319
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 121us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.348434
last_received_ts = 197.347931
last_seq = 453
current_ts = 197.365097
current_received_ts = 197.364532
current_seq = 454
count = 320
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 495us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.365097
last_received_ts = 197.364532
last_seq = 454
current_ts = 197.381760
current_received_ts = 197.381287
current_seq = 455
count = 321
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 172us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.381760
last_received_ts = 197.381287
last_seq = 455
current_ts = 197.398422
current_received_ts = 197.397919
current_seq = 456
count = 322
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 133us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.398422
last_received_ts = 197.397919
last_seq = 456
current_ts = 197.415085
current_received_ts = 197.414429
current_seq = 457
count = 323
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 167us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.415085
last_received_ts = 197.414429
last_seq = 457
current_ts = 197.431747
current_received_ts = 197.431259
current_seq = 458
count = 324
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 346us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.431747
last_received_ts = 197.431259
last_seq = 458
current_ts = 197.448425
current_received_ts = 197.447922
current_seq = 459
count = 325
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 124us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.448425
last_received_ts = 197.447922
last_seq = 459
current_ts = 197.465088
current_received_ts = 197.464432
current_seq = 460
count = 326
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 162us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.465088
last_received_ts = 197.464432
last_seq = 460
current_ts = 197.481750
current_received_ts = 197.481247
current_seq = 461
count = 327
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 445us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.481750
last_received_ts = 197.481247
last_seq = 461
current_ts = 197.498413
current_received_ts = 197.497910
current_seq = 462
count = 328
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 132us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.498413
last_received_ts = 197.497910
last_seq = 462
current_ts = 197.515091
current_received_ts = 197.514420
current_seq = 463
count = 329
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 305us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.515091
last_received_ts = 197.514420
last_seq = 463
current_ts = 197.531754
current_received_ts = 197.531219
current_seq = 464
count = 330
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.531754
last_received_ts = 197.531219
last_seq = 464
current_ts = 197.548416
current_received_ts = 197.547897
current_seq = 465
count = 331
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 142us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.548416
last_received_ts = 197.547897
last_seq = 465
current_ts = 197.565079
current_received_ts = 197.564423
current_seq = 466
count = 332
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 218us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.565079
last_received_ts = 197.564423
last_seq = 466
current_ts = 197.581741
current_received_ts = 197.581238
current_seq = 467
count = 333
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 358us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.581741
last_received_ts = 197.581238
last_seq = 467
current_ts = 197.598404
current_received_ts = 197.597885
current_seq = 468
count = 334
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 160us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.598404
last_received_ts = 197.597885
last_seq = 468
current_ts = 197.615067
current_received_ts = 197.614456
current_seq = 469
count = 335
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 282us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.615067
last_received_ts = 197.614456
last_seq = 469
current_ts = 197.631744
current_received_ts = 197.631256
current_seq = 470
count = 336
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 381us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.631744
last_received_ts = 197.631256
last_seq = 470
current_ts = 197.648407
current_received_ts = 197.647888
current_seq = 471
count = 337
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 150us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.648407
last_received_ts = 197.647888
last_seq = 471
current_ts = 197.665070
current_received_ts = 197.664459
current_seq = 472
count = 338
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 329us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.665070
last_received_ts = 197.664459
last_seq = 472
current_ts = 197.681732
current_received_ts = 197.681213
current_seq = 473
count = 339
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 53us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.681732
last_received_ts = 197.681213
last_seq = 473
current_ts = 197.698395
current_received_ts = 197.697922
current_seq = 474
count = 340
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 130us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.698395
last_received_ts = 197.697922
last_seq = 474
current_ts = 197.715073
current_received_ts = 197.714417
current_seq = 475
count = 341
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 280us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.715073
last_received_ts = 197.714417
last_seq = 475
current_ts = 197.731735
current_received_ts = 197.731186
current_seq = 476
count = 342
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 51us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.731735
last_received_ts = 197.731186
last_seq = 476
current_ts = 197.748398
current_received_ts = 197.747894
current_seq = 477
count = 343
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 144us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.748398
last_received_ts = 197.747894
last_seq = 477
current_ts = 197.765060
current_received_ts = 197.764404
current_seq = 478
count = 344
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 263us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.765060
last_received_ts = 197.764404
last_seq = 478
current_ts = 197.781723
current_received_ts = 197.781219
current_seq = 479
count = 345
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 364us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.781723
last_received_ts = 197.781219
last_seq = 479
current_ts = 197.798386
current_received_ts = 197.797882
current_seq = 480
count = 346
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 436us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.798386
last_received_ts = 197.797882
last_seq = 480
current_ts = 197.815048
current_received_ts = 197.814453
current_seq = 481
count = 347
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 268us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.815048
last_received_ts = 197.814453
last_seq = 481
current_ts = 197.831726
current_received_ts = 197.831223
current_seq = 482
count = 348
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.831726
last_received_ts = 197.831223
last_seq = 482
current_ts = 197.848389
current_received_ts = 197.847885
current_seq = 483
count = 349
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 175us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.848389
last_received_ts = 197.847885
last_seq = 483
current_ts = 197.865051
current_received_ts = 197.864395
current_seq = 484
count = 350
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 178us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.865051
last_received_ts = 197.864395
last_seq = 484
current_ts = 197.881714
current_received_ts = 197.881210
current_seq = 485
count = 351
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 430us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.881714
last_received_ts = 197.881210
last_seq = 485
current_ts = 197.898376
current_received_ts = 197.897858
current_seq = 486
count = 352
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 201us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.898376
last_received_ts = 197.897858
last_seq = 486
current_ts = 197.915054
current_received_ts = 197.914459
current_seq = 487
count = 353
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 442us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.915054
last_received_ts = 197.914459
last_seq = 487
current_ts = 197.931702
current_received_ts = 197.931213
current_seq = 488
count = 354
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 248us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.931702
last_received_ts = 197.931213
last_seq = 488
current_ts = 197.948380
current_received_ts = 197.947876
current_seq = 489
count = 355
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 220us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.948380
last_received_ts = 197.947876
last_seq = 489
current_ts = 197.965042
current_received_ts = 197.964401
current_seq = 490
count = 356
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 347us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.965042
last_received_ts = 197.964401
last_seq = 490
current_ts = 197.981705
current_received_ts = 197.981216
current_seq = 491
count = 357
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 365us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.981705
last_received_ts = 197.981216
last_seq = 491
current_ts = 197.998367
current_received_ts = 197.997879
current_seq = 492
count = 358
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 176us
(kms_flip:2909) DEBUG: name = flip
last_ts = 197.998367
last_received_ts = 197.997879
last_seq = 492
current_ts = 198.015030
current_received_ts = 198.014450
current_seq = 493
count = 359
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 354us
(kms_flip:2909) DEBUG: name = flip
last_ts = 198.015030
last_received_ts = 198.014450
last_seq = 493
current_ts = 198.031708
current_received_ts = 198.031204
current_seq = 494
count = 360
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 289us
(kms_flip:2909) DEBUG: name = flip
last_ts = 198.031708
last_received_ts = 198.031204
last_seq = 494
current_ts = 198.048370
current_received_ts = 198.047867
current_seq = 495
count = 361
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 198us
(kms_flip:2909) DEBUG: name = flip
last_ts = 198.048370
last_received_ts = 198.047867
last_seq = 495
current_ts = 198.065033
current_received_ts = 198.064423
current_seq = 496
count = 362
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 264us
(kms_flip:2909) DEBUG: name = flip
last_ts = 198.065033
last_received_ts = 198.064423
last_seq = 496
current_ts = 198.081696
current_received_ts = 198.081207
current_seq = 497
count = 363
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 445us
(kms_flip:2909) DEBUG: name = flip
last_ts = 198.081696
last_received_ts = 198.081207
last_seq = 497
current_ts = 198.098358
current_received_ts = 198.097839
current_seq = 498
count = 364
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 198us
(kms_flip:2909) DEBUG: name = flip
last_ts = 198.098358
last_received_ts = 198.097839
last_seq = 498
current_ts = 198.115036
current_received_ts = 198.114395
current_seq = 499
count = 365
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 198.115036
last_received_ts = 198.114395
last_seq = 499
current_ts = 198.131699
current_received_ts = 198.131195
current_seq = 500
count = 366
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 554us
(kms_flip:2909) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2909) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2909) igt_core-INFO: Stack trace:
(kms_flip:2909) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2909) igt_core-INFO:   #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
(kms_flip:2909) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2909) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2909) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2909) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2909) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2909) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (7.740s)
Starting dynamic subtest: B-eDP1
(kms_flip:2909) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2909) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:2909) DEBUG: name = flip
last_ts = 205.992310
last_received_ts = 205.991791
last_seq = 377
current_ts = 206.008972
current_received_ts = 206.008408
current_seq = 378
count = 374
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 51us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.008972
last_received_ts = 206.008408
last_seq = 378
current_ts = 206.025650
current_received_ts = 206.025146
current_seq = 379
count = 375
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 51us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.025650
last_received_ts = 206.025146
last_seq = 379
current_ts = 206.042313
current_received_ts = 206.041824
current_seq = 380
count = 376
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 227us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.042313
last_received_ts = 206.041824
last_seq = 380
current_ts = 206.058975
current_received_ts = 206.058395
current_seq = 381
count = 377
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.058975
last_received_ts = 206.058395
last_seq = 381
current_ts = 206.075638
current_received_ts = 206.075134
current_seq = 382
count = 378
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 440us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.075638
last_received_ts = 206.075134
last_seq = 382
current_ts = 206.092300
current_received_ts = 206.091812
current_seq = 383
count = 379
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 223us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.092300
last_received_ts = 206.091812
last_seq = 383
current_ts = 206.108978
current_received_ts = 206.108398
current_seq = 384
count = 380
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 389us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.108978
last_received_ts = 206.108398
last_seq = 384
current_ts = 206.125641
current_received_ts = 206.125137
current_seq = 385
count = 381
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 337us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.125641
last_received_ts = 206.125137
last_seq = 385
current_ts = 206.142303
current_received_ts = 206.141769
current_seq = 386
count = 382
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 272us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.142303
last_received_ts = 206.141769
last_seq = 386
current_ts = 206.158966
current_received_ts = 206.158401
current_seq = 387
count = 383
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.158966
last_received_ts = 206.158401
last_seq = 387
current_ts = 206.175629
current_received_ts = 206.175110
current_seq = 388
count = 384
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 224us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.175629
last_received_ts = 206.175110
last_seq = 388
current_ts = 206.192307
current_received_ts = 206.191788
current_seq = 389
count = 385
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 250us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.192307
last_received_ts = 206.191788
last_seq = 389
current_ts = 206.208954
current_received_ts = 206.208389
current_seq = 390
count = 386
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.208954
last_received_ts = 206.208389
last_seq = 390
current_ts = 206.225632
current_received_ts = 206.225113
current_seq = 391
count = 387
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.225632
last_received_ts = 206.225113
last_seq = 391
current_ts = 206.242294
current_received_ts = 206.241776
current_seq = 392
count = 388
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 260us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.242294
last_received_ts = 206.241776
last_seq = 392
current_ts = 206.258957
current_received_ts = 206.258408
current_seq = 393
count = 389
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 269us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.258957
last_received_ts = 206.258408
last_seq = 393
current_ts = 206.275620
current_received_ts = 206.275116
current_seq = 394
count = 390
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 483us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.275620
last_received_ts = 206.275116
last_seq = 394
current_ts = 206.292282
current_received_ts = 206.291748
current_seq = 395
count = 391
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 289us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.292282
last_received_ts = 206.291748
last_seq = 395
current_ts = 206.308945
current_received_ts = 206.308365
current_seq = 396
count = 392
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.308945
last_received_ts = 206.308365
last_seq = 396
current_ts = 206.325623
current_received_ts = 206.325104
current_seq = 397
count = 393
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 242us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.325623
last_received_ts = 206.325104
last_seq = 397
current_ts = 206.342285
current_received_ts = 206.341721
current_seq = 398
count = 394
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 305us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.342285
last_received_ts = 206.341721
last_seq = 398
current_ts = 206.358948
current_received_ts = 206.358398
current_seq = 399
count = 395
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.358948
last_received_ts = 206.358398
last_seq = 399
current_ts = 206.375610
current_received_ts = 206.375122
current_seq = 400
count = 396
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 387us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.375610
last_received_ts = 206.375122
last_seq = 400
current_ts = 206.392273
current_received_ts = 206.391754
current_seq = 401
count = 397
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 294us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.392273
last_received_ts = 206.391754
last_seq = 401
current_ts = 206.408936
current_received_ts = 206.408371
current_seq = 402
count = 398
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 321us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.408936
last_received_ts = 206.408371
last_seq = 402
current_ts = 206.425598
current_received_ts = 206.425095
current_seq = 403
count = 399
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 309us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.425598
last_received_ts = 206.425095
last_seq = 403
current_ts = 206.442261
current_received_ts = 206.441742
current_seq = 404
count = 400
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 297us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.442261
last_received_ts = 206.441742
last_seq = 404
current_ts = 206.458939
current_received_ts = 206.458405
current_seq = 405
count = 401
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 53us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.458939
last_received_ts = 206.458405
last_seq = 405
current_ts = 206.475601
current_received_ts = 206.475128
current_seq = 406
count = 402
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 53us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.475601
last_received_ts = 206.475128
last_seq = 406
current_ts = 206.492264
current_received_ts = 206.491714
current_seq = 407
count = 403
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 318us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.492264
last_received_ts = 206.491714
last_seq = 407
current_ts = 206.508926
current_received_ts = 206.508423
current_seq = 408
count = 404
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 410us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.508926
last_received_ts = 206.508423
last_seq = 408
current_ts = 206.525589
current_received_ts = 206.525085
current_seq = 409
count = 405
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 311us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.525589
last_received_ts = 206.525085
last_seq = 409
current_ts = 206.542267
current_received_ts = 206.541702
current_seq = 410
count = 406
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 315us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.542267
last_received_ts = 206.541702
last_seq = 410
current_ts = 206.558929
current_received_ts = 206.558441
current_seq = 411
count = 407
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 446us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.558929
last_received_ts = 206.558441
last_seq = 411
current_ts = 206.575592
current_received_ts = 206.575104
current_seq = 412
count = 408
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 311us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.575592
last_received_ts = 206.575104
last_seq = 412
current_ts = 206.592255
current_received_ts = 206.591721
current_seq = 413
count = 409
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 307us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.592255
last_received_ts = 206.591721
last_seq = 413
current_ts = 206.608917
current_received_ts = 206.608414
current_seq = 414
count = 410
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 395us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.608917
last_received_ts = 206.608414
last_seq = 414
current_ts = 206.625580
current_received_ts = 206.625092
current_seq = 415
count = 411
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 220us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.625580
last_received_ts = 206.625092
last_seq = 415
current_ts = 206.642258
current_received_ts = 206.641708
current_seq = 416
count = 412
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 324us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.642258
last_received_ts = 206.641708
last_seq = 416
current_ts = 206.658920
current_received_ts = 206.658386
current_seq = 417
count = 413
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 115us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.658920
last_received_ts = 206.658386
last_seq = 417
current_ts = 206.675583
current_received_ts = 206.675079
current_seq = 418
count = 414
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 461us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.675583
last_received_ts = 206.675079
last_seq = 418
current_ts = 206.692245
current_received_ts = 206.691681
current_seq = 419
count = 415
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 377us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.692245
last_received_ts = 206.691681
last_seq = 419
current_ts = 206.708908
current_received_ts = 206.708389
current_seq = 420
count = 416
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 57us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.708908
last_received_ts = 206.708389
last_seq = 420
current_ts = 206.725571
current_received_ts = 206.725113
current_seq = 421
count = 417
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 453us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.725571
last_received_ts = 206.725113
last_seq = 421
current_ts = 206.742233
current_received_ts = 206.741714
current_seq = 422
count = 418
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 247us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.742233
last_received_ts = 206.741714
last_seq = 422
current_ts = 206.758911
current_received_ts = 206.758408
current_seq = 423
count = 419
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 437us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.758911
last_received_ts = 206.758408
last_seq = 423
current_ts = 206.775574
current_received_ts = 206.775085
current_seq = 424
count = 420
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 333us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.775574
last_received_ts = 206.775085
last_seq = 424
current_ts = 206.792236
current_received_ts = 206.791687
current_seq = 425
count = 421
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 345us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.792236
last_received_ts = 206.791687
last_seq = 425
current_ts = 206.808899
current_received_ts = 206.808395
current_seq = 426
count = 422
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 254us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.808899
last_received_ts = 206.808395
last_seq = 426
current_ts = 206.825562
current_received_ts = 206.825073
current_seq = 427
count = 423
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 293us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.825562
last_received_ts = 206.825073
last_seq = 427
current_ts = 206.842239
current_received_ts = 206.841675
current_seq = 428
count = 424
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 356us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.842239
last_received_ts = 206.841675
last_seq = 428
current_ts = 206.858887
current_received_ts = 206.858398
current_seq = 429
count = 425
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 467us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.858887
last_received_ts = 206.858398
last_seq = 429
current_ts = 206.875565
current_received_ts = 206.875092
current_seq = 430
count = 426
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 433us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.875565
last_received_ts = 206.875092
last_seq = 430
current_ts = 206.892227
current_received_ts = 206.891693
current_seq = 431
count = 427
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 351us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.892227
last_received_ts = 206.891693
last_seq = 431
current_ts = 206.908890
current_received_ts = 206.908371
current_seq = 432
count = 428
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 53us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.908890
last_received_ts = 206.908371
last_seq = 432
current_ts = 206.925552
current_received_ts = 206.925064
current_seq = 433
count = 429
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 459us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.925552
last_received_ts = 206.925064
last_seq = 433
current_ts = 206.942215
current_received_ts = 206.941666
current_seq = 434
count = 430
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 276us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.942215
last_received_ts = 206.941666
last_seq = 434
current_ts = 206.958893
current_received_ts = 206.958420
current_seq = 435
count = 431
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 343us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.958893
last_received_ts = 206.958420
last_seq = 435
current_ts = 206.975540
current_received_ts = 206.975082
current_seq = 436
count = 432
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 335us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.975540
last_received_ts = 206.975082
last_seq = 436
current_ts = 206.992218
current_received_ts = 206.991699
current_seq = 437
count = 433
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 338us
(kms_flip:2909) DEBUG: name = flip
last_ts = 206.992218
last_received_ts = 206.991699
last_seq = 437
current_ts = 207.008881
current_received_ts = 207.008362
current_seq = 438
count = 434
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 50us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.008881
last_received_ts = 207.008362
last_seq = 438
current_ts = 207.025543
current_received_ts = 207.025055
current_seq = 439
count = 435
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 329us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.025543
last_received_ts = 207.025055
last_seq = 439
current_ts = 207.042206
current_received_ts = 207.041687
current_seq = 440
count = 436
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 333us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.042206
last_received_ts = 207.041687
last_seq = 440
current_ts = 207.058868
current_received_ts = 207.058350
current_seq = 441
count = 437
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 52us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.058868
last_received_ts = 207.058350
last_seq = 441
current_ts = 207.075531
current_received_ts = 207.075058
current_seq = 442
count = 438
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 263us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.075531
last_received_ts = 207.075058
last_seq = 442
current_ts = 207.092209
current_received_ts = 207.091644
current_seq = 443
count = 439
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 429us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.092209
last_received_ts = 207.091644
last_seq = 443
current_ts = 207.108871
current_received_ts = 207.108353
current_seq = 444
count = 440
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.108871
last_received_ts = 207.108353
last_seq = 444
current_ts = 207.125534
current_received_ts = 207.125061
current_seq = 445
count = 441
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 295us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.125534
last_received_ts = 207.125061
last_seq = 445
current_ts = 207.142197
current_received_ts = 207.141647
current_seq = 446
count = 442
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 306us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.142197
last_received_ts = 207.141647
last_seq = 446
current_ts = 207.158859
current_received_ts = 207.158371
current_seq = 447
count = 443
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 378us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.158859
last_received_ts = 207.158371
last_seq = 447
current_ts = 207.175522
current_received_ts = 207.175034
current_seq = 448
count = 444
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 438us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.175522
last_received_ts = 207.175034
last_seq = 448
current_ts = 207.192200
current_received_ts = 207.191635
current_seq = 449
count = 445
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 377us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.192200
last_received_ts = 207.191635
last_seq = 449
current_ts = 207.208862
current_received_ts = 207.208374
current_seq = 450
count = 446
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 430us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.208862
last_received_ts = 207.208374
last_seq = 450
current_ts = 207.225525
current_received_ts = 207.225067
current_seq = 451
count = 447
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 456us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.225525
last_received_ts = 207.225067
last_seq = 451
current_ts = 207.242188
current_received_ts = 207.241653
current_seq = 452
count = 448
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 372us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.242188
last_received_ts = 207.241653
last_seq = 452
current_ts = 207.258850
current_received_ts = 207.258316
current_seq = 453
count = 449
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 51us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.258850
last_received_ts = 207.258316
last_seq = 453
current_ts = 207.275513
current_received_ts = 207.274979
current_seq = 454
count = 450
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 423us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.275513
last_received_ts = 207.274979
last_seq = 454
current_ts = 207.292191
current_received_ts = 207.291641
current_seq = 455
count = 451
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 407us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.292191
last_received_ts = 207.291641
last_seq = 455
current_ts = 207.308838
current_received_ts = 207.308304
current_seq = 456
count = 452
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.308838
last_received_ts = 207.308304
last_seq = 456
current_ts = 207.325516
current_received_ts = 207.324997
current_seq = 457
count = 453
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 240us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.325516
last_received_ts = 207.324997
last_seq = 457
current_ts = 207.342178
current_received_ts = 207.341629
current_seq = 458
count = 454
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 391us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.342178
last_received_ts = 207.341629
last_seq = 458
current_ts = 207.358841
current_received_ts = 207.358322
current_seq = 459
count = 455
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 260us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.358841
last_received_ts = 207.358322
last_seq = 459
current_ts = 207.375504
current_received_ts = 207.375046
current_seq = 460
count = 456
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 410us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.375504
last_received_ts = 207.375046
last_seq = 460
current_ts = 207.392166
current_received_ts = 207.391632
current_seq = 461
count = 457
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 398us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.392166
last_received_ts = 207.391632
last_seq = 461
current_ts = 207.408844
current_received_ts = 207.408325
current_seq = 462
count = 458
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 317us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.408844
last_received_ts = 207.408325
last_seq = 462
current_ts = 207.425507
current_received_ts = 207.424988
current_seq = 463
count = 459
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 344us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.425507
last_received_ts = 207.424988
last_seq = 463
current_ts = 207.442169
current_received_ts = 207.441620
current_seq = 464
count = 460
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 410us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.442169
last_received_ts = 207.441620
last_seq = 464
current_ts = 207.458832
current_received_ts = 207.458313
current_seq = 465
count = 461
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 51us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.458832
last_received_ts = 207.458313
last_seq = 465
current_ts = 207.475494
current_received_ts = 207.474960
current_seq = 466
count = 462
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 288us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.475494
last_received_ts = 207.474960
last_seq = 466
current_ts = 207.492157
current_received_ts = 207.491608
current_seq = 467
count = 463
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 437us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.492157
last_received_ts = 207.491608
last_seq = 467
current_ts = 207.508835
current_received_ts = 207.508331
current_seq = 468
count = 464
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 347us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.508835
last_received_ts = 207.508331
last_seq = 468
current_ts = 207.525497
current_received_ts = 207.524963
current_seq = 469
count = 465
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 182us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.525497
last_received_ts = 207.524963
last_seq = 469
current_ts = 207.542160
current_received_ts = 207.541611
current_seq = 470
count = 466
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 315us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.542160
last_received_ts = 207.541611
last_seq = 470
current_ts = 207.558823
current_received_ts = 207.558304
current_seq = 471
count = 467
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 50us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.558823
last_received_ts = 207.558304
last_seq = 471
current_ts = 207.575485
current_received_ts = 207.574966
current_seq = 472
count = 468
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 330us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.575485
last_received_ts = 207.574966
last_seq = 472
current_ts = 207.592148
current_received_ts = 207.591599
current_seq = 473
count = 469
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 299us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.592148
last_received_ts = 207.591599
last_seq = 473
current_ts = 207.608810
current_received_ts = 207.608215
current_seq = 474
count = 470
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.608810
last_received_ts = 207.608215
last_seq = 474
current_ts = 207.625488
current_received_ts = 207.624954
current_seq = 475
count = 471
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 139us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.625488
last_received_ts = 207.624954
last_seq = 475
current_ts = 207.642151
current_received_ts = 207.641586
current_seq = 476
count = 472
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 437us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.642151
last_received_ts = 207.641586
last_seq = 476
current_ts = 207.658813
current_received_ts = 207.658295
current_seq = 477
count = 473
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 490us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.658813
last_received_ts = 207.658295
last_seq = 477
current_ts = 207.675476
current_received_ts = 207.674973
current_seq = 478
count = 474
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 383us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.675476
last_received_ts = 207.674973
last_seq = 478
current_ts = 207.692139
current_received_ts = 207.691605
current_seq = 479
count = 475
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 427us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.692139
last_received_ts = 207.691605
last_seq = 479
current_ts = 207.708801
current_received_ts = 207.708206
current_seq = 480
count = 476
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 50us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.708801
last_received_ts = 207.708206
last_seq = 480
current_ts = 207.725464
current_received_ts = 207.724976
current_seq = 481
count = 477
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 347us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.725464
last_received_ts = 207.724976
last_seq = 481
current_ts = 207.742142
current_received_ts = 207.741577
current_seq = 482
count = 478
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 388us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.742142
last_received_ts = 207.741577
last_seq = 482
current_ts = 207.758804
current_received_ts = 207.758286
current_seq = 483
count = 479
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 247us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.758804
last_received_ts = 207.758286
last_seq = 483
current_ts = 207.775467
current_received_ts = 207.774948
current_seq = 484
count = 480
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 241us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.775467
last_received_ts = 207.774948
last_seq = 484
current_ts = 207.792130
current_received_ts = 207.791595
current_seq = 485
count = 481
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 336us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.792130
last_received_ts = 207.791595
last_seq = 485
current_ts = 207.808792
current_received_ts = 207.808273
current_seq = 486
count = 482
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 387us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.808792
last_received_ts = 207.808273
last_seq = 486
current_ts = 207.825455
current_received_ts = 207.824951
current_seq = 487
count = 483
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 123us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.825455
last_received_ts = 207.824951
last_seq = 487
current_ts = 207.842133
current_received_ts = 207.841568
current_seq = 488
count = 484
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 447us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.842133
last_received_ts = 207.841568
last_seq = 488
current_ts = 207.858795
current_received_ts = 207.858292
current_seq = 489
count = 485
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 417us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.858795
last_received_ts = 207.858292
last_seq = 489
current_ts = 207.875458
current_received_ts = 207.874939
current_seq = 490
count = 486
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 129us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.875458
last_received_ts = 207.874939
last_seq = 490
current_ts = 207.892120
current_received_ts = 207.891556
current_seq = 491
count = 487
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 469us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.892120
last_received_ts = 207.891556
last_seq = 491
current_ts = 207.908783
current_received_ts = 207.908203
current_seq = 492
count = 488
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 53us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.908783
last_received_ts = 207.908203
last_seq = 492
current_ts = 207.925446
current_received_ts = 207.924957
current_seq = 493
count = 489
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 108us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.925446
last_received_ts = 207.924957
last_seq = 493
current_ts = 207.942108
current_received_ts = 207.941544
current_seq = 494
count = 490
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 409us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.942108
last_received_ts = 207.941544
last_seq = 494
current_ts = 207.958771
current_received_ts = 207.958191
current_seq = 495
count = 491
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 50us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.958771
last_received_ts = 207.958191
last_seq = 495
current_ts = 207.975449
current_received_ts = 207.974945
current_seq = 496
count = 492
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 127us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.975449
last_received_ts = 207.974945
last_seq = 496
current_ts = 207.992111
current_received_ts = 207.991592
current_seq = 497
count = 493
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 424us
(kms_flip:2909) DEBUG: name = flip
last_ts = 207.992111
last_received_ts = 207.991592
last_seq = 497
current_ts = 208.008774
current_received_ts = 208.008194
current_seq = 498
count = 494
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 208.008774
last_received_ts = 208.008194
last_seq = 498
current_ts = 208.025436
current_received_ts = 208.024918
current_seq = 499
count = 495
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 515us
(kms_flip:2909) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2909) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2909) igt_core-INFO: Stack trace:
(kms_flip:2909) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2909) igt_core-INFO:   #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
(kms_flip:2909) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2909) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2909) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2909) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2909) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2909) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (9.808s)
Starting dynamic subtest: C-eDP1
(kms_flip:2909) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2909) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest C-eDP1 failed.
**** DEBUG ****
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.313004
last_received_ts = 216.312485
last_seq = 413
current_ts = 216.329666
current_received_ts = 216.329163
current_seq = 414
count = 410
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.329666
last_received_ts = 216.329163
last_seq = 414
current_ts = 216.346329
current_received_ts = 216.345810
current_seq = 415
count = 411
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 50us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.346329
last_received_ts = 216.345810
last_seq = 415
current_ts = 216.363007
current_received_ts = 216.362457
current_seq = 416
count = 412
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.363007
last_received_ts = 216.362457
last_seq = 416
current_ts = 216.379669
current_received_ts = 216.379166
current_seq = 417
count = 413
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 52us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.379669
last_received_ts = 216.379166
last_seq = 417
current_ts = 216.396332
current_received_ts = 216.395813
current_seq = 418
count = 414
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.396332
last_received_ts = 216.395813
last_seq = 418
current_ts = 216.412994
current_received_ts = 216.412460
current_seq = 419
count = 415
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.412994
last_received_ts = 216.412460
last_seq = 419
current_ts = 216.429657
current_received_ts = 216.429153
current_seq = 420
count = 416
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 53us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.429657
last_received_ts = 216.429153
last_seq = 420
current_ts = 216.446320
current_received_ts = 216.445831
current_seq = 421
count = 417
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 51us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.446320
last_received_ts = 216.445831
last_seq = 421
current_ts = 216.462997
current_received_ts = 216.462448
current_seq = 422
count = 418
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.462997
last_received_ts = 216.462448
last_seq = 422
current_ts = 216.479660
current_received_ts = 216.479156
current_seq = 423
count = 419
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 56us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.479660
last_received_ts = 216.479156
last_seq = 423
current_ts = 216.496323
current_received_ts = 216.495804
current_seq = 424
count = 420
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 51us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.496323
last_received_ts = 216.495804
last_seq = 424
current_ts = 216.512985
current_received_ts = 216.512421
current_seq = 425
count = 421
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.512985
last_received_ts = 216.512421
last_seq = 425
current_ts = 216.529648
current_received_ts = 216.529129
current_seq = 426
count = 422
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 52us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.529648
last_received_ts = 216.529129
last_seq = 426
current_ts = 216.546310
current_received_ts = 216.545792
current_seq = 427
count = 423
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 56us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.546310
last_received_ts = 216.545792
last_seq = 427
current_ts = 216.562973
current_received_ts = 216.562439
current_seq = 428
count = 424
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 56us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.562973
last_received_ts = 216.562439
last_seq = 428
current_ts = 216.579651
current_received_ts = 216.579117
current_seq = 429
count = 425
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.579651
last_received_ts = 216.579117
last_seq = 429
current_ts = 216.596313
current_received_ts = 216.595779
current_seq = 430
count = 426
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 56us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.596313
last_received_ts = 216.595779
last_seq = 430
current_ts = 216.612976
current_received_ts = 216.612396
current_seq = 431
count = 427
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 56us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.612976
last_received_ts = 216.612396
last_seq = 431
current_ts = 216.629639
current_received_ts = 216.629120
current_seq = 432
count = 428
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.629639
last_received_ts = 216.629120
last_seq = 432
current_ts = 216.646301
current_received_ts = 216.645782
current_seq = 433
count = 429
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.646301
last_received_ts = 216.645782
last_seq = 433
current_ts = 216.662964
current_received_ts = 216.662415
current_seq = 434
count = 430
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.662964
last_received_ts = 216.662415
last_seq = 434
current_ts = 216.679626
current_received_ts = 216.679108
current_seq = 435
count = 431
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 57us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.679626
last_received_ts = 216.679108
last_seq = 435
current_ts = 216.696304
current_received_ts = 216.695755
current_seq = 436
count = 432
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.696304
last_received_ts = 216.695755
last_seq = 436
current_ts = 216.712967
current_received_ts = 216.712387
current_seq = 437
count = 433
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.712967
last_received_ts = 216.712387
last_seq = 437
current_ts = 216.729630
current_received_ts = 216.729095
current_seq = 438
count = 434
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 52us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.729630
last_received_ts = 216.729095
last_seq = 438
current_ts = 216.746292
current_received_ts = 216.745773
current_seq = 439
count = 435
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.746292
last_received_ts = 216.745773
last_seq = 439
current_ts = 216.762955
current_received_ts = 216.762375
current_seq = 440
count = 436
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.762955
last_received_ts = 216.762375
last_seq = 440
current_ts = 216.779617
current_received_ts = 216.779114
current_seq = 441
count = 437
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.779617
last_received_ts = 216.779114
last_seq = 441
current_ts = 216.796295
current_received_ts = 216.795761
current_seq = 442
count = 438
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 56us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.796295
last_received_ts = 216.795761
last_seq = 442
current_ts = 216.812958
current_received_ts = 216.812408
current_seq = 443
count = 439
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.812958
last_received_ts = 216.812408
last_seq = 443
current_ts = 216.829620
current_received_ts = 216.829086
current_seq = 444
count = 440
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.829620
last_received_ts = 216.829086
last_seq = 444
current_ts = 216.846283
current_received_ts = 216.845749
current_seq = 445
count = 441
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 56us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.846283
last_received_ts = 216.845749
last_seq = 445
current_ts = 216.862946
current_received_ts = 216.862427
current_seq = 446
count = 442
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 292us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.862946
last_received_ts = 216.862427
last_seq = 446
current_ts = 216.879608
current_received_ts = 216.879105
current_seq = 447
count = 443
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 435us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.879608
last_received_ts = 216.879105
last_seq = 447
current_ts = 216.896271
current_received_ts = 216.895721
current_seq = 448
count = 444
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 309us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.896271
last_received_ts = 216.895721
last_seq = 448
current_ts = 216.912933
current_received_ts = 216.912384
current_seq = 449
count = 445
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 236us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.912933
last_received_ts = 216.912384
last_seq = 449
current_ts = 216.929611
current_received_ts = 216.929092
current_seq = 450
count = 446
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 118us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.929611
last_received_ts = 216.929092
last_seq = 450
current_ts = 216.946274
current_received_ts = 216.945709
current_seq = 451
count = 447
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 323us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.946274
last_received_ts = 216.945709
last_seq = 451
current_ts = 216.962936
current_received_ts = 216.962387
current_seq = 452
count = 448
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.962936
last_received_ts = 216.962387
last_seq = 452
current_ts = 216.979599
current_received_ts = 216.979095
current_seq = 453
count = 449
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 314us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.979599
last_received_ts = 216.979095
last_seq = 453
current_ts = 216.996262
current_received_ts = 216.995728
current_seq = 454
count = 450
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 298us
(kms_flip:2909) DEBUG: name = flip
last_ts = 216.996262
last_received_ts = 216.995728
last_seq = 454
current_ts = 217.012924
current_received_ts = 217.012421
current_seq = 455
count = 451
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 418us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.012924
last_received_ts = 217.012421
last_seq = 455
current_ts = 217.029602
current_received_ts = 217.029083
current_seq = 456
count = 452
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 391us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.029602
last_received_ts = 217.029083
last_seq = 456
current_ts = 217.046265
current_received_ts = 217.045700
current_seq = 457
count = 453
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 327us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.046265
last_received_ts = 217.045700
last_seq = 457
current_ts = 217.062927
current_received_ts = 217.062424
current_seq = 458
count = 454
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 320us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.062927
last_received_ts = 217.062424
last_seq = 458
current_ts = 217.079590
current_received_ts = 217.079086
current_seq = 459
count = 455
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 235us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.079590
last_received_ts = 217.079086
last_seq = 459
current_ts = 217.096252
current_received_ts = 217.095703
current_seq = 460
count = 456
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 330us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.096252
last_received_ts = 217.095703
last_seq = 460
current_ts = 217.112915
current_received_ts = 217.112366
current_seq = 461
count = 457
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 150us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.112915
last_received_ts = 217.112366
last_seq = 461
current_ts = 217.129578
current_received_ts = 217.129089
current_seq = 462
count = 458
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 459us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.129578
last_received_ts = 217.129089
last_seq = 462
current_ts = 217.146240
current_received_ts = 217.145721
current_seq = 463
count = 459
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 309us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.146240
last_received_ts = 217.145721
last_seq = 463
current_ts = 217.162918
current_received_ts = 217.162369
current_seq = 464
count = 460
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 248us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.162918
last_received_ts = 217.162369
last_seq = 464
current_ts = 217.179581
current_received_ts = 217.179092
current_seq = 465
count = 461
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 460us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.179581
last_received_ts = 217.179092
last_seq = 465
current_ts = 217.196243
current_received_ts = 217.195679
current_seq = 466
count = 462
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 354us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.196243
last_received_ts = 217.195679
last_seq = 466
current_ts = 217.212906
current_received_ts = 217.212402
current_seq = 467
count = 463
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 482us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.212906
last_received_ts = 217.212402
last_seq = 467
current_ts = 217.229568
current_received_ts = 217.229065
current_seq = 468
count = 464
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 393us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.229568
last_received_ts = 217.229065
last_seq = 468
current_ts = 217.246231
current_received_ts = 217.245697
current_seq = 469
count = 465
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 346us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.246231
last_received_ts = 217.245697
last_seq = 469
current_ts = 217.262909
current_received_ts = 217.262405
current_seq = 470
count = 466
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 341us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.262909
last_received_ts = 217.262405
last_seq = 470
current_ts = 217.279572
current_received_ts = 217.279068
current_seq = 471
count = 467
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 404us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.279572
last_received_ts = 217.279068
last_seq = 471
current_ts = 217.296234
current_received_ts = 217.295715
current_seq = 472
count = 468
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 325us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.296234
last_received_ts = 217.295715
last_seq = 472
current_ts = 217.312897
current_received_ts = 217.312363
current_seq = 473
count = 469
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 144us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.312897
last_received_ts = 217.312363
last_seq = 473
current_ts = 217.329559
current_received_ts = 217.329071
current_seq = 474
count = 470
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 428us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.329559
last_received_ts = 217.329071
last_seq = 474
current_ts = 217.346222
current_received_ts = 217.345657
current_seq = 475
count = 471
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 378us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.346222
last_received_ts = 217.345657
last_seq = 475
current_ts = 217.362885
current_received_ts = 217.362350
current_seq = 476
count = 472
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 51us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.362885
last_received_ts = 217.362350
last_seq = 476
current_ts = 217.379547
current_received_ts = 217.379059
current_seq = 477
count = 473
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 493us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.379547
last_received_ts = 217.379059
last_seq = 477
current_ts = 217.396225
current_received_ts = 217.395660
current_seq = 478
count = 474
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 374us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.396225
last_received_ts = 217.395660
last_seq = 478
current_ts = 217.412888
current_received_ts = 217.412369
current_seq = 479
count = 475
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 171us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.412888
last_received_ts = 217.412369
last_seq = 479
current_ts = 217.429550
current_received_ts = 217.429047
current_seq = 480
count = 476
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 238us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.429550
last_received_ts = 217.429047
last_seq = 480
current_ts = 217.446213
current_received_ts = 217.445663
current_seq = 481
count = 477
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 385us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.446213
last_received_ts = 217.445663
last_seq = 481
current_ts = 217.462875
current_received_ts = 217.462418
current_seq = 482
count = 478
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 279us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.462875
last_received_ts = 217.462418
last_seq = 482
current_ts = 217.479538
current_received_ts = 217.479050
current_seq = 483
count = 479
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 332us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.479538
last_received_ts = 217.479050
last_seq = 483
current_ts = 217.496216
current_received_ts = 217.495636
current_seq = 484
count = 480
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 386us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.496216
last_received_ts = 217.495636
last_seq = 484
current_ts = 217.512878
current_received_ts = 217.512405
current_seq = 485
count = 481
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 264us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.512878
last_received_ts = 217.512405
last_seq = 485
current_ts = 217.529541
current_received_ts = 217.529037
current_seq = 486
count = 482
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 463us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.529541
last_received_ts = 217.529037
last_seq = 486
current_ts = 217.546204
current_received_ts = 217.545639
current_seq = 487
count = 483
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 399us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.546204
last_received_ts = 217.545639
last_seq = 487
current_ts = 217.562866
current_received_ts = 217.562363
current_seq = 488
count = 484
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 461us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.562866
last_received_ts = 217.562363
last_seq = 488
current_ts = 217.579529
current_received_ts = 217.579041
current_seq = 489
count = 485
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 466us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.579529
last_received_ts = 217.579041
last_seq = 489
current_ts = 217.596191
current_received_ts = 217.595642
current_seq = 490
count = 486
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 387us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.596191
last_received_ts = 217.595642
last_seq = 490
current_ts = 217.612869
current_received_ts = 217.612381
current_seq = 491
count = 487
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 448us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.612869
last_received_ts = 217.612381
last_seq = 491
current_ts = 217.629532
current_received_ts = 217.629074
current_seq = 492
count = 488
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 352us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.629532
last_received_ts = 217.629074
last_seq = 492
current_ts = 217.646194
current_received_ts = 217.645645
current_seq = 493
count = 489
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 391us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.646194
last_received_ts = 217.645645
last_seq = 493
current_ts = 217.662857
current_received_ts = 217.662338
current_seq = 494
count = 490
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 122us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.662857
last_received_ts = 217.662338
last_seq = 494
current_ts = 217.679520
current_received_ts = 217.678986
current_seq = 495
count = 491
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 283us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.679520
last_received_ts = 217.678986
last_seq = 495
current_ts = 217.696182
current_received_ts = 217.695633
current_seq = 496
count = 492
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 397us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.696182
last_received_ts = 217.695633
last_seq = 496
current_ts = 217.712845
current_received_ts = 217.712387
current_seq = 497
count = 493
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 262us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.712845
last_received_ts = 217.712387
last_seq = 497
current_ts = 217.729523
current_received_ts = 217.729034
current_seq = 498
count = 494
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 435us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.729523
last_received_ts = 217.729034
last_seq = 498
current_ts = 217.746185
current_received_ts = 217.745621
current_seq = 499
count = 495
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 339us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.746185
last_received_ts = 217.745621
last_seq = 499
current_ts = 217.762848
current_received_ts = 217.762329
current_seq = 500
count = 496
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 56us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.762848
last_received_ts = 217.762329
last_seq = 500
current_ts = 217.779510
current_received_ts = 217.778976
current_seq = 501
count = 497
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 410us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.779510
last_received_ts = 217.778976
last_seq = 501
current_ts = 217.796173
current_received_ts = 217.795609
current_seq = 502
count = 498
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 318us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.796173
last_received_ts = 217.795609
last_seq = 502
current_ts = 217.812836
current_received_ts = 217.812317
current_seq = 503
count = 499
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 459us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.812836
last_received_ts = 217.812317
last_seq = 503
current_ts = 217.829498
current_received_ts = 217.829056
current_seq = 504
count = 500
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 333us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.829498
last_received_ts = 217.829056
last_seq = 504
current_ts = 217.846161
current_received_ts = 217.845612
current_seq = 505
count = 501
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 349us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.846161
last_received_ts = 217.845612
last_seq = 505
current_ts = 217.862839
current_received_ts = 217.862213
current_seq = 506
count = 502
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.862839
last_received_ts = 217.862213
last_seq = 506
current_ts = 217.879501
current_received_ts = 217.878967
current_seq = 507
count = 503
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 363us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.879501
last_received_ts = 217.878967
last_seq = 507
current_ts = 217.896164
current_received_ts = 217.895599
current_seq = 508
count = 504
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 429us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.896164
last_received_ts = 217.895599
last_seq = 508
current_ts = 217.912827
current_received_ts = 217.912308
current_seq = 509
count = 505
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 350us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.912827
last_received_ts = 217.912308
last_seq = 509
current_ts = 217.929489
current_received_ts = 217.928970
current_seq = 510
count = 506
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 238us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.929489
last_received_ts = 217.928970
last_seq = 510
current_ts = 217.946167
current_received_ts = 217.945602
current_seq = 511
count = 507
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 419us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.946167
last_received_ts = 217.945602
last_seq = 511
current_ts = 217.962830
current_received_ts = 217.962311
current_seq = 512
count = 508
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 229us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.962830
last_received_ts = 217.962311
last_seq = 512
current_ts = 217.979492
current_received_ts = 217.978958
current_seq = 513
count = 509
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 159us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.979492
last_received_ts = 217.978958
last_seq = 513
current_ts = 217.996155
current_received_ts = 217.995605
current_seq = 514
count = 510
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 334us
(kms_flip:2909) DEBUG: name = flip
last_ts = 217.996155
last_received_ts = 217.995605
last_seq = 514
current_ts = 218.012817
current_received_ts = 218.012222
current_seq = 515
count = 511
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 54us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.012817
last_received_ts = 218.012222
last_seq = 515
current_ts = 218.029480
current_received_ts = 218.028961
current_seq = 516
count = 512
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 94us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.029480
last_received_ts = 218.028961
last_seq = 516
current_ts = 218.046143
current_received_ts = 218.045578
current_seq = 517
count = 513
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 307us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.046143
last_received_ts = 218.045578
last_seq = 517
current_ts = 218.062805
current_received_ts = 218.062195
current_seq = 518
count = 514
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 55us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.062805
last_received_ts = 218.062195
last_seq = 518
current_ts = 218.079483
current_received_ts = 218.078934
current_seq = 519
count = 515
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 149us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.079483
last_received_ts = 218.078934
last_seq = 519
current_ts = 218.096146
current_received_ts = 218.095581
current_seq = 520
count = 516
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 451us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.096146
last_received_ts = 218.095581
last_seq = 520
current_ts = 218.112808
current_received_ts = 218.112289
current_seq = 521
count = 517
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 390us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.112808
last_received_ts = 218.112289
last_seq = 521
current_ts = 218.129471
current_received_ts = 218.128967
current_seq = 522
count = 518
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 244us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.129471
last_received_ts = 218.128967
last_seq = 522
current_ts = 218.146133
current_received_ts = 218.145584
current_seq = 523
count = 519
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 380us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.146133
last_received_ts = 218.145584
last_seq = 523
current_ts = 218.162796
current_received_ts = 218.162201
current_seq = 524
count = 520
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 56us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.162796
last_received_ts = 218.162201
last_seq = 524
current_ts = 218.179459
current_received_ts = 218.178940
current_seq = 525
count = 521
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 304us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.179459
last_received_ts = 218.178940
last_seq = 525
current_ts = 218.196136
current_received_ts = 218.195557
current_seq = 526
count = 522
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 356us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.196136
last_received_ts = 218.195557
last_seq = 526
current_ts = 218.212799
current_received_ts = 218.212189
current_seq = 527
count = 523
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 53us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.212799
last_received_ts = 218.212189
last_seq = 527
current_ts = 218.229462
current_received_ts = 218.228943
current_seq = 528
count = 524
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 207us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.229462
last_received_ts = 218.228943
last_seq = 528
current_ts = 218.246124
current_received_ts = 218.245483
current_seq = 529
count = 525
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 52us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.246124
last_received_ts = 218.245483
last_seq = 529
current_ts = 218.262787
current_received_ts = 218.262177
current_seq = 530
count = 526
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 53us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.262787
last_received_ts = 218.262177
last_seq = 530
current_ts = 218.279449
current_received_ts = 218.278915
current_seq = 531
count = 527
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 138us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.279449
last_received_ts = 218.278915
last_seq = 531
current_ts = 218.296127
current_received_ts = 218.295532
current_seq = 532
count = 528
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 405us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.296127
last_received_ts = 218.295532
last_seq = 532
current_ts = 218.312790
current_received_ts = 218.312256
current_seq = 533
count = 529
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 339us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.312790
last_received_ts = 218.312256
last_seq = 533
current_ts = 218.329453
current_received_ts = 218.328918
current_seq = 534
count = 530
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 132us
(kms_flip:2909) DEBUG: name = flip
last_ts = 218.329453
last_received_ts = 218.328918
last_seq = 534
current_ts = 218.346115
current_received_ts = 218.345520
current_seq = 535
count = 531
seq_step = 1
(kms_flip:2909) DEBUG: Vblank took 500us
(kms_flip:2909) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2909) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2909) igt_core-INFO: Stack trace:
(kms_flip:2909) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2909) igt_core-INFO:   #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
(kms_flip:2909) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2909) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2909) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2909) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2909) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2909) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-eDP1: FAIL (10.351s)
Subtest flip-vs-expired-vblank: FAIL (27.910s)
(kms_flip:2909) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:2909) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2909) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2909) igt_kms-CRITICAL: DPMS property not found on 189