Results for igt@kms_flip@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=1741738173 for randomisation
Opened device: /dev/dri/card1
Using monotonic timestamps
Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-HDMI-A6
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Dynamic subtest A-HDMI-A6: SUCCESS (4.124s)
Starting dynamic subtest: B-HDMI-A6
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Dynamic subtest B-HDMI-A6: SUCCESS (3.961s)
Starting dynamic subtest: C-HDMI-A6
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Dynamic subtest C-HDMI-A6: SUCCESS (3.978s)
Starting dynamic subtest: D-HDMI-A6
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Dynamic subtest D-HDMI-A6: SUCCESS (3.961s)
Starting dynamic subtest: A-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-DP4: FAIL (2.649s)
Starting dynamic subtest: B-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-DP4: FAIL (1.326s)
Starting dynamic subtest: C-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Dynamic subtest C-DP4: SUCCESS (3.979s)
Starting dynamic subtest: D-DP4
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest D-DP4: FAIL (2.481s)
Subtest flip-vs-expired-vblank: FAIL (26.478s)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2246 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2934 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2390 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-HDMI-A6
Dynamic subtest A-HDMI-A6: SUCCESS (4.124s)
Starting dynamic subtest: B-HDMI-A6
Dynamic subtest B-HDMI-A6: SUCCESS (3.961s)
Starting dynamic subtest: C-HDMI-A6
Dynamic subtest C-HDMI-A6: SUCCESS (3.978s)
Starting dynamic subtest: D-HDMI-A6
Dynamic subtest D-HDMI-A6: SUCCESS (3.961s)
Starting dynamic subtest: A-DP4
(kms_flip:2376) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2376) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest A-DP4 failed.
**** DEBUG ****
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.667938
last_received_ts = 95.667412
last_seq = 1849
current_ts = 95.684593
current_received_ts = 95.684074
current_seq = 1850
count = 3
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.684593
last_received_ts = 95.684074
last_seq = 1850
current_ts = 95.701263
current_received_ts = 95.700737
current_seq = 1851
count = 4
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.701263
last_received_ts = 95.700737
last_seq = 1851
current_ts = 95.717934
current_received_ts = 95.717400
current_seq = 1852
count = 5
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.717934
last_received_ts = 95.717400
last_seq = 1852
current_ts = 95.734604
current_received_ts = 95.734070
current_seq = 1853
count = 6
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 20us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.734604
last_received_ts = 95.734070
last_seq = 1853
current_ts = 95.751274
current_received_ts = 95.750755
current_seq = 1854
count = 7
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.751274
last_received_ts = 95.750755
last_seq = 1854
current_ts = 95.767929
current_received_ts = 95.767410
current_seq = 1855
count = 8
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.767929
last_received_ts = 95.767410
last_seq = 1855
current_ts = 95.784599
current_received_ts = 95.784081
current_seq = 1856
count = 9
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.784599
last_received_ts = 95.784081
last_seq = 1856
current_ts = 95.801277
current_received_ts = 95.800735
current_seq = 1857
count = 10
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.801277
last_received_ts = 95.800735
last_seq = 1857
current_ts = 95.817932
current_received_ts = 95.817413
current_seq = 1858
count = 11
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.817932
last_received_ts = 95.817413
last_seq = 1858
current_ts = 95.834602
current_received_ts = 95.834068
current_seq = 1859
count = 12
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.834602
last_received_ts = 95.834068
last_seq = 1859
current_ts = 95.851273
current_received_ts = 95.850754
current_seq = 1860
count = 13
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.851273
last_received_ts = 95.850754
last_seq = 1860
current_ts = 95.867943
current_received_ts = 95.867416
current_seq = 1861
count = 14
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.867943
last_received_ts = 95.867416
last_seq = 1861
current_ts = 95.884605
current_received_ts = 95.884087
current_seq = 1862
count = 15
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.884605
last_received_ts = 95.884087
last_seq = 1862
current_ts = 95.901283
current_received_ts = 95.900749
current_seq = 1863
count = 16
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.901283
last_received_ts = 95.900749
last_seq = 1863
current_ts = 95.917938
current_received_ts = 95.917419
current_seq = 1864
count = 17
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.917938
last_received_ts = 95.917419
last_seq = 1864
current_ts = 95.934608
current_received_ts = 95.934090
current_seq = 1865
count = 18
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.934608
last_received_ts = 95.934090
last_seq = 1865
current_ts = 95.951279
current_received_ts = 95.950745
current_seq = 1866
count = 19
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.951279
last_received_ts = 95.950745
last_seq = 1866
current_ts = 95.967941
current_received_ts = 95.967430
current_seq = 1867
count = 20
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.967941
last_received_ts = 95.967430
last_seq = 1867
current_ts = 95.984619
current_received_ts = 95.984131
current_seq = 1868
count = 21
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 202us
(kms_flip:2376) DEBUG: name = flip
last_ts = 95.984619
last_received_ts = 95.984131
last_seq = 1868
current_ts = 96.001289
current_received_ts = 96.000854
current_seq = 1869
count = 22
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 167us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.001289
last_received_ts = 96.000854
last_seq = 1869
current_ts = 96.017952
current_received_ts = 96.017517
current_seq = 1870
count = 23
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 337us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.017952
last_received_ts = 96.017517
last_seq = 1870
current_ts = 96.034622
current_received_ts = 96.034134
current_seq = 1871
count = 24
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 388us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.034622
last_received_ts = 96.034134
last_seq = 1871
current_ts = 96.051285
current_received_ts = 96.050758
current_seq = 1872
count = 25
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.051285
last_received_ts = 96.050758
last_seq = 1872
current_ts = 96.067963
current_received_ts = 96.067429
current_seq = 1873
count = 26
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 20us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.067963
last_received_ts = 96.067429
last_seq = 1873
current_ts = 96.084618
current_received_ts = 96.084099
current_seq = 1874
count = 27
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.084618
last_received_ts = 96.084099
last_seq = 1874
current_ts = 96.101295
current_received_ts = 96.100761
current_seq = 1875
count = 28
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.101295
last_received_ts = 96.100761
last_seq = 1875
current_ts = 96.117958
current_received_ts = 96.117432
current_seq = 1876
count = 29
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.117958
last_received_ts = 96.117432
last_seq = 1876
current_ts = 96.134628
current_received_ts = 96.134094
current_seq = 1877
count = 30
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.134628
last_received_ts = 96.134094
last_seq = 1877
current_ts = 96.151299
current_received_ts = 96.150871
current_seq = 1878
count = 31
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 163us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.151299
last_received_ts = 96.150871
last_seq = 1878
current_ts = 96.167961
current_received_ts = 96.167526
current_seq = 1879
count = 32
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 337us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.167961
last_received_ts = 96.167526
last_seq = 1879
current_ts = 96.184631
current_received_ts = 96.184151
current_seq = 1880
count = 33
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 196us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.184631
last_received_ts = 96.184151
last_seq = 1880
current_ts = 96.201302
current_received_ts = 96.200768
current_seq = 1881
count = 34
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.201302
last_received_ts = 96.200768
last_seq = 1881
current_ts = 96.217964
current_received_ts = 96.217438
current_seq = 1882
count = 35
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.217964
last_received_ts = 96.217438
last_seq = 1882
current_ts = 96.234634
current_received_ts = 96.234100
current_seq = 1883
count = 36
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 19us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.234634
last_received_ts = 96.234100
last_seq = 1883
current_ts = 96.251297
current_received_ts = 96.250824
current_seq = 1884
count = 37
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 189us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.251297
last_received_ts = 96.250824
last_seq = 1884
current_ts = 96.267975
current_received_ts = 96.267448
current_seq = 1885
count = 38
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 25us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.267975
last_received_ts = 96.267448
last_seq = 1885
current_ts = 96.284645
current_received_ts = 96.284111
current_seq = 1886
count = 39
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 20us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.284645
last_received_ts = 96.284111
last_seq = 1886
current_ts = 96.301315
current_received_ts = 96.300774
current_seq = 1887
count = 40
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 20us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.301315
last_received_ts = 96.300774
last_seq = 1887
current_ts = 96.317978
current_received_ts = 96.317444
current_seq = 1888
count = 41
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.317978
last_received_ts = 96.317444
last_seq = 1888
current_ts = 96.334641
current_received_ts = 96.334114
current_seq = 1889
count = 42
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.334641
last_received_ts = 96.334114
last_seq = 1889
current_ts = 96.351311
current_received_ts = 96.350777
current_seq = 1890
count = 43
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.351311
last_received_ts = 96.350777
last_seq = 1890
current_ts = 96.367973
current_received_ts = 96.367447
current_seq = 1891
count = 44
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 20us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.367973
last_received_ts = 96.367447
last_seq = 1891
current_ts = 96.384644
current_received_ts = 96.384132
current_seq = 1892
count = 45
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.384644
last_received_ts = 96.384132
last_seq = 1892
current_ts = 96.401314
current_received_ts = 96.400787
current_seq = 1893
count = 46
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.401314
last_received_ts = 96.400787
last_seq = 1893
current_ts = 96.417984
current_received_ts = 96.417450
current_seq = 1894
count = 47
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.417984
last_received_ts = 96.417450
last_seq = 1894
current_ts = 96.434647
current_received_ts = 96.434128
current_seq = 1895
count = 48
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.434647
last_received_ts = 96.434128
last_seq = 1895
current_ts = 96.451309
current_received_ts = 96.450790
current_seq = 1896
count = 49
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.451309
last_received_ts = 96.450790
last_seq = 1896
current_ts = 96.467979
current_received_ts = 96.467461
current_seq = 1897
count = 50
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.467979
last_received_ts = 96.467461
last_seq = 1897
current_ts = 96.484657
current_received_ts = 96.484116
current_seq = 1898
count = 51
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.484657
last_received_ts = 96.484116
last_seq = 1898
current_ts = 96.501328
current_received_ts = 96.500786
current_seq = 1899
count = 52
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.501328
last_received_ts = 96.500786
last_seq = 1899
current_ts = 96.517982
current_received_ts = 96.517448
current_seq = 1900
count = 53
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.517982
last_received_ts = 96.517448
last_seq = 1900
current_ts = 96.534660
current_received_ts = 96.534126
current_seq = 1901
count = 54
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.534660
last_received_ts = 96.534126
last_seq = 1901
current_ts = 96.551315
current_received_ts = 96.550797
current_seq = 1902
count = 55
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.551315
last_received_ts = 96.550797
last_seq = 1902
current_ts = 96.567993
current_received_ts = 96.567459
current_seq = 1903
count = 56
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.567993
last_received_ts = 96.567459
last_seq = 1903
current_ts = 96.584656
current_received_ts = 96.584122
current_seq = 1904
count = 57
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.584656
last_received_ts = 96.584122
last_seq = 1904
current_ts = 96.601318
current_received_ts = 96.600792
current_seq = 1905
count = 58
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 19us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.601318
last_received_ts = 96.600792
last_seq = 1905
current_ts = 96.617989
current_received_ts = 96.617470
current_seq = 1906
count = 59
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.617989
last_received_ts = 96.617470
last_seq = 1906
current_ts = 96.634659
current_received_ts = 96.634140
current_seq = 1907
count = 60
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.634659
last_received_ts = 96.634140
last_seq = 1907
current_ts = 96.651337
current_received_ts = 96.650803
current_seq = 1908
count = 61
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.651337
last_received_ts = 96.650803
last_seq = 1908
current_ts = 96.667999
current_received_ts = 96.667465
current_seq = 1909
count = 62
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.667999
last_received_ts = 96.667465
last_seq = 1909
current_ts = 96.684669
current_received_ts = 96.684128
current_seq = 1910
count = 63
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.684669
last_received_ts = 96.684128
last_seq = 1910
current_ts = 96.701332
current_received_ts = 96.700798
current_seq = 1911
count = 64
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.701332
last_received_ts = 96.700798
last_seq = 1911
current_ts = 96.718002
current_received_ts = 96.717461
current_seq = 1912
count = 65
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.718002
last_received_ts = 96.717461
last_seq = 1912
current_ts = 96.734665
current_received_ts = 96.734131
current_seq = 1913
count = 66
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.734665
last_received_ts = 96.734131
last_seq = 1913
current_ts = 96.751343
current_received_ts = 96.750824
current_seq = 1914
count = 67
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.751343
last_received_ts = 96.750824
last_seq = 1914
current_ts = 96.768005
current_received_ts = 96.767471
current_seq = 1915
count = 68
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.768005
last_received_ts = 96.767471
last_seq = 1915
current_ts = 96.784668
current_received_ts = 96.784142
current_seq = 1916
count = 69
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.784668
last_received_ts = 96.784142
last_seq = 1916
current_ts = 96.801338
current_received_ts = 96.800812
current_seq = 1917
count = 70
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.801338
last_received_ts = 96.800812
last_seq = 1917
current_ts = 96.818008
current_received_ts = 96.817467
current_seq = 1918
count = 71
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.818008
last_received_ts = 96.817467
last_seq = 1918
current_ts = 96.834671
current_received_ts = 96.834152
current_seq = 1919
count = 72
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.834671
last_received_ts = 96.834152
last_seq = 1919
current_ts = 96.851341
current_received_ts = 96.850815
current_seq = 1920
count = 73
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.851341
last_received_ts = 96.850815
last_seq = 1920
current_ts = 96.868004
current_received_ts = 96.867485
current_seq = 1921
count = 74
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.868004
last_received_ts = 96.867485
last_seq = 1921
current_ts = 96.884682
current_received_ts = 96.884148
current_seq = 1922
count = 75
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.884682
last_received_ts = 96.884148
last_seq = 1922
current_ts = 96.901344
current_received_ts = 96.900826
current_seq = 1923
count = 76
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.901344
last_received_ts = 96.900826
last_seq = 1923
current_ts = 96.918007
current_received_ts = 96.917488
current_seq = 1924
count = 77
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.918007
last_received_ts = 96.917488
last_seq = 1924
current_ts = 96.934685
current_received_ts = 96.934151
current_seq = 1925
count = 78
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.934685
last_received_ts = 96.934151
last_seq = 1925
current_ts = 96.951347
current_received_ts = 96.950813
current_seq = 1926
count = 79
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.951347
last_received_ts = 96.950813
last_seq = 1926
current_ts = 96.968018
current_received_ts = 96.967484
current_seq = 1927
count = 80
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 20us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.968018
last_received_ts = 96.967484
last_seq = 1927
current_ts = 96.984680
current_received_ts = 96.984146
current_seq = 1928
count = 81
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 96.984680
last_received_ts = 96.984146
last_seq = 1928
current_ts = 97.001350
current_received_ts = 97.000816
current_seq = 1929
count = 82
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.001350
last_received_ts = 97.000816
last_seq = 1929
current_ts = 97.018021
current_received_ts = 97.017487
current_seq = 1930
count = 83
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.018021
last_received_ts = 97.017487
last_seq = 1930
current_ts = 97.034691
current_received_ts = 97.034164
current_seq = 1931
count = 84
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.034691
last_received_ts = 97.034164
last_seq = 1931
current_ts = 97.051361
current_received_ts = 97.050819
current_seq = 1932
count = 85
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.051361
last_received_ts = 97.050819
last_seq = 1932
current_ts = 97.068024
current_received_ts = 97.067490
current_seq = 1933
count = 86
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.068024
last_received_ts = 97.067490
last_seq = 1933
current_ts = 97.084686
current_received_ts = 97.084152
current_seq = 1934
count = 87
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.084686
last_received_ts = 97.084152
last_seq = 1934
current_ts = 97.101364
current_received_ts = 97.100822
current_seq = 1935
count = 88
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.101364
last_received_ts = 97.100822
last_seq = 1935
current_ts = 97.118027
current_received_ts = 97.117493
current_seq = 1936
count = 89
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.118027
last_received_ts = 97.117493
last_seq = 1936
current_ts = 97.134689
current_received_ts = 97.134171
current_seq = 1937
count = 90
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.134689
last_received_ts = 97.134171
last_seq = 1937
current_ts = 97.151367
current_received_ts = 97.150833
current_seq = 1938
count = 91
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.151367
last_received_ts = 97.150833
last_seq = 1938
current_ts = 97.168037
current_received_ts = 97.167496
current_seq = 1939
count = 92
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.168037
last_received_ts = 97.167496
last_seq = 1939
current_ts = 97.184700
current_received_ts = 97.184151
current_seq = 1940
count = 93
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.184700
last_received_ts = 97.184151
last_seq = 1940
current_ts = 97.201363
current_received_ts = 97.200844
current_seq = 1941
count = 94
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.201363
last_received_ts = 97.200844
last_seq = 1941
current_ts = 97.218033
current_received_ts = 97.217499
current_seq = 1942
count = 95
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.218033
last_received_ts = 97.217499
last_seq = 1942
current_ts = 97.234703
current_received_ts = 97.234161
current_seq = 1943
count = 96
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.234703
last_received_ts = 97.234161
last_seq = 1943
current_ts = 97.251373
current_received_ts = 97.250832
current_seq = 1944
count = 97
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.251373
last_received_ts = 97.250832
last_seq = 1944
current_ts = 97.268036
current_received_ts = 97.267509
current_seq = 1945
count = 98
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.268036
last_received_ts = 97.267509
last_seq = 1945
current_ts = 97.284698
current_received_ts = 97.284164
current_seq = 1946
count = 99
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.284698
last_received_ts = 97.284164
last_seq = 1946
current_ts = 97.301376
current_received_ts = 97.300842
current_seq = 1947
count = 100
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.301376
last_received_ts = 97.300842
last_seq = 1947
current_ts = 97.318039
current_received_ts = 97.317505
current_seq = 1948
count = 101
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.318039
last_received_ts = 97.317505
last_seq = 1948
current_ts = 97.334709
current_received_ts = 97.334160
current_seq = 1949
count = 102
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.334709
last_received_ts = 97.334160
last_seq = 1949
current_ts = 97.351379
current_received_ts = 97.350845
current_seq = 1950
count = 103
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.351379
last_received_ts = 97.350845
last_seq = 1950
current_ts = 97.368042
current_received_ts = 97.367508
current_seq = 1951
count = 104
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.368042
last_received_ts = 97.367508
last_seq = 1951
current_ts = 97.384712
current_received_ts = 97.384163
current_seq = 1952
count = 105
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 19us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.384712
last_received_ts = 97.384163
last_seq = 1952
current_ts = 97.401375
current_received_ts = 97.400856
current_seq = 1953
count = 106
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.401375
last_received_ts = 97.400856
last_seq = 1953
current_ts = 97.418045
current_received_ts = 97.417511
current_seq = 1954
count = 107
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 20us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.418045
last_received_ts = 97.417511
last_seq = 1954
current_ts = 97.434723
current_received_ts = 97.434181
current_seq = 1955
count = 108
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.434723
last_received_ts = 97.434181
last_seq = 1955
current_ts = 97.451378
current_received_ts = 97.450859
current_seq = 1956
count = 109
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.451378
last_received_ts = 97.450859
last_seq = 1956
current_ts = 97.468056
current_received_ts = 97.467514
current_seq = 1957
count = 110
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.468056
last_received_ts = 97.467514
last_seq = 1957
current_ts = 97.484718
current_received_ts = 97.484192
current_seq = 1958
count = 111
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.484718
last_received_ts = 97.484192
last_seq = 1958
current_ts = 97.501389
current_received_ts = 97.500854
current_seq = 1959
count = 112
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.501389
last_received_ts = 97.500854
last_seq = 1959
current_ts = 97.518059
current_received_ts = 97.517517
current_seq = 1960
count = 113
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.518059
last_received_ts = 97.517517
last_seq = 1960
current_ts = 97.534721
current_received_ts = 97.534157
current_seq = 1961
count = 114
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.534721
last_received_ts = 97.534157
last_seq = 1961
current_ts = 97.551384
current_received_ts = 97.550865
current_seq = 1962
count = 115
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.551384
last_received_ts = 97.550865
last_seq = 1962
current_ts = 97.568062
current_received_ts = 97.567535
current_seq = 1963
count = 116
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.568062
last_received_ts = 97.567535
last_seq = 1963
current_ts = 97.584732
current_received_ts = 97.584152
current_seq = 1964
count = 117
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.584732
last_received_ts = 97.584152
last_seq = 1964
current_ts = 97.601395
current_received_ts = 97.600891
current_seq = 1965
count = 118
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 19us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.601395
last_received_ts = 97.600891
last_seq = 1965
current_ts = 97.618057
current_received_ts = 97.617508
current_seq = 1966
count = 119
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 33us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.618057
last_received_ts = 97.617508
last_seq = 1966
current_ts = 97.634735
current_received_ts = 97.634125
current_seq = 1967
count = 120
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 17us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.634735
last_received_ts = 97.634125
last_seq = 1967
current_ts = 97.651398
current_received_ts = 97.650764
current_seq = 1968
count = 121
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 14us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.651398
last_received_ts = 97.650764
last_seq = 1968
current_ts = 97.668076
current_received_ts = 97.667542
current_seq = 1969
count = 122
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 31us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.668076
last_received_ts = 97.667542
last_seq = 1969
current_ts = 97.684738
current_received_ts = 97.684196
current_seq = 1970
count = 123
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 33us
(kms_flip:2376) DEBUG: name = flip
last_ts = 97.684738
last_received_ts = 97.684196
last_seq = 1970
current_ts = 97.701401
current_received_ts = 97.700928
current_seq = 1971
count = 124
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 687us
(kms_flip:2376) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2376) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2376) igt_core-INFO: Stack trace:
(kms_flip:2376) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2376) igt_core-INFO:   #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
(kms_flip:2376) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2376) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2376) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2376) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2376) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2376) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-DP4: FAIL (2.649s)
Starting dynamic subtest: B-DP4
(kms_flip:2376) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2376) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest B-DP4 failed.
**** DEBUG ****
(kms_flip:2376) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2376) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:2376) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2376) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2376) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=7680)
(kms_flip:2376) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2376) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89d37800, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89d37800, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89d376f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89d376f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89d376f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89d376f0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89d35bd0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89d35bd0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2376) DEBUG: No stale events found
(kms_flip:2376) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2376) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2376) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 98.300293
current_received_ts = 98.299690
current_seq = 1824
count = 0
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 30us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.300293
last_received_ts = 98.299690
last_seq = 1824
current_ts = 98.316971
current_received_ts = 98.316437
current_seq = 1825
count = 1
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.316971
last_received_ts = 98.316437
last_seq = 1825
current_ts = 98.333633
current_received_ts = 98.333115
current_seq = 1826
count = 2
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.333633
last_received_ts = 98.333115
last_seq = 1826
current_ts = 98.350304
current_received_ts = 98.349770
current_seq = 1827
count = 3
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.350304
last_received_ts = 98.349770
last_seq = 1827
current_ts = 98.366974
current_received_ts = 98.366440
current_seq = 1828
count = 4
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 20us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.366974
last_received_ts = 98.366440
last_seq = 1828
current_ts = 98.383629
current_received_ts = 98.383110
current_seq = 1829
count = 5
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.383629
last_received_ts = 98.383110
last_seq = 1829
current_ts = 98.400307
current_received_ts = 98.399773
current_seq = 1830
count = 6
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.400307
last_received_ts = 98.399773
last_seq = 1830
current_ts = 98.416977
current_received_ts = 98.416443
current_seq = 1831
count = 7
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.416977
last_received_ts = 98.416443
last_seq = 1831
current_ts = 98.433647
current_received_ts = 98.433105
current_seq = 1832
count = 8
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.433647
last_received_ts = 98.433105
last_seq = 1832
current_ts = 98.450302
current_received_ts = 98.449768
current_seq = 1833
count = 9
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.450302
last_received_ts = 98.449768
last_seq = 1833
current_ts = 98.466980
current_received_ts = 98.466438
current_seq = 1834
count = 10
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.466980
last_received_ts = 98.466438
last_seq = 1834
current_ts = 98.483643
current_received_ts = 98.483124
current_seq = 1835
count = 11
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.483643
last_received_ts = 98.483124
last_seq = 1835
current_ts = 98.500305
current_received_ts = 98.499786
current_seq = 1836
count = 12
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.500305
last_received_ts = 98.499786
last_seq = 1836
current_ts = 98.516975
current_received_ts = 98.516441
current_seq = 1837
count = 13
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.516975
last_received_ts = 98.516441
last_seq = 1837
current_ts = 98.533646
current_received_ts = 98.533127
current_seq = 1838
count = 14
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.533646
last_received_ts = 98.533127
last_seq = 1838
current_ts = 98.550323
current_received_ts = 98.549805
current_seq = 1839
count = 15
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.550323
last_received_ts = 98.549805
last_seq = 1839
current_ts = 98.566986
current_received_ts = 98.566452
current_seq = 1840
count = 16
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 20us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.566986
last_received_ts = 98.566452
last_seq = 1840
current_ts = 98.583656
current_received_ts = 98.583122
current_seq = 1841
count = 17
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.583656
last_received_ts = 98.583122
last_seq = 1841
current_ts = 98.600319
current_received_ts = 98.599785
current_seq = 1842
count = 18
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.600319
last_received_ts = 98.599785
last_seq = 1842
current_ts = 98.616989
current_received_ts = 98.616470
current_seq = 1843
count = 19
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.616989
last_received_ts = 98.616470
last_seq = 1843
current_ts = 98.633652
current_received_ts = 98.633125
current_seq = 1844
count = 20
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.633652
last_received_ts = 98.633125
last_seq = 1844
current_ts = 98.650322
current_received_ts = 98.649788
current_seq = 1845
count = 21
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.650322
last_received_ts = 98.649788
last_seq = 1845
current_ts = 98.666992
current_received_ts = 98.666458
current_seq = 1846
count = 22
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.666992
last_received_ts = 98.666458
last_seq = 1846
current_ts = 98.683655
current_received_ts = 98.683121
current_seq = 1847
count = 23
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 20us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.683655
last_received_ts = 98.683121
last_seq = 1847
current_ts = 98.700325
current_received_ts = 98.699791
current_seq = 1848
count = 24
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.700325
last_received_ts = 98.699791
last_seq = 1848
current_ts = 98.716995
current_received_ts = 98.716461
current_seq = 1849
count = 25
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.716995
last_received_ts = 98.716461
last_seq = 1849
current_ts = 98.733658
current_received_ts = 98.733124
current_seq = 1850
count = 26
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.733658
last_received_ts = 98.733124
last_seq = 1850
current_ts = 98.750336
current_received_ts = 98.749802
current_seq = 1851
count = 27
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.750336
last_received_ts = 98.749802
last_seq = 1851
current_ts = 98.766998
current_received_ts = 98.766464
current_seq = 1852
count = 28
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 20us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.766998
last_received_ts = 98.766464
last_seq = 1852
current_ts = 98.783661
current_received_ts = 98.783134
current_seq = 1853
count = 29
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.783661
last_received_ts = 98.783134
last_seq = 1853
current_ts = 98.800339
current_received_ts = 98.799805
current_seq = 1854
count = 30
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.800339
last_received_ts = 98.799805
last_seq = 1854
current_ts = 98.817009
current_received_ts = 98.816467
current_seq = 1855
count = 31
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.817009
last_received_ts = 98.816467
last_seq = 1855
current_ts = 98.833672
current_received_ts = 98.833138
current_seq = 1856
count = 32
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.833672
last_received_ts = 98.833138
last_seq = 1856
current_ts = 98.850342
current_received_ts = 98.849808
current_seq = 1857
count = 33
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.850342
last_received_ts = 98.849808
last_seq = 1857
current_ts = 98.867004
current_received_ts = 98.866486
current_seq = 1858
count = 34
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.867004
last_received_ts = 98.866486
last_seq = 1858
current_ts = 98.883667
current_received_ts = 98.883148
current_seq = 1859
count = 35
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.883667
last_received_ts = 98.883148
last_seq = 1859
current_ts = 98.900337
current_received_ts = 98.899818
current_seq = 1860
count = 36
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.900337
last_received_ts = 98.899818
last_seq = 1860
current_ts = 98.917007
current_received_ts = 98.916473
current_seq = 1861
count = 37
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.917007
last_received_ts = 98.916473
last_seq = 1861
current_ts = 98.933678
current_received_ts = 98.933144
current_seq = 1862
count = 38
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.933678
last_received_ts = 98.933144
last_seq = 1862
current_ts = 98.950340
current_received_ts = 98.949814
current_seq = 1863
count = 39
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.950340
last_received_ts = 98.949814
last_seq = 1863
current_ts = 98.967010
current_received_ts = 98.966476
current_seq = 1864
count = 40
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.967010
last_received_ts = 98.966476
last_seq = 1864
current_ts = 98.983673
current_received_ts = 98.983154
current_seq = 1865
count = 41
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 98.983673
last_received_ts = 98.983154
last_seq = 1865
current_ts = 99.000351
current_received_ts = 98.999809
current_seq = 1866
count = 42
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.000351
last_received_ts = 98.999809
last_seq = 1866
current_ts = 99.017014
current_received_ts = 99.016472
current_seq = 1867
count = 43
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.017014
last_received_ts = 99.016472
last_seq = 1867
current_ts = 99.033684
current_received_ts = 99.033150
current_seq = 1868
count = 44
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.033684
last_received_ts = 99.033150
last_seq = 1868
current_ts = 99.050346
current_received_ts = 99.049828
current_seq = 1869
count = 45
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.050346
last_received_ts = 99.049828
last_seq = 1869
current_ts = 99.067017
current_received_ts = 99.066483
current_seq = 1870
count = 46
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.067017
last_received_ts = 99.066483
last_seq = 1870
current_ts = 99.083679
current_received_ts = 99.083145
current_seq = 1871
count = 47
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.083679
last_received_ts = 99.083145
last_seq = 1871
current_ts = 99.100357
current_received_ts = 99.099815
current_seq = 1872
count = 48
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.100357
last_received_ts = 99.099815
last_seq = 1872
current_ts = 99.117020
current_received_ts = 99.116486
current_seq = 1873
count = 49
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.117020
last_received_ts = 99.116486
last_seq = 1873
current_ts = 99.133682
current_received_ts = 99.133179
current_seq = 1874
count = 50
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.133682
last_received_ts = 99.133179
last_seq = 1874
current_ts = 99.150360
current_received_ts = 99.149826
current_seq = 1875
count = 51
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.150360
last_received_ts = 99.149826
last_seq = 1875
current_ts = 99.167023
current_received_ts = 99.166496
current_seq = 1876
count = 52
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.167023
last_received_ts = 99.166496
last_seq = 1876
current_ts = 99.183685
current_received_ts = 99.183151
current_seq = 1877
count = 53
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.183685
last_received_ts = 99.183151
last_seq = 1877
current_ts = 99.200363
current_received_ts = 99.199829
current_seq = 1878
count = 54
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.200363
last_received_ts = 99.199829
last_seq = 1878
current_ts = 99.217026
current_received_ts = 99.216492
current_seq = 1879
count = 55
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.217026
last_received_ts = 99.216492
last_seq = 1879
current_ts = 99.233688
current_received_ts = 99.233170
current_seq = 1880
count = 56
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.233688
last_received_ts = 99.233170
last_seq = 1880
current_ts = 99.250366
current_received_ts = 99.249840
current_seq = 1881
count = 57
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.250366
last_received_ts = 99.249840
last_seq = 1881
current_ts = 99.267029
current_received_ts = 99.266495
current_seq = 1882
count = 58
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.267029
last_received_ts = 99.266495
last_seq = 1882
current_ts = 99.283691
current_received_ts = 99.283173
current_seq = 1883
count = 59
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.283691
last_received_ts = 99.283173
last_seq = 1883
current_ts = 99.300369
current_received_ts = 99.299843
current_seq = 1884
count = 60
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.300369
last_received_ts = 99.299843
last_seq = 1884
current_ts = 99.317032
current_received_ts = 99.316498
current_seq = 1885
count = 61
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.317032
last_received_ts = 99.316498
last_seq = 1885
current_ts = 99.333702
current_received_ts = 99.333183
current_seq = 1886
count = 62
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.333702
last_received_ts = 99.333183
last_seq = 1886
current_ts = 99.350365
current_received_ts = 99.349846
current_seq = 1887
count = 63
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 99.350365
last_received_ts = 99.349846
last_seq = 1887
current_ts = 99.367035
current_received_ts = 99.366547
current_seq = 1888
count = 64
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 520us
(kms_flip:2376) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2376) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2376) igt_core-INFO: Stack trace:
(kms_flip:2376) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2376) igt_core-INFO:   #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
(kms_flip:2376) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2376) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2376) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2376) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2376) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2376) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-DP4: FAIL (1.326s)
Starting dynamic subtest: C-DP4
Dynamic subtest C-DP4: SUCCESS (3.979s)
Starting dynamic subtest: D-DP4
(kms_flip:2376) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2376) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest D-DP4 failed.
**** DEBUG ****
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89cd9330, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89d5c360, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89d5c360, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89cd96b0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89cd96b0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89d5c360, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) intel_allocator_simple-DEBUG: <ial: 0x623c89d5c360, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:2376) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2376) DEBUG: No stale events found
(kms_flip:2376) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2376) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2376) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 103.609680
current_received_ts = 103.609123
current_seq = 240
count = 0
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 205us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.609680
last_received_ts = 103.609123
last_seq = 240
current_ts = 103.626350
current_received_ts = 103.625748
current_seq = 241
count = 1
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 258us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.626350
last_received_ts = 103.625748
last_seq = 241
current_ts = 103.643021
current_received_ts = 103.642380
current_seq = 242
count = 2
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 13us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.643021
last_received_ts = 103.642380
last_seq = 242
current_ts = 103.659683
current_received_ts = 103.659058
current_seq = 243
count = 3
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 312us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.659683
last_received_ts = 103.659058
last_seq = 243
current_ts = 103.676353
current_received_ts = 103.675720
current_seq = 244
count = 4
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 18us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.676353
last_received_ts = 103.675720
last_seq = 244
current_ts = 103.693024
current_received_ts = 103.692421
current_seq = 245
count = 5
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 25us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.693024
last_received_ts = 103.692421
last_seq = 245
current_ts = 103.709694
current_received_ts = 103.709106
current_seq = 246
count = 6
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 32us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.709694
last_received_ts = 103.709106
last_seq = 246
current_ts = 103.726349
current_received_ts = 103.725853
current_seq = 247
count = 7
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.726349
last_received_ts = 103.725853
last_seq = 247
current_ts = 103.743019
current_received_ts = 103.742500
current_seq = 248
count = 8
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 26us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.743019
last_received_ts = 103.742500
last_seq = 248
current_ts = 103.759689
current_received_ts = 103.759163
current_seq = 249
count = 9
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.759689
last_received_ts = 103.759163
last_seq = 249
current_ts = 103.776352
current_received_ts = 103.775833
current_seq = 250
count = 10
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.776352
last_received_ts = 103.775833
last_seq = 250
current_ts = 103.793030
current_received_ts = 103.792496
current_seq = 251
count = 11
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.793030
last_received_ts = 103.792496
last_seq = 251
current_ts = 103.809700
current_received_ts = 103.809242
current_seq = 252
count = 12
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 328us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.809700
last_received_ts = 103.809242
last_seq = 252
current_ts = 103.826363
current_received_ts = 103.825829
current_seq = 253
count = 13
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 26us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.826363
last_received_ts = 103.825829
last_seq = 253
current_ts = 103.843033
current_received_ts = 103.842491
current_seq = 254
count = 14
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.843033
last_received_ts = 103.842491
last_seq = 254
current_ts = 103.859703
current_received_ts = 103.859268
current_seq = 255
count = 15
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 438us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.859703
last_received_ts = 103.859268
last_seq = 255
current_ts = 103.876358
current_received_ts = 103.875839
current_seq = 256
count = 16
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 25us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.876358
last_received_ts = 103.875839
last_seq = 256
current_ts = 103.893028
current_received_ts = 103.892502
current_seq = 257
count = 17
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.893028
last_received_ts = 103.892502
last_seq = 257
current_ts = 103.909698
current_received_ts = 103.909180
current_seq = 258
count = 18
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.909698
last_received_ts = 103.909180
last_seq = 258
current_ts = 103.926369
current_received_ts = 103.925835
current_seq = 259
count = 19
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.926369
last_received_ts = 103.925835
last_seq = 259
current_ts = 103.943031
current_received_ts = 103.942497
current_seq = 260
count = 20
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.943031
last_received_ts = 103.942497
last_seq = 260
current_ts = 103.959702
current_received_ts = 103.959183
current_seq = 261
count = 21
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 25us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.959702
last_received_ts = 103.959183
last_seq = 261
current_ts = 103.976379
current_received_ts = 103.975838
current_seq = 262
count = 22
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.976379
last_received_ts = 103.975838
last_seq = 262
current_ts = 103.993034
current_received_ts = 103.992500
current_seq = 263
count = 23
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 103.993034
last_received_ts = 103.992500
last_seq = 263
current_ts = 104.009705
current_received_ts = 104.009171
current_seq = 264
count = 24
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 25us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.009705
last_received_ts = 104.009171
last_seq = 264
current_ts = 104.026375
current_received_ts = 104.025848
current_seq = 265
count = 25
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.026375
last_received_ts = 104.025848
last_seq = 265
current_ts = 104.043045
current_received_ts = 104.042503
current_seq = 266
count = 26
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.043045
last_received_ts = 104.042503
last_seq = 266
current_ts = 104.059715
current_received_ts = 104.059181
current_seq = 267
count = 27
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.059715
last_received_ts = 104.059181
last_seq = 267
current_ts = 104.076378
current_received_ts = 104.075844
current_seq = 268
count = 28
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.076378
last_received_ts = 104.075844
last_seq = 268
current_ts = 104.093040
current_received_ts = 104.092506
current_seq = 269
count = 29
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.093040
last_received_ts = 104.092506
last_seq = 269
current_ts = 104.109718
current_received_ts = 104.109184
current_seq = 270
count = 30
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.109718
last_received_ts = 104.109184
last_seq = 270
current_ts = 104.126381
current_received_ts = 104.125839
current_seq = 271
count = 31
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.126381
last_received_ts = 104.125839
last_seq = 271
current_ts = 104.143044
current_received_ts = 104.142525
current_seq = 272
count = 32
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.143044
last_received_ts = 104.142525
last_seq = 272
current_ts = 104.159721
current_received_ts = 104.159180
current_seq = 273
count = 33
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.159721
last_received_ts = 104.159180
last_seq = 273
current_ts = 104.176384
current_received_ts = 104.175850
current_seq = 274
count = 34
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.176384
last_received_ts = 104.175850
last_seq = 274
current_ts = 104.193054
current_received_ts = 104.192513
current_seq = 275
count = 35
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.193054
last_received_ts = 104.192513
last_seq = 275
current_ts = 104.209717
current_received_ts = 104.209183
current_seq = 276
count = 36
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.209717
last_received_ts = 104.209183
last_seq = 276
current_ts = 104.226387
current_received_ts = 104.225868
current_seq = 277
count = 37
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.226387
last_received_ts = 104.225868
last_seq = 277
current_ts = 104.243057
current_received_ts = 104.242516
current_seq = 278
count = 38
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.243057
last_received_ts = 104.242516
last_seq = 278
current_ts = 104.259720
current_received_ts = 104.259186
current_seq = 279
count = 39
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.259720
last_received_ts = 104.259186
last_seq = 279
current_ts = 104.276390
current_received_ts = 104.275856
current_seq = 280
count = 40
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.276390
last_received_ts = 104.275856
last_seq = 280
current_ts = 104.293060
current_received_ts = 104.292526
current_seq = 281
count = 41
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.293060
last_received_ts = 104.292526
last_seq = 281
current_ts = 104.309723
current_received_ts = 104.309189
current_seq = 282
count = 42
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.309723
last_received_ts = 104.309189
last_seq = 282
current_ts = 104.326401
current_received_ts = 104.325867
current_seq = 283
count = 43
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.326401
last_received_ts = 104.325867
last_seq = 283
current_ts = 104.343071
current_received_ts = 104.342529
current_seq = 284
count = 44
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.343071
last_received_ts = 104.342529
last_seq = 284
current_ts = 104.359734
current_received_ts = 104.359200
current_seq = 285
count = 45
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.359734
last_received_ts = 104.359200
last_seq = 285
current_ts = 104.376396
current_received_ts = 104.375862
current_seq = 286
count = 46
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.376396
last_received_ts = 104.375862
last_seq = 286
current_ts = 104.393066
current_received_ts = 104.392532
current_seq = 287
count = 47
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.393066
last_received_ts = 104.392532
last_seq = 287
current_ts = 104.409737
current_received_ts = 104.409203
current_seq = 288
count = 48
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.409737
last_received_ts = 104.409203
last_seq = 288
current_ts = 104.426399
current_received_ts = 104.425880
current_seq = 289
count = 49
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.426399
last_received_ts = 104.425880
last_seq = 289
current_ts = 104.443062
current_received_ts = 104.442543
current_seq = 290
count = 50
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.443062
last_received_ts = 104.442543
last_seq = 290
current_ts = 104.459740
current_received_ts = 104.459206
current_seq = 291
count = 51
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.459740
last_received_ts = 104.459206
last_seq = 291
current_ts = 104.476410
current_received_ts = 104.475883
current_seq = 292
count = 52
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 25us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.476410
last_received_ts = 104.475883
last_seq = 292
current_ts = 104.493080
current_received_ts = 104.492561
current_seq = 293
count = 53
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.493080
last_received_ts = 104.492561
last_seq = 293
current_ts = 104.509743
current_received_ts = 104.509178
current_seq = 294
count = 54
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.509743
last_received_ts = 104.509178
last_seq = 294
current_ts = 104.526405
current_received_ts = 104.525826
current_seq = 295
count = 55
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.526405
last_received_ts = 104.525826
last_seq = 295
current_ts = 104.543083
current_received_ts = 104.542480
current_seq = 296
count = 56
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.543083
last_received_ts = 104.542480
last_seq = 296
current_ts = 104.559746
current_received_ts = 104.559204
current_seq = 297
count = 57
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.559746
last_received_ts = 104.559204
last_seq = 297
current_ts = 104.576408
current_received_ts = 104.575890
current_seq = 298
count = 58
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.576408
last_received_ts = 104.575890
last_seq = 298
current_ts = 104.593079
current_received_ts = 104.592560
current_seq = 299
count = 59
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.593079
last_received_ts = 104.592560
last_seq = 299
current_ts = 104.609749
current_received_ts = 104.609230
current_seq = 300
count = 60
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.609749
last_received_ts = 104.609230
last_seq = 300
current_ts = 104.626419
current_received_ts = 104.625885
current_seq = 301
count = 61
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.626419
last_received_ts = 104.625885
last_seq = 301
current_ts = 104.643082
current_received_ts = 104.642555
current_seq = 302
count = 62
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.643082
last_received_ts = 104.642555
last_seq = 302
current_ts = 104.659744
current_received_ts = 104.659225
current_seq = 303
count = 63
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.659744
last_received_ts = 104.659225
last_seq = 303
current_ts = 104.676414
current_received_ts = 104.675903
current_seq = 304
count = 64
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 29us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.676414
last_received_ts = 104.675903
last_seq = 304
current_ts = 104.693092
current_received_ts = 104.692566
current_seq = 305
count = 65
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 27us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.693092
last_received_ts = 104.692566
last_seq = 305
current_ts = 104.709755
current_received_ts = 104.709221
current_seq = 306
count = 66
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 25us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.709755
last_received_ts = 104.709221
last_seq = 306
current_ts = 104.726425
current_received_ts = 104.725899
current_seq = 307
count = 67
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.726425
last_received_ts = 104.725899
last_seq = 307
current_ts = 104.743088
current_received_ts = 104.742561
current_seq = 308
count = 68
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.743088
last_received_ts = 104.742561
last_seq = 308
current_ts = 104.759750
current_received_ts = 104.759232
current_seq = 309
count = 69
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.759750
last_received_ts = 104.759232
last_seq = 309
current_ts = 104.776428
current_received_ts = 104.775894
current_seq = 310
count = 70
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.776428
last_received_ts = 104.775894
last_seq = 310
current_ts = 104.793091
current_received_ts = 104.792572
current_seq = 311
count = 71
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.793091
last_received_ts = 104.792572
last_seq = 311
current_ts = 104.809753
current_received_ts = 104.809235
current_seq = 312
count = 72
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.809753
last_received_ts = 104.809235
last_seq = 312
current_ts = 104.826424
current_received_ts = 104.825905
current_seq = 313
count = 73
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 20us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.826424
last_received_ts = 104.825905
last_seq = 313
current_ts = 104.843094
current_received_ts = 104.842575
current_seq = 314
count = 74
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.843094
last_received_ts = 104.842575
last_seq = 314
current_ts = 104.859764
current_received_ts = 104.859230
current_seq = 315
count = 75
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.859764
last_received_ts = 104.859230
last_seq = 315
current_ts = 104.876434
current_received_ts = 104.875900
current_seq = 316
count = 76
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.876434
last_received_ts = 104.875900
last_seq = 316
current_ts = 104.893105
current_received_ts = 104.892563
current_seq = 317
count = 77
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.893105
last_received_ts = 104.892563
last_seq = 317
current_ts = 104.909767
current_received_ts = 104.909233
current_seq = 318
count = 78
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.909767
last_received_ts = 104.909233
last_seq = 318
current_ts = 104.926437
current_received_ts = 104.925903
current_seq = 319
count = 79
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.926437
last_received_ts = 104.925903
last_seq = 319
current_ts = 104.943108
current_received_ts = 104.942574
current_seq = 320
count = 80
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 25us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.943108
last_received_ts = 104.942574
last_seq = 320
current_ts = 104.959770
current_received_ts = 104.959236
current_seq = 321
count = 81
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.959770
last_received_ts = 104.959236
last_seq = 321
current_ts = 104.976440
current_received_ts = 104.975906
current_seq = 322
count = 82
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 26us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.976440
last_received_ts = 104.975906
last_seq = 322
current_ts = 104.993103
current_received_ts = 104.992584
current_seq = 323
count = 83
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 104.993103
last_received_ts = 104.992584
last_seq = 323
current_ts = 105.009773
current_received_ts = 105.009239
current_seq = 324
count = 84
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.009773
last_received_ts = 105.009239
last_seq = 324
current_ts = 105.026443
current_received_ts = 105.025909
current_seq = 325
count = 85
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.026443
last_received_ts = 105.025909
last_seq = 325
current_ts = 105.043114
current_received_ts = 105.042580
current_seq = 326
count = 86
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 22us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.043114
last_received_ts = 105.042580
last_seq = 326
current_ts = 105.059776
current_received_ts = 105.059242
current_seq = 327
count = 87
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.059776
last_received_ts = 105.059242
last_seq = 327
current_ts = 105.076454
current_received_ts = 105.075912
current_seq = 328
count = 88
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.076454
last_received_ts = 105.075912
last_seq = 328
current_ts = 105.093117
current_received_ts = 105.092575
current_seq = 329
count = 89
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.093117
last_received_ts = 105.092575
last_seq = 329
current_ts = 105.109779
current_received_ts = 105.109245
current_seq = 330
count = 90
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.109779
last_received_ts = 105.109245
last_seq = 330
current_ts = 105.126442
current_received_ts = 105.125923
current_seq = 331
count = 91
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.126442
last_received_ts = 105.125923
last_seq = 331
current_ts = 105.143112
current_received_ts = 105.142586
current_seq = 332
count = 92
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.143112
last_received_ts = 105.142586
last_seq = 332
current_ts = 105.159782
current_received_ts = 105.159264
current_seq = 333
count = 93
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.159782
last_received_ts = 105.159264
last_seq = 333
current_ts = 105.176453
current_received_ts = 105.175919
current_seq = 334
count = 94
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 20us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.176453
last_received_ts = 105.175919
last_seq = 334
current_ts = 105.193115
current_received_ts = 105.192596
current_seq = 335
count = 95
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 25us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.193115
last_received_ts = 105.192596
last_seq = 335
current_ts = 105.209785
current_received_ts = 105.209251
current_seq = 336
count = 96
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.209785
last_received_ts = 105.209251
last_seq = 336
current_ts = 105.226456
current_received_ts = 105.225937
current_seq = 337
count = 97
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.226456
last_received_ts = 105.225937
last_seq = 337
current_ts = 105.243118
current_received_ts = 105.242599
current_seq = 338
count = 98
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.243118
last_received_ts = 105.242599
last_seq = 338
current_ts = 105.259796
current_received_ts = 105.259254
current_seq = 339
count = 99
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 23us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.259796
last_received_ts = 105.259254
last_seq = 339
current_ts = 105.276466
current_received_ts = 105.275932
current_seq = 340
count = 100
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 24us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.276466
last_received_ts = 105.275932
last_seq = 340
current_ts = 105.293121
current_received_ts = 105.292603
current_seq = 341
count = 101
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 21us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.293121
last_received_ts = 105.292603
last_seq = 341
current_ts = 105.309792
current_received_ts = 105.309273
current_seq = 342
count = 102
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 35us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.309792
last_received_ts = 105.309273
last_seq = 342
current_ts = 105.326462
current_received_ts = 105.325874
current_seq = 343
count = 103
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 16us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.326462
last_received_ts = 105.325874
last_seq = 343
current_ts = 105.343132
current_received_ts = 105.342529
current_seq = 344
count = 104
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 251us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.343132
last_received_ts = 105.342529
last_seq = 344
current_ts = 105.359795
current_received_ts = 105.359200
current_seq = 345
count = 105
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 13us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.359795
last_received_ts = 105.359200
last_seq = 345
current_ts = 105.376465
current_received_ts = 105.375893
current_seq = 346
count = 106
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 15us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.376465
last_received_ts = 105.375893
last_seq = 346
current_ts = 105.393135
current_received_ts = 105.392586
current_seq = 347
count = 107
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 25us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.393135
last_received_ts = 105.392586
last_seq = 347
current_ts = 105.409805
current_received_ts = 105.409286
current_seq = 348
count = 108
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 33us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.409805
last_received_ts = 105.409286
last_seq = 348
current_ts = 105.426468
current_received_ts = 105.425941
current_seq = 349
count = 109
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 27us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.426468
last_received_ts = 105.425941
last_seq = 349
current_ts = 105.443146
current_received_ts = 105.442680
current_seq = 350
count = 110
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 350us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.443146
last_received_ts = 105.442680
last_seq = 350
current_ts = 105.459808
current_received_ts = 105.459282
current_seq = 351
count = 111
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 31us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.459808
last_received_ts = 105.459282
last_seq = 351
current_ts = 105.476471
current_received_ts = 105.475960
current_seq = 352
count = 112
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 86us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.476471
last_received_ts = 105.475960
last_seq = 352
current_ts = 105.493134
current_received_ts = 105.492706
current_seq = 353
count = 113
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 35us
(kms_flip:2376) DEBUG: name = flip
last_ts = 105.493134
last_received_ts = 105.492706
last_seq = 353
current_ts = 105.509796
current_received_ts = 105.509315
current_seq = 354
count = 114
seq_step = 1
(kms_flip:2376) DEBUG: Vblank took 601us
(kms_flip:2376) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:910:
(kms_flip:2376) CRITICAL: Failed assertion: end - start < 500
(kms_flip:2376) igt_core-INFO: Stack trace:
(kms_flip:2376) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2376) igt_core-INFO:   #1 ../tests/kms_flip.c:905 run_test_on_crtc_set.constprop.0()
(kms_flip:2376) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2376) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2376) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2376) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2376) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2376) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest D-DP4: FAIL (2.481s)
Subtest flip-vs-expired-vblank: FAIL (26.478s)
(kms_flip:2376) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:2376) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2376) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2376) igt_kms-CRITICAL: DPMS property not found on 264