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

shard-dg2-433

IGT-Version: 1.29-NO-GIT (x86_64) (Linux: 6.12.0-rc7-xe x86_64)

Using IGT_SRANDOM=1731529594 for randomisation
Opened device: /dev/dri/card1
Using monotonic timestamps
Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-HDMI-A6
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A6: FAIL (2.808s)
Starting dynamic subtest: B-HDMI-A6
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A6: FAIL (0.369s)
Starting dynamic subtest: C-HDMI-A6
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-HDMI-A6: FAIL (0.205s)
Starting dynamic subtest: D-HDMI-A6
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest D-HDMI-A6: FAIL (0.211s)
Starting dynamic subtest: A-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-DP4: FAIL (0.273s)
Starting dynamic subtest: B-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-DP4: FAIL (3.178s)
Starting dynamic subtest: C-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-DP4: FAIL (0.251s)
Starting dynamic subtest: D-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest D-DP4: FAIL (0.527s)
Subtest flip-vs-expired-vblank: FAIL (7.832s)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2234 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2930 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2386 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-HDMI-A6
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest A-HDMI-A6 failed.
**** DEBUG ****
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.309097
last_received_ts = 76.308678
last_seq = 707
current_ts = 76.325768
current_received_ts = 76.325348
current_seq = 708
count = 7
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 231us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.325768
last_received_ts = 76.325348
last_seq = 708
current_ts = 76.342445
current_received_ts = 76.342018
current_seq = 709
count = 8
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.342445
last_received_ts = 76.342018
last_seq = 709
current_ts = 76.359116
current_received_ts = 76.358688
current_seq = 710
count = 9
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 32us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.359116
last_received_ts = 76.358688
last_seq = 710
current_ts = 76.375786
current_received_ts = 76.375366
current_seq = 711
count = 10
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 219us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.375786
last_received_ts = 76.375366
last_seq = 711
current_ts = 76.392464
current_received_ts = 76.392075
current_seq = 712
count = 11
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.392464
last_received_ts = 76.392075
last_seq = 712
current_ts = 76.409134
current_received_ts = 76.408714
current_seq = 713
count = 12
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 32us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.409134
last_received_ts = 76.408714
last_seq = 713
current_ts = 76.425804
current_received_ts = 76.425377
current_seq = 714
count = 13
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.425804
last_received_ts = 76.425377
last_seq = 714
current_ts = 76.442474
current_received_ts = 76.442055
current_seq = 715
count = 14
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 32us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.442474
last_received_ts = 76.442055
last_seq = 715
current_ts = 76.459152
current_received_ts = 76.458725
current_seq = 716
count = 15
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 32us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.459152
last_received_ts = 76.458725
last_seq = 716
current_ts = 76.475822
current_received_ts = 76.475395
current_seq = 717
count = 16
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 32us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.475822
last_received_ts = 76.475395
last_seq = 717
current_ts = 76.492493
current_received_ts = 76.492104
current_seq = 718
count = 17
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.492493
last_received_ts = 76.492104
last_seq = 718
current_ts = 76.509163
current_received_ts = 76.508743
current_seq = 719
count = 18
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 247us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.509163
last_received_ts = 76.508743
last_seq = 719
current_ts = 76.525833
current_received_ts = 76.525414
current_seq = 720
count = 19
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 212us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.525833
last_received_ts = 76.525414
last_seq = 720
current_ts = 76.542511
current_received_ts = 76.542084
current_seq = 721
count = 20
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 217us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.542511
last_received_ts = 76.542084
last_seq = 721
current_ts = 76.559181
current_received_ts = 76.558762
current_seq = 722
count = 21
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 221us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.559181
last_received_ts = 76.558762
last_seq = 722
current_ts = 76.575844
current_received_ts = 76.575439
current_seq = 723
count = 22
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 253us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.575844
last_received_ts = 76.575439
last_seq = 723
current_ts = 76.592522
current_received_ts = 76.592140
current_seq = 724
count = 23
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 32us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.592522
last_received_ts = 76.592140
last_seq = 724
current_ts = 76.609200
current_received_ts = 76.608772
current_seq = 725
count = 24
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 213us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.609200
last_received_ts = 76.608772
last_seq = 725
current_ts = 76.625870
current_received_ts = 76.625443
current_seq = 726
count = 25
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 211us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.625870
last_received_ts = 76.625443
last_seq = 726
current_ts = 76.642540
current_received_ts = 76.642113
current_seq = 727
count = 26
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 212us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.642540
last_received_ts = 76.642113
last_seq = 727
current_ts = 76.659210
current_received_ts = 76.658791
current_seq = 728
count = 27
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 223us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.659210
last_received_ts = 76.658791
last_seq = 728
current_ts = 76.675888
current_received_ts = 76.675461
current_seq = 729
count = 28
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 220us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.675888
last_received_ts = 76.675461
last_seq = 729
current_ts = 76.692558
current_received_ts = 76.692162
current_seq = 730
count = 29
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 272us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.692558
last_received_ts = 76.692162
last_seq = 730
current_ts = 76.709229
current_received_ts = 76.708794
current_seq = 731
count = 30
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 244us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.709229
last_received_ts = 76.708794
last_seq = 731
current_ts = 76.725899
current_received_ts = 76.725464
current_seq = 732
count = 31
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 299us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.725899
last_received_ts = 76.725464
last_seq = 732
current_ts = 76.742577
current_received_ts = 76.742134
current_seq = 733
count = 32
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 245us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.742577
last_received_ts = 76.742134
last_seq = 733
current_ts = 76.759247
current_received_ts = 76.758804
current_seq = 734
count = 33
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 276us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.759247
last_received_ts = 76.758804
last_seq = 734
current_ts = 76.775917
current_received_ts = 76.775490
current_seq = 735
count = 34
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 234us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.775917
last_received_ts = 76.775490
last_seq = 735
current_ts = 76.792587
current_received_ts = 76.792183
current_seq = 736
count = 35
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 211us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.792587
last_received_ts = 76.792183
last_seq = 736
current_ts = 76.809265
current_received_ts = 76.808838
current_seq = 737
count = 36
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 212us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.809265
last_received_ts = 76.808838
last_seq = 737
current_ts = 76.825935
current_received_ts = 76.825500
current_seq = 738
count = 37
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.825935
last_received_ts = 76.825500
last_seq = 738
current_ts = 76.842606
current_received_ts = 76.842178
current_seq = 739
count = 38
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 231us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.842606
last_received_ts = 76.842178
last_seq = 739
current_ts = 76.859276
current_received_ts = 76.858856
current_seq = 740
count = 39
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 212us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.859276
last_received_ts = 76.858856
last_seq = 740
current_ts = 76.875954
current_received_ts = 76.875526
current_seq = 741
count = 40
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 243us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.875954
last_received_ts = 76.875526
last_seq = 741
current_ts = 76.892624
current_received_ts = 76.892197
current_seq = 742
count = 41
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 274us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.892624
last_received_ts = 76.892197
last_seq = 742
current_ts = 76.909294
current_received_ts = 76.908859
current_seq = 743
count = 42
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 246us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.909294
last_received_ts = 76.908859
last_seq = 743
current_ts = 76.925964
current_received_ts = 76.925529
current_seq = 744
count = 43
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 276us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.925964
last_received_ts = 76.925529
last_seq = 744
current_ts = 76.942635
current_received_ts = 76.943604
current_seq = 745
count = 44
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 22us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.942635
last_received_ts = 76.943604
last_seq = 745
current_ts = 76.959312
current_received_ts = 76.958687
current_seq = 746
count = 45
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 191us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.959312
last_received_ts = 76.958687
last_seq = 746
current_ts = 76.975990
current_received_ts = 76.975372
current_seq = 747
count = 46
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 189us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.975990
last_received_ts = 76.975372
last_seq = 747
current_ts = 76.992661
current_received_ts = 76.992050
current_seq = 748
count = 47
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 196us
(kms_flip:2250) DEBUG: name = flip
last_ts = 76.992661
last_received_ts = 76.992050
last_seq = 748
current_ts = 77.009323
current_received_ts = 77.008995
current_seq = 749
count = 48
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 51us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.009323
last_received_ts = 77.008995
last_seq = 749
current_ts = 77.025993
current_received_ts = 77.025459
current_seq = 750
count = 49
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 15us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.025993
last_received_ts = 77.025459
last_seq = 750
current_ts = 77.042664
current_received_ts = 77.042130
current_seq = 751
count = 50
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 30us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.042664
last_received_ts = 77.042130
last_seq = 751
current_ts = 77.059341
current_received_ts = 77.058823
current_seq = 752
count = 51
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 22us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.059341
last_received_ts = 77.058823
last_seq = 752
current_ts = 77.076012
current_received_ts = 77.075546
current_seq = 753
count = 52
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 34us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.076012
last_received_ts = 77.075546
last_seq = 753
current_ts = 77.092697
current_received_ts = 77.092293
current_seq = 754
count = 53
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 214us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.092697
last_received_ts = 77.092293
last_seq = 754
current_ts = 77.109360
current_received_ts = 77.108887
current_seq = 755
count = 54
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 34us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.109360
last_received_ts = 77.108887
last_seq = 755
current_ts = 77.126030
current_received_ts = 77.125565
current_seq = 756
count = 55
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 32us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.126030
last_received_ts = 77.125565
last_seq = 756
current_ts = 77.142700
current_received_ts = 77.142235
current_seq = 757
count = 56
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.142700
last_received_ts = 77.142235
last_seq = 757
current_ts = 77.159370
current_received_ts = 77.158905
current_seq = 758
count = 57
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.159370
last_received_ts = 77.158905
last_seq = 758
current_ts = 77.176048
current_received_ts = 77.175575
current_seq = 759
count = 58
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.176048
last_received_ts = 77.175575
last_seq = 759
current_ts = 77.192726
current_received_ts = 77.192322
current_seq = 760
count = 59
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 250us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.192726
last_received_ts = 77.192322
last_seq = 760
current_ts = 77.209389
current_received_ts = 77.208969
current_seq = 761
count = 60
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 254us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.209389
last_received_ts = 77.208969
last_seq = 761
current_ts = 77.226067
current_received_ts = 77.225655
current_seq = 762
count = 61
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 272us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.226067
last_received_ts = 77.225655
last_seq = 762
current_ts = 77.242737
current_received_ts = 77.242317
current_seq = 763
count = 62
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 218us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.242737
last_received_ts = 77.242317
last_seq = 763
current_ts = 77.259399
current_received_ts = 77.258987
current_seq = 764
count = 63
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 252us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.259399
last_received_ts = 77.258987
last_seq = 764
current_ts = 77.276077
current_received_ts = 77.275658
current_seq = 765
count = 64
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 217us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.276077
last_received_ts = 77.275658
last_seq = 765
current_ts = 77.292755
current_received_ts = 77.292290
current_seq = 766
count = 65
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 263us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.292755
last_received_ts = 77.292290
last_seq = 766
current_ts = 77.309418
current_received_ts = 77.309006
current_seq = 767
count = 66
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 215us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.309418
last_received_ts = 77.309006
last_seq = 767
current_ts = 77.326096
current_received_ts = 77.325676
current_seq = 768
count = 67
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 272us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.326096
last_received_ts = 77.325676
last_seq = 768
current_ts = 77.342758
current_received_ts = 77.342346
current_seq = 769
count = 68
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 216us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.342758
last_received_ts = 77.342346
last_seq = 769
current_ts = 77.359436
current_received_ts = 77.359024
current_seq = 770
count = 69
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 250us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.359436
last_received_ts = 77.359024
last_seq = 770
current_ts = 77.376106
current_received_ts = 77.375694
current_seq = 771
count = 70
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 236us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.376106
last_received_ts = 77.375694
last_seq = 771
current_ts = 77.392776
current_received_ts = 77.392311
current_seq = 772
count = 71
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 246us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.392776
last_received_ts = 77.392311
last_seq = 772
current_ts = 77.409439
current_received_ts = 77.409027
current_seq = 773
count = 72
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 215us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.409439
last_received_ts = 77.409027
last_seq = 773
current_ts = 77.426102
current_received_ts = 77.425690
current_seq = 774
count = 73
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 248us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.426102
last_received_ts = 77.425690
last_seq = 774
current_ts = 77.442764
current_received_ts = 77.442352
current_seq = 775
count = 74
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 217us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.442764
last_received_ts = 77.442352
last_seq = 775
current_ts = 77.459427
current_received_ts = 77.458954
current_seq = 776
count = 75
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.459427
last_received_ts = 77.458954
last_seq = 776
current_ts = 77.476089
current_received_ts = 77.475677
current_seq = 777
count = 76
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 216us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.476089
last_received_ts = 77.475677
last_seq = 777
current_ts = 77.492760
current_received_ts = 77.492294
current_seq = 778
count = 77
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 260us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.492760
last_received_ts = 77.492294
last_seq = 778
current_ts = 77.509422
current_received_ts = 77.509003
current_seq = 779
count = 78
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 218us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.509422
last_received_ts = 77.509003
last_seq = 779
current_ts = 77.526085
current_received_ts = 77.525665
current_seq = 780
count = 79
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 273us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.526085
last_received_ts = 77.525665
last_seq = 780
current_ts = 77.542747
current_received_ts = 77.542336
current_seq = 781
count = 80
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 216us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.542747
last_received_ts = 77.542336
last_seq = 781
current_ts = 77.559410
current_received_ts = 77.558975
current_seq = 782
count = 81
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 289us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.559410
last_received_ts = 77.558975
last_seq = 782
current_ts = 77.576073
current_received_ts = 77.575661
current_seq = 783
count = 82
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 215us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.576073
last_received_ts = 77.575661
last_seq = 783
current_ts = 77.592743
current_received_ts = 77.592316
current_seq = 784
count = 83
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.592743
last_received_ts = 77.592316
last_seq = 784
current_ts = 77.609406
current_received_ts = 77.608978
current_seq = 785
count = 84
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 213us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.609406
last_received_ts = 77.608978
last_seq = 785
current_ts = 77.626068
current_received_ts = 77.625641
current_seq = 786
count = 85
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 214us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.626068
last_received_ts = 77.625641
last_seq = 786
current_ts = 77.642731
current_received_ts = 77.642303
current_seq = 787
count = 86
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 215us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.642731
last_received_ts = 77.642303
last_seq = 787
current_ts = 77.659393
current_received_ts = 77.658928
current_seq = 788
count = 87
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.659393
last_received_ts = 77.658928
last_seq = 788
current_ts = 77.676056
current_received_ts = 77.675636
current_seq = 789
count = 88
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 210us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.676056
last_received_ts = 77.675636
last_seq = 789
current_ts = 77.692719
current_received_ts = 77.692772
current_seq = 790
count = 89
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 287us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.692719
last_received_ts = 77.692772
last_seq = 790
current_ts = 77.709381
current_received_ts = 77.708961
current_seq = 791
count = 90
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 229us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.709381
last_received_ts = 77.708961
last_seq = 791
current_ts = 77.726051
current_received_ts = 77.725639
current_seq = 792
count = 91
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 244us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.726051
last_received_ts = 77.725639
last_seq = 792
current_ts = 77.742714
current_received_ts = 77.742294
current_seq = 793
count = 92
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 241us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.742714
last_received_ts = 77.742294
last_seq = 793
current_ts = 77.759377
current_received_ts = 77.758904
current_seq = 794
count = 93
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.759377
last_received_ts = 77.758904
last_seq = 794
current_ts = 77.776039
current_received_ts = 77.775612
current_seq = 795
count = 94
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 32us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.776039
last_received_ts = 77.775612
last_seq = 795
current_ts = 77.792702
current_received_ts = 77.792282
current_seq = 796
count = 95
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 231us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.792702
last_received_ts = 77.792282
last_seq = 796
current_ts = 77.809364
current_received_ts = 77.808945
current_seq = 797
count = 96
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.809364
last_received_ts = 77.808945
last_seq = 797
current_ts = 77.826027
current_received_ts = 77.825607
current_seq = 798
count = 97
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 212us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.826027
last_received_ts = 77.825607
last_seq = 798
current_ts = 77.842690
current_received_ts = 77.842262
current_seq = 799
count = 98
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.842690
last_received_ts = 77.842262
last_seq = 799
current_ts = 77.859360
current_received_ts = 77.858887
current_seq = 800
count = 99
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.859360
last_received_ts = 77.858887
last_seq = 800
current_ts = 77.876022
current_received_ts = 77.875610
current_seq = 801
count = 100
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.876022
last_received_ts = 77.875610
last_seq = 801
current_ts = 77.892685
current_received_ts = 77.892235
current_seq = 802
count = 101
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 216us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.892685
last_received_ts = 77.892235
last_seq = 802
current_ts = 77.909348
current_received_ts = 77.908867
current_seq = 803
count = 102
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 28us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.909348
last_received_ts = 77.908867
last_seq = 803
current_ts = 77.926010
current_received_ts = 77.925529
current_seq = 804
count = 103
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.926010
last_received_ts = 77.925529
last_seq = 804
current_ts = 77.942673
current_received_ts = 77.942192
current_seq = 805
count = 104
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.942673
last_received_ts = 77.942192
last_seq = 805
current_ts = 77.959335
current_received_ts = 77.958855
current_seq = 806
count = 105
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 28us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.959335
last_received_ts = 77.958855
last_seq = 806
current_ts = 77.975998
current_received_ts = 77.975517
current_seq = 807
count = 106
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.975998
last_received_ts = 77.975517
last_seq = 807
current_ts = 77.992661
current_received_ts = 77.992233
current_seq = 808
count = 107
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 28us
(kms_flip:2250) DEBUG: name = flip
last_ts = 77.992661
last_received_ts = 77.992233
last_seq = 808
current_ts = 78.009331
current_received_ts = 78.008850
current_seq = 809
count = 108
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.009331
last_received_ts = 78.008850
last_seq = 809
current_ts = 78.025993
current_received_ts = 78.025513
current_seq = 810
count = 109
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.025993
last_received_ts = 78.025513
last_seq = 810
current_ts = 78.042656
current_received_ts = 78.042175
current_seq = 811
count = 110
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.042656
last_received_ts = 78.042175
last_seq = 811
current_ts = 78.059319
current_received_ts = 78.058838
current_seq = 812
count = 111
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.059319
last_received_ts = 78.058838
last_seq = 812
current_ts = 78.075981
current_received_ts = 78.075500
current_seq = 813
count = 112
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.075981
last_received_ts = 78.075500
last_seq = 813
current_ts = 78.092644
current_received_ts = 78.092201
current_seq = 814
count = 113
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.092644
last_received_ts = 78.092201
last_seq = 814
current_ts = 78.109314
current_received_ts = 78.108826
current_seq = 815
count = 114
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.109314
last_received_ts = 78.108826
last_seq = 815
current_ts = 78.125977
current_received_ts = 78.125488
current_seq = 816
count = 115
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.125977
last_received_ts = 78.125488
last_seq = 816
current_ts = 78.142639
current_received_ts = 78.142159
current_seq = 817
count = 116
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.142639
last_received_ts = 78.142159
last_seq = 817
current_ts = 78.159302
current_received_ts = 78.158821
current_seq = 818
count = 117
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.159302
last_received_ts = 78.158821
last_seq = 818
current_ts = 78.175964
current_received_ts = 78.175484
current_seq = 819
count = 118
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 28us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.175964
last_received_ts = 78.175484
last_seq = 819
current_ts = 78.192627
current_received_ts = 78.192184
current_seq = 820
count = 119
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.192627
last_received_ts = 78.192184
last_seq = 820
current_ts = 78.209290
current_received_ts = 78.208809
current_seq = 821
count = 120
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.209290
last_received_ts = 78.208809
last_seq = 821
current_ts = 78.225952
current_received_ts = 78.225471
current_seq = 822
count = 121
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.225952
last_received_ts = 78.225471
last_seq = 822
current_ts = 78.242615
current_received_ts = 78.242210
current_seq = 823
count = 122
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 212us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.242615
last_received_ts = 78.242210
last_seq = 823
current_ts = 78.259285
current_received_ts = 78.258865
current_seq = 824
count = 123
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 211us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.259285
last_received_ts = 78.258865
last_seq = 824
current_ts = 78.275948
current_received_ts = 78.275520
current_seq = 825
count = 124
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 219us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.275948
last_received_ts = 78.275520
last_seq = 825
current_ts = 78.292610
current_received_ts = 78.292206
current_seq = 826
count = 125
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 249us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.292610
last_received_ts = 78.292206
last_seq = 826
current_ts = 78.309273
current_received_ts = 78.308800
current_seq = 827
count = 126
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.309273
last_received_ts = 78.308800
last_seq = 827
current_ts = 78.325935
current_received_ts = 78.325516
current_seq = 828
count = 127
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 32us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.325935
last_received_ts = 78.325516
last_seq = 828
current_ts = 78.342598
current_received_ts = 78.342194
current_seq = 829
count = 128
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 683us
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2250) igt_core-INFO: Stack trace:
(kms_flip:2250) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2250) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:2250) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2250) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2250) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2250) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2250) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2250) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A6: FAIL (2.808s)
Starting dynamic subtest: B-HDMI-A6
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-HDMI-A6 failed.
**** DEBUG ****
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:2250) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=7680)
(kms_flip:2250) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce616e8d0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce616e8d0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce619bb50, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce619bb50, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce619bb50, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce619bb50, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce619bb50, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce619bb50, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2250) DEBUG: No stale events found
(kms_flip:2250) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2250) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2250) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 78.938988
current_received_ts = 78.938499
current_seq = 681
count = 0
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 218us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.938988
last_received_ts = 78.938499
last_seq = 681
current_ts = 78.955666
current_received_ts = 78.955154
current_seq = 682
count = 1
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 394us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.955666
last_received_ts = 78.955154
last_seq = 682
current_ts = 78.972328
current_received_ts = 78.971825
current_seq = 683
count = 2
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 195us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.972328
last_received_ts = 78.971825
last_seq = 683
current_ts = 78.988991
current_received_ts = 78.988548
current_seq = 684
count = 3
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 238us
(kms_flip:2250) DEBUG: name = flip
last_ts = 78.988991
last_received_ts = 78.988548
last_seq = 684
current_ts = 79.005646
current_received_ts = 79.005211
current_seq = 685
count = 4
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 271us
(kms_flip:2250) DEBUG: name = flip
last_ts = 79.005646
last_received_ts = 79.005211
last_seq = 685
current_ts = 79.022308
current_received_ts = 79.021873
current_seq = 686
count = 5
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 242us
(kms_flip:2250) DEBUG: name = flip
last_ts = 79.022308
last_received_ts = 79.021873
last_seq = 686
current_ts = 79.038979
current_received_ts = 79.038536
current_seq = 687
count = 6
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 273us
(kms_flip:2250) DEBUG: name = flip
last_ts = 79.038979
last_received_ts = 79.038536
last_seq = 687
current_ts = 79.055649
current_received_ts = 79.055183
current_seq = 688
count = 7
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 30us
(kms_flip:2250) DEBUG: name = flip
last_ts = 79.055649
last_received_ts = 79.055183
last_seq = 688
current_ts = 79.072304
current_received_ts = 79.071899
current_seq = 689
count = 8
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 741us
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2250) igt_core-INFO: Stack trace:
(kms_flip:2250) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2250) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:2250) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2250) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2250) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2250) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2250) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2250) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A6: FAIL (0.369s)
Starting dynamic subtest: C-HDMI-A6
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest C-HDMI-A6 failed.
**** DEBUG ****
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=5, pitch=7680)
(kms_flip:2250) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=6, pitch=7680)
(kms_flip:2250) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6191b70, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6191b70, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6191f20, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6191f20, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6191c20, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6191c20, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6191e60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6191e60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2250) DEBUG: No stale events found
(kms_flip:2250) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2250) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2250) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 79.278809
current_received_ts = 79.278366
current_seq = 18
count = 0
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 687us
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2250) igt_core-INFO: Stack trace:
(kms_flip:2250) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2250) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:2250) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2250) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2250) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2250) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2250) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2250) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A6: FAIL (0.205s)
Starting dynamic subtest: D-HDMI-A6
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest D-HDMI-A6 failed.
**** DEBUG ****
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=7, pitch=7680)
(kms_flip:2250) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=8, pitch=7680)
(kms_flip:2250) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce60ce0f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce60ce0f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce60ce0f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce60ce0f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce616f330, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce616f330, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6176d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6176d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2250) DEBUG: No stale events found
(kms_flip:2250) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2250) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2250) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 79.490028
current_received_ts = 79.489594
current_seq = 18
count = 0
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 608us
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2250) igt_core-INFO: Stack trace:
(kms_flip:2250) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2250) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:2250) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2250) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2250) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2250) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2250) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2250) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest D-HDMI-A6: FAIL (0.211s)
Starting dynamic subtest: A-DP4
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest A-DP4 failed.
**** DEBUG ****
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=9, pitch=7680)
(kms_flip:2250) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=10, pitch=7680)
(kms_flip:2250) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce61a02c0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce61a02c0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6183ec0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6183ec0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce61a02c0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce61a02c0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6192d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6192d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2250) DEBUG: No stale events found
(kms_flip:2250) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2250) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2250) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 79.729401
current_received_ts = 79.728958
current_seq = 863
count = 0
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 456us
(kms_flip:2250) DEBUG: name = flip
last_ts = 79.729401
last_received_ts = 79.728958
last_seq = 863
current_ts = 79.746063
current_received_ts = 79.745628
current_seq = 864
count = 1
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 79.746063
last_received_ts = 79.745628
last_seq = 864
current_ts = 79.762733
current_received_ts = 79.762306
current_seq = 865
count = 2
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 538us
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2250) igt_core-INFO: Stack trace:
(kms_flip:2250) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2250) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:2250) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2250) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2250) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2250) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2250) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2250) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-DP4: FAIL (0.273s)
Starting dynamic subtest: B-DP4
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-DP4 failed.
**** DEBUG ****
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.554672
last_received_ts = 80.554260
last_seq = 732
current_ts = 80.571342
current_received_ts = 80.570923
current_seq = 733
count = 33
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 214us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.571342
last_received_ts = 80.570923
last_seq = 733
current_ts = 80.588005
current_received_ts = 80.587601
current_seq = 734
count = 34
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 245us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.588005
last_received_ts = 80.587601
last_seq = 734
current_ts = 80.604675
current_received_ts = 80.604218
current_seq = 735
count = 35
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.604675
last_received_ts = 80.604218
last_seq = 735
current_ts = 80.621330
current_received_ts = 80.620911
current_seq = 736
count = 36
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 227us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.621330
last_received_ts = 80.620911
last_seq = 736
current_ts = 80.638000
current_received_ts = 80.637573
current_seq = 737
count = 37
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 249us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.638000
last_received_ts = 80.637573
last_seq = 737
current_ts = 80.654663
current_received_ts = 80.654243
current_seq = 738
count = 38
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 283us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.654663
last_received_ts = 80.654243
last_seq = 738
current_ts = 80.671326
current_received_ts = 80.670906
current_seq = 739
count = 39
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 255us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.671326
last_received_ts = 80.670906
last_seq = 739
current_ts = 80.687988
current_received_ts = 80.687569
current_seq = 740
count = 40
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 221us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.687988
last_received_ts = 80.687569
last_seq = 740
current_ts = 80.704659
current_received_ts = 80.704193
current_seq = 741
count = 41
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 34us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.704659
last_received_ts = 80.704193
last_seq = 741
current_ts = 80.721321
current_received_ts = 80.720901
current_seq = 742
count = 42
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 226us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.721321
last_received_ts = 80.720901
last_seq = 742
current_ts = 80.737984
current_received_ts = 80.737572
current_seq = 743
count = 43
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 251us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.737984
last_received_ts = 80.737572
last_seq = 743
current_ts = 80.754646
current_received_ts = 80.754234
current_seq = 744
count = 44
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 229us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.754646
last_received_ts = 80.754234
last_seq = 744
current_ts = 80.771309
current_received_ts = 80.770912
current_seq = 745
count = 45
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 247us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.771309
last_received_ts = 80.770912
last_seq = 745
current_ts = 80.787971
current_received_ts = 80.787560
current_seq = 746
count = 46
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 226us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.787971
last_received_ts = 80.787560
last_seq = 746
current_ts = 80.804634
current_received_ts = 80.804184
current_seq = 747
count = 47
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.804634
last_received_ts = 80.804184
last_seq = 747
current_ts = 80.821304
current_received_ts = 80.820885
current_seq = 748
count = 48
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 224us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.821304
last_received_ts = 80.820885
last_seq = 748
current_ts = 80.837967
current_received_ts = 80.837555
current_seq = 749
count = 49
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 258us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.837967
last_received_ts = 80.837555
last_seq = 749
current_ts = 80.854630
current_received_ts = 80.854210
current_seq = 750
count = 50
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.854630
last_received_ts = 80.854210
last_seq = 750
current_ts = 80.871300
current_received_ts = 80.870872
current_seq = 751
count = 51
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 256us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.871300
last_received_ts = 80.870872
last_seq = 751
current_ts = 80.887962
current_received_ts = 80.887535
current_seq = 752
count = 52
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 223us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.887962
last_received_ts = 80.887535
last_seq = 752
current_ts = 80.904625
current_received_ts = 80.904182
current_seq = 753
count = 53
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 34us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.904625
last_received_ts = 80.904182
last_seq = 753
current_ts = 80.921288
current_received_ts = 80.920868
current_seq = 754
count = 54
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 223us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.921288
last_received_ts = 80.920868
last_seq = 754
current_ts = 80.937958
current_received_ts = 80.937531
current_seq = 755
count = 55
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 253us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.937958
last_received_ts = 80.937531
last_seq = 755
current_ts = 80.954620
current_received_ts = 80.954193
current_seq = 756
count = 56
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 229us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.954620
last_received_ts = 80.954193
last_seq = 756
current_ts = 80.971283
current_received_ts = 80.970863
current_seq = 757
count = 57
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 248us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.971283
last_received_ts = 80.970863
last_seq = 757
current_ts = 80.987946
current_received_ts = 80.987534
current_seq = 758
count = 58
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 230us
(kms_flip:2250) DEBUG: name = flip
last_ts = 80.987946
last_received_ts = 80.987534
last_seq = 758
current_ts = 81.004608
current_received_ts = 81.004173
current_seq = 759
count = 59
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 259us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.004608
last_received_ts = 81.004173
last_seq = 759
current_ts = 81.021278
current_received_ts = 81.020866
current_seq = 760
count = 60
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 241us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.021278
last_received_ts = 81.020866
last_seq = 760
current_ts = 81.037941
current_received_ts = 81.037529
current_seq = 761
count = 61
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 216us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.037941
last_received_ts = 81.037529
last_seq = 761
current_ts = 81.054604
current_received_ts = 81.054192
current_seq = 762
count = 62
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 250us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.054604
last_received_ts = 81.054192
last_seq = 762
current_ts = 81.071266
current_received_ts = 81.070862
current_seq = 763
count = 63
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 211us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.071266
last_received_ts = 81.070862
last_seq = 763
current_ts = 81.087929
current_received_ts = 81.087524
current_seq = 764
count = 64
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 246us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.087929
last_received_ts = 81.087524
last_seq = 764
current_ts = 81.104599
current_received_ts = 81.104187
current_seq = 765
count = 65
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 253us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.104599
last_received_ts = 81.104187
last_seq = 765
current_ts = 81.121262
current_received_ts = 81.120842
current_seq = 766
count = 66
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 256us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.121262
last_received_ts = 81.120842
last_seq = 766
current_ts = 81.137932
current_received_ts = 81.137512
current_seq = 767
count = 67
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 220us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.137932
last_received_ts = 81.137512
last_seq = 767
current_ts = 81.154594
current_received_ts = 81.154175
current_seq = 768
count = 68
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 256us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.154594
last_received_ts = 81.154175
last_seq = 768
current_ts = 81.171257
current_received_ts = 81.170845
current_seq = 769
count = 69
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 210us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.171257
last_received_ts = 81.170845
last_seq = 769
current_ts = 81.187920
current_received_ts = 81.187508
current_seq = 770
count = 70
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 245us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.187920
last_received_ts = 81.187508
last_seq = 770
current_ts = 81.204582
current_received_ts = 81.204193
current_seq = 771
count = 71
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 247us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.204582
last_received_ts = 81.204193
last_seq = 771
current_ts = 81.221245
current_received_ts = 81.220840
current_seq = 772
count = 72
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 225us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.221245
last_received_ts = 81.220840
last_seq = 772
current_ts = 81.237907
current_received_ts = 81.237488
current_seq = 773
count = 73
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 246us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.237907
last_received_ts = 81.237488
last_seq = 773
current_ts = 81.254578
current_received_ts = 81.254158
current_seq = 774
count = 74
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 222us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.254578
last_received_ts = 81.254158
last_seq = 774
current_ts = 81.271240
current_received_ts = 81.270821
current_seq = 775
count = 75
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 246us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.271240
last_received_ts = 81.270821
last_seq = 775
current_ts = 81.287903
current_received_ts = 81.287491
current_seq = 776
count = 76
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 226us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.287903
last_received_ts = 81.287491
last_seq = 776
current_ts = 81.304565
current_received_ts = 81.304184
current_seq = 777
count = 77
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 243us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.304565
last_received_ts = 81.304184
last_seq = 777
current_ts = 81.321236
current_received_ts = 81.320808
current_seq = 778
count = 78
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 226us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.321236
last_received_ts = 81.320808
last_seq = 778
current_ts = 81.337898
current_received_ts = 81.337479
current_seq = 779
count = 79
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 252us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.337898
last_received_ts = 81.337479
last_seq = 779
current_ts = 81.354561
current_received_ts = 81.354134
current_seq = 780
count = 80
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 220us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.354561
last_received_ts = 81.354134
last_seq = 780
current_ts = 81.371223
current_received_ts = 81.370804
current_seq = 781
count = 81
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 250us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.371223
last_received_ts = 81.370804
last_seq = 781
current_ts = 81.387894
current_received_ts = 81.387466
current_seq = 782
count = 82
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 221us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.387894
last_received_ts = 81.387466
last_seq = 782
current_ts = 81.404556
current_received_ts = 81.404175
current_seq = 783
count = 83
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 234us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.404556
last_received_ts = 81.404175
last_seq = 783
current_ts = 81.421227
current_received_ts = 81.420807
current_seq = 784
count = 84
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 229us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.421227
last_received_ts = 81.420807
last_seq = 784
current_ts = 81.437881
current_received_ts = 81.437454
current_seq = 785
count = 85
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 253us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.437881
last_received_ts = 81.437454
last_seq = 785
current_ts = 81.454552
current_received_ts = 81.454132
current_seq = 786
count = 86
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 230us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.454552
last_received_ts = 81.454132
last_seq = 786
current_ts = 81.471214
current_received_ts = 81.470787
current_seq = 787
count = 87
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 34us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.471214
last_received_ts = 81.470787
last_seq = 787
current_ts = 81.487877
current_received_ts = 81.487457
current_seq = 788
count = 88
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 224us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.487877
last_received_ts = 81.487457
last_seq = 788
current_ts = 81.504539
current_received_ts = 81.504158
current_seq = 789
count = 89
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 240us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.504539
last_received_ts = 81.504158
last_seq = 789
current_ts = 81.521210
current_received_ts = 81.520782
current_seq = 790
count = 90
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 225us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.521210
last_received_ts = 81.520782
last_seq = 790
current_ts = 81.537872
current_received_ts = 81.537445
current_seq = 791
count = 91
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 220us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.537872
last_received_ts = 81.537445
last_seq = 791
current_ts = 81.554535
current_received_ts = 81.554108
current_seq = 792
count = 92
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 224us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.554535
last_received_ts = 81.554108
last_seq = 792
current_ts = 81.571198
current_received_ts = 81.570770
current_seq = 793
count = 93
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 235us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.571198
last_received_ts = 81.570770
last_seq = 793
current_ts = 81.587860
current_received_ts = 81.587440
current_seq = 794
count = 94
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 209us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.587860
last_received_ts = 81.587440
last_seq = 794
current_ts = 81.604530
current_received_ts = 81.604156
current_seq = 795
count = 95
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 229us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.604530
last_received_ts = 81.604156
last_seq = 795
current_ts = 81.621193
current_received_ts = 81.620773
current_seq = 796
count = 96
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 224us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.621193
last_received_ts = 81.620773
last_seq = 796
current_ts = 81.637863
current_received_ts = 81.637444
current_seq = 797
count = 97
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 218us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.637863
last_received_ts = 81.637444
last_seq = 797
current_ts = 81.654518
current_received_ts = 81.654099
current_seq = 798
count = 98
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 224us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.654518
last_received_ts = 81.654099
last_seq = 798
current_ts = 81.671188
current_received_ts = 81.670761
current_seq = 799
count = 99
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 229us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.671188
last_received_ts = 81.670761
last_seq = 799
current_ts = 81.687851
current_received_ts = 81.687431
current_seq = 800
count = 100
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 34us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.687851
last_received_ts = 81.687431
last_seq = 800
current_ts = 81.704514
current_received_ts = 81.704117
current_seq = 801
count = 101
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 253us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.704514
last_received_ts = 81.704117
last_seq = 801
current_ts = 81.721184
current_received_ts = 81.720757
current_seq = 802
count = 102
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 224us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.721184
last_received_ts = 81.720757
last_seq = 802
current_ts = 81.737846
current_received_ts = 81.737419
current_seq = 803
count = 103
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.737846
last_received_ts = 81.737419
last_seq = 803
current_ts = 81.754509
current_received_ts = 81.754082
current_seq = 804
count = 104
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.754509
last_received_ts = 81.754082
last_seq = 804
current_ts = 81.771172
current_received_ts = 81.770744
current_seq = 805
count = 105
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 248us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.771172
last_received_ts = 81.770744
last_seq = 805
current_ts = 81.787834
current_received_ts = 81.787415
current_seq = 806
count = 106
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 220us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.787834
last_received_ts = 81.787415
last_seq = 806
current_ts = 81.804497
current_received_ts = 81.804123
current_seq = 807
count = 107
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 246us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.804497
last_received_ts = 81.804123
last_seq = 807
current_ts = 81.821167
current_received_ts = 81.820747
current_seq = 808
count = 108
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 230us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.821167
last_received_ts = 81.820747
last_seq = 808
current_ts = 81.837830
current_received_ts = 81.837418
current_seq = 809
count = 109
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 242us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.837830
last_received_ts = 81.837418
last_seq = 809
current_ts = 81.854492
current_received_ts = 81.854073
current_seq = 810
count = 110
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 226us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.854492
last_received_ts = 81.854073
last_seq = 810
current_ts = 81.871162
current_received_ts = 81.870735
current_seq = 811
count = 111
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 252us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.871162
last_received_ts = 81.870735
last_seq = 811
current_ts = 81.887825
current_received_ts = 81.887421
current_seq = 812
count = 112
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 251us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.887825
last_received_ts = 81.887421
last_seq = 812
current_ts = 81.904488
current_received_ts = 81.904106
current_seq = 813
count = 113
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 34us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.904488
last_received_ts = 81.904106
last_seq = 813
current_ts = 81.921150
current_received_ts = 81.920731
current_seq = 814
count = 114
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 286us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.921150
last_received_ts = 81.920731
last_seq = 814
current_ts = 81.937820
current_received_ts = 81.937401
current_seq = 815
count = 115
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 250us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.937820
last_received_ts = 81.937401
last_seq = 815
current_ts = 81.954483
current_received_ts = 81.954056
current_seq = 816
count = 116
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 285us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.954483
last_received_ts = 81.954056
last_seq = 816
current_ts = 81.971146
current_received_ts = 81.970726
current_seq = 817
count = 117
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 248us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.971146
last_received_ts = 81.970726
last_seq = 817
current_ts = 81.987808
current_received_ts = 81.987389
current_seq = 818
count = 118
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 293us
(kms_flip:2250) DEBUG: name = flip
last_ts = 81.987808
last_received_ts = 81.987389
last_seq = 818
current_ts = 82.004478
current_received_ts = 82.004089
current_seq = 819
count = 119
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 34us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.004478
last_received_ts = 82.004089
last_seq = 819
current_ts = 82.021149
current_received_ts = 82.020721
current_seq = 820
count = 120
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 293us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.021149
last_received_ts = 82.020721
last_seq = 820
current_ts = 82.037804
current_received_ts = 82.037384
current_seq = 821
count = 121
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 256us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.037804
last_received_ts = 82.037384
last_seq = 821
current_ts = 82.054466
current_received_ts = 82.054047
current_seq = 822
count = 122
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 284us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.054466
last_received_ts = 82.054047
last_seq = 822
current_ts = 82.071129
current_received_ts = 82.070709
current_seq = 823
count = 123
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 256us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.071129
last_received_ts = 82.070709
last_seq = 823
current_ts = 82.087799
current_received_ts = 82.087379
current_seq = 824
count = 124
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 222us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.087799
last_received_ts = 82.087379
last_seq = 824
current_ts = 82.104462
current_received_ts = 82.104073
current_seq = 825
count = 125
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.104462
last_received_ts = 82.104073
last_seq = 825
current_ts = 82.121124
current_received_ts = 82.120697
current_seq = 826
count = 126
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 223us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.121124
last_received_ts = 82.120697
last_seq = 826
current_ts = 82.137787
current_received_ts = 82.137375
current_seq = 827
count = 127
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 253us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.137787
last_received_ts = 82.137375
last_seq = 827
current_ts = 82.154457
current_received_ts = 82.154037
current_seq = 828
count = 128
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 222us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.154457
last_received_ts = 82.154037
last_seq = 828
current_ts = 82.171120
current_received_ts = 82.170700
current_seq = 829
count = 129
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 255us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.171120
last_received_ts = 82.170700
last_seq = 829
current_ts = 82.187782
current_received_ts = 82.187355
current_seq = 830
count = 130
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.187782
last_received_ts = 82.187355
last_seq = 830
current_ts = 82.204445
current_received_ts = 82.204071
current_seq = 831
count = 131
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 32us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.204445
last_received_ts = 82.204071
last_seq = 831
current_ts = 82.221115
current_received_ts = 82.220688
current_seq = 832
count = 132
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 221us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.221115
last_received_ts = 82.220688
last_seq = 832
current_ts = 82.237770
current_received_ts = 82.237373
current_seq = 833
count = 133
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 247us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.237770
last_received_ts = 82.237373
last_seq = 833
current_ts = 82.254440
current_received_ts = 82.254021
current_seq = 834
count = 134
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 228us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.254440
last_received_ts = 82.254021
last_seq = 834
current_ts = 82.271103
current_received_ts = 82.270683
current_seq = 835
count = 135
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 251us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.271103
last_received_ts = 82.270683
last_seq = 835
current_ts = 82.287773
current_received_ts = 82.287346
current_seq = 836
count = 136
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 220us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.287773
last_received_ts = 82.287346
last_seq = 836
current_ts = 82.304436
current_received_ts = 82.304062
current_seq = 837
count = 137
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.304436
last_received_ts = 82.304062
last_seq = 837
current_ts = 82.321098
current_received_ts = 82.320679
current_seq = 838
count = 138
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 229us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.321098
last_received_ts = 82.320679
last_seq = 838
current_ts = 82.337761
current_received_ts = 82.337341
current_seq = 839
count = 139
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 249us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.337761
last_received_ts = 82.337341
last_seq = 839
current_ts = 82.354431
current_received_ts = 82.354004
current_seq = 840
count = 140
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 225us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.354431
last_received_ts = 82.354004
last_seq = 840
current_ts = 82.371094
current_received_ts = 82.370667
current_seq = 841
count = 141
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 256us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.371094
last_received_ts = 82.370667
last_seq = 841
current_ts = 82.387756
current_received_ts = 82.387329
current_seq = 842
count = 142
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 221us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.387756
last_received_ts = 82.387329
last_seq = 842
current_ts = 82.404419
current_received_ts = 82.403999
current_seq = 843
count = 143
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 34us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.404419
last_received_ts = 82.403999
last_seq = 843
current_ts = 82.421089
current_received_ts = 82.420662
current_seq = 844
count = 144
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 286us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.421089
last_received_ts = 82.420662
last_seq = 844
current_ts = 82.437752
current_received_ts = 82.437325
current_seq = 845
count = 145
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 251us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.437752
last_received_ts = 82.437325
last_seq = 845
current_ts = 82.454414
current_received_ts = 82.453995
current_seq = 846
count = 146
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.454414
last_received_ts = 82.453995
last_seq = 846
current_ts = 82.471085
current_received_ts = 82.470657
current_seq = 847
count = 147
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 255us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.471085
last_received_ts = 82.470657
last_seq = 847
current_ts = 82.487747
current_received_ts = 82.487320
current_seq = 848
count = 148
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 226us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.487747
last_received_ts = 82.487320
last_seq = 848
current_ts = 82.504410
current_received_ts = 82.503944
current_seq = 849
count = 149
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 29us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.504410
last_received_ts = 82.503944
last_seq = 849
current_ts = 82.521072
current_received_ts = 82.520653
current_seq = 850
count = 150
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 293us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.521072
last_received_ts = 82.520653
last_seq = 850
current_ts = 82.537743
current_received_ts = 82.537315
current_seq = 851
count = 151
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 254us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.537743
last_received_ts = 82.537315
last_seq = 851
current_ts = 82.554405
current_received_ts = 82.553978
current_seq = 852
count = 152
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 433us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.554405
last_received_ts = 82.553978
last_seq = 852
current_ts = 82.571068
current_received_ts = 82.570641
current_seq = 853
count = 153
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 33us
(kms_flip:2250) DEBUG: name = flip
last_ts = 82.571068
last_received_ts = 82.570641
last_seq = 853
current_ts = 82.587730
current_received_ts = 82.587311
current_seq = 854
count = 154
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 714us
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2250) igt_core-INFO: Stack trace:
(kms_flip:2250) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2250) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:2250) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2250) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2250) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2250) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2250) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2250) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-DP4: FAIL (3.178s)
Starting dynamic subtest: C-DP4
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest C-DP4 failed.
**** DEBUG ****
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=13, pitch=7680)
(kms_flip:2250) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=14, pitch=7680)
(kms_flip:2250) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6192d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6192d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6192d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6192d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6192d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6192d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6192d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6192d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2250) DEBUG: No stale events found
(kms_flip:2250) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2250) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2250) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 83.193336
current_received_ts = 83.192909
current_seq = 29
count = 0
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 634us
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2250) igt_core-INFO: Stack trace:
(kms_flip:2250) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2250) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:2250) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2250) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2250) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2250) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2250) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2250) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-DP4: FAIL (0.251s)
Starting dynamic subtest: D-DP4
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest D-DP4 failed.
**** DEBUG ****
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=15, pitch=7680)
(kms_flip:2250) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2250) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=16, pitch=7680)
(kms_flip:2250) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6192d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6192d60, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce615e6a0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce615e6a0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce61969b0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce61969b0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6196790, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) intel_allocator_simple-DEBUG: <ial: 0x55bce6196790, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2250) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2250) DEBUG: No stale events found
(kms_flip:2250) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2250) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2250) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 83.433357
current_received_ts = 83.432861
current_seq = 29
count = 0
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 31us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.433357
last_received_ts = 83.432861
last_seq = 29
current_ts = 83.450027
current_received_ts = 83.449539
current_seq = 30
count = 1
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 31us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.450027
last_received_ts = 83.449539
last_seq = 30
current_ts = 83.466682
current_received_ts = 83.466171
current_seq = 31
count = 2
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 25us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.466682
last_received_ts = 83.466171
last_seq = 31
current_ts = 83.483345
current_received_ts = 83.482803
current_seq = 32
count = 3
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 17us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.483345
last_received_ts = 83.482803
last_seq = 32
current_ts = 83.500023
current_received_ts = 83.499435
current_seq = 33
count = 4
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 12us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.500023
last_received_ts = 83.499435
last_seq = 33
current_ts = 83.516685
current_received_ts = 83.516129
current_seq = 34
count = 5
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 13us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.516685
last_received_ts = 83.516129
last_seq = 34
current_ts = 83.533340
current_received_ts = 83.532822
current_seq = 35
count = 6
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 15us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.533340
last_received_ts = 83.532822
last_seq = 35
current_ts = 83.550011
current_received_ts = 83.549500
current_seq = 36
count = 7
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 26us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.550011
last_received_ts = 83.549500
last_seq = 36
current_ts = 83.566673
current_received_ts = 83.566200
current_seq = 37
count = 8
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 30us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.566673
last_received_ts = 83.566200
last_seq = 37
current_ts = 83.583344
current_received_ts = 83.582863
current_seq = 38
count = 9
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 30us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.583344
last_received_ts = 83.582863
last_seq = 38
current_ts = 83.600006
current_received_ts = 83.599525
current_seq = 39
count = 10
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 31us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.600006
last_received_ts = 83.599525
last_seq = 39
current_ts = 83.616676
current_received_ts = 83.616211
current_seq = 40
count = 11
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 229us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.616676
last_received_ts = 83.616211
last_seq = 40
current_ts = 83.633331
current_received_ts = 83.632851
current_seq = 41
count = 12
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 30us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.633331
last_received_ts = 83.632851
last_seq = 41
current_ts = 83.650002
current_received_ts = 83.649529
current_seq = 42
count = 13
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 30us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.650002
last_received_ts = 83.649529
last_seq = 42
current_ts = 83.666664
current_received_ts = 83.666183
current_seq = 43
count = 14
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 30us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.666664
last_received_ts = 83.666183
last_seq = 43
current_ts = 83.683327
current_received_ts = 83.682846
current_seq = 44
count = 15
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 30us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.683327
last_received_ts = 83.682846
last_seq = 44
current_ts = 83.699989
current_received_ts = 83.699509
current_seq = 45
count = 16
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 31us
(kms_flip:2250) DEBUG: name = flip
last_ts = 83.699989
last_received_ts = 83.699509
last_seq = 45
current_ts = 83.716660
current_received_ts = 83.716209
current_seq = 46
count = 17
seq_step = 1
(kms_flip:2250) DEBUG: Vblank took 687us
(kms_flip:2250) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:924:
(kms_flip:2250) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2250) igt_core-INFO: Stack trace:
(kms_flip:2250) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2250) igt_core-INFO:   #1 ../tests/kms_flip.c:919 run_test_on_crtc_set.constprop.0()
(kms_flip:2250) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2250) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2250) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2250) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2250) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2250) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest D-DP4: FAIL (0.527s)
Subtest flip-vs-expired-vblank: FAIL (7.832s)
(kms_flip:2250) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2234:
(kms_flip:2250) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2250) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2250) igt_kms-CRITICAL: DPMS property not found on 264