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

shard-dg2-466

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

Using IGT_SRANDOM=1741714400 for randomisation
Opened device: /dev/dri/card1
Using monotonic timestamps
Starting subtest: 2x-flip-vs-expired-vblank
Starting dynamic subtest: AB-HDMI-A6-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Dynamic subtest AB-HDMI-A6-DP4: SUCCESS (5.428s)
Starting dynamic subtest: AC-HDMI-A6-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1916 run_pair()
  #3 ../tests/kms_flip.c:2073 __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 AC-HDMI-A6-DP4: FAIL (2.794s)
Starting dynamic subtest: AD-HDMI-A6-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Dynamic subtest AD-HDMI-A6-DP4: SUCCESS (5.379s)
Starting dynamic subtest: BC-HDMI-A6-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1916 run_pair()
  #3 ../tests/kms_flip.c:2073 __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 BC-HDMI-A6-DP4: FAIL (2.249s)
Starting dynamic subtest: BD-HDMI-A6-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1916 run_pair()
  #3 ../tests/kms_flip.c:2073 __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 BD-HDMI-A6-DP4: FAIL (4.085s)
Starting dynamic subtest: CD-HDMI-A6-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1916 run_pair()
  #3 ../tests/kms_flip.c:2073 __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 CD-HDMI-A6-DP4: FAIL (0.613s)
Subtest 2x-flip-vs-expired-vblank: FAIL (20.598s)
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: 2x-flip-vs-expired-vblank
Starting dynamic subtest: AB-HDMI-A6-DP4
Dynamic subtest AB-HDMI-A6-DP4: SUCCESS (5.428s)
Starting dynamic subtest: AC-HDMI-A6-DP4
(kms_flip:2231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2231) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest AC-HDMI-A6-DP4 failed.
**** DEBUG ****
(kms_flip:2231) DEBUG: name = flip
last_ts = 66.799431
last_received_ts = 66.798813
last_seq = 802
current_ts = 66.816101
current_received_ts = 66.815483
current_seq = 803
count = 4
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 66.816101
last_received_ts = 66.815483
last_seq = 803
current_ts = 66.832771
current_received_ts = 66.832123
current_seq = 804
count = 5
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 66.832771
last_received_ts = 66.832123
last_seq = 804
current_ts = 66.849434
current_received_ts = 66.848816
current_seq = 805
count = 6
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 16us
(kms_flip:2231) DEBUG: name = flip
last_ts = 66.849434
last_received_ts = 66.848816
last_seq = 805
current_ts = 66.866104
current_received_ts = 66.865479
current_seq = 806
count = 7
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 263us
(kms_flip:2231) DEBUG: name = flip
last_ts = 66.866104
last_received_ts = 66.865479
last_seq = 806
current_ts = 66.882774
current_received_ts = 66.882126
current_seq = 807
count = 8
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 66.882774
last_received_ts = 66.882126
last_seq = 807
current_ts = 66.899437
current_received_ts = 66.898819
current_seq = 808
count = 9
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 14us
(kms_flip:2231) DEBUG: name = flip
last_ts = 66.899437
last_received_ts = 66.898819
last_seq = 808
current_ts = 66.916107
current_received_ts = 66.915504
current_seq = 809
count = 10
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 265us
(kms_flip:2231) DEBUG: name = flip
last_ts = 66.916107
last_received_ts = 66.915504
last_seq = 809
current_ts = 66.932777
current_received_ts = 66.932137
current_seq = 810
count = 11
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 12us
(kms_flip:2231) DEBUG: name = flip
last_ts = 66.932777
last_received_ts = 66.932137
last_seq = 810
current_ts = 66.949448
current_received_ts = 66.948822
current_seq = 811
count = 12
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 66.949448
last_received_ts = 66.948822
last_seq = 811
current_ts = 66.966110
current_received_ts = 66.965492
current_seq = 812
count = 13
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 12us
(kms_flip:2231) DEBUG: name = flip
last_ts = 66.966110
last_received_ts = 66.965492
last_seq = 812
current_ts = 66.982773
current_received_ts = 66.982147
current_seq = 813
count = 14
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 66.982773
last_received_ts = 66.982147
last_seq = 813
current_ts = 66.999451
current_received_ts = 66.998825
current_seq = 814
count = 15
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 14us
(kms_flip:2231) DEBUG: name = flip
last_ts = 66.999451
last_received_ts = 66.998825
last_seq = 814
current_ts = 67.016113
current_received_ts = 67.015495
current_seq = 815
count = 16
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 16us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.016113
last_received_ts = 67.015495
last_seq = 815
current_ts = 67.032784
current_received_ts = 67.032143
current_seq = 816
count = 17
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.032784
last_received_ts = 67.032143
last_seq = 816
current_ts = 67.049454
current_received_ts = 67.048836
current_seq = 817
count = 18
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 284us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.049454
last_received_ts = 67.048836
last_seq = 817
current_ts = 67.066116
current_received_ts = 67.065506
current_seq = 818
count = 19
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 10us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.066116
last_received_ts = 67.065506
last_seq = 818
current_ts = 67.082787
current_received_ts = 67.082138
current_seq = 819
count = 20
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.082787
last_received_ts = 67.082138
last_seq = 819
current_ts = 67.099457
current_received_ts = 67.098839
current_seq = 820
count = 21
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.099457
last_received_ts = 67.098839
last_seq = 820
current_ts = 67.116119
current_received_ts = 67.115501
current_seq = 821
count = 22
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.116119
last_received_ts = 67.115501
last_seq = 821
current_ts = 67.132790
current_received_ts = 67.132156
current_seq = 822
count = 23
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.132790
last_received_ts = 67.132156
last_seq = 822
current_ts = 67.149460
current_received_ts = 67.148842
current_seq = 823
count = 24
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 192us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.149460
last_received_ts = 67.148842
last_seq = 823
current_ts = 67.166122
current_received_ts = 67.165512
current_seq = 824
count = 25
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 185us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.166122
last_received_ts = 67.165512
last_seq = 824
current_ts = 67.182793
current_received_ts = 67.182152
current_seq = 825
count = 26
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.182793
last_received_ts = 67.182152
last_seq = 825
current_ts = 67.199463
current_received_ts = 67.198845
current_seq = 826
count = 27
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 204us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.199463
last_received_ts = 67.198845
last_seq = 826
current_ts = 67.216125
current_received_ts = 67.215508
current_seq = 827
count = 28
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 190us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.216125
last_received_ts = 67.215508
last_seq = 827
current_ts = 67.232796
current_received_ts = 67.232155
current_seq = 828
count = 29
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 10us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.232796
last_received_ts = 67.232155
last_seq = 828
current_ts = 67.249466
current_received_ts = 67.248856
current_seq = 829
count = 30
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 273us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.249466
last_received_ts = 67.248856
last_seq = 829
current_ts = 67.266136
current_received_ts = 67.265518
current_seq = 830
count = 31
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.266136
last_received_ts = 67.265518
last_seq = 830
current_ts = 67.282799
current_received_ts = 67.282158
current_seq = 831
count = 32
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 10us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.282799
last_received_ts = 67.282158
last_seq = 831
current_ts = 67.299469
current_received_ts = 67.298851
current_seq = 832
count = 33
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 10us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.299469
last_received_ts = 67.298851
last_seq = 832
current_ts = 67.316139
current_received_ts = 67.315521
current_seq = 833
count = 34
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 10us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.316139
last_received_ts = 67.315521
last_seq = 833
current_ts = 67.332802
current_received_ts = 67.332161
current_seq = 834
count = 35
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 10us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.332802
last_received_ts = 67.332161
last_seq = 834
current_ts = 67.349472
current_received_ts = 67.348854
current_seq = 835
count = 36
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 14us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.349472
last_received_ts = 67.348854
last_seq = 835
current_ts = 67.366142
current_received_ts = 67.365524
current_seq = 836
count = 37
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.366142
last_received_ts = 67.365524
last_seq = 836
current_ts = 67.382805
current_received_ts = 67.382164
current_seq = 837
count = 38
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.382805
last_received_ts = 67.382164
last_seq = 837
current_ts = 67.399475
current_received_ts = 67.398857
current_seq = 838
count = 39
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.399475
last_received_ts = 67.398857
last_seq = 838
current_ts = 67.416145
current_received_ts = 67.415527
current_seq = 839
count = 40
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 193us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.416145
last_received_ts = 67.415527
last_seq = 839
current_ts = 67.432808
current_received_ts = 67.432167
current_seq = 840
count = 41
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.432808
last_received_ts = 67.432167
last_seq = 840
current_ts = 67.449478
current_received_ts = 67.448853
current_seq = 841
count = 42
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 10us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.449478
last_received_ts = 67.448853
last_seq = 841
current_ts = 67.466148
current_received_ts = 67.465523
current_seq = 842
count = 43
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.466148
last_received_ts = 67.465523
last_seq = 842
current_ts = 67.482811
current_received_ts = 67.482170
current_seq = 843
count = 44
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.482811
last_received_ts = 67.482170
last_seq = 843
current_ts = 67.499481
current_received_ts = 67.498863
current_seq = 844
count = 45
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.499481
last_received_ts = 67.498863
last_seq = 844
current_ts = 67.516151
current_received_ts = 67.515526
current_seq = 845
count = 46
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 10us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.516151
last_received_ts = 67.515526
last_seq = 845
current_ts = 67.532814
current_received_ts = 67.532173
current_seq = 846
count = 47
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.532814
last_received_ts = 67.532173
last_seq = 846
current_ts = 67.549484
current_received_ts = 67.548866
current_seq = 847
count = 48
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.549484
last_received_ts = 67.548866
last_seq = 847
current_ts = 67.566154
current_received_ts = 67.565536
current_seq = 848
count = 49
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 267us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.566154
last_received_ts = 67.565536
last_seq = 848
current_ts = 67.582817
current_received_ts = 67.582176
current_seq = 849
count = 50
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.582817
last_received_ts = 67.582176
last_seq = 849
current_ts = 67.599487
current_received_ts = 67.598869
current_seq = 850
count = 51
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 275us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.599487
last_received_ts = 67.598869
last_seq = 850
current_ts = 67.616158
current_received_ts = 67.615540
current_seq = 851
count = 52
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 263us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.616158
last_received_ts = 67.615540
last_seq = 851
current_ts = 67.632828
current_received_ts = 67.632179
current_seq = 852
count = 53
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.632828
last_received_ts = 67.632179
last_seq = 852
current_ts = 67.649490
current_received_ts = 67.648872
current_seq = 853
count = 54
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 11us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.649490
last_received_ts = 67.648872
last_seq = 853
current_ts = 67.666161
current_received_ts = 67.665543
current_seq = 854
count = 55
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 262us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.666161
last_received_ts = 67.665543
last_seq = 854
current_ts = 67.682831
current_received_ts = 67.682228
current_seq = 855
count = 56
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 10us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.682831
last_received_ts = 67.682228
last_seq = 855
current_ts = 67.699501
current_received_ts = 67.698891
current_seq = 856
count = 57
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 12us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.699501
last_received_ts = 67.698891
last_seq = 856
current_ts = 67.716164
current_received_ts = 67.715553
current_seq = 857
count = 58
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.716164
last_received_ts = 67.715553
last_seq = 857
current_ts = 67.732834
current_received_ts = 67.732224
current_seq = 858
count = 59
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.732834
last_received_ts = 67.732224
last_seq = 858
current_ts = 67.749504
current_received_ts = 67.748894
current_seq = 859
count = 60
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.749504
last_received_ts = 67.748894
last_seq = 859
current_ts = 67.766174
current_received_ts = 67.765556
current_seq = 860
count = 61
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.766174
last_received_ts = 67.765556
last_seq = 860
current_ts = 67.782837
current_received_ts = 67.782227
current_seq = 861
count = 62
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.782837
last_received_ts = 67.782227
last_seq = 861
current_ts = 67.799507
current_received_ts = 67.798897
current_seq = 862
count = 63
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.799507
last_received_ts = 67.798897
last_seq = 862
current_ts = 67.816177
current_received_ts = 67.815559
current_seq = 863
count = 64
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.816177
last_received_ts = 67.815559
last_seq = 863
current_ts = 67.832840
current_received_ts = 67.832230
current_seq = 864
count = 65
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.832840
last_received_ts = 67.832230
last_seq = 864
current_ts = 67.849510
current_received_ts = 67.848900
current_seq = 865
count = 66
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.849510
last_received_ts = 67.848900
last_seq = 865
current_ts = 67.866180
current_received_ts = 67.865570
current_seq = 866
count = 67
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.866180
last_received_ts = 67.865570
last_seq = 866
current_ts = 67.882843
current_received_ts = 67.882233
current_seq = 867
count = 68
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.882843
last_received_ts = 67.882233
last_seq = 867
current_ts = 67.899513
current_received_ts = 67.898903
current_seq = 868
count = 69
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.899513
last_received_ts = 67.898903
last_seq = 868
current_ts = 67.916183
current_received_ts = 67.915565
current_seq = 869
count = 70
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.916183
last_received_ts = 67.915565
last_seq = 869
current_ts = 67.932846
current_received_ts = 67.932236
current_seq = 870
count = 71
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.932846
last_received_ts = 67.932236
last_seq = 870
current_ts = 67.949516
current_received_ts = 67.948906
current_seq = 871
count = 72
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.949516
last_received_ts = 67.948906
last_seq = 871
current_ts = 67.966187
current_received_ts = 67.965569
current_seq = 872
count = 73
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.966187
last_received_ts = 67.965569
last_seq = 872
current_ts = 67.982849
current_received_ts = 67.982239
current_seq = 873
count = 74
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.982849
last_received_ts = 67.982239
last_seq = 873
current_ts = 67.999519
current_received_ts = 67.998909
current_seq = 874
count = 75
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 67.999519
last_received_ts = 67.998909
last_seq = 874
current_ts = 68.016190
current_received_ts = 68.015572
current_seq = 875
count = 76
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.016190
last_received_ts = 68.015572
last_seq = 875
current_ts = 68.032852
current_received_ts = 68.032242
current_seq = 876
count = 77
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.032852
last_received_ts = 68.032242
last_seq = 876
current_ts = 68.049522
current_received_ts = 68.048912
current_seq = 877
count = 78
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.049522
last_received_ts = 68.048912
last_seq = 877
current_ts = 68.066193
current_received_ts = 68.065575
current_seq = 878
count = 79
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.066193
last_received_ts = 68.065575
last_seq = 878
current_ts = 68.082855
current_received_ts = 68.082245
current_seq = 879
count = 80
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.082855
last_received_ts = 68.082245
last_seq = 879
current_ts = 68.099525
current_received_ts = 68.098915
current_seq = 880
count = 81
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.099525
last_received_ts = 68.098915
last_seq = 880
current_ts = 68.116196
current_received_ts = 68.115585
current_seq = 881
count = 82
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.116196
last_received_ts = 68.115585
last_seq = 881
current_ts = 68.132858
current_received_ts = 68.132248
current_seq = 882
count = 83
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.132858
last_received_ts = 68.132248
last_seq = 882
current_ts = 68.149529
current_received_ts = 68.148918
current_seq = 883
count = 84
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.149529
last_received_ts = 68.148918
last_seq = 883
current_ts = 68.166199
current_received_ts = 68.165588
current_seq = 884
count = 85
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.166199
last_received_ts = 68.165588
last_seq = 884
current_ts = 68.182861
current_received_ts = 68.182251
current_seq = 885
count = 86
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.182861
last_received_ts = 68.182251
last_seq = 885
current_ts = 68.199532
current_received_ts = 68.198921
current_seq = 886
count = 87
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.199532
last_received_ts = 68.198921
last_seq = 886
current_ts = 68.216202
current_received_ts = 68.215591
current_seq = 887
count = 88
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.216202
last_received_ts = 68.215591
last_seq = 887
current_ts = 68.232872
current_received_ts = 68.232254
current_seq = 888
count = 89
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.232872
last_received_ts = 68.232254
last_seq = 888
current_ts = 68.249535
current_received_ts = 68.248924
current_seq = 889
count = 90
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.249535
last_received_ts = 68.248924
last_seq = 889
current_ts = 68.266205
current_received_ts = 68.265594
current_seq = 890
count = 91
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.266205
last_received_ts = 68.265594
last_seq = 890
current_ts = 68.282875
current_received_ts = 68.282257
current_seq = 891
count = 92
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.282875
last_received_ts = 68.282257
last_seq = 891
current_ts = 68.299538
current_received_ts = 68.298927
current_seq = 892
count = 93
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.299538
last_received_ts = 68.298927
last_seq = 892
current_ts = 68.316208
current_received_ts = 68.315598
current_seq = 893
count = 94
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.316208
last_received_ts = 68.315598
last_seq = 893
current_ts = 68.332878
current_received_ts = 68.332260
current_seq = 894
count = 95
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.332878
last_received_ts = 68.332260
last_seq = 894
current_ts = 68.349541
current_received_ts = 68.348930
current_seq = 895
count = 96
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.349541
last_received_ts = 68.348930
last_seq = 895
current_ts = 68.366211
current_received_ts = 68.365601
current_seq = 896
count = 97
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.366211
last_received_ts = 68.365601
last_seq = 896
current_ts = 68.382881
current_received_ts = 68.382263
current_seq = 897
count = 98
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.382881
last_received_ts = 68.382263
last_seq = 897
current_ts = 68.399544
current_received_ts = 68.398933
current_seq = 898
count = 99
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.399544
last_received_ts = 68.398933
last_seq = 898
current_ts = 68.416214
current_received_ts = 68.415604
current_seq = 899
count = 100
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.416214
last_received_ts = 68.415604
last_seq = 899
current_ts = 68.432884
current_received_ts = 68.432266
current_seq = 900
count = 101
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.432884
last_received_ts = 68.432266
last_seq = 900
current_ts = 68.449547
current_received_ts = 68.448936
current_seq = 901
count = 102
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.449547
last_received_ts = 68.448936
last_seq = 901
current_ts = 68.466217
current_received_ts = 68.465607
current_seq = 902
count = 103
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.466217
last_received_ts = 68.465607
last_seq = 902
current_ts = 68.482887
current_received_ts = 68.482269
current_seq = 903
count = 104
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.482887
last_received_ts = 68.482269
last_seq = 903
current_ts = 68.499550
current_received_ts = 68.498940
current_seq = 904
count = 105
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.499550
last_received_ts = 68.498940
last_seq = 904
current_ts = 68.516220
current_received_ts = 68.515610
current_seq = 905
count = 106
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.516220
last_received_ts = 68.515610
last_seq = 905
current_ts = 68.532890
current_received_ts = 68.532288
current_seq = 906
count = 107
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 24us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.532890
last_received_ts = 68.532288
last_seq = 906
current_ts = 68.549561
current_received_ts = 68.548943
current_seq = 907
count = 108
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.549561
last_received_ts = 68.548943
last_seq = 907
current_ts = 68.566223
current_received_ts = 68.565613
current_seq = 908
count = 109
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.566223
last_received_ts = 68.565613
last_seq = 908
current_ts = 68.582893
current_received_ts = 68.582275
current_seq = 909
count = 110
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.582893
last_received_ts = 68.582275
last_seq = 909
current_ts = 68.599564
current_received_ts = 68.598946
current_seq = 910
count = 111
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.599564
last_received_ts = 68.598946
last_seq = 910
current_ts = 68.616226
current_received_ts = 68.615616
current_seq = 911
count = 112
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.616226
last_received_ts = 68.615616
last_seq = 911
current_ts = 68.632896
current_received_ts = 68.632286
current_seq = 912
count = 113
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.632896
last_received_ts = 68.632286
last_seq = 912
current_ts = 68.649567
current_received_ts = 68.648949
current_seq = 913
count = 114
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.649567
last_received_ts = 68.648949
last_seq = 913
current_ts = 68.666229
current_received_ts = 68.665619
current_seq = 914
count = 115
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.666229
last_received_ts = 68.665619
last_seq = 914
current_ts = 68.682899
current_received_ts = 68.682289
current_seq = 915
count = 116
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.682899
last_received_ts = 68.682289
last_seq = 915
current_ts = 68.699570
current_received_ts = 68.698952
current_seq = 916
count = 117
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.699570
last_received_ts = 68.698952
last_seq = 916
current_ts = 68.716232
current_received_ts = 68.715622
current_seq = 917
count = 118
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.716232
last_received_ts = 68.715622
last_seq = 917
current_ts = 68.732903
current_received_ts = 68.732307
current_seq = 918
count = 119
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 25us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.732903
last_received_ts = 68.732307
last_seq = 918
current_ts = 68.749573
current_received_ts = 68.748955
current_seq = 919
count = 120
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.749573
last_received_ts = 68.748955
last_seq = 919
current_ts = 68.766235
current_received_ts = 68.765625
current_seq = 920
count = 121
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.766235
last_received_ts = 68.765625
last_seq = 920
current_ts = 68.782906
current_received_ts = 68.782295
current_seq = 921
count = 122
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.782906
last_received_ts = 68.782295
last_seq = 921
current_ts = 68.799576
current_received_ts = 68.798958
current_seq = 922
count = 123
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.799576
last_received_ts = 68.798958
last_seq = 922
current_ts = 68.816238
current_received_ts = 68.815628
current_seq = 923
count = 124
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 68.816238
last_received_ts = 68.815628
last_seq = 923
current_ts = 68.832909
current_received_ts = 68.832329
current_seq = 924
count = 125
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 556us
(kms_flip:2231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2231) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2231) igt_core-INFO: Stack trace:
(kms_flip:2231) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2231) igt_core-INFO:   #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
(kms_flip:2231) igt_core-INFO:   #2 ../tests/kms_flip.c:1916 run_pair()
(kms_flip:2231) igt_core-INFO:   #3 ../tests/kms_flip.c:2073 __igt_unique____real_main1987()
(kms_flip:2231) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2231) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2231) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2231) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest AC-HDMI-A6-DP4: FAIL (2.794s)
Starting dynamic subtest: AD-HDMI-A6-DP4
Dynamic subtest AD-HDMI-A6-DP4: SUCCESS (5.379s)
Starting dynamic subtest: BC-HDMI-A6-DP4
(kms_flip:2231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2231) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest BC-HDMI-A6-DP4 failed.
**** DEBUG ****
(kms_flip:2231) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2231) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:2231) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2231) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2231) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=7680)
(kms_flip:2231) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2231) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb2286660, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb2286660, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb226cc90, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb226cc90, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb226c6c0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb226c6c0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb22867a0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb22867a0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2231) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2231) DEBUG: No stale events found
(kms_flip:2231) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2231) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2231) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2231) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2231) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 74.925369
current_received_ts = 74.924767
current_seq = 782
count = 0
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 26us
(kms_flip:2231) DEBUG: name = flip
last_ts = 74.925369
last_received_ts = 74.924767
last_seq = 782
current_ts = 74.942047
current_received_ts = 74.941444
current_seq = 783
count = 1
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 74.942047
last_received_ts = 74.941444
last_seq = 783
current_ts = 74.958717
current_received_ts = 74.958107
current_seq = 784
count = 2
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 74.958717
last_received_ts = 74.958107
last_seq = 784
current_ts = 74.975388
current_received_ts = 74.974777
current_seq = 785
count = 3
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 74.975388
last_received_ts = 74.974777
last_seq = 785
current_ts = 74.992050
current_received_ts = 74.991447
current_seq = 786
count = 4
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 74.992050
last_received_ts = 74.991447
last_seq = 786
current_ts = 75.008720
current_received_ts = 75.008110
current_seq = 787
count = 5
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.008720
last_received_ts = 75.008110
last_seq = 787
current_ts = 75.025391
current_received_ts = 75.024780
current_seq = 788
count = 6
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.025391
last_received_ts = 75.024780
last_seq = 788
current_ts = 75.042053
current_received_ts = 75.041451
current_seq = 789
count = 7
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.042053
last_received_ts = 75.041451
last_seq = 789
current_ts = 75.058723
current_received_ts = 75.058113
current_seq = 790
count = 8
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.058723
last_received_ts = 75.058113
last_seq = 790
current_ts = 75.075394
current_received_ts = 75.074783
current_seq = 791
count = 9
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.075394
last_received_ts = 75.074783
last_seq = 791
current_ts = 75.092056
current_received_ts = 75.091454
current_seq = 792
count = 10
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.092056
last_received_ts = 75.091454
last_seq = 792
current_ts = 75.108727
current_received_ts = 75.108124
current_seq = 793
count = 11
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.108727
last_received_ts = 75.108124
last_seq = 793
current_ts = 75.125397
current_received_ts = 75.124786
current_seq = 794
count = 12
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.125397
last_received_ts = 75.124786
last_seq = 794
current_ts = 75.142067
current_received_ts = 75.141457
current_seq = 795
count = 13
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.142067
last_received_ts = 75.141457
last_seq = 795
current_ts = 75.158730
current_received_ts = 75.158127
current_seq = 796
count = 14
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.158730
last_received_ts = 75.158127
last_seq = 796
current_ts = 75.175400
current_received_ts = 75.174789
current_seq = 797
count = 15
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.175400
last_received_ts = 75.174789
last_seq = 797
current_ts = 75.192070
current_received_ts = 75.191467
current_seq = 798
count = 16
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.192070
last_received_ts = 75.191467
last_seq = 798
current_ts = 75.208740
current_received_ts = 75.208130
current_seq = 799
count = 17
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.208740
last_received_ts = 75.208130
last_seq = 799
current_ts = 75.225403
current_received_ts = 75.224800
current_seq = 800
count = 18
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.225403
last_received_ts = 75.224800
last_seq = 800
current_ts = 75.242073
current_received_ts = 75.241463
current_seq = 801
count = 19
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.242073
last_received_ts = 75.241463
last_seq = 801
current_ts = 75.258743
current_received_ts = 75.258133
current_seq = 802
count = 20
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.258743
last_received_ts = 75.258133
last_seq = 802
current_ts = 75.275406
current_received_ts = 75.274803
current_seq = 803
count = 21
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.275406
last_received_ts = 75.274803
last_seq = 803
current_ts = 75.292076
current_received_ts = 75.291473
current_seq = 804
count = 22
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.292076
last_received_ts = 75.291473
last_seq = 804
current_ts = 75.308746
current_received_ts = 75.308136
current_seq = 805
count = 23
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.308746
last_received_ts = 75.308136
last_seq = 805
current_ts = 75.325417
current_received_ts = 75.324806
current_seq = 806
count = 24
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.325417
last_received_ts = 75.324806
last_seq = 806
current_ts = 75.342079
current_received_ts = 75.341476
current_seq = 807
count = 25
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.342079
last_received_ts = 75.341476
last_seq = 807
current_ts = 75.358749
current_received_ts = 75.358139
current_seq = 808
count = 26
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.358749
last_received_ts = 75.358139
last_seq = 808
current_ts = 75.375420
current_received_ts = 75.374809
current_seq = 809
count = 27
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.375420
last_received_ts = 75.374809
last_seq = 809
current_ts = 75.392082
current_received_ts = 75.391479
current_seq = 810
count = 28
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.392082
last_received_ts = 75.391479
last_seq = 810
current_ts = 75.408752
current_received_ts = 75.408142
current_seq = 811
count = 29
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.408752
last_received_ts = 75.408142
last_seq = 811
current_ts = 75.425423
current_received_ts = 75.424812
current_seq = 812
count = 30
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.425423
last_received_ts = 75.424812
last_seq = 812
current_ts = 75.442093
current_received_ts = 75.441483
current_seq = 813
count = 31
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.442093
last_received_ts = 75.441483
last_seq = 813
current_ts = 75.458755
current_received_ts = 75.458153
current_seq = 814
count = 32
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.458755
last_received_ts = 75.458153
last_seq = 814
current_ts = 75.475426
current_received_ts = 75.474815
current_seq = 815
count = 33
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.475426
last_received_ts = 75.474815
last_seq = 815
current_ts = 75.492096
current_received_ts = 75.491486
current_seq = 816
count = 34
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.492096
last_received_ts = 75.491486
last_seq = 816
current_ts = 75.508759
current_received_ts = 75.508156
current_seq = 817
count = 35
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.508759
last_received_ts = 75.508156
last_seq = 817
current_ts = 75.525429
current_received_ts = 75.524818
current_seq = 818
count = 36
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.525429
last_received_ts = 75.524818
last_seq = 818
current_ts = 75.542099
current_received_ts = 75.541489
current_seq = 819
count = 37
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.542099
last_received_ts = 75.541489
last_seq = 819
current_ts = 75.558769
current_received_ts = 75.558159
current_seq = 820
count = 38
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.558769
last_received_ts = 75.558159
last_seq = 820
current_ts = 75.575432
current_received_ts = 75.574829
current_seq = 821
count = 39
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.575432
last_received_ts = 75.574829
last_seq = 821
current_ts = 75.592102
current_received_ts = 75.591492
current_seq = 822
count = 40
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.592102
last_received_ts = 75.591492
last_seq = 822
current_ts = 75.608772
current_received_ts = 75.608162
current_seq = 823
count = 41
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.608772
last_received_ts = 75.608162
last_seq = 823
current_ts = 75.625443
current_received_ts = 75.624832
current_seq = 824
count = 42
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.625443
last_received_ts = 75.624832
last_seq = 824
current_ts = 75.642105
current_received_ts = 75.641495
current_seq = 825
count = 43
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.642105
last_received_ts = 75.641495
last_seq = 825
current_ts = 75.658775
current_received_ts = 75.658165
current_seq = 826
count = 44
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.658775
last_received_ts = 75.658165
last_seq = 826
current_ts = 75.675446
current_received_ts = 75.674835
current_seq = 827
count = 45
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.675446
last_received_ts = 75.674835
last_seq = 827
current_ts = 75.692108
current_received_ts = 75.691505
current_seq = 828
count = 46
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.692108
last_received_ts = 75.691505
last_seq = 828
current_ts = 75.708778
current_received_ts = 75.708176
current_seq = 829
count = 47
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.708778
last_received_ts = 75.708176
last_seq = 829
current_ts = 75.725449
current_received_ts = 75.724838
current_seq = 830
count = 48
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.725449
last_received_ts = 75.724838
last_seq = 830
current_ts = 75.742111
current_received_ts = 75.741508
current_seq = 831
count = 49
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.742111
last_received_ts = 75.741508
last_seq = 831
current_ts = 75.758781
current_received_ts = 75.758179
current_seq = 832
count = 50
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.758781
last_received_ts = 75.758179
last_seq = 832
current_ts = 75.775452
current_received_ts = 75.774841
current_seq = 833
count = 51
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.775452
last_received_ts = 75.774841
last_seq = 833
current_ts = 75.792122
current_received_ts = 75.791512
current_seq = 834
count = 52
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.792122
last_received_ts = 75.791512
last_seq = 834
current_ts = 75.808784
current_received_ts = 75.808182
current_seq = 835
count = 53
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.808784
last_received_ts = 75.808182
last_seq = 835
current_ts = 75.825455
current_received_ts = 75.824852
current_seq = 836
count = 54
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.825455
last_received_ts = 75.824852
last_seq = 836
current_ts = 75.842125
current_received_ts = 75.841515
current_seq = 837
count = 55
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.842125
last_received_ts = 75.841515
last_seq = 837
current_ts = 75.858788
current_received_ts = 75.858185
current_seq = 838
count = 56
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.858788
last_received_ts = 75.858185
last_seq = 838
current_ts = 75.875458
current_received_ts = 75.874847
current_seq = 839
count = 57
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.875458
last_received_ts = 75.874847
last_seq = 839
current_ts = 75.892128
current_received_ts = 75.891518
current_seq = 840
count = 58
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.892128
last_received_ts = 75.891518
last_seq = 840
current_ts = 75.908798
current_received_ts = 75.908188
current_seq = 841
count = 59
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.908798
last_received_ts = 75.908188
last_seq = 841
current_ts = 75.925461
current_received_ts = 75.924858
current_seq = 842
count = 60
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.925461
last_received_ts = 75.924858
last_seq = 842
current_ts = 75.942131
current_received_ts = 75.941559
current_seq = 843
count = 61
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 30us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.942131
last_received_ts = 75.941559
last_seq = 843
current_ts = 75.958794
current_received_ts = 75.958160
current_seq = 844
count = 62
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 291us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.958794
last_received_ts = 75.958160
last_seq = 844
current_ts = 75.975464
current_received_ts = 75.974838
current_seq = 845
count = 63
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 12us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.975464
last_received_ts = 75.974838
last_seq = 845
current_ts = 75.992134
current_received_ts = 75.991508
current_seq = 846
count = 64
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 25us
(kms_flip:2231) DEBUG: name = flip
last_ts = 75.992134
last_received_ts = 75.991508
last_seq = 846
current_ts = 76.008797
current_received_ts = 76.008156
current_seq = 847
count = 65
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 286us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.008797
last_received_ts = 76.008156
last_seq = 847
current_ts = 76.025475
current_received_ts = 76.024849
current_seq = 848
count = 66
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 13us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.025475
last_received_ts = 76.024849
last_seq = 848
current_ts = 76.042137
current_received_ts = 76.041534
current_seq = 849
count = 67
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.042137
last_received_ts = 76.041534
last_seq = 849
current_ts = 76.058807
current_received_ts = 76.058205
current_seq = 850
count = 68
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.058807
last_received_ts = 76.058205
last_seq = 850
current_ts = 76.075478
current_received_ts = 76.074875
current_seq = 851
count = 69
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.075478
last_received_ts = 76.074875
last_seq = 851
current_ts = 76.092140
current_received_ts = 76.091537
current_seq = 852
count = 70
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.092140
last_received_ts = 76.091537
last_seq = 852
current_ts = 76.108810
current_received_ts = 76.108215
current_seq = 853
count = 71
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.108810
last_received_ts = 76.108215
last_seq = 853
current_ts = 76.125481
current_received_ts = 76.124870
current_seq = 854
count = 72
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.125481
last_received_ts = 76.124870
last_seq = 854
current_ts = 76.142151
current_received_ts = 76.141541
current_seq = 855
count = 73
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 25us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.142151
last_received_ts = 76.141541
last_seq = 855
current_ts = 76.158813
current_received_ts = 76.158211
current_seq = 856
count = 74
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.158813
last_received_ts = 76.158211
last_seq = 856
current_ts = 76.175484
current_received_ts = 76.174873
current_seq = 857
count = 75
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.175484
last_received_ts = 76.174873
last_seq = 857
current_ts = 76.192154
current_received_ts = 76.191551
current_seq = 858
count = 76
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 25us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.192154
last_received_ts = 76.191551
last_seq = 858
current_ts = 76.208817
current_received_ts = 76.208214
current_seq = 859
count = 77
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.208817
last_received_ts = 76.208214
last_seq = 859
current_ts = 76.225487
current_received_ts = 76.224884
current_seq = 860
count = 78
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.225487
last_received_ts = 76.224884
last_seq = 860
current_ts = 76.242157
current_received_ts = 76.241554
current_seq = 861
count = 79
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 25us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.242157
last_received_ts = 76.241554
last_seq = 861
current_ts = 76.258827
current_received_ts = 76.258224
current_seq = 862
count = 80
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.258827
last_received_ts = 76.258224
last_seq = 862
current_ts = 76.275490
current_received_ts = 76.274887
current_seq = 863
count = 81
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.275490
last_received_ts = 76.274887
last_seq = 863
current_ts = 76.292160
current_received_ts = 76.291557
current_seq = 864
count = 82
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 241us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.292160
last_received_ts = 76.291557
last_seq = 864
current_ts = 76.308830
current_received_ts = 76.308228
current_seq = 865
count = 83
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.308830
last_received_ts = 76.308228
last_seq = 865
current_ts = 76.325493
current_received_ts = 76.324890
current_seq = 866
count = 84
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.325493
last_received_ts = 76.324890
last_seq = 866
current_ts = 76.342163
current_received_ts = 76.341560
current_seq = 867
count = 85
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.342163
last_received_ts = 76.341560
last_seq = 867
current_ts = 76.358833
current_received_ts = 76.358231
current_seq = 868
count = 86
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.358833
last_received_ts = 76.358231
last_seq = 868
current_ts = 76.375504
current_received_ts = 76.374893
current_seq = 869
count = 87
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.375504
last_received_ts = 76.374893
last_seq = 869
current_ts = 76.392166
current_received_ts = 76.391571
current_seq = 870
count = 88
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 462us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.392166
last_received_ts = 76.391571
last_seq = 870
current_ts = 76.408836
current_received_ts = 76.408234
current_seq = 871
count = 89
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.408836
last_received_ts = 76.408234
last_seq = 871
current_ts = 76.425507
current_received_ts = 76.424896
current_seq = 872
count = 90
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.425507
last_received_ts = 76.424896
last_seq = 872
current_ts = 76.442169
current_received_ts = 76.441566
current_seq = 873
count = 91
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 76.442169
last_received_ts = 76.441566
last_seq = 873
current_ts = 76.458839
current_received_ts = 76.458244
current_seq = 874
count = 92
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 661us
(kms_flip:2231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2231) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2231) igt_core-INFO: Stack trace:
(kms_flip:2231) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2231) igt_core-INFO:   #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
(kms_flip:2231) igt_core-INFO:   #2 ../tests/kms_flip.c:1916 run_pair()
(kms_flip:2231) igt_core-INFO:   #3 ../tests/kms_flip.c:2073 __igt_unique____real_main1987()
(kms_flip:2231) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2231) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2231) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2231) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest BC-HDMI-A6-DP4: FAIL (2.249s)
Starting dynamic subtest: BD-HDMI-A6-DP4
(kms_flip:2231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2231) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest BD-HDMI-A6-DP4 failed.
**** DEBUG ****
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.534035
last_received_ts = 78.533424
last_seq = 988
current_ts = 78.550697
current_received_ts = 78.550110
current_seq = 989
count = 82
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.550697
last_received_ts = 78.550110
last_seq = 989
current_ts = 78.567368
current_received_ts = 78.566757
current_seq = 990
count = 83
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.567368
last_received_ts = 78.566757
last_seq = 990
current_ts = 78.584038
current_received_ts = 78.583427
current_seq = 991
count = 84
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.584038
last_received_ts = 78.583427
last_seq = 991
current_ts = 78.600700
current_received_ts = 78.600105
current_seq = 992
count = 85
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 25us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.600700
last_received_ts = 78.600105
last_seq = 992
current_ts = 78.617371
current_received_ts = 78.616768
current_seq = 993
count = 86
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.617371
last_received_ts = 78.616768
last_seq = 993
current_ts = 78.634041
current_received_ts = 78.633430
current_seq = 994
count = 87
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.634041
last_received_ts = 78.633430
last_seq = 994
current_ts = 78.650703
current_received_ts = 78.650101
current_seq = 995
count = 88
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.650703
last_received_ts = 78.650101
last_seq = 995
current_ts = 78.667374
current_received_ts = 78.666763
current_seq = 996
count = 89
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.667374
last_received_ts = 78.666763
last_seq = 996
current_ts = 78.684044
current_received_ts = 78.683434
current_seq = 997
count = 90
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.684044
last_received_ts = 78.683434
last_seq = 997
current_ts = 78.700714
current_received_ts = 78.700104
current_seq = 998
count = 91
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.700714
last_received_ts = 78.700104
last_seq = 998
current_ts = 78.717377
current_received_ts = 78.716774
current_seq = 999
count = 92
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 24us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.717377
last_received_ts = 78.716774
last_seq = 999
current_ts = 78.734047
current_received_ts = 78.733437
current_seq = 1000
count = 93
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.734047
last_received_ts = 78.733437
last_seq = 1000
current_ts = 78.750702
current_received_ts = 78.750130
current_seq = 1001
count = 94
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 30us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.750702
last_received_ts = 78.750130
last_seq = 1001
current_ts = 78.767387
current_received_ts = 78.766785
current_seq = 1002
count = 95
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 24us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.767387
last_received_ts = 78.766785
last_seq = 1002
current_ts = 78.784050
current_received_ts = 78.783455
current_seq = 1003
count = 96
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 26us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.784050
last_received_ts = 78.783455
last_seq = 1003
current_ts = 78.800720
current_received_ts = 78.800117
current_seq = 1004
count = 97
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 26us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.800720
last_received_ts = 78.800117
last_seq = 1004
current_ts = 78.817390
current_received_ts = 78.816788
current_seq = 1005
count = 98
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 25us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.817390
last_received_ts = 78.816788
last_seq = 1005
current_ts = 78.834053
current_received_ts = 78.833450
current_seq = 1006
count = 99
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 24us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.834053
last_received_ts = 78.833450
last_seq = 1006
current_ts = 78.850723
current_received_ts = 78.850121
current_seq = 1007
count = 100
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.850723
last_received_ts = 78.850121
last_seq = 1007
current_ts = 78.867393
current_received_ts = 78.866791
current_seq = 1008
count = 101
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 24us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.867393
last_received_ts = 78.866791
last_seq = 1008
current_ts = 78.884056
current_received_ts = 78.883453
current_seq = 1009
count = 102
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 24us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.884056
last_received_ts = 78.883453
last_seq = 1009
current_ts = 78.900726
current_received_ts = 78.900124
current_seq = 1010
count = 103
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.900726
last_received_ts = 78.900124
last_seq = 1010
current_ts = 78.917397
current_received_ts = 78.916786
current_seq = 1011
count = 104
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.917397
last_received_ts = 78.916786
last_seq = 1011
current_ts = 78.934067
current_received_ts = 78.933487
current_seq = 1012
count = 105
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 33us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.934067
last_received_ts = 78.933487
last_seq = 1012
current_ts = 78.950729
current_received_ts = 78.950134
current_seq = 1013
count = 106
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 24us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.950729
last_received_ts = 78.950134
last_seq = 1013
current_ts = 78.967400
current_received_ts = 78.966797
current_seq = 1014
count = 107
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.967400
last_received_ts = 78.966797
last_seq = 1014
current_ts = 78.984070
current_received_ts = 78.983459
current_seq = 1015
count = 108
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 78.984070
last_received_ts = 78.983459
last_seq = 1015
current_ts = 79.000732
current_received_ts = 79.000137
current_seq = 1016
count = 109
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 25us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.000732
last_received_ts = 79.000137
last_seq = 1016
current_ts = 79.017403
current_received_ts = 79.016800
current_seq = 1017
count = 110
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 24us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.017403
last_received_ts = 79.016800
last_seq = 1017
current_ts = 79.034073
current_received_ts = 79.033470
current_seq = 1018
count = 111
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.034073
last_received_ts = 79.033470
last_seq = 1018
current_ts = 79.050735
current_received_ts = 79.050133
current_seq = 1019
count = 112
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 24us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.050735
last_received_ts = 79.050133
last_seq = 1019
current_ts = 79.067406
current_received_ts = 79.066803
current_seq = 1020
count = 113
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.067406
last_received_ts = 79.066803
last_seq = 1020
current_ts = 79.084076
current_received_ts = 79.083473
current_seq = 1021
count = 114
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 24us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.084076
last_received_ts = 79.083473
last_seq = 1021
current_ts = 79.100746
current_received_ts = 79.100136
current_seq = 1022
count = 115
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.100746
last_received_ts = 79.100136
last_seq = 1022
current_ts = 79.117409
current_received_ts = 79.116806
current_seq = 1023
count = 116
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.117409
last_received_ts = 79.116806
last_seq = 1023
current_ts = 79.134064
current_received_ts = 79.133530
current_seq = 1024
count = 117
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 307us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.134064
last_received_ts = 79.133530
last_seq = 1024
current_ts = 79.150749
current_received_ts = 79.150177
current_seq = 1025
count = 118
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 30us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.150749
last_received_ts = 79.150177
last_seq = 1025
current_ts = 79.167412
current_received_ts = 79.166832
current_seq = 1026
count = 119
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 28us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.167412
last_received_ts = 79.166832
last_seq = 1026
current_ts = 79.184082
current_received_ts = 79.183479
current_seq = 1027
count = 120
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 27us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.184082
last_received_ts = 79.183479
last_seq = 1027
current_ts = 79.200752
current_received_ts = 79.200142
current_seq = 1028
count = 121
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.200752
last_received_ts = 79.200142
last_seq = 1028
current_ts = 79.217422
current_received_ts = 79.216805
current_seq = 1029
count = 122
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.217422
last_received_ts = 79.216805
last_seq = 1029
current_ts = 79.234085
current_received_ts = 79.233482
current_seq = 1030
count = 123
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 24us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.234085
last_received_ts = 79.233482
last_seq = 1030
current_ts = 79.250755
current_received_ts = 79.250145
current_seq = 1031
count = 124
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.250755
last_received_ts = 79.250145
last_seq = 1031
current_ts = 79.267426
current_received_ts = 79.266815
current_seq = 1032
count = 125
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.267426
last_received_ts = 79.266815
last_seq = 1032
current_ts = 79.284088
current_received_ts = 79.283478
current_seq = 1033
count = 126
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.284088
last_received_ts = 79.283478
last_seq = 1033
current_ts = 79.300758
current_received_ts = 79.300148
current_seq = 1034
count = 127
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.300758
last_received_ts = 79.300148
last_seq = 1034
current_ts = 79.317429
current_received_ts = 79.316818
current_seq = 1035
count = 128
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.317429
last_received_ts = 79.316818
last_seq = 1035
current_ts = 79.334091
current_received_ts = 79.333481
current_seq = 1036
count = 129
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.334091
last_received_ts = 79.333481
last_seq = 1036
current_ts = 79.350761
current_received_ts = 79.350151
current_seq = 1037
count = 130
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.350761
last_received_ts = 79.350151
last_seq = 1037
current_ts = 79.367432
current_received_ts = 79.366821
current_seq = 1038
count = 131
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.367432
last_received_ts = 79.366821
last_seq = 1038
current_ts = 79.384102
current_received_ts = 79.383492
current_seq = 1039
count = 132
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.384102
last_received_ts = 79.383492
last_seq = 1039
current_ts = 79.400764
current_received_ts = 79.400154
current_seq = 1040
count = 133
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.400764
last_received_ts = 79.400154
last_seq = 1040
current_ts = 79.417435
current_received_ts = 79.416824
current_seq = 1041
count = 134
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.417435
last_received_ts = 79.416824
last_seq = 1041
current_ts = 79.434105
current_received_ts = 79.433495
current_seq = 1042
count = 135
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.434105
last_received_ts = 79.433495
last_seq = 1042
current_ts = 79.450768
current_received_ts = 79.450157
current_seq = 1043
count = 136
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.450768
last_received_ts = 79.450157
last_seq = 1043
current_ts = 79.467438
current_received_ts = 79.466827
current_seq = 1044
count = 137
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.467438
last_received_ts = 79.466827
last_seq = 1044
current_ts = 79.484108
current_received_ts = 79.483498
current_seq = 1045
count = 138
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.484108
last_received_ts = 79.483498
last_seq = 1045
current_ts = 79.500778
current_received_ts = 79.500160
current_seq = 1046
count = 139
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.500778
last_received_ts = 79.500160
last_seq = 1046
current_ts = 79.517441
current_received_ts = 79.516830
current_seq = 1047
count = 140
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 24us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.517441
last_received_ts = 79.516830
last_seq = 1047
current_ts = 79.534111
current_received_ts = 79.533501
current_seq = 1048
count = 141
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.534111
last_received_ts = 79.533501
last_seq = 1048
current_ts = 79.550781
current_received_ts = 79.550171
current_seq = 1049
count = 142
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.550781
last_received_ts = 79.550171
last_seq = 1049
current_ts = 79.567444
current_received_ts = 79.566833
current_seq = 1050
count = 143
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.567444
last_received_ts = 79.566833
last_seq = 1050
current_ts = 79.584114
current_received_ts = 79.583504
current_seq = 1051
count = 144
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.584114
last_received_ts = 79.583504
last_seq = 1051
current_ts = 79.600784
current_received_ts = 79.600174
current_seq = 1052
count = 145
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.600784
last_received_ts = 79.600174
last_seq = 1052
current_ts = 79.617455
current_received_ts = 79.616837
current_seq = 1053
count = 146
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.617455
last_received_ts = 79.616837
last_seq = 1053
current_ts = 79.634117
current_received_ts = 79.633507
current_seq = 1054
count = 147
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.634117
last_received_ts = 79.633507
last_seq = 1054
current_ts = 79.650787
current_received_ts = 79.650177
current_seq = 1055
count = 148
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.650787
last_received_ts = 79.650177
last_seq = 1055
current_ts = 79.667458
current_received_ts = 79.666840
current_seq = 1056
count = 149
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.667458
last_received_ts = 79.666840
last_seq = 1056
current_ts = 79.684120
current_received_ts = 79.683517
current_seq = 1057
count = 150
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.684120
last_received_ts = 79.683517
last_seq = 1057
current_ts = 79.700790
current_received_ts = 79.700180
current_seq = 1058
count = 151
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.700790
last_received_ts = 79.700180
last_seq = 1058
current_ts = 79.717461
current_received_ts = 79.716850
current_seq = 1059
count = 152
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.717461
last_received_ts = 79.716850
last_seq = 1059
current_ts = 79.734123
current_received_ts = 79.733513
current_seq = 1060
count = 153
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.734123
last_received_ts = 79.733513
last_seq = 1060
current_ts = 79.750793
current_received_ts = 79.750183
current_seq = 1061
count = 154
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.750793
last_received_ts = 79.750183
last_seq = 1061
current_ts = 79.767464
current_received_ts = 79.766853
current_seq = 1062
count = 155
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.767464
last_received_ts = 79.766853
last_seq = 1062
current_ts = 79.784134
current_received_ts = 79.783524
current_seq = 1063
count = 156
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.784134
last_received_ts = 79.783524
last_seq = 1063
current_ts = 79.800797
current_received_ts = 79.800186
current_seq = 1064
count = 157
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.800797
last_received_ts = 79.800186
last_seq = 1064
current_ts = 79.817467
current_received_ts = 79.816856
current_seq = 1065
count = 158
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.817467
last_received_ts = 79.816856
last_seq = 1065
current_ts = 79.834137
current_received_ts = 79.833527
current_seq = 1066
count = 159
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.834137
last_received_ts = 79.833527
last_seq = 1066
current_ts = 79.850800
current_received_ts = 79.850189
current_seq = 1067
count = 160
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.850800
last_received_ts = 79.850189
last_seq = 1067
current_ts = 79.867470
current_received_ts = 79.866859
current_seq = 1068
count = 161
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.867470
last_received_ts = 79.866859
last_seq = 1068
current_ts = 79.884140
current_received_ts = 79.883530
current_seq = 1069
count = 162
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.884140
last_received_ts = 79.883530
last_seq = 1069
current_ts = 79.900810
current_received_ts = 79.900192
current_seq = 1070
count = 163
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.900810
last_received_ts = 79.900192
last_seq = 1070
current_ts = 79.917473
current_received_ts = 79.916862
current_seq = 1071
count = 164
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.917473
last_received_ts = 79.916862
last_seq = 1071
current_ts = 79.934143
current_received_ts = 79.933533
current_seq = 1072
count = 165
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.934143
last_received_ts = 79.933533
last_seq = 1072
current_ts = 79.950813
current_received_ts = 79.950195
current_seq = 1073
count = 166
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.950813
last_received_ts = 79.950195
last_seq = 1073
current_ts = 79.967476
current_received_ts = 79.966866
current_seq = 1074
count = 167
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.967476
last_received_ts = 79.966866
last_seq = 1074
current_ts = 79.984146
current_received_ts = 79.983536
current_seq = 1075
count = 168
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 79.984146
last_received_ts = 79.983536
last_seq = 1075
current_ts = 80.000816
current_received_ts = 80.000206
current_seq = 1076
count = 169
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.000816
last_received_ts = 80.000206
last_seq = 1076
current_ts = 80.017479
current_received_ts = 80.016869
current_seq = 1077
count = 170
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.017479
last_received_ts = 80.016869
last_seq = 1077
current_ts = 80.034149
current_received_ts = 80.033539
current_seq = 1078
count = 171
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.034149
last_received_ts = 80.033539
last_seq = 1078
current_ts = 80.050819
current_received_ts = 80.050209
current_seq = 1079
count = 172
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.050819
last_received_ts = 80.050209
last_seq = 1079
current_ts = 80.067490
current_received_ts = 80.066872
current_seq = 1080
count = 173
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.067490
last_received_ts = 80.066872
last_seq = 1080
current_ts = 80.084152
current_received_ts = 80.083542
current_seq = 1081
count = 174
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.084152
last_received_ts = 80.083542
last_seq = 1081
current_ts = 80.100822
current_received_ts = 80.100212
current_seq = 1082
count = 175
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.100822
last_received_ts = 80.100212
last_seq = 1082
current_ts = 80.117493
current_received_ts = 80.116882
current_seq = 1083
count = 176
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.117493
last_received_ts = 80.116882
last_seq = 1083
current_ts = 80.134155
current_received_ts = 80.133545
current_seq = 1084
count = 177
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.134155
last_received_ts = 80.133545
last_seq = 1084
current_ts = 80.150826
current_received_ts = 80.150215
current_seq = 1085
count = 178
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.150826
last_received_ts = 80.150215
last_seq = 1085
current_ts = 80.167496
current_received_ts = 80.166885
current_seq = 1086
count = 179
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.167496
last_received_ts = 80.166885
last_seq = 1086
current_ts = 80.184158
current_received_ts = 80.183548
current_seq = 1087
count = 180
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.184158
last_received_ts = 80.183548
last_seq = 1087
current_ts = 80.200829
current_received_ts = 80.200218
current_seq = 1088
count = 181
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.200829
last_received_ts = 80.200218
last_seq = 1088
current_ts = 80.217499
current_received_ts = 80.216888
current_seq = 1089
count = 182
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.217499
last_received_ts = 80.216888
last_seq = 1089
current_ts = 80.234169
current_received_ts = 80.233551
current_seq = 1090
count = 183
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.234169
last_received_ts = 80.233551
last_seq = 1090
current_ts = 80.250832
current_received_ts = 80.250221
current_seq = 1091
count = 184
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.250832
last_received_ts = 80.250221
last_seq = 1091
current_ts = 80.267502
current_received_ts = 80.266891
current_seq = 1092
count = 185
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.267502
last_received_ts = 80.266891
last_seq = 1092
current_ts = 80.284172
current_received_ts = 80.283562
current_seq = 1093
count = 186
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.284172
last_received_ts = 80.283562
last_seq = 1093
current_ts = 80.300835
current_received_ts = 80.300224
current_seq = 1094
count = 187
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.300835
last_received_ts = 80.300224
last_seq = 1094
current_ts = 80.317505
current_received_ts = 80.316895
current_seq = 1095
count = 188
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.317505
last_received_ts = 80.316895
last_seq = 1095
current_ts = 80.334175
current_received_ts = 80.333565
current_seq = 1096
count = 189
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.334175
last_received_ts = 80.333565
last_seq = 1096
current_ts = 80.350845
current_received_ts = 80.350227
current_seq = 1097
count = 190
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.350845
last_received_ts = 80.350227
last_seq = 1097
current_ts = 80.367508
current_received_ts = 80.366898
current_seq = 1098
count = 191
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.367508
last_received_ts = 80.366898
last_seq = 1098
current_ts = 80.384178
current_received_ts = 80.383568
current_seq = 1099
count = 192
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.384178
last_received_ts = 80.383568
last_seq = 1099
current_ts = 80.400848
current_received_ts = 80.400253
current_seq = 1100
count = 193
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 27us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.400848
last_received_ts = 80.400253
last_seq = 1100
current_ts = 80.417511
current_received_ts = 80.416908
current_seq = 1101
count = 194
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 22us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.417511
last_received_ts = 80.416908
last_seq = 1101
current_ts = 80.434181
current_received_ts = 80.433693
current_seq = 1102
count = 195
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 36us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.434181
last_received_ts = 80.433693
last_seq = 1102
current_ts = 80.450851
current_received_ts = 80.450294
current_seq = 1103
count = 196
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 35us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.450851
last_received_ts = 80.450294
last_seq = 1103
current_ts = 80.467522
current_received_ts = 80.466911
current_seq = 1104
count = 197
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.467522
last_received_ts = 80.466911
last_seq = 1104
current_ts = 80.484184
current_received_ts = 80.483574
current_seq = 1105
count = 198
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.484184
last_received_ts = 80.483574
last_seq = 1105
current_ts = 80.500854
current_received_ts = 80.500244
current_seq = 1106
count = 199
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.500854
last_received_ts = 80.500244
last_seq = 1106
current_ts = 80.517525
current_received_ts = 80.516914
current_seq = 1107
count = 200
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.517525
last_received_ts = 80.516914
last_seq = 1107
current_ts = 80.534187
current_received_ts = 80.533585
current_seq = 1108
count = 201
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.534187
last_received_ts = 80.533585
last_seq = 1108
current_ts = 80.550858
current_received_ts = 80.550247
current_seq = 1109
count = 202
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 80.550858
last_received_ts = 80.550247
last_seq = 1109
current_ts = 80.567528
current_received_ts = 80.567047
current_seq = 1110
count = 203
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 583us
(kms_flip:2231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2231) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2231) igt_core-INFO: Stack trace:
(kms_flip:2231) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2231) igt_core-INFO:   #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
(kms_flip:2231) igt_core-INFO:   #2 ../tests/kms_flip.c:1916 run_pair()
(kms_flip:2231) igt_core-INFO:   #3 ../tests/kms_flip.c:2073 __igt_unique____real_main1987()
(kms_flip:2231) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2231) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2231) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2231) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest BD-HDMI-A6-DP4: FAIL (4.085s)
Starting dynamic subtest: CD-HDMI-A6-DP4
(kms_flip:2231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2231) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest CD-HDMI-A6-DP4 failed.
**** DEBUG ****
(kms_flip:2231) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2231) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=7, pitch=7680)
(kms_flip:2231) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2231) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2231) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=8, pitch=7680)
(kms_flip:2231) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2231) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb227f600, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb227f600, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb227f600, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb227f600, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb228f190, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb228f190, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb226c4e0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) intel_allocator_simple-DEBUG: <ial: 0x61acb226c4e0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2231) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2231) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2231) DEBUG: No stale events found
(kms_flip:2231) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2231) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2231) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2231) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2231) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 81.286324
current_received_ts = 81.285721
current_seq = 302
count = 0
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 25us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.286324
last_received_ts = 81.285721
last_seq = 302
current_ts = 81.303009
current_received_ts = 81.302399
current_seq = 303
count = 1
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.303009
last_received_ts = 81.302399
last_seq = 303
current_ts = 81.319664
current_received_ts = 81.319069
current_seq = 304
count = 2
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.319664
last_received_ts = 81.319069
last_seq = 304
current_ts = 81.336342
current_received_ts = 81.335732
current_seq = 305
count = 3
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.336342
last_received_ts = 81.335732
last_seq = 305
current_ts = 81.353012
current_received_ts = 81.352402
current_seq = 306
count = 4
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.353012
last_received_ts = 81.352402
last_seq = 306
current_ts = 81.369675
current_received_ts = 81.369080
current_seq = 307
count = 5
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.369675
last_received_ts = 81.369080
last_seq = 307
current_ts = 81.386345
current_received_ts = 81.385742
current_seq = 308
count = 6
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.386345
last_received_ts = 81.385742
last_seq = 308
current_ts = 81.403015
current_received_ts = 81.402405
current_seq = 309
count = 7
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 21us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.403015
last_received_ts = 81.402405
last_seq = 309
current_ts = 81.419670
current_received_ts = 81.419083
current_seq = 310
count = 8
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 19us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.419670
last_received_ts = 81.419083
last_seq = 310
current_ts = 81.436348
current_received_ts = 81.435745
current_seq = 311
count = 9
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.436348
last_received_ts = 81.435745
last_seq = 311
current_ts = 81.453018
current_received_ts = 81.452408
current_seq = 312
count = 10
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.453018
last_received_ts = 81.452408
last_seq = 312
current_ts = 81.469673
current_received_ts = 81.469078
current_seq = 313
count = 11
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 23us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.469673
last_received_ts = 81.469078
last_seq = 313
current_ts = 81.486351
current_received_ts = 81.485748
current_seq = 314
count = 12
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 20us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.486351
last_received_ts = 81.485748
last_seq = 314
current_ts = 81.503014
current_received_ts = 81.502480
current_seq = 315
count = 13
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 37us
(kms_flip:2231) DEBUG: name = flip
last_ts = 81.503014
last_received_ts = 81.502480
last_seq = 315
current_ts = 81.519691
current_received_ts = 81.519180
current_seq = 316
count = 14
seq_step = 1
(kms_flip:2231) DEBUG: Vblank took 731us
(kms_flip:2231) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2231) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2231) igt_core-INFO: Stack trace:
(kms_flip:2231) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2231) igt_core-INFO:   #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
(kms_flip:2231) igt_core-INFO:   #2 ../tests/kms_flip.c:1916 run_pair()
(kms_flip:2231) igt_core-INFO:   #3 ../tests/kms_flip.c:2073 __igt_unique____real_main1987()
(kms_flip:2231) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2231) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2231) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2231) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest CD-HDMI-A6-DP4: FAIL (0.613s)
Subtest 2x-flip-vs-expired-vblank: FAIL (20.598s)
(kms_flip:2231) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:2231) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2231) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2231) igt_kms-CRITICAL: DPMS property not found on 260