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

Machine description: shard-mtlp-6

Result: Fail

git-log-oneline i915_display_info21 igt_runner21 runtimes21 results21.json results21-i915-load.json i915_display_info_post_exec21 boot21 dmesg21

DetailValue
Duration 8.07 seconds
Hostname 
shard-mtlp-6
Igt-Version 
IGT-Version: 2.0-gf05383af3 (x86_64) (Linux: 6.14.0-rc7-CI_DRM_16300-g74f632d1bd3b+ x86_64)
Out 
Starting dynamic subtest: B-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Expected frametime: 11111us; measured 10977.1us +- 2.516us accuracy 0.07%
vblank interval differs from modeline! expected 11111.1us, measured 10977us +- 2.516us, difference 134.1us (53.3 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (8.073s)
Err 
Starting dynamic subtest: B-eDP1
(kms_flip:2440) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2440) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:2440) DEBUG: flip ts/seq: last 212.061539/248, current 212.072540/249: elapsed=11004.0us expected=10977.1us +- 54.9us, error 0.2%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.072540
last_received_ts = 212.072189
last_seq = 249
current_ts = 212.083557
current_received_ts = 212.083206
current_seq = 250
count = 175
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.072540/249, current 212.083557/250: elapsed=11008.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.083557
last_received_ts = 212.083206
last_seq = 250
current_ts = 212.094559
current_received_ts = 212.094193
current_seq = 251
count = 176
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.083557/250, current 212.094559/251: elapsed=11007.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.094559
last_received_ts = 212.094193
last_seq = 251
current_ts = 212.105576
current_received_ts = 212.105225
current_seq = 252
count = 177
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.094559/251, current 212.105576/252: elapsed=11006.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.105576
last_received_ts = 212.105225
last_seq = 252
current_ts = 212.116577
current_received_ts = 212.116211
current_seq = 253
count = 178
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.105576/252, current 212.116577/253: elapsed=11009.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.116577
last_received_ts = 212.116211
last_seq = 253
current_ts = 212.127579
current_received_ts = 212.127213
current_seq = 254
count = 179
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.116577/253, current 212.127579/254: elapsed=11006.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.127579
last_received_ts = 212.127213
last_seq = 254
current_ts = 212.138596
current_received_ts = 212.138260
current_seq = 255
count = 180
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.127579/254, current 212.138596/255: elapsed=11011.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.138596
last_received_ts = 212.138260
last_seq = 255
current_ts = 212.149597
current_received_ts = 212.149246
current_seq = 256
count = 181
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.138596/255, current 212.149597/256: elapsed=11003.0us expected=10977.1us +- 54.9us, error 0.2%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.149597
last_received_ts = 212.149246
last_seq = 256
current_ts = 212.160599
current_received_ts = 212.160233
current_seq = 257
count = 182
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.149597/256, current 212.160599/257: elapsed=11009.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.160599
last_received_ts = 212.160233
last_seq = 257
current_ts = 212.171616
current_received_ts = 212.171280
current_seq = 258
count = 183
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.160599/257, current 212.171616/258: elapsed=11006.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.171616
last_received_ts = 212.171280
last_seq = 258
current_ts = 212.182617
current_received_ts = 212.182281
current_seq = 259
count = 184
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.171616/258, current 212.182617/259: elapsed=11007.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.182617
last_received_ts = 212.182281
last_seq = 259
current_ts = 212.193634
current_received_ts = 212.193237
current_seq = 260
count = 185
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.182617/259, current 212.193634/260: elapsed=11011.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.193634
last_received_ts = 212.193237
last_seq = 260
current_ts = 212.204636
current_received_ts = 212.204300
current_seq = 261
count = 186
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.193634/260, current 212.204636/261: elapsed=11007.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.204636
last_received_ts = 212.204300
last_seq = 261
current_ts = 212.215637
current_received_ts = 212.215302
current_seq = 262
count = 187
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.204636/261, current 212.215637/262: elapsed=11007.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.215637
last_received_ts = 212.215302
last_seq = 262
current_ts = 212.226654
current_received_ts = 212.226303
current_seq = 263
count = 188
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.215637/262, current 212.226654/263: elapsed=11008.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.226654
last_received_ts = 212.226303
last_seq = 263
current_ts = 212.237656
current_received_ts = 212.237335
current_seq = 264
count = 189
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.226654/263, current 212.237656/264: elapsed=11004.0us expected=10977.1us +- 54.9us, error 0.2%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.237656
last_received_ts = 212.237335
last_seq = 264
current_ts = 212.248657
current_received_ts = 212.248352
current_seq = 265
count = 190
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.237656/264, current 212.248657/265: elapsed=11007.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.248657
last_received_ts = 212.248352
last_seq = 265
current_ts = 212.259674
current_received_ts = 212.259354
current_seq = 266
count = 191
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.248657/265, current 212.259674/266: elapsed=11008.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.259674
last_received_ts = 212.259354
last_seq = 266
current_ts = 212.270676
current_received_ts = 212.270370
current_seq = 267
count = 192
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.259674/266, current 212.270676/267: elapsed=11007.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.270676
last_received_ts = 212.270370
last_seq = 267
current_ts = 212.281693
current_received_ts = 212.281326
current_seq = 268
count = 193
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.270676/267, current 212.281693/268: elapsed=11010.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.281693
last_received_ts = 212.281326
last_seq = 268
current_ts = 212.292694
current_received_ts = 212.292358
current_seq = 269
count = 194
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.281693/268, current 212.292694/269: elapsed=11003.0us expected=10977.1us +- 54.9us, error 0.2%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.292694
last_received_ts = 212.292358
last_seq = 269
current_ts = 212.303696
current_received_ts = 212.303406
current_seq = 270
count = 195
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.292694/269, current 212.303696/270: elapsed=11006.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.303696
last_received_ts = 212.303406
last_seq = 270
current_ts = 212.314713
current_received_ts = 212.314331
current_seq = 271
count = 196
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.303696/270, current 212.314713/271: elapsed=11008.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.314713
last_received_ts = 212.314331
last_seq = 271
current_ts = 212.325714
current_received_ts = 212.325394
current_seq = 272
count = 197
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.314713/271, current 212.325714/272: elapsed=11009.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.325714
last_received_ts = 212.325394
last_seq = 272
current_ts = 212.336716
current_received_ts = 212.336426
current_seq = 273
count = 198
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.325714/272, current 212.336716/273: elapsed=11005.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.336716
last_received_ts = 212.336426
last_seq = 273
current_ts = 212.347733
current_received_ts = 212.347397
current_seq = 274
count = 199
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.336716/273, current 212.347733/274: elapsed=11008.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.347733
last_received_ts = 212.347397
last_seq = 274
current_ts = 212.358734
current_received_ts = 212.358398
current_seq = 275
count = 200
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.347733/274, current 212.358734/275: elapsed=11006.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.358734
last_received_ts = 212.358398
last_seq = 275
current_ts = 212.369751
current_received_ts = 212.369415
current_seq = 276
count = 201
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.358734/275, current 212.369751/276: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.369751
last_received_ts = 212.369415
last_seq = 276
current_ts = 212.380768
current_received_ts = 212.380417
current_seq = 277
count = 202
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.369751/276, current 212.380768/277: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.380768
last_received_ts = 212.380417
last_seq = 277
current_ts = 212.391785
current_received_ts = 212.391464
current_seq = 278
count = 203
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.380768/277, current 212.391785/278: elapsed=11016.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.391785
last_received_ts = 212.391464
last_seq = 278
current_ts = 212.402817
current_received_ts = 212.402481
current_seq = 279
count = 204
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.391785/278, current 212.402817/279: elapsed=11023.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.402817
last_received_ts = 212.402481
last_seq = 279
current_ts = 212.413818
current_received_ts = 212.413498
current_seq = 280
count = 205
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.402817/279, current 212.413818/280: elapsed=11014.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.413818
last_received_ts = 212.413498
last_seq = 280
current_ts = 212.424850
current_received_ts = 212.424515
current_seq = 281
count = 206
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.413818/280, current 212.424850/281: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.424850
last_received_ts = 212.424515
last_seq = 281
current_ts = 212.435867
current_received_ts = 212.435547
current_seq = 282
count = 207
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.424850/281, current 212.435867/282: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.435867
last_received_ts = 212.435547
last_seq = 282
current_ts = 212.446884
current_received_ts = 212.446564
current_seq = 283
count = 208
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.435867/282, current 212.446884/283: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.446884
last_received_ts = 212.446564
last_seq = 283
current_ts = 212.457901
current_received_ts = 212.457581
current_seq = 284
count = 209
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.446884/283, current 212.457901/284: elapsed=11020.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.457901
last_received_ts = 212.457581
last_seq = 284
current_ts = 212.468918
current_received_ts = 212.468597
current_seq = 285
count = 210
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.457901/284, current 212.468918/285: elapsed=11018.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.468918
last_received_ts = 212.468597
last_seq = 285
current_ts = 212.479950
current_received_ts = 212.479614
current_seq = 286
count = 211
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.468918/285, current 212.479950/286: elapsed=11022.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.479950
last_received_ts = 212.479614
last_seq = 286
current_ts = 212.490967
current_received_ts = 212.490646
current_seq = 287
count = 212
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.479950/286, current 212.490967/287: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.490967
last_received_ts = 212.490646
last_seq = 287
current_ts = 212.501984
current_received_ts = 212.501648
current_seq = 288
count = 213
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.490967/287, current 212.501984/288: elapsed=11017.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.501984
last_received_ts = 212.501648
last_seq = 288
current_ts = 212.513000
current_received_ts = 212.512665
current_seq = 289
count = 214
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.501984/288, current 212.513000/289: elapsed=11020.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.513000
last_received_ts = 212.512665
last_seq = 289
current_ts = 212.524033
current_received_ts = 212.523697
current_seq = 290
count = 215
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.513000/289, current 212.524033/290: elapsed=11020.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.524033
last_received_ts = 212.523697
last_seq = 290
current_ts = 212.535049
current_received_ts = 212.534698
current_seq = 291
count = 216
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.524033/290, current 212.535049/291: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.535049
last_received_ts = 212.534698
last_seq = 291
current_ts = 212.546066
current_received_ts = 212.545731
current_seq = 292
count = 217
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.535049/291, current 212.546066/292: elapsed=11016.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.546066
last_received_ts = 212.545731
last_seq = 292
current_ts = 212.557083
current_received_ts = 212.556793
current_seq = 293
count = 218
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.546066/292, current 212.557083/293: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.557083
last_received_ts = 212.556793
last_seq = 293
current_ts = 212.568100
current_received_ts = 212.567764
current_seq = 294
count = 219
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.557083/293, current 212.568100/294: elapsed=11023.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.568100
last_received_ts = 212.567764
last_seq = 294
current_ts = 212.579117
current_received_ts = 212.578796
current_seq = 295
count = 220
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.568100/294, current 212.579117/295: elapsed=11014.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.579117
last_received_ts = 212.578796
last_seq = 295
current_ts = 212.590134
current_received_ts = 212.589813
current_seq = 296
count = 221
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.579117/295, current 212.590134/296: elapsed=11022.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.590134
last_received_ts = 212.589813
last_seq = 296
current_ts = 212.601166
current_received_ts = 212.600830
current_seq = 297
count = 222
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.590134/296, current 212.601166/297: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.601166
last_received_ts = 212.600830
last_seq = 297
current_ts = 212.612183
current_received_ts = 212.611816
current_seq = 298
count = 223
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.601166/297, current 212.612183/298: elapsed=11022.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.612183
last_received_ts = 212.611816
last_seq = 298
current_ts = 212.623199
current_received_ts = 212.622879
current_seq = 299
count = 224
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.612183/298, current 212.623199/299: elapsed=11020.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.623199
last_received_ts = 212.622879
last_seq = 299
current_ts = 212.634216
current_received_ts = 212.633881
current_seq = 300
count = 225
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.623199/299, current 212.634216/300: elapsed=11020.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.634216
last_received_ts = 212.633881
last_seq = 300
current_ts = 212.645233
current_received_ts = 212.644897
current_seq = 301
count = 226
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.634216/300, current 212.645233/301: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.645233
last_received_ts = 212.644897
last_seq = 301
current_ts = 212.656250
current_received_ts = 212.655930
current_seq = 302
count = 227
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.645233/301, current 212.656250/302: elapsed=11015.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.656250
last_received_ts = 212.655930
last_seq = 302
current_ts = 212.667282
current_received_ts = 212.666946
current_seq = 303
count = 228
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.656250/302, current 212.667282/303: elapsed=11023.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.667282
last_received_ts = 212.666946
last_seq = 303
current_ts = 212.678299
current_received_ts = 212.677979
current_seq = 304
count = 229
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.667282/303, current 212.678299/304: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.678299
last_received_ts = 212.677979
last_seq = 304
current_ts = 212.689316
current_received_ts = 212.689056
current_seq = 305
count = 230
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.678299/304, current 212.689316/305: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.689316
last_received_ts = 212.689056
last_seq = 305
current_ts = 212.700333
current_received_ts = 212.700058
current_seq = 306
count = 231
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.689316/305, current 212.700333/306: elapsed=11018.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.700333
last_received_ts = 212.700058
last_seq = 306
current_ts = 212.711349
current_received_ts = 212.711060
current_seq = 307
count = 232
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.700333/306, current 212.711349/307: elapsed=11020.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.711349
last_received_ts = 212.711060
last_seq = 307
current_ts = 212.722382
current_received_ts = 212.722107
current_seq = 308
count = 233
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.711349/307, current 212.722382/308: elapsed=11018.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.722382
last_received_ts = 212.722107
last_seq = 308
current_ts = 212.733398
current_received_ts = 212.733078
current_seq = 309
count = 234
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.722382/308, current 212.733398/309: elapsed=11022.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.733398
last_received_ts = 212.733078
last_seq = 309
current_ts = 212.744415
current_received_ts = 212.744110
current_seq = 310
count = 235
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.733398/309, current 212.744415/310: elapsed=11018.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.744415
last_received_ts = 212.744110
last_seq = 310
current_ts = 212.755432
current_received_ts = 212.755142
current_seq = 311
count = 236
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.744415/310, current 212.755432/311: elapsed=11020.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.755432
last_received_ts = 212.755142
last_seq = 311
current_ts = 212.766449
current_received_ts = 212.766144
current_seq = 312
count = 237
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.755432/311, current 212.766449/312: elapsed=11020.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.766449
last_received_ts = 212.766144
last_seq = 312
current_ts = 212.777466
current_received_ts = 212.777191
current_seq = 313
count = 238
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.766449/312, current 212.777466/313: elapsed=11016.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.777466
last_received_ts = 212.777191
last_seq = 313
current_ts = 212.788483
current_received_ts = 212.788177
current_seq = 314
count = 239
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.777466/313, current 212.788483/314: elapsed=11020.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.788483
last_received_ts = 212.788177
last_seq = 314
current_ts = 212.799515
current_received_ts = 212.799210
current_seq = 315
count = 240
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.788483/314, current 212.799515/315: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.799515
last_received_ts = 212.799210
last_seq = 315
current_ts = 212.810532
current_received_ts = 212.810257
current_seq = 316
count = 241
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.799515/315, current 212.810532/316: elapsed=11022.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.810532
last_received_ts = 212.810257
last_seq = 316
current_ts = 212.821548
current_received_ts = 212.821228
current_seq = 317
count = 242
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.810532/316, current 212.821548/317: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.821548
last_received_ts = 212.821228
last_seq = 317
current_ts = 212.832565
current_received_ts = 212.832260
current_seq = 318
count = 243
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.821548/317, current 212.832565/318: elapsed=11016.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.832565
last_received_ts = 212.832260
last_seq = 318
current_ts = 212.843597
current_received_ts = 212.843323
current_seq = 319
count = 244
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.832565/318, current 212.843597/319: elapsed=11024.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.843597
last_received_ts = 212.843323
last_seq = 319
current_ts = 212.854614
current_received_ts = 212.854294
current_seq = 320
count = 245
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.843597/319, current 212.854614/320: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.854614
last_received_ts = 212.854294
last_seq = 320
current_ts = 212.865631
current_received_ts = 212.865326
current_seq = 321
count = 246
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.854614/320, current 212.865631/321: elapsed=11013.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.865631
last_received_ts = 212.865326
last_seq = 321
current_ts = 212.876648
current_received_ts = 212.876358
current_seq = 322
count = 247
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.865631/321, current 212.876648/322: elapsed=11020.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.876648
last_received_ts = 212.876358
last_seq = 322
current_ts = 212.887665
current_received_ts = 212.887375
current_seq = 323
count = 248
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.876648/322, current 212.887665/323: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.887665
last_received_ts = 212.887375
last_seq = 323
current_ts = 212.898682
current_received_ts = 212.898376
current_seq = 324
count = 249
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.887665/323, current 212.898682/324: elapsed=11022.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.898682
last_received_ts = 212.898376
last_seq = 324
current_ts = 212.909698
current_received_ts = 212.909393
current_seq = 325
count = 250
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.898682/324, current 212.909698/325: elapsed=11018.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.909698
last_received_ts = 212.909393
last_seq = 325
current_ts = 212.920731
current_received_ts = 212.920425
current_seq = 326
count = 251
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.909698/325, current 212.920731/326: elapsed=11023.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.920731
last_received_ts = 212.920425
last_seq = 326
current_ts = 212.931747
current_received_ts = 212.931442
current_seq = 327
count = 252
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.920731/326, current 212.931747/327: elapsed=11018.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.931747
last_received_ts = 212.931442
last_seq = 327
current_ts = 212.942764
current_received_ts = 212.942474
current_seq = 328
count = 253
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.931747/327, current 212.942764/328: elapsed=11022.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.942764
last_received_ts = 212.942474
last_seq = 328
current_ts = 212.953781
current_received_ts = 212.953461
current_seq = 329
count = 254
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.942764/328, current 212.953781/329: elapsed=11015.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.953781
last_received_ts = 212.953461
last_seq = 329
current_ts = 212.964798
current_received_ts = 212.964508
current_seq = 330
count = 255
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.953781/329, current 212.964798/330: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.964798
last_received_ts = 212.964508
last_seq = 330
current_ts = 212.975830
current_received_ts = 212.975540
current_seq = 331
count = 256
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.964798/330, current 212.975830/331: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.975830
last_received_ts = 212.975540
last_seq = 331
current_ts = 212.986847
current_received_ts = 212.986542
current_seq = 332
count = 257
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.975830/331, current 212.986847/332: elapsed=11018.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.986847
last_received_ts = 212.986542
last_seq = 332
current_ts = 212.997864
current_received_ts = 212.997559
current_seq = 333
count = 258
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.986847/332, current 212.997864/333: elapsed=11022.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 212.997864
last_received_ts = 212.997559
last_seq = 333
current_ts = 213.008881
current_received_ts = 213.008606
current_seq = 334
count = 259
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 212.997864/333, current 213.008881/334: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.008881
last_received_ts = 213.008606
last_seq = 334
current_ts = 213.019897
current_received_ts = 213.019592
current_seq = 335
count = 260
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.008881/334, current 213.019897/335: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.019897
last_received_ts = 213.019592
last_seq = 335
current_ts = 213.030914
current_received_ts = 213.030609
current_seq = 336
count = 261
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.019897/335, current 213.030914/336: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.030914
last_received_ts = 213.030609
last_seq = 336
current_ts = 213.041946
current_received_ts = 213.041641
current_seq = 337
count = 262
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.030914/336, current 213.041946/337: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.041946
last_received_ts = 213.041641
last_seq = 337
current_ts = 213.052963
current_received_ts = 213.052673
current_seq = 338
count = 263
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.041946/337, current 213.052963/338: elapsed=11017.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.052963
last_received_ts = 213.052673
last_seq = 338
current_ts = 213.063980
current_received_ts = 213.063690
current_seq = 339
count = 264
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.052963/338, current 213.063980/339: elapsed=11020.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.063980
last_received_ts = 213.063690
last_seq = 339
current_ts = 213.074997
current_received_ts = 213.074692
current_seq = 340
count = 265
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.063980/339, current 213.074997/340: elapsed=11017.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.074997
last_received_ts = 213.074692
last_seq = 340
current_ts = 213.086014
current_received_ts = 213.085709
current_seq = 341
count = 266
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.074997/340, current 213.086014/341: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.086014
last_received_ts = 213.085709
last_seq = 341
current_ts = 213.097031
current_received_ts = 213.096771
current_seq = 342
count = 267
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.086014/341, current 213.097031/342: elapsed=11024.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.097031
last_received_ts = 213.096771
last_seq = 342
current_ts = 213.108063
current_received_ts = 213.107758
current_seq = 343
count = 268
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.097031/342, current 213.108063/343: elapsed=11020.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.108063
last_received_ts = 213.107758
last_seq = 343
current_ts = 213.119080
current_received_ts = 213.118774
current_seq = 344
count = 269
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.108063/343, current 213.119080/344: elapsed=11018.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.119080
last_received_ts = 213.118774
last_seq = 344
current_ts = 213.130096
current_received_ts = 213.129807
current_seq = 345
count = 270
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.119080/344, current 213.130096/345: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.130096
last_received_ts = 213.129807
last_seq = 345
current_ts = 213.141113
current_received_ts = 213.140823
current_seq = 346
count = 271
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.130096/345, current 213.141113/346: elapsed=11016.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.141113
last_received_ts = 213.140823
last_seq = 346
current_ts = 213.152130
current_received_ts = 213.151840
current_seq = 347
count = 272
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.141113/346, current 213.152130/347: elapsed=11024.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.152130
last_received_ts = 213.151840
last_seq = 347
current_ts = 213.163162
current_received_ts = 213.162857
current_seq = 348
count = 273
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.152130/347, current 213.163162/348: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.163162
last_received_ts = 213.162857
last_seq = 348
current_ts = 213.174164
current_received_ts = 213.173859
current_seq = 349
count = 274
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.163162/348, current 213.174164/349: elapsed=11014.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.174164
last_received_ts = 213.173859
last_seq = 349
current_ts = 213.185196
current_received_ts = 213.184875
current_seq = 350
count = 275
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.174164/349, current 213.185196/350: elapsed=11025.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.185196
last_received_ts = 213.184875
last_seq = 350
current_ts = 213.196213
current_received_ts = 213.195923
current_seq = 351
count = 276
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.185196/350, current 213.196213/351: elapsed=11018.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.196213
last_received_ts = 213.195923
last_seq = 351
current_ts = 213.207230
current_received_ts = 213.206909
current_seq = 352
count = 277
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.196213/351, current 213.207230/352: elapsed=11017.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.207230
last_received_ts = 213.206909
last_seq = 352
current_ts = 213.218246
current_received_ts = 213.217941
current_seq = 353
count = 278
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.207230/352, current 213.218246/353: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.218246
last_received_ts = 213.217941
last_seq = 353
current_ts = 213.229279
current_received_ts = 213.228958
current_seq = 354
count = 279
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.218246/353, current 213.229279/354: elapsed=11022.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.229279
last_received_ts = 213.228958
last_seq = 354
current_ts = 213.240280
current_received_ts = 213.239975
current_seq = 355
count = 280
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.229279/354, current 213.240280/355: elapsed=11016.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.240280
last_received_ts = 213.239975
last_seq = 355
current_ts = 213.251312
current_received_ts = 213.250992
current_seq = 356
count = 281
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.240280/355, current 213.251312/356: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.251312
last_received_ts = 213.250992
last_seq = 356
current_ts = 213.262329
current_received_ts = 213.262054
current_seq = 357
count = 282
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.251312/356, current 213.262329/357: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.262329
last_received_ts = 213.262054
last_seq = 357
current_ts = 213.273346
current_received_ts = 213.273056
current_seq = 358
count = 283
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.262329/357, current 213.273346/358: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.273346
last_received_ts = 213.273056
last_seq = 358
current_ts = 213.284363
current_received_ts = 213.284058
current_seq = 359
count = 284
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.273346/358, current 213.284363/359: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.284363
last_received_ts = 213.284058
last_seq = 359
current_ts = 213.295380
current_received_ts = 213.295074
current_seq = 360
count = 285
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.284363/359, current 213.295380/360: elapsed=11017.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.295380
last_received_ts = 213.295074
last_seq = 360
current_ts = 213.306412
current_received_ts = 213.306091
current_seq = 361
count = 286
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.295380/360, current 213.306412/361: elapsed=11021.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.306412
last_received_ts = 213.306091
last_seq = 361
current_ts = 213.317429
current_received_ts = 213.317184
current_seq = 362
count = 287
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.306412/361, current 213.317429/362: elapsed=11017.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.317429
last_received_ts = 213.317184
last_seq = 362
current_ts = 213.328445
current_received_ts = 213.328140
current_seq = 363
count = 288
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.317429/362, current 213.328445/363: elapsed=11019.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.328445
last_received_ts = 213.328140
last_seq = 363
current_ts = 213.339462
current_received_ts = 213.339172
current_seq = 364
count = 289
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.328445/363, current 213.339462/364: elapsed=11024.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.339462
last_received_ts = 213.339172
last_seq = 364
current_ts = 213.350479
current_received_ts = 213.350235
current_seq = 365
count = 290
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.339462/364, current 213.350479/365: elapsed=11014.0us expected=10977.1us +- 54.9us, error 0.3%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.350479
last_received_ts = 213.350235
last_seq = 365
current_ts = 213.361511
current_received_ts = 213.361206
current_seq = 366
count = 291
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.350479/365, current 213.361511/366: elapsed=11023.0us expected=10977.1us +- 54.9us, error 0.4%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.361511
last_received_ts = 213.361206
last_seq = 366
current_ts = 213.372528
current_received_ts = 213.372223
current_seq = 367
count = 292
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.361511/366, current 213.372528/367: elapsed=11029.0us expected=10977.1us +- 54.9us, error 0.5%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.372528
last_received_ts = 213.372223
last_seq = 367
current_ts = 213.383560
current_received_ts = 213.383255
current_seq = 368
count = 293
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.372528/367, current 213.383560/368: elapsed=11028.0us expected=10977.1us +- 54.9us, error 0.5%
(kms_flip:2440) DEBUG: name = flip
last_ts = 213.383560
last_received_ts = 213.383255
last_seq = 368
current_ts = 213.394592
current_received_ts = 213.394287
current_seq = 369
count = 294
seq_step = 1
(kms_flip:2440) DEBUG: flip ts/seq: last 213.383560/368, current 213.394592/369: elapsed=11035.0us expected=10977.1us +- 54.9us, error 0.5%
(kms_flip:2440) DEBUG: inconsistent flip ts/seq: last 213.383560/368, current 213.394592/369: elapsed=11035.0us expected=10977.1us
(kms_flip:2440) DEBUG: expected 102137, counted 294, encoder type 2
(kms_flip:2440) DEBUG: dropped frames, expected 102137, counted 294, encoder type 2
(kms_flip:2440) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2440) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2440) igt_core-INFO: Stack trace:
(kms_flip:2440) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2440) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2440) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2440) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2440) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2440) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2440) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2440) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (8.073s)
Dmesg
<6> [255.491806] [IGT] kms_flip: starting dynamic subtest B-eDP1
<7> [255.492256] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:302]
<7> [255.492368] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:303]
<7> [255.502203] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [255.502493] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [255.529312] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [255.529559] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [255.551765] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [255.551992] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [255.584249] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [255.584489] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [255.613569] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:82:pipe A]
<7> [255.613830] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.enable (expected yes, found no)
<7> [255.614310] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.active (expected yes, found no)
<7> [255.614761] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)
<7> [255.615160] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in lane_count (expected 4, found 0)
<7> [255.615391] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 7483046/8388608 link 498869/524288, found tu 0, data 0/0 link 0/0)
<7> [255.615590] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)
<7> [255.615811] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [255.616010] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0)
<7> [255.616208] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0)
<7> [255.616404] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0)
<7> [255.616584] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0)
<7> [255.616761] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0)
<7> [255.616928] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0)
<7> [255.617094] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0)
<7> [255.617261] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0)
<7> [255.617432] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0)
<7> [255.617598] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0)
<7> [255.617769] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1878, found 0)
<7> [255.617936] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1878, found 0)
<7> [255.618101] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0)
<7> [255.618265] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0)
<7> [255.618428] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0)
<7> [255.618594] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0)
<7> [255.618761] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0)
<7> [255.618928] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0)
<7> [255.619092] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0)
<7> [255.619256] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0)
<7> [255.619422] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0)
<7> [255.619588] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0)
<7> [255.619753] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1878, found 0)
<7> [255.619933] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1878, found 0)
<7> [255.620100] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [255.620264] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [255.620430] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [255.620599] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in enhanced_framing (expected yes, found no)
<7> [255.620769] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0)
<7> [255.620951] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 513820, found 0)
<7> [255.621117] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 513820, found 0)
<7> [255.621281] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in port_clock (expected 540000, found 0)
<7> [255.621453] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] fastset requirement not met, forcing full modeset
<7> [255.621672] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no
<7> [255.621790] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:82:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0
<7> [255.621962] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] ddb ( 0 - 4001) -> ( 0 - 0), size 4001 -> 0
<7> [255.622072] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:77:cursor A] ddb (4001 - 4096) -> ( 0 - 0), size 95 -> 0
<7> [255.622180] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] level *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm
<7> [255.622316] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] lines 2, 16, 16, 19, 19, 28, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [255.622436] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] blocks 49, 385, 385, 457, 457, 673, 0, 0, 63, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [255.622593] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] min_ddb 55, 425, 425, 504, 504, 742, 0, 0, 64, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [255.622782] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:82:pipe A] data rate 0 num active planes 0
<7> [255.622919] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 0 qgv_peak_bw: 51200
<7> [255.623044] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [255.623158] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [255.623270] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [255.623395] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 0
<7> [255.623579] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing
<7> [255.623756] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz
<7> [255.623916] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [255.624054] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:82:pipe A] enable: no [modeset]
<7> [255.624186] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:plane 1A] fb: [NOFB], visible: no
<7> [255.624318] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:41:plane 2A] fb: [NOFB], visible: no
<7> [255.624453] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:50:plane 3A] fb: [NOFB], visible: no
<7> [255.624576] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:59:plane 4A] fb: [NOFB], visible: no
<7> [255.624690] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:68:plane 5A] fb: [NOFB], visible: no
<7> [255.624803] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:77:cursor A] fb: [NOFB], visible: no
<7> [255.624988] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off
<7> [255.625726] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00
<7> [255.625920] i915 0000:00:02.0: [drm:intel_psr_disable_locked [i915]] Disabling PSR2
<7> [255.626178] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD on
<7> [255.626403] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006f
<7> [255.627238] i915 0000:00:02.0: [drm:intel_edp_backlight_off [i915]]
<7> [255.835026] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 0
<7> [255.835993] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [255.837848] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power off
<7> [255.838354] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x00000089, pins 0x00000010, long 0x00000000
<7> [255.838784] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - short
<7> [255.839304] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power off time
<7> [255.839667] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060
<7> [255.889989] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [255.890617] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring short hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [255.890635] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling AUX_A
<7> [255.891179] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A]
<7> [255.891634] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B]
<7> [255.891814] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [255.892032] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A]
<7> [255.892275] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long
<7> [255.892423] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B]
<7> [255.892698] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 10
<7> [255.892861] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C]
<7> [255.893131] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [255.893280] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D]
<7> [255.893550] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1]
<7> [255.893748] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A]
<7> [255.893947] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B]
<7> [255.894147] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C]
<7> [255.894351] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D]
<7> [255.894573] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2]
<7> [255.894785] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3]
<7> [255.894993] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A]
<7> [255.895138] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B]
<7> [255.895269] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C]
<7> [255.895421] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D]
<7> [255.895557] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4]
<7> [255.895712] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A]
<7> [255.895836] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B]
<7> [255.895953] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C]
<7> [255.896069] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D]
<7> [255.896188] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1]
<7> [255.896335] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no)
<7> [255.896546] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: yes -> no (pipe: *)
<7> [255.896712] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1
<7> [255.896994] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_A
<7> [255.897236] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:82:pipe A]
<7> [255.897413] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Post changing CDCLK to 172800 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0
<7> [255.897590] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=432
<7> [255.897907] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:134:pipe B]
<7> [255.898047] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:186:pipe C]
<7> [255.898180] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:238:pipe D]
<7> [255.898322] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:134:pipe B]
<7> [255.898353] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:241:eDP-1]
<7> [255.898413] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:241:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36)
<7> [255.898552] i915 0000:00:02.0: [drm:intel_dp_compute_config_limits [i915]] [ENCODER:240:DDI A/PHY A][CRTC:134:pipe B] DP link limits: pixel clock 513820 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 30 max link_bpp 30.0000
<7> [255.898711] i915 0000:00:02.0: [drm:intel_dp_compute_link_config [i915]] DP lane count 4 clock 540000 bpp input 30 compressed 0.0000 link rate required 1926825 available 2160000
<7> [255.898845] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:134:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0
<7> [255.898970] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:240:DDI A/PHY A] [CRTC:134:pipe B]
<7> [255.899087] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [255.899216] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [255.899338] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [255.899464] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in lane_count (expected 0, found 4)
<7> [255.899591] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7483046/8388608 link 498869/524288)
<7> [255.899735] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)
<7> [255.899860] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [255.899983] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880)
<7> [255.900107] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040)
<7> [255.900230] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880)
<7> [255.900351] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040)
<7> [255.900473] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928)
<7> [255.900595] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960)
<7> [255.900733] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800)
<7> [255.900854] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800)
<7> [255.900977] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803)
<7> [255.901099] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809)
<7> [255.901220] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1878)
<7> [255.901342] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1878)
<7> [255.901464] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880)
<7> [255.901588] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040)
<7> [255.901730] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880)
<7> [255.901858] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040)
<7> [255.901978] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928)
<7> [255.902099] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960)
<7> [255.902221] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800)
<7> [255.902342] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800)
<7> [255.902462] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803)
<7> [255.902583] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809)
<7> [255.902730] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1878)
<7> [255.902852] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1878)
<7> [255.902974] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [255.903095] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [255.903215] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [255.903335] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in enhanced_framing (expected no, found yes)
<7> [255.903456] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30)
<7> [255.903577] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 513820)
<7> [255.903722] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 513820)
<7> [255.903845] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:134:pipe B] fastset requirement not met in port_clock (expected 0, found 540000)
<7> [255.903964] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:134:pipe B] fastset requirement not met, forcing full modeset
<7> [255.904111] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes
<7> [255.904234] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:134:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2
<7> [255.904378] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] ddb ( 0 - 0) -> ( 0 - 4001), size 0 -> 4001
<7> [255.904497] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:129:cursor B] ddb ( 0 - 0) -> (4001 - 4096), size 0 -> 95
<7> [255.904625] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm
<7> [255.904761] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 2, 16, 16, 19, 19, 28, 0, 0, 0, 3, 0
<7> [255.904891] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 49, 385, 385, 457, 457, 673, 0, 0, 63, 73, 87
<7> [255.905014] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:84:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 55, 425, 425, 504, 504, 742, 0, 0, 64, 82, 88
<7> [255.905134] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:134:pipe B] data rate 2055280 num active planes 1
<7> [255.905263] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 2159 qgv_peak_bw: 51200
<7> [255.905389] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [255.905525] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [255.905649] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [255.905787] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 2159
<7> [255.905914] i915 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [i915]] [PLANE:84:plane 1B] min cdclk (256910 kHz) > [CRTC:134:pipe B] min cdclk (0 kHz)
<7> [255.906041] i915 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [i915]] new bandwidth min cdclk (40143 kHz) > old min cdclk (0 kHz)
<7> [255.906166] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing
<7> [255.906293] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 307200 kHz, actual 307200 kHz
<7> [255.906422] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [255.906565] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:134:pipe B] enable: yes [modeset]
<7> [255.906694] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB
<7> [255.906853] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: B, pipe bpp: 30, dithering: 0
<7> [255.906982] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [255.907105] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [255.907227] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [255.907350] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [255.907478] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m_n: lanes: 4; data_m: 7483046, data_n: 8388608, link_m: 498869, link_n: 524288, tu: 64
<7> [255.907601] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0
<7> [255.907724] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fec: disabled, enhanced framing: enabled
<7> [255.907925] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sdp split: disabled
<7> [255.908057] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled
<7> [255.908179] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] minimum HBlank: 0
<7> [255.908301] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x4
<7> [255.908423] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] DP SDP: VSC, revision 4, length 14
<7> [255.908544] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pixelformat: RGB
<7> [255.908667] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] colorimetry: sRGB
<7> [255.908822] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] bpc: 0
<7> [255.908943] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dynamic range: VESA range
<7> [255.909062] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] content type: Not defined
<7> [255.909183] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [255.909306] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0
<7> [255.909431] 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> [255.909556] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0
<7> [255.909677] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa
<7> [255.909815] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa
<7> [255.909940] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1878 vs=1803-1809 vt=1878, flags=0xa
<7> [255.910062] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x40 0xa
<7> [255.910184] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1878 vs=1803-1809 vt=1878, flags=0xa
<7> [255.910306] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 540000, pipe src: 2880x1800+0+0, pixel rate 513820
<7> [255.910429] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 48, ips linetime: 0
<7> [255.910555] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0
<7> [255.910676] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [255.910810] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [255.910937] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x83d60, dpll_md: 0xf42110, fp0: 0xf8, fp1: 0x1000000
<7> [255.911056] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [255.911177] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [255.911299] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000
<7> [255.911420] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [255.911541] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [255.911660] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [255.911783] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000
<7> [255.911920] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [255.912049] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [255.912169] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [255.912290] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [255.912410] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000
<7> [255.912531] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:84:plane 1B] fb: [FB:302] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x0, visible: yes
<7> [255.912652] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [255.912771] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0
<7> [255.912915] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:93:plane 2B] fb: [NOFB], visible: no
<7> [255.913042] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:102:plane 3B] fb: [NOFB], visible: no
<7> [255.913162] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:111:plane 4B] fb: [NOFB], visible: no
<7> [255.913285] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:120:plane 5B] fb: [NOFB], visible: no
<7> [255.913413] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:129:cursor B] fb: [NOFB], visible: no
<7> [255.915754] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_2
<7> [255.915959] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_B
<7> [255.916242] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 307200 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0
<7> [255.916411] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=768
<7> [255.916537] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A]
<7> [255.916659] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B]
<7> [255.916780] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A]
<7> [255.916925] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B]
<7> [255.917046] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C]
<7> [255.917163] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D]
<7> [255.917280] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1]
<7> [255.917397] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A]
<7> [255.917514] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B]
<7> [255.917628] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C]
<7> [255.917746] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D]
<7> [255.917864] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2]
<7> [255.917999] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3]
<7> [255.918123] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A]
<7> [255.918240] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B]
<7> [255.918356] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C]
<7> [255.918484] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D]
<7> [255.918612] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4]
<7> [255.918733] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A]
<7> [255.918855] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B]
<7> [255.918996] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C]
<7> [255.919117] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D]
<7> [255.919240] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0xf
<7> [255.919486] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: no -> yes (pipe: *)
<7> [255.919612] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 4 (mbus joined: yes)
<7> [255.919768] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling AUX_A
<7> [255.920960] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power on
<7> [255.921125] i915 0000:00:02.0: [drm:wait_panel_power_cycle [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power cycle (470 ms remaining)
<7> [256.402335] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060
<7> [256.461386] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [256.461899] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power on
<7> [256.462383] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063
<7> [256.493795] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [256.494259] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long
<7> [256.494690] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 20
<7> [256.495126] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [256.664154] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [256.666770] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD on
<7> [256.667382] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b
<7> [256.672324] i915 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 14 c4 41 00 00 01 c0 02 00 00 00 00 0b 80
<7> [256.673202] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Reloading eDP link rates
<7> [256.674249] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 07
<7> [256.675207] i915 0000:00:02.0: [drm:intel_dp_set_signal_levels [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0
<7> [256.675857] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using DP training pattern TPS1
<7> [256.676955] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Clock recovery OK
<7> [256.677062] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using DP training pattern TPS3
<7> [256.678601] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful
<7> [256.678708] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Link Training passed at link rate = 540000, lane count = 4
<7> [256.679273] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe B
<7> [256.679501] i915 0000:00:02.0: [drm:intel_edp_backlight_on [i915]]
<7> [256.679609] i915 0000:00:02.0: [drm:intel_backlight_enable [i915]] pipe B
<7> [256.679770] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 13892
<7> [256.690731] i915 0000:00:02.0: [drm:intel_psr_post_plane_update [i915]] Enabling PSR2
<7> [256.692469] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1]
<7> [256.693090] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:134:pipe B]
<7> [259.248792] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD off
<7> [259.249311] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067
<7> [260.186577] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off
<7> [260.187145] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6
<7> [260.187655] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02
<6> [263.564959] [IGT] kms_flip: finished subtest B-eDP1, FAIL
Created at 2025-03-21 22:58:27