Results for igt@kms_flip@plain-flip-ts-check@b-vga1

Machine description: shard-snb4

Result: Fail

git-log-oneline i915_display_info3 igt_runner3 runtimes3 results3.json results3-i915-load.json i915_display_info_post_exec3 boot3 dmesg3

DetailValue
Duration 7.71 seconds
Hostname 
shard-snb4
Igt-Version 
IGT-Version: 1.30-g858841cdd (x86_64) (Linux: 6.14.0-rc5-CI_DRM_16222-gff2d693d8872+ x86_64)
Out 
Starting dynamic subtest: B-VGA1
  1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa 
Expected frametime: 16666us; measured 16899.1us +- 1.996us accuracy 0.04%
vblank interval differs from modeline! expected 16665.6us, measured 16899us +- 1.996us, difference 233.5us (117.0 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-VGA1: FAIL (7.715s)
Err 
Starting dynamic subtest: B-VGA1
(kms_flip:3070) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3070) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-VGA1 failed.
**** DEBUG ****
(kms_flip:3070) DEBUG: flip ts/seq: last 319.632385/3360, current 319.649231/3361: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.649231
last_received_ts = 319.648651
last_seq = 3361
current_ts = 319.666077
current_received_ts = 319.665527
current_seq = 3362
count = 126
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.649231/3361, current 319.666077/3362: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.666077
last_received_ts = 319.665527
last_seq = 3362
current_ts = 319.682922
current_received_ts = 319.682312
current_seq = 3363
count = 127
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.666077/3362, current 319.682922/3363: elapsed=16832.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.682922
last_received_ts = 319.682312
last_seq = 3363
current_ts = 319.699768
current_received_ts = 319.699219
current_seq = 3364
count = 128
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.682922/3363, current 319.699768/3364: elapsed=16852.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.699768
last_received_ts = 319.699219
last_seq = 3364
current_ts = 319.716614
current_received_ts = 319.716064
current_seq = 3365
count = 129
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.699768/3364, current 319.716614/3365: elapsed=16840.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.716614
last_received_ts = 319.716064
last_seq = 3365
current_ts = 319.733429
current_received_ts = 319.732849
current_seq = 3366
count = 130
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.716614/3365, current 319.733429/3366: elapsed=16837.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.733429
last_received_ts = 319.732849
last_seq = 3366
current_ts = 319.750275
current_received_ts = 319.749725
current_seq = 3367
count = 131
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.733429/3366, current 319.750275/3367: elapsed=16846.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.750275
last_received_ts = 319.749725
last_seq = 3367
current_ts = 319.767120
current_received_ts = 319.766571
current_seq = 3368
count = 132
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.750275/3367, current 319.767120/3368: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.767120
last_received_ts = 319.766571
last_seq = 3368
current_ts = 319.783966
current_received_ts = 319.783386
current_seq = 3369
count = 133
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.767120/3368, current 319.783966/3369: elapsed=16839.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.783966
last_received_ts = 319.783386
last_seq = 3369
current_ts = 319.800812
current_received_ts = 319.800201
current_seq = 3370
count = 134
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.783966/3369, current 319.800812/3370: elapsed=16846.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.800812
last_received_ts = 319.800201
last_seq = 3370
current_ts = 319.817657
current_received_ts = 319.817169
current_seq = 3371
count = 135
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.800812/3370, current 319.817657/3371: elapsed=16840.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.817657
last_received_ts = 319.817169
last_seq = 3371
current_ts = 319.834503
current_received_ts = 319.833923
current_seq = 3372
count = 136
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.817657/3371, current 319.834503/3372: elapsed=16837.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.834503
last_received_ts = 319.833923
last_seq = 3372
current_ts = 319.851349
current_received_ts = 319.850800
current_seq = 3373
count = 137
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.834503/3372, current 319.851349/3373: elapsed=16847.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.851349
last_received_ts = 319.850800
last_seq = 3373
current_ts = 319.868195
current_received_ts = 319.867615
current_seq = 3374
count = 138
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.851349/3373, current 319.868195/3374: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.868195
last_received_ts = 319.867615
last_seq = 3374
current_ts = 319.885010
current_received_ts = 319.884460
current_seq = 3375
count = 139
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.868195/3374, current 319.885010/3375: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.885010
last_received_ts = 319.884460
last_seq = 3375
current_ts = 319.901855
current_received_ts = 319.901306
current_seq = 3376
count = 140
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.885010/3375, current 319.901855/3376: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.901855
last_received_ts = 319.901306
last_seq = 3376
current_ts = 319.918701
current_received_ts = 319.918152
current_seq = 3377
count = 141
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.901855/3376, current 319.918701/3377: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.918701
last_received_ts = 319.918152
last_seq = 3377
current_ts = 319.935547
current_received_ts = 319.934937
current_seq = 3378
count = 142
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.918701/3377, current 319.935547/3378: elapsed=16836.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.935547
last_received_ts = 319.934937
last_seq = 3378
current_ts = 319.952393
current_received_ts = 319.951843
current_seq = 3379
count = 143
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.935547/3378, current 319.952393/3379: elapsed=16846.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.952393
last_received_ts = 319.951843
last_seq = 3379
current_ts = 319.969238
current_received_ts = 319.968658
current_seq = 3380
count = 144
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.952393/3379, current 319.969238/3380: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.969238
last_received_ts = 319.968658
last_seq = 3380
current_ts = 319.986084
current_received_ts = 319.985504
current_seq = 3381
count = 145
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.969238/3380, current 319.986084/3381: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 319.986084
last_received_ts = 319.985504
last_seq = 3381
current_ts = 320.002899
current_received_ts = 320.002350
current_seq = 3382
count = 146
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 319.986084/3381, current 320.002899/3382: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.002899
last_received_ts = 320.002350
last_seq = 3382
current_ts = 320.019745
current_received_ts = 320.019196
current_seq = 3383
count = 147
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.002899/3382, current 320.019745/3383: elapsed=16846.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.019745
last_received_ts = 320.019196
last_seq = 3383
current_ts = 320.036591
current_received_ts = 320.036011
current_seq = 3384
count = 148
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.019745/3383, current 320.036591/3384: elapsed=16834.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.036591
last_received_ts = 320.036011
last_seq = 3384
current_ts = 320.053436
current_received_ts = 320.052856
current_seq = 3385
count = 149
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.036591/3384, current 320.053436/3385: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.053436
last_received_ts = 320.052856
last_seq = 3385
current_ts = 320.070282
current_received_ts = 320.069702
current_seq = 3386
count = 150
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.053436/3385, current 320.070282/3386: elapsed=16846.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.070282
last_received_ts = 320.069702
last_seq = 3386
current_ts = 320.087128
current_received_ts = 320.086548
current_seq = 3387
count = 151
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.070282/3386, current 320.087128/3387: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.087128
last_received_ts = 320.086548
last_seq = 3387
current_ts = 320.103973
current_received_ts = 320.103363
current_seq = 3388
count = 152
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.087128/3387, current 320.103973/3388: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.103973
last_received_ts = 320.103363
last_seq = 3388
current_ts = 320.120789
current_received_ts = 320.120239
current_seq = 3389
count = 153
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.103973/3388, current 320.120789/3389: elapsed=16840.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.120789
last_received_ts = 320.120239
last_seq = 3389
current_ts = 320.137634
current_received_ts = 320.137115
current_seq = 3390
count = 154
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.120789/3389, current 320.137634/3390: elapsed=16844.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.137634
last_received_ts = 320.137115
last_seq = 3390
current_ts = 320.154480
current_received_ts = 320.153931
current_seq = 3391
count = 155
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.137634/3390, current 320.154480/3391: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.154480
last_received_ts = 320.153931
last_seq = 3391
current_ts = 320.171326
current_received_ts = 320.170715
current_seq = 3392
count = 156
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.154480/3391, current 320.171326/3392: elapsed=16840.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.171326
last_received_ts = 320.170715
last_seq = 3392
current_ts = 320.188171
current_received_ts = 320.187622
current_seq = 3393
count = 157
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.171326/3392, current 320.188171/3393: elapsed=16844.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.188171
last_received_ts = 320.187622
last_seq = 3393
current_ts = 320.205017
current_received_ts = 320.204468
current_seq = 3394
count = 158
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.188171/3393, current 320.205017/3394: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.205017
last_received_ts = 320.204468
last_seq = 3394
current_ts = 320.221863
current_received_ts = 320.221313
current_seq = 3395
count = 159
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.205017/3394, current 320.221863/3395: elapsed=16840.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.221863
last_received_ts = 320.221313
last_seq = 3395
current_ts = 320.238708
current_received_ts = 320.238129
current_seq = 3396
count = 160
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.221863/3395, current 320.238708/3396: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.238708
last_received_ts = 320.238129
last_seq = 3396
current_ts = 320.255524
current_received_ts = 320.254944
current_seq = 3397
count = 161
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.238708/3396, current 320.255524/3397: elapsed=16837.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.255524
last_received_ts = 320.254944
last_seq = 3397
current_ts = 320.272369
current_received_ts = 320.271820
current_seq = 3398
count = 162
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.255524/3397, current 320.272369/3398: elapsed=16847.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.272369
last_received_ts = 320.271820
last_seq = 3398
current_ts = 320.289215
current_received_ts = 320.288666
current_seq = 3399
count = 163
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.272369/3398, current 320.289215/3399: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.289215
last_received_ts = 320.288666
last_seq = 3399
current_ts = 320.306061
current_received_ts = 320.305511
current_seq = 3400
count = 164
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.289215/3399, current 320.306061/3400: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.306061
last_received_ts = 320.305511
last_seq = 3400
current_ts = 320.322906
current_received_ts = 320.322327
current_seq = 3401
count = 165
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.306061/3400, current 320.322906/3401: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.322906
last_received_ts = 320.322327
last_seq = 3401
current_ts = 320.339752
current_received_ts = 320.339172
current_seq = 3402
count = 166
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.322906/3401, current 320.339752/3402: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.339752
last_received_ts = 320.339172
last_seq = 3402
current_ts = 320.356598
current_received_ts = 320.356049
current_seq = 3403
count = 167
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.339752/3402, current 320.356598/3403: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.356598
last_received_ts = 320.356049
last_seq = 3403
current_ts = 320.373413
current_received_ts = 320.372864
current_seq = 3404
count = 168
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.356598/3403, current 320.373413/3404: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.373413
last_received_ts = 320.372864
last_seq = 3404
current_ts = 320.390259
current_received_ts = 320.389679
current_seq = 3405
count = 169
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.373413/3404, current 320.390259/3405: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.390259
last_received_ts = 320.389679
last_seq = 3405
current_ts = 320.407104
current_received_ts = 320.406525
current_seq = 3406
count = 170
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.390259/3405, current 320.407104/3406: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.407104
last_received_ts = 320.406525
last_seq = 3406
current_ts = 320.423950
current_received_ts = 320.423370
current_seq = 3407
count = 171
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.407104/3406, current 320.423950/3407: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.423950
last_received_ts = 320.423370
last_seq = 3407
current_ts = 320.440796
current_received_ts = 320.440216
current_seq = 3408
count = 172
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.423950/3407, current 320.440796/3408: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.440796
last_received_ts = 320.440216
last_seq = 3408
current_ts = 320.457642
current_received_ts = 320.457092
current_seq = 3409
count = 173
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.440796/3408, current 320.457642/3409: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.457642
last_received_ts = 320.457092
last_seq = 3409
current_ts = 320.474487
current_received_ts = 320.473938
current_seq = 3410
count = 174
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.457642/3409, current 320.474487/3410: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.474487
last_received_ts = 320.473938
last_seq = 3410
current_ts = 320.491302
current_received_ts = 320.490753
current_seq = 3411
count = 175
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.474487/3410, current 320.491302/3411: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.491302
last_received_ts = 320.490753
last_seq = 3411
current_ts = 320.508148
current_received_ts = 320.507599
current_seq = 3412
count = 176
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.491302/3411, current 320.508148/3412: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.508148
last_received_ts = 320.507599
last_seq = 3412
current_ts = 320.524994
current_received_ts = 320.524445
current_seq = 3413
count = 177
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.508148/3412, current 320.524994/3413: elapsed=16841.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.524994
last_received_ts = 320.524445
last_seq = 3413
current_ts = 320.541840
current_received_ts = 320.541290
current_seq = 3414
count = 178
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.524994/3413, current 320.541840/3414: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.541840
last_received_ts = 320.541290
last_seq = 3414
current_ts = 320.558685
current_received_ts = 320.558136
current_seq = 3415
count = 179
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.541840/3414, current 320.558685/3415: elapsed=16843.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.558685
last_received_ts = 320.558136
last_seq = 3415
current_ts = 320.575531
current_received_ts = 320.574982
current_seq = 3416
count = 180
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.558685/3415, current 320.575531/3416: elapsed=16843.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.575531
last_received_ts = 320.574982
last_seq = 3416
current_ts = 320.592377
current_received_ts = 320.591766
current_seq = 3417
count = 181
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.575531/3416, current 320.592377/3417: elapsed=16846.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.592377
last_received_ts = 320.591766
last_seq = 3417
current_ts = 320.609192
current_received_ts = 320.608612
current_seq = 3418
count = 182
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.592377/3417, current 320.609192/3418: elapsed=16832.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.609192
last_received_ts = 320.608612
last_seq = 3418
current_ts = 320.626068
current_received_ts = 320.625519
current_seq = 3419
count = 183
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.609192/3418, current 320.626068/3419: elapsed=16848.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.626068
last_received_ts = 320.625519
last_seq = 3419
current_ts = 320.642883
current_received_ts = 320.642365
current_seq = 3420
count = 184
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.626068/3419, current 320.642883/3420: elapsed=16833.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.642883
last_received_ts = 320.642365
last_seq = 3420
current_ts = 320.659698
current_received_ts = 320.659180
current_seq = 3421
count = 185
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.642883/3420, current 320.659698/3421: elapsed=16822.0us expected=16899.1us +- 84.5us, error 0.5%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.659698
last_received_ts = 320.659180
last_seq = 3421
current_ts = 320.676544
current_received_ts = 320.675964
current_seq = 3422
count = 186
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.659698/3421, current 320.676544/3422: elapsed=16830.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.676544
last_received_ts = 320.675964
last_seq = 3422
current_ts = 320.693359
current_received_ts = 320.692780
current_seq = 3423
count = 187
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.676544/3422, current 320.693359/3423: elapsed=16822.0us expected=16899.1us +- 84.5us, error 0.5%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.693359
last_received_ts = 320.692780
last_seq = 3423
current_ts = 320.710205
current_received_ts = 320.709656
current_seq = 3424
count = 188
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.693359/3423, current 320.710205/3424: elapsed=16836.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.710205
last_received_ts = 320.709656
last_seq = 3424
current_ts = 320.727020
current_received_ts = 320.726471
current_seq = 3425
count = 189
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.710205/3424, current 320.727020/3425: elapsed=16826.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.727020
last_received_ts = 320.726471
last_seq = 3425
current_ts = 320.743866
current_received_ts = 320.743286
current_seq = 3426
count = 190
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.727020/3425, current 320.743866/3426: elapsed=16828.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.743866
last_received_ts = 320.743286
last_seq = 3426
current_ts = 320.760681
current_received_ts = 320.760101
current_seq = 3427
count = 191
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.743866/3426, current 320.760681/3427: elapsed=16818.0us expected=16899.1us +- 84.5us, error 0.5%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.760681
last_received_ts = 320.760101
last_seq = 3427
current_ts = 320.777496
current_received_ts = 320.776947
current_seq = 3428
count = 192
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.760681/3427, current 320.777496/3428: elapsed=16835.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.777496
last_received_ts = 320.776947
last_seq = 3428
current_ts = 320.794342
current_received_ts = 320.793762
current_seq = 3429
count = 193
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.777496/3428, current 320.794342/3429: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.794342
last_received_ts = 320.793762
last_seq = 3429
current_ts = 320.811157
current_received_ts = 320.810577
current_seq = 3430
count = 194
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.794342/3429, current 320.811157/3430: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.811157
last_received_ts = 320.810577
last_seq = 3430
current_ts = 320.827972
current_received_ts = 320.827423
current_seq = 3431
count = 195
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.811157/3430, current 320.827972/3431: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.827972
last_received_ts = 320.827423
last_seq = 3431
current_ts = 320.844818
current_received_ts = 320.844238
current_seq = 3432
count = 196
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.827972/3431, current 320.844818/3432: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.844818
last_received_ts = 320.844238
last_seq = 3432
current_ts = 320.861633
current_received_ts = 320.861084
current_seq = 3433
count = 197
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.844818/3432, current 320.861633/3433: elapsed=16828.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.861633
last_received_ts = 320.861084
last_seq = 3433
current_ts = 320.878479
current_received_ts = 320.877869
current_seq = 3434
count = 198
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.861633/3433, current 320.878479/3434: elapsed=16834.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.878479
last_received_ts = 320.877869
last_seq = 3434
current_ts = 320.895294
current_received_ts = 320.894745
current_seq = 3435
count = 199
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.878479/3434, current 320.895294/3435: elapsed=16822.0us expected=16899.1us +- 84.5us, error 0.5%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.895294
last_received_ts = 320.894745
last_seq = 3435
current_ts = 320.912109
current_received_ts = 320.911560
current_seq = 3436
count = 200
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.895294/3435, current 320.912109/3436: elapsed=16824.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.912109
last_received_ts = 320.911560
last_seq = 3436
current_ts = 320.928955
current_received_ts = 320.928375
current_seq = 3437
count = 201
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.912109/3436, current 320.928955/3437: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.928955
last_received_ts = 320.928375
last_seq = 3437
current_ts = 320.945770
current_received_ts = 320.945221
current_seq = 3438
count = 202
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.928955/3437, current 320.945770/3438: elapsed=16828.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.945770
last_received_ts = 320.945221
last_seq = 3438
current_ts = 320.962616
current_received_ts = 320.962067
current_seq = 3439
count = 203
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.945770/3438, current 320.962616/3439: elapsed=16826.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.962616
last_received_ts = 320.962067
last_seq = 3439
current_ts = 320.979431
current_received_ts = 320.978882
current_seq = 3440
count = 204
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.962616/3439, current 320.979431/3440: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.979431
last_received_ts = 320.978882
last_seq = 3440
current_ts = 320.996246
current_received_ts = 320.995667
current_seq = 3441
count = 205
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.979431/3440, current 320.996246/3441: elapsed=16829.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 320.996246
last_received_ts = 320.995667
last_seq = 3441
current_ts = 321.013092
current_received_ts = 321.012512
current_seq = 3442
count = 206
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 320.996246/3441, current 321.013092/3442: elapsed=16826.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.013092
last_received_ts = 321.012512
last_seq = 3442
current_ts = 321.029907
current_received_ts = 321.029358
current_seq = 3443
count = 207
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.013092/3442, current 321.029907/3443: elapsed=16826.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.029907
last_received_ts = 321.029358
last_seq = 3443
current_ts = 321.046753
current_received_ts = 321.046173
current_seq = 3444
count = 208
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.029907/3443, current 321.046753/3444: elapsed=16829.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.046753
last_received_ts = 321.046173
last_seq = 3444
current_ts = 321.063568
current_received_ts = 321.063019
current_seq = 3445
count = 209
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.046753/3444, current 321.063568/3445: elapsed=16823.0us expected=16899.1us +- 84.5us, error 0.5%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.063568
last_received_ts = 321.063019
last_seq = 3445
current_ts = 321.080383
current_received_ts = 321.079803
current_seq = 3446
count = 210
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.063568/3445, current 321.080383/3446: elapsed=16836.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.080383
last_received_ts = 321.079803
last_seq = 3446
current_ts = 321.097229
current_received_ts = 321.096680
current_seq = 3447
count = 211
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.080383/3446, current 321.097229/3447: elapsed=16820.0us expected=16899.1us +- 84.5us, error 0.5%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.097229
last_received_ts = 321.096680
last_seq = 3447
current_ts = 321.114044
current_received_ts = 321.113495
current_seq = 3448
count = 212
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.097229/3447, current 321.114044/3448: elapsed=16828.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.114044
last_received_ts = 321.113495
last_seq = 3448
current_ts = 321.130859
current_received_ts = 321.130310
current_seq = 3449
count = 213
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.114044/3448, current 321.130859/3449: elapsed=16826.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.130859
last_received_ts = 321.130310
last_seq = 3449
current_ts = 321.147705
current_received_ts = 321.147125
current_seq = 3450
count = 214
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.130859/3449, current 321.147705/3450: elapsed=16829.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.147705
last_received_ts = 321.147125
last_seq = 3450
current_ts = 321.164520
current_received_ts = 321.163971
current_seq = 3451
count = 215
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.147705/3450, current 321.164520/3451: elapsed=16820.0us expected=16899.1us +- 84.5us, error 0.5%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.164520
last_received_ts = 321.163971
last_seq = 3451
current_ts = 321.181366
current_received_ts = 321.180756
current_seq = 3452
count = 216
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.164520/3451, current 321.181366/3452: elapsed=16842.0us expected=16899.1us +- 84.5us, error 0.3%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.181366
last_received_ts = 321.180756
last_seq = 3452
current_ts = 321.198181
current_received_ts = 321.197540
current_seq = 3453
count = 217
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.181366/3452, current 321.198181/3453: elapsed=16825.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.198181
last_received_ts = 321.197540
last_seq = 3453
current_ts = 321.214996
current_received_ts = 321.214417
current_seq = 3454
count = 218
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.198181/3453, current 321.214996/3454: elapsed=16815.0us expected=16899.1us +- 84.5us, error 0.5%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.214996
last_received_ts = 321.214417
last_seq = 3454
current_ts = 321.231842
current_received_ts = 321.231262
current_seq = 3455
count = 219
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.214996/3454, current 321.231842/3455: elapsed=16832.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.231842
last_received_ts = 321.231262
last_seq = 3455
current_ts = 321.248657
current_received_ts = 321.248108
current_seq = 3456
count = 220
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.231842/3455, current 321.248657/3456: elapsed=16828.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.248657
last_received_ts = 321.248108
last_seq = 3456
current_ts = 321.265503
current_received_ts = 321.264923
current_seq = 3457
count = 221
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.248657/3456, current 321.265503/3457: elapsed=16826.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.265503
last_received_ts = 321.264923
last_seq = 3457
current_ts = 321.282318
current_received_ts = 321.281769
current_seq = 3458
count = 222
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.265503/3457, current 321.282318/3458: elapsed=16826.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.282318
last_received_ts = 321.281769
last_seq = 3458
current_ts = 321.299133
current_received_ts = 321.298584
current_seq = 3459
count = 223
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.282318/3458, current 321.299133/3459: elapsed=16829.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.299133
last_received_ts = 321.298584
last_seq = 3459
current_ts = 321.315979
current_received_ts = 321.315399
current_seq = 3460
count = 224
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.299133/3459, current 321.315979/3460: elapsed=16826.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.315979
last_received_ts = 321.315399
last_seq = 3460
current_ts = 321.332794
current_received_ts = 321.332245
current_seq = 3461
count = 225
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.315979/3460, current 321.332794/3461: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.332794
last_received_ts = 321.332245
last_seq = 3461
current_ts = 321.349609
current_received_ts = 321.349091
current_seq = 3462
count = 226
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.332794/3461, current 321.349609/3462: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.349609
last_received_ts = 321.349091
last_seq = 3462
current_ts = 321.366455
current_received_ts = 321.365875
current_seq = 3463
count = 227
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.349609/3462, current 321.366455/3463: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.366455
last_received_ts = 321.365875
last_seq = 3463
current_ts = 321.383270
current_received_ts = 321.382721
current_seq = 3464
count = 228
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.366455/3463, current 321.383270/3464: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.383270
last_received_ts = 321.382721
last_seq = 3464
current_ts = 321.400116
current_received_ts = 321.399536
current_seq = 3465
count = 229
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.383270/3464, current 321.400116/3465: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.400116
last_received_ts = 321.399536
last_seq = 3465
current_ts = 321.416931
current_received_ts = 321.416382
current_seq = 3466
count = 230
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.400116/3465, current 321.416931/3466: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.416931
last_received_ts = 321.416382
last_seq = 3466
current_ts = 321.433746
current_received_ts = 321.433197
current_seq = 3467
count = 231
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.416931/3466, current 321.433746/3467: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.433746
last_received_ts = 321.433197
last_seq = 3467
current_ts = 321.450592
current_received_ts = 321.450043
current_seq = 3468
count = 232
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.433746/3467, current 321.450592/3468: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.450592
last_received_ts = 321.450043
last_seq = 3468
current_ts = 321.467407
current_received_ts = 321.466858
current_seq = 3469
count = 233
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.450592/3468, current 321.467407/3469: elapsed=16828.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.467407
last_received_ts = 321.466858
last_seq = 3469
current_ts = 321.484253
current_received_ts = 321.483673
current_seq = 3470
count = 234
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.467407/3469, current 321.484253/3470: elapsed=16826.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.484253
last_received_ts = 321.483673
last_seq = 3470
current_ts = 321.501068
current_received_ts = 321.500488
current_seq = 3471
count = 235
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.484253/3470, current 321.501068/3471: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.501068
last_received_ts = 321.500488
last_seq = 3471
current_ts = 321.517883
current_received_ts = 321.517303
current_seq = 3472
count = 236
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.501068/3471, current 321.517883/3472: elapsed=16821.0us expected=16899.1us +- 84.5us, error 0.5%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.517883
last_received_ts = 321.517303
last_seq = 3472
current_ts = 321.534729
current_received_ts = 321.534149
current_seq = 3473
count = 237
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.517883/3472, current 321.534729/3473: elapsed=16834.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.534729
last_received_ts = 321.534149
last_seq = 3473
current_ts = 321.551544
current_received_ts = 321.550995
current_seq = 3474
count = 238
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.534729/3473, current 321.551544/3474: elapsed=16826.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.551544
last_received_ts = 321.550995
last_seq = 3474
current_ts = 321.568359
current_received_ts = 321.567810
current_seq = 3475
count = 239
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.551544/3474, current 321.568359/3475: elapsed=16821.0us expected=16899.1us +- 84.5us, error 0.5%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.568359
last_received_ts = 321.567810
last_seq = 3475
current_ts = 321.585205
current_received_ts = 321.584656
current_seq = 3476
count = 240
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.568359/3475, current 321.585205/3476: elapsed=16833.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.585205
last_received_ts = 321.584656
last_seq = 3476
current_ts = 321.602020
current_received_ts = 321.601440
current_seq = 3477
count = 241
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.585205/3476, current 321.602020/3477: elapsed=16827.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.602020
last_received_ts = 321.601440
last_seq = 3477
current_ts = 321.618866
current_received_ts = 321.618286
current_seq = 3478
count = 242
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.602020/3477, current 321.618866/3478: elapsed=16828.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.618866
last_received_ts = 321.618286
last_seq = 3478
current_ts = 321.635681
current_received_ts = 321.635132
current_seq = 3479
count = 243
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.618866/3478, current 321.635681/3479: elapsed=16826.0us expected=16899.1us +- 84.5us, error 0.4%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.635681
last_received_ts = 321.635132
last_seq = 3479
current_ts = 321.652496
current_received_ts = 321.651917
current_seq = 3480
count = 244
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.635681/3479, current 321.652496/3480: elapsed=16817.0us expected=16899.1us +- 84.5us, error 0.5%
(kms_flip:3070) DEBUG: name = flip
last_ts = 321.652496
last_received_ts = 321.651917
last_seq = 3480
current_ts = 321.669312
current_received_ts = 321.668762
current_seq = 3481
count = 245
seq_step = 1
(kms_flip:3070) DEBUG: flip ts/seq: last 321.652496/3480, current 321.669312/3481: elapsed=16813.0us expected=16899.1us +- 84.5us, error 0.5%
(kms_flip:3070) DEBUG: inconsistent flip ts/seq: last 321.652496/3480, current 321.669312/3481: elapsed=16813.0us expected=16899.1us
(kms_flip:3070) DEBUG: expected 168782, counted 245, encoder type 1
(kms_flip:3070) DEBUG: dropped frames, expected 168782, counted 245, encoder type 1
(kms_flip:3070) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3070) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3070) igt_core-INFO: Stack trace:
(kms_flip:3070) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3070) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3070) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3070) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3070) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3070) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3070) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3070) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-VGA1: FAIL (7.715s)
Dmesg
<6> [331.931698] [IGT] kms_flip: starting dynamic subtest B-VGA1
<7> [331.932196] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:84]
<7> [331.932296] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:85]
<7> [331.967392] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:47:pipe A]
<7> [331.967598] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.enable (expected yes, found no)
<7> [331.968059] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.active (expected yes, found no)
<7> [331.968525] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)
<7> [331.968991] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in has_pch_encoder (expected yes, found no)
<7> [331.969390] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in fdi_lanes (expected 1, found 0)
<7> [331.969807] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in fdi_m_n (expected tu 64 data 6039797/8388608 link 125829/524288, found tu 0, data 0/0 link 0/0)
<7> [331.970159] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000)
<7> [331.970555] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [331.970952] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0)
<7> [331.971278] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0)
<7> [331.971697] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0)
<7> [331.972074] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0)
<7> [331.972405] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0)
<7> [331.972662] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0)
<7> [331.972872] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0)
<7> [331.973083] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0)
<7> [331.973311] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0)
<7> [331.973549] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0)
<7> [331.973760] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0)
<7> [331.973970] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0)
<7> [331.974180] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0)
<7> [331.974427] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0)
<7> [331.974662] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0)
<7> [331.974872] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0)
<7> [331.975083] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0)
<7> [331.975313] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0)
<7> [331.975546] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0)
<7> [331.975757] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0)
<7> [331.975967] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0)
<7> [331.976177] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0)
<7> [331.976407] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0)
<7> [331.976649] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0)
<7> [331.976859] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [331.977070] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [331.977296] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [331.977532] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in pipe_bpp (expected 24, found 0)
<7> [331.977743] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0)
<7> [331.977953] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0)
<7> [331.978163] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:47:pipe A] fastset requirement not met in port_clock (expected 64800, found 0)
<7> [331.978401] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:47:pipe A] fastset requirement not met, forcing full modeset
<7> [331.978644] i915 0000:00:02.0: [drm:intel_unreference_shared_dpll_crtc [i915]] [CRTC:47:pipe A] releasing PCH DPLL A
<7> [331.978923] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [331.979144] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [331.979381] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:47:pipe A] enable: no [modeset]
<7> [331.979612] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:primary A] fb: [NOFB], visible: no
<7> [331.979927] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [331.990226] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found
<7> [331.990440] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found
<7> [331.990660] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found
<7> [332.006473] i915 0000:00:02.0: [drm:intel_disable_shared_dpll [i915]] disable PCH DPLL A (active 0x1, on? 1) for [CRTC:47:pipe A]
<7> [332.006820] i915 0000:00:02.0: [drm:intel_disable_shared_dpll [i915]] disabling PCH DPLL A
<7> [332.007417] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:65:CRT]
<7> [332.007738] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:66:HDMI D]
<7> [332.008086] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:DP D]
<7> [332.008427] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:64:VGA-1]
<7> [332.008800] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:47:pipe A]
<7> [332.009264] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:63:pipe B]
<7> [332.009517] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:63:pipe B]
<7> [332.009554] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:64:VGA-1]
<7> [332.009680] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:64:VGA-1] Limiting display bpp to 24 (EDID bpp 0, max requested bpp 0, max platform bpp 36)
<7> [332.010042] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:63:pipe B] hw max bpp: 24, pipe bpp: 24, dithering: 0
<7> [332.010263] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe B, lanes 1
<7> [332.010471] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [332.010682] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [332.010904] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [332.011116] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in has_pch_encoder (expected no, found yes)
<7> [332.011327] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in fdi_lanes (expected 0, found 1)
<7> [332.011538] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in fdi_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6039797/8388608 link 125829/524288)
<7> [332.011750] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000002)
<7> [332.011980] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [332.012191] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1024)
<7> [332.012402] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 1344)
<7> [332.012612] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1024)
<7> [332.012826] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 1344)
<7> [332.013065] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 1048)
<7> [332.013276] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 1184)
<7> [332.013486] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 768)
<7> [332.013702] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 768)
<7> [332.013937] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 771)
<7> [332.014160] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 777)
<7> [332.014364] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 806)
<7> [332.014568] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 806)
<7> [332.014772] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1024)
<7> [332.015006] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 1344)
<7> [332.015230] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1024)
<7> [332.015442] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 1344)
<7> [332.015652] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 1048)
<7> [332.015889] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 1184)
<7> [332.016152] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 768)
<7> [332.016363] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 768)
<7> [332.016573] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 771)
<7> [332.016782] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 777)
<7> [332.017018] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 806)
<7> [332.017229] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 806)
<7> [332.017440] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [332.017652] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [332.017880] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [332.018092] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in dpll_hw_state
<7> [332.018302] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:
<7> [332.018511] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06
<7> [332.018721] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:
<7> [332.018944] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [332.019155] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 24)
<7> [332.019365] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 64800)
<7> [332.019575] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 64800)
<7> [332.019808] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:63:pipe B] fastset requirement not met in port_clock (expected 0, found 64800)
<7> [332.020026] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:63:pipe B] fastset requirement not met, forcing full modeset
<7> [332.020276] i915 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [i915]] [PLANE:48:primary B] min cdclk (64800 kHz) > [CRTC:63:pipe B] min cdclk (0 kHz)
<7> [332.020484] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 400000 kHz, actual 400000 kHz
<7> [332.020698] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [332.020944] i915 0000:00:02.0: [drm:intel_find_shared_dpll [i915]] [CRTC:63:pipe B] allocated PCH DPLL A
<7> [332.021167] i915 0000:00:02.0: [drm:intel_reference_shared_dpll_crtc [i915]] [CRTC:63:pipe B] reserving PCH DPLL A
<7> [332.021381] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:63:pipe B] enable: yes [modeset]
<7> [332.021593] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: ANALOG (0x2), output format: RGB, sink format: RGB
<7> [332.021848] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 24, dithering: 0
<7> [332.022071] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [332.022283] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [332.022493] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [332.022703] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [332.022931] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fdi: lanes: 1; data_m: 6039797, data_n: 8388608, link_m: 125829, link_n: 524288, tu: 64
<7> [332.023154] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x0
<7> [332.023359] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [332.023563] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0
<7> [332.023800] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0
<7> [332.024023] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: -1, vmax vblank: -2, vmin vtotal: 1, vmax vtotal: 0
<7> [332.024240] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa
<7> [332.024451] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1024x768": 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa
<7> [332.024662] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa
<7> [332.024891] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1024x768": 60 64800 1024 1048 1184 1344 768 771 777 806 0x40 0xa
<7> [332.025115] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=64800, hd=1024 hb=1024-1344 hs=1048-1184 ht=1344, vd=768 vb=768-806 vs=771-777 vt=806, flags=0xa
<7> [332.025321] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 64800, pipe src: 1024x768+0+0, pixel rate 64800
<7> [332.025536] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0
<7> [332.025777] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [332.025998] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [332.026202] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09
<7> [332.026406] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [332.026611] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [332.026851] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [332.026869] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on
<7> [332.027116] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [332.027353] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [332.027567] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [332.027816] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:48:primary B] fb: [FB:84] 1024x768 format = XR24 little-endian (0x34325258) modifier = 0x0, visible: yes
<7> [332.028040] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [332.028244] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1024.000000x768.000000+0.000000+0.000000 dst: 1024x768+0+0
<7> [332.029321] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on
<7> [332.029564] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:65:CRT]
<7> [332.029807] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:66:HDMI D]
<7> [332.030025] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:DP D]
<7> [332.030811] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [332.031864] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100
<7> [332.032114] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.
<7> [332.033027] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x200
<7> [332.033231] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.
<7> [332.033476] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.
<7> [332.033763] i915 0000:00:02.0: [drm:intel_enable_shared_dpll [i915]] enable PCH DPLL A (active 0x2, on? 0) for [CRTC:63:pipe B]
<7> [332.034003] i915 0000:00:02.0: [drm:intel_enable_shared_dpll [i915]] enabling PCH DPLL A
<7> [332.086005] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:64:VGA-1]
<7> [332.086568] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:63:pipe B]
<6> [339.647843] [IGT] kms_flip: finished subtest B-VGA1, FAIL
Created at 2025-03-05 09:47:26