igt@kms_flip@flip-vs-expired-vblank@a-hdmi-a1 on shard-snb@Patchwork

Detail	Value
Duration	7.06 seconds
Hostname	shard-snb6
Igt-Version	IGT-Version: 2.4-g0e365bfe5 (x86_64) (Linux: 7.1.0-rc5-Patchwork_167481v1-g3561a5c5f9c0+ x86_64)
Out	Starting dynamic subtest: A-HDMI-A1 1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 Stack trace: #0 ../lib/igt_core.c:2106 __igt_fail_assert() #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() #2 ../tests/kms_flip.c:1920 run_test() #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() #4 ../tests/kms_flip.c:2105 main() #5 [__libc_init_first+0x8a] #6 [__libc_start_main+0x8b] #7 [_start+0x25] Dynamic subtest A-HDMI-A1: FAIL (7.059s)
Err	Starting dynamic subtest: A-HDMI-A1 [154.078658] (kms_flip:7140) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [154.078718] (kms_flip:7140) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest A-HDMI-A1 failed. ** DEBUG [152.065538] (kms_flip:7140) DEBUG: name = flip last_ts = 152.461548 last_received_ts = 152.460968 last_seq = 3361 current_ts = 152.478165 current_received_ts = 152.477585 current_seq = 3362 count = 266 seq_step = 1 [152.065555] (kms_flip:7140) DEBUG: Vblank took 7us [152.082143] (kms_flip:7140) DEBUG: name = flip last_ts = 152.478165 last_received_ts = 152.477585 last_seq = 3362 current_ts = 152.494797 current_received_ts = 152.494186 current_seq = 3363 count = 267 seq_step = 1 [152.082158] (kms_flip:7140) DEBUG: Vblank took 7us [152.098775] (kms_flip:7140) DEBUG: name = flip last_ts = 152.494797 last_received_ts = 152.494186 last_seq = 3363 current_ts = 152.511429 current_received_ts = 152.510818 current_seq = 3364 count = 268 seq_step = 1 [152.098794] (kms_flip:7140) DEBUG: Vblank took 9us [152.115426] (kms_flip:7140) DEBUG: name = flip last_ts = 152.511429 last_received_ts = 152.510818 last_seq = 3364 current_ts = 152.528076 current_received_ts = 152.527466 current_seq = 3365 count = 269 seq_step = 1 [152.115442] (kms_flip:7140) DEBUG: Vblank took 8us [152.132079] (kms_flip:7140) DEBUG: name = flip last_ts = 152.528076 last_received_ts = 152.527466 last_seq = 3365 current_ts = 152.544693 current_received_ts = 152.544128 current_seq = 3366 count = 270 seq_step = 1 [152.132093] (kms_flip:7140) DEBUG: Vblank took 6us [152.148701] (kms_flip:7140) DEBUG: name = flip last_ts = 152.544693 last_received_ts = 152.544128 last_seq = 3366 current_ts = 152.561325 current_received_ts = 152.560745 current_seq = 3367 count = 271 seq_step = 1 [152.148712] (kms_flip:7140) DEBUG: Vblank took 6us [152.165314] (kms_flip:7140) DEBUG: name = flip last_ts = 152.561325 last_received_ts = 152.560745 last_seq = 3367 current_ts = 152.577957 current_received_ts = 152.577347 current_seq = 3368 count = 272 seq_step = 1 [152.165332] (kms_flip:7140) DEBUG: Vblank took 9us [152.182017] (kms_flip:7140) DEBUG: name = flip last_ts = 152.577957 last_received_ts = 152.577347 last_seq = 3368 current_ts = 152.594604 current_received_ts = 152.594040 current_seq = 3369 count = 273 seq_step = 1 [152.182034] (kms_flip:7140) DEBUG: Vblank took 8us [152.198609] (kms_flip:7140) DEBUG: name = flip last_ts = 152.594604 last_received_ts = 152.594040 last_seq = 3369 current_ts = 152.611221 current_received_ts = 152.610641 current_seq = 3370 count = 274 seq_step = 1 [152.198624] (kms_flip:7140) DEBUG: Vblank took 7us [152.215244] (kms_flip:7140) DEBUG: name = flip last_ts = 152.611221 last_received_ts = 152.610641 last_seq = 3370 current_ts = 152.627853 current_received_ts = 152.627274 current_seq = 3371 count = 275 seq_step = 1 [152.215259] (kms_flip:7140) DEBUG: Vblank took 7us [152.231892] (kms_flip:7140) DEBUG: name = flip last_ts = 152.627853 last_received_ts = 152.627274 last_seq = 3371 current_ts = 152.644485 current_received_ts = 152.643921 current_seq = 3372 count = 276 seq_step = 1 [152.231905] (kms_flip:7140) DEBUG: Vblank took 6us [152.248508] (kms_flip:7140) DEBUG: name = flip last_ts = 152.644485 last_received_ts = 152.643921 last_seq = 3372 current_ts = 152.661118 current_received_ts = 152.660538 current_seq = 3373 count = 277 seq_step = 1 [152.248527] (kms_flip:7140) DEBUG: Vblank took 8us [152.265124] (kms_flip:7140) DEBUG: name = flip last_ts = 152.661118 last_received_ts = 152.660538 last_seq = 3373 current_ts = 152.677750 current_received_ts = 152.677155 current_seq = 3374 count = 278 seq_step = 1 [152.265144] (kms_flip:7140) DEBUG: Vblank took 8us [152.281747] (kms_flip:7140) DEBUG: name = flip last_ts = 152.677750 last_received_ts = 152.677155 last_seq = 3374 current_ts = 152.694382 current_received_ts = 152.693771 current_seq = 3375 count = 279 seq_step = 1 [152.281765] (kms_flip:7140) DEBUG: Vblank took 9us [152.298376] (kms_flip:7140) DEBUG: name = flip last_ts = 152.694382 last_received_ts = 152.693771 last_seq = 3375 current_ts = 152.711014 current_received_ts = 152.710403 current_seq = 3376 count = 280 seq_step = 1 [152.298392] (kms_flip:7140) DEBUG: Vblank took 8us [152.315016] (kms_flip:7140) DEBUG: name = flip last_ts = 152.711014 last_received_ts = 152.710403 last_seq = 3376 current_ts = 152.727631 current_received_ts = 152.727036 current_seq = 3377 count = 281 seq_step = 1 [152.315032] (kms_flip:7140) DEBUG: Vblank took 8us [152.331632] (kms_flip:7140) DEBUG: name = flip last_ts = 152.727631 last_received_ts = 152.727036 last_seq = 3377 current_ts = 152.744278 current_received_ts = 152.743652 current_seq = 3378 count = 282 seq_step = 1 [152.331646] (kms_flip:7140) DEBUG: Vblank took 7us [152.348293] (kms_flip:7140) DEBUG: name = flip last_ts = 152.744278 last_received_ts = 152.743652 last_seq = 3378 current_ts = 152.760910 current_received_ts = 152.760315 current_seq = 3379 count = 283 seq_step = 1 [152.348309] (kms_flip:7140) DEBUG: Vblank took 8us [152.364946] (kms_flip:7140) DEBUG: name = flip last_ts = 152.760910 last_received_ts = 152.760315 last_seq = 3379 current_ts = 152.777542 current_received_ts = 152.776962 current_seq = 3380 count = 284 seq_step = 1 [152.364965] (kms_flip:7140) DEBUG: Vblank took 8us [152.381549] (kms_flip:7140) DEBUG: name = flip last_ts = 152.777542 last_received_ts = 152.776962 last_seq = 3380 current_ts = 152.794174 current_received_ts = 152.793564 current_seq = 3381 count = 285 seq_step = 1 [152.381568] (kms_flip:7140) DEBUG: Vblank took 8us [152.398210] (kms_flip:7140) DEBUG: name = flip last_ts = 152.794174 last_received_ts = 152.793564 last_seq = 3381 current_ts = 152.810806 current_received_ts = 152.810226 current_seq = 3382 count = 286 seq_step = 1 [152.398229] (kms_flip:7140) DEBUG: Vblank took 9us [152.414839] (kms_flip:7140) DEBUG: name = flip last_ts = 152.810806 last_received_ts = 152.810226 last_seq = 3382 current_ts = 152.827438 current_received_ts = 152.826859 current_seq = 3383 count = 287 seq_step = 1 [152.414857] (kms_flip:7140) DEBUG: Vblank took 7us [152.431468] (kms_flip:7140) DEBUG: name = flip last_ts = 152.827438 last_received_ts = 152.826859 last_seq = 3383 current_ts = 152.844070 current_received_ts = 152.843475 current_seq = 3384 count = 288 seq_step = 1 [152.431485] (kms_flip:7140) DEBUG: Vblank took 8us [152.448067] (kms_flip:7140) DEBUG: name = flip last_ts = 152.844070 last_received_ts = 152.843475 last_seq = 3384 current_ts = 152.860703 current_received_ts = 152.860077 current_seq = 3385 count = 289 seq_step = 1 [152.448085] (kms_flip:7140) DEBUG: Vblank took 9us [152.464717] (kms_flip:7140) DEBUG: name = flip last_ts = 152.860703 last_received_ts = 152.860077 last_seq = 3385 current_ts = 152.877335 current_received_ts = 152.876724 current_seq = 3386 count = 290 seq_step = 1 [152.464734] (kms_flip:7140) DEBUG: Vblank took 7us [152.481350] (kms_flip:7140) DEBUG: name = flip last_ts = 152.877335 last_received_ts = 152.876724 last_seq = 3386 current_ts = 152.893967 current_received_ts = 152.893356 current_seq = 3387 count = 291 seq_step = 1 [152.481367] (kms_flip:7140) DEBUG: Vblank took 7us [152.497990] (kms_flip:7140) DEBUG: name = flip last_ts = 152.893967 last_received_ts = 152.893356 last_seq = 3387 current_ts = 152.910583 current_received_ts = 152.909988 current_seq = 3388 count = 292 seq_step = 1 [152.498008] (kms_flip:7140) DEBUG: Vblank took 7us [152.514640] (kms_flip:7140) DEBUG: name = flip last_ts = 152.910583 last_received_ts = 152.909988 last_seq = 3388 current_ts = 152.927216 current_received_ts = 152.926651 current_seq = 3389 count = 293 seq_step = 1 [152.514658] (kms_flip:7140) DEBUG: Vblank took 8us [152.531268] (kms_flip:7140) DEBUG: name = flip last_ts = 152.927216 last_received_ts = 152.926651 last_seq = 3389 current_ts = 152.943848 current_received_ts = 152.943268 current_seq = 3390 count = 294 seq_step = 1 [152.531286] (kms_flip:7140) DEBUG: Vblank took 7us [152.547875] (kms_flip:7140) DEBUG: name = flip last_ts = 152.943848 last_received_ts = 152.943268 last_seq = 3390 current_ts = 152.960480 current_received_ts = 152.959885 current_seq = 3391 count = 295 seq_step = 1 [152.547892] (kms_flip:7140) DEBUG: Vblank took 8us [152.564543] (kms_flip:7140) DEBUG: name = flip last_ts = 152.960480 last_received_ts = 152.959885 last_seq = 3391 current_ts = 152.977127 current_received_ts = 152.976547 current_seq = 3392 count = 296 seq_step = 1 [152.564562] (kms_flip:7140) DEBUG: Vblank took 9us [152.581149] (kms_flip:7140) DEBUG: name = flip last_ts = 152.977127 last_received_ts = 152.976547 last_seq = 3392 current_ts = 152.993744 current_received_ts = 152.993149 current_seq = 3393 count = 297 seq_step = 1 [152.581168] (kms_flip:7140) DEBUG: Vblank took 9us [152.597804] (kms_flip:7140) DEBUG: name = flip last_ts = 152.993744 last_received_ts = 152.993149 last_seq = 3393 current_ts = 153.010376 current_received_ts = 153.009811 current_seq = 3394 count = 298 seq_step = 1 [152.597820] (kms_flip:7140) DEBUG: Vblank took 7us [152.614435] (kms_flip:7140) DEBUG: name = flip last_ts = 153.010376 last_received_ts = 153.009811 last_seq = 3394 current_ts = 153.027008 current_received_ts = 153.026428 current_seq = 3395 count = 299 seq_step = 1 [152.614452] (kms_flip:7140) DEBUG: Vblank took 8us [152.631047] (kms_flip:7140) DEBUG: name = flip last_ts = 153.027008 last_received_ts = 153.026428 last_seq = 3395 current_ts = 153.043640 current_received_ts = 153.043045 current_seq = 3396 count = 300 seq_step = 1 [152.631064] (kms_flip:7140) DEBUG: Vblank took 7us [152.647698] (kms_flip:7140) DEBUG: name = flip last_ts = 153.043640 last_received_ts = 153.043045 last_seq = 3396 current_ts = 153.060272 current_received_ts = 153.059692 current_seq = 3397 count = 301 seq_step = 1 [152.647716] (kms_flip:7140) DEBUG: Vblank took 8us [152.664310] (kms_flip:7140) DEBUG: name = flip last_ts = 153.060272 last_received_ts = 153.059692 last_seq = 3397 current_ts = 153.076904 current_received_ts = 153.076309 current_seq = 3398 count = 302 seq_step = 1 [152.664327] (kms_flip:7140) DEBUG: Vblank took 8us [152.680931] (kms_flip:7140) DEBUG: name = flip last_ts = 153.076904 last_received_ts = 153.076309 last_seq = 3398 current_ts = 153.093536 current_received_ts = 153.092926 current_seq = 3399 count = 303 seq_step = 1 [152.680948] (kms_flip:7140) DEBUG: Vblank took 8us [152.697576] (kms_flip:7140) DEBUG: name = flip last_ts = 153.093536 last_received_ts = 153.092926 last_seq = 3399 current_ts = 153.110168 current_received_ts = 153.109573 current_seq = 3400 count = 304 seq_step = 1 [152.697593] (kms_flip:7140) DEBUG: Vblank took 7us [152.714214] (kms_flip:7140) DEBUG: name = flip last_ts = 153.110168 last_received_ts = 153.109573 last_seq = 3400 current_ts = 153.126801 current_received_ts = 153.126205 current_seq = 3401 count = 305 seq_step = 1 [152.714232] (kms_flip:7140) DEBUG: Vblank took 8us [152.730897] (kms_flip:7140) DEBUG: name = flip last_ts = 153.126801 last_received_ts = 153.126205 last_seq = 3401 current_ts = 153.143433 current_received_ts = 153.142883 current_seq = 3402 count = 306 seq_step = 1 [152.730914] (kms_flip:7140) DEBUG: Vblank took 8us [152.747502] (kms_flip:7140) DEBUG: name = flip last_ts = 153.143433 last_received_ts = 153.142883 last_seq = 3402 current_ts = 153.160065 current_received_ts = 153.159485 current_seq = 3403 count = 307 seq_step = 1 [152.747520] (kms_flip:7140) DEBUG: Vblank took 8us [152.764100] (kms_flip:7140) DEBUG: name = flip last_ts = 153.160065 last_received_ts = 153.159485 last_seq = 3403 current_ts = 153.176697 current_received_ts = 153.176086 current_seq = 3404 count = 308 seq_step = 1 [152.764118] (kms_flip:7140) DEBUG: Vblank took 9us [152.780728] (kms_flip:7140) DEBUG: name = flip last_ts = 153.176697 last_received_ts = 153.176086 last_seq = 3404 current_ts = 153.193329 current_received_ts = 153.192703 current_seq = 3405 count = 309 seq_step = 1 [152.780746] (kms_flip:7140) DEBUG: Vblank took 9us [152.797361] (kms_flip:7140) DEBUG: name = flip last_ts = 153.193329 last_received_ts = 153.192703 last_seq = 3405 current_ts = 153.209961 current_received_ts = 153.209351 current_seq = 3406 count = 310 seq_step = 1 [152.797379] (kms_flip:7140) DEBUG: Vblank took 8us [152.814028] (kms_flip:7140) DEBUG: name = flip last_ts = 153.209961 last_received_ts = 153.209351 last_seq = 3406 current_ts = 153.226593 current_received_ts = 153.225998 current_seq = 3407 count = 311 seq_step = 1 [152.814045] (kms_flip:7140) DEBUG: Vblank took 7us [152.830650] (kms_flip:7140) DEBUG: name = flip last_ts = 153.226593 last_received_ts = 153.225998 last_seq = 3407 current_ts = 153.243225 current_received_ts = 153.242630 current_seq = 3408 count = 312 seq_step = 1 [152.830669] (kms_flip:7140) DEBUG: Vblank took 9us [152.847267] (kms_flip:7140) DEBUG: name = flip last_ts = 153.243225 last_received_ts = 153.242630 last_seq = 3408 current_ts = 153.259857 current_received_ts = 153.259247 current_seq = 3409 count = 313 seq_step = 1 [152.847285] (kms_flip:7140) DEBUG: Vblank took 9us [152.863926] (kms_flip:7140) DEBUG: name = flip last_ts = 153.259857 last_received_ts = 153.259247 last_seq = 3409 current_ts = 153.276489 current_received_ts = 153.275894 current_seq = 3410 count = 314 seq_step = 1 [152.863946] (kms_flip:7140) DEBUG: Vblank took 10us [152.880538] (kms_flip:7140) DEBUG: name = flip last_ts = 153.276489 last_received_ts = 153.275894 last_seq = 3410 current_ts = 153.293121 current_received_ts = 153.292511 current_seq = 3411 count = 315 seq_step = 1 [152.880558] (kms_flip:7140) DEBUG: Vblank took 9us [152.897177] (kms_flip:7140) DEBUG: name = flip last_ts = 153.293121 last_received_ts = 153.292511 last_seq = 3411 current_ts = 153.309753 current_received_ts = 153.309143 current_seq = 3412 count = 316 seq_step = 1 [152.897196] (kms_flip:7140) DEBUG: Vblank took 9us [152.913806] (kms_flip:7140) DEBUG: name = flip last_ts = 153.309753 last_received_ts = 153.309143 last_seq = 3412 current_ts = 153.326385 current_received_ts = 153.325775 current_seq = 3413 count = 317 seq_step = 1 [152.913825] (kms_flip:7140) DEBUG: Vblank took 10us [152.930430] (kms_flip:7140) DEBUG: name = flip last_ts = 153.326385 last_received_ts = 153.325775 last_seq = 3413 current_ts = 153.343018 current_received_ts = 153.342407 current_seq = 3414 count = 318 seq_step = 1 [152.930448] (kms_flip:7140) DEBUG: Vblank took 9us [152.947201] (kms_flip:7140) DEBUG: name = flip last_ts = 153.343018 last_received_ts = 153.342407 last_seq = 3414 current_ts = 153.359650 current_received_ts = 153.359177 current_seq = 3415 count = 319 seq_step = 1 [152.947218] (kms_flip:7140) DEBUG: Vblank took 9us [152.963738] (kms_flip:7140) DEBUG: name = flip last_ts = 153.359650 last_received_ts = 153.359177 last_seq = 3415 current_ts = 153.376282 current_received_ts = 153.375702 current_seq = 3416 count = 320 seq_step = 1 [152.963756] (kms_flip:7140) DEBUG: Vblank took 8us [152.980354] (kms_flip:7140) DEBUG: name = flip last_ts = 153.376282 last_received_ts = 153.375702 last_seq = 3416 current_ts = 153.392899 current_received_ts = 153.392319 current_seq = 3417 count = 321 seq_step = 1 [152.980374] (kms_flip:7140) DEBUG: Vblank took 9us [152.996990] (kms_flip:7140) DEBUG: name = flip last_ts = 153.392899 last_received_ts = 153.392319 last_seq = 3417 current_ts = 153.409531 current_received_ts = 153.408951 current_seq = 3418 count = 322 seq_step = 1 [152.997008] (kms_flip:7140) DEBUG: Vblank took 8us [153.013627] (kms_flip:7140) DEBUG: name = flip last_ts = 153.409531 last_received_ts = 153.408951 last_seq = 3418 current_ts = 153.426178 current_received_ts = 153.425598 current_seq = 3419 count = 323 seq_step = 1 [153.013644] (kms_flip:7140) DEBUG: Vblank took 8us [153.030238] (kms_flip:7140) DEBUG: name = flip last_ts = 153.426178 last_received_ts = 153.425598 last_seq = 3419 current_ts = 153.442810 current_received_ts = 153.442200 current_seq = 3420 count = 324 seq_step = 1 [153.030256] (kms_flip:7140) DEBUG: Vblank took 8us [153.046889] (kms_flip:7140) DEBUG: name = flip last_ts = 153.442810 last_received_ts = 153.442200 last_seq = 3420 current_ts = 153.459442 current_received_ts = 153.458847 current_seq = 3421 count = 325 seq_step = 1 [153.046905] (kms_flip:7140) DEBUG: Vblank took 8us [153.063526] (kms_flip:7140) DEBUG: name = flip last_ts = 153.459442 last_received_ts = 153.458847 last_seq = 3421 current_ts = 153.476074 current_received_ts = 153.475494 current_seq = 3422 count = 326 seq_step = 1 [153.063542] (kms_flip:7140) DEBUG: Vblank took 7us [153.080166] (kms_flip:7140) DEBUG: name = flip last_ts = 153.476074 last_received_ts = 153.475494 last_seq = 3422 current_ts = 153.492691 current_received_ts = 153.492126 current_seq = 3423 count = 327 seq_step = 1 [153.080184] (kms_flip:7140) DEBUG: Vblank took 8us [153.096770] (kms_flip:7140) DEBUG: name = flip last_ts = 153.492691 last_received_ts = 153.492126 last_seq = 3423 current_ts = 153.509323 current_received_ts = 153.508728 current_seq = 3424 count = 328 seq_step = 1 [153.096787] (kms_flip:7140) DEBUG: Vblank took 7us [153.113425] (kms_flip:7140) DEBUG: name = flip last_ts = 153.509323 last_received_ts = 153.508728 last_seq = 3424 current_ts = 153.525955 current_received_ts = 153.525375 current_seq = 3425 count = 329 seq_step = 1 [153.113441] (kms_flip:7140) DEBUG: Vblank took 7us [153.130073] (kms_flip:7140) DEBUG: name = flip last_ts = 153.525955 last_received_ts = 153.525375 last_seq = 3425 current_ts = 153.542587 current_received_ts = 153.542023 current_seq = 3426 count = 330 seq_step = 1 [153.130088] (kms_flip:7140) DEBUG: Vblank took 7us [153.146689] (kms_flip:7140) DEBUG: name = flip last_ts = 153.542587 last_received_ts = 153.542023 last_seq = 3426 current_ts = 153.559219 current_received_ts = 153.558640 current_seq = 3427 count = 331 seq_step = 1 [153.146705] (kms_flip:7140) DEBUG: Vblank took 8us [153.163282] (kms_flip:7140) DEBUG: name = flip last_ts = 153.559219 last_received_ts = 153.558640 last_seq = 3427 current_ts = 153.575851 current_received_ts = 153.575241 current_seq = 3428 count = 332 seq_step = 1 [153.163299] (kms_flip:7140) DEBUG: Vblank took 8us [153.179991] (kms_flip:7140) DEBUG: name = flip last_ts = 153.575851 last_received_ts = 153.575241 last_seq = 3428 current_ts = 153.592484 current_received_ts = 153.591934 current_seq = 3429 count = 333 seq_step = 1 [153.180009] (kms_flip:7140) DEBUG: Vblank took 8us [153.196565] (kms_flip:7140) DEBUG: name = flip last_ts = 153.592484 last_received_ts = 153.591934 last_seq = 3429 current_ts = 153.609116 current_received_ts = 153.608521 current_seq = 3430 count = 334 seq_step = 1 [153.196580] (kms_flip:7140) DEBUG: Vblank took 7us [153.213199] (kms_flip:7140) DEBUG: name = flip last_ts = 153.609116 last_received_ts = 153.608521 last_seq = 3430 current_ts = 153.625748 current_received_ts = 153.625153 current_seq = 3431 count = 335 seq_step = 1 [153.213213] (kms_flip:7140) DEBUG: Vblank took 7us [153.229831] (kms_flip:7140) DEBUG: name = flip last_ts = 153.625748 last_received_ts = 153.625153 last_seq = 3431 current_ts = 153.642380 current_received_ts = 153.641785 current_seq = 3432 count = 336 seq_step = 1 [153.229846] (kms_flip:7140) DEBUG: Vblank took 7us [153.246465] (kms_flip:7140) DEBUG: name = flip last_ts = 153.642380 last_received_ts = 153.641785 last_seq = 3432 current_ts = 153.659012 current_received_ts = 153.658417 current_seq = 3433 count = 337 seq_step = 1 [153.246479] (kms_flip:7140) DEBUG: Vblank took 6us [153.263122] (kms_flip:7140) DEBUG: name = flip last_ts = 153.659012 last_received_ts = 153.658417 last_seq = 3433 current_ts = 153.675644 current_received_ts = 153.675064 current_seq = 3434 count = 338 seq_step = 1 [153.263136] (kms_flip:7140) DEBUG: Vblank took 6us [153.279755] (kms_flip:7140) DEBUG: name = flip last_ts = 153.675644 last_received_ts = 153.675064 last_seq = 3434 current_ts = 153.692276 current_received_ts = 153.691696 current_seq = 3435 count = 339 seq_step = 1 [153.279770] (kms_flip:7140) DEBUG: Vblank took 7us [153.296373] (kms_flip:7140) DEBUG: name = flip last_ts = 153.692276 last_received_ts = 153.691696 last_seq = 3435 current_ts = 153.708908 current_received_ts = 153.708313 current_seq = 3436 count = 340 seq_step = 1 [153.296389] (kms_flip:7140) DEBUG: Vblank took 8us [153.312987] (kms_flip:7140) DEBUG: name = flip last_ts = 153.708908 last_received_ts = 153.708313 last_seq = 3436 current_ts = 153.725540 current_received_ts = 153.724930 current_seq = 3437 count = 341 seq_step = 1 [153.313005] (kms_flip:7140) DEBUG: Vblank took 9us [153.329632] (kms_flip:7140) DEBUG: name = flip last_ts = 153.725540 last_received_ts = 153.724930 last_seq = 3437 current_ts = 153.742172 current_received_ts = 153.741577 current_seq = 3438 count = 342 seq_step = 1 [153.329650] (kms_flip:7140) DEBUG: Vblank took 9us [153.346273] (kms_flip:7140) DEBUG: name = flip last_ts = 153.742172 last_received_ts = 153.741577 last_seq = 3438 current_ts = 153.758804 current_received_ts = 153.758209 current_seq = 3439 count = 343 seq_step = 1 [153.346290] (kms_flip:7140) DEBUG: Vblank took 8us [153.362880] (kms_flip:7140) DEBUG: name = flip last_ts = 153.758804 last_received_ts = 153.758209 last_seq = 3439 current_ts = 153.775436 current_received_ts = 153.774811 current_seq = 3440 count = 344 seq_step = 1 [153.362898] (kms_flip:7140) DEBUG: Vblank took 9us [153.379641] (kms_flip:7140) DEBUG: name = flip last_ts = 153.775436 last_received_ts = 153.774811 last_seq = 3440 current_ts = 153.792068 current_received_ts = 153.791580 current_seq = 3441 count = 345 seq_step = 1 [153.379659] (kms_flip:7140) DEBUG: Vblank took 9us [153.396207] (kms_flip:7140) DEBUG: name = flip last_ts = 153.792068 last_received_ts = 153.791580 last_seq = 3441 current_ts = 153.808701 current_received_ts = 153.808136 current_seq = 3442 count = 346 seq_step = 1 [153.396225] (kms_flip:7140) DEBUG: Vblank took 8us [153.412782] (kms_flip:7140) DEBUG: name = flip last_ts = 153.808701 last_received_ts = 153.808136 last_seq = 3442 current_ts = 153.825333 current_received_ts = 153.824707 current_seq = 3443 count = 347 seq_step = 1 [153.412801] (kms_flip:7140) DEBUG: Vblank took 9us [153.429432] (kms_flip:7140) DEBUG: name = flip last_ts = 153.825333 last_received_ts = 153.824707 last_seq = 3443 current_ts = 153.841965 current_received_ts = 153.841354 current_seq = 3444 count = 348 seq_step = 1 [153.429450] (kms_flip:7140) DEBUG: Vblank took 9us [153.446044] (kms_flip:7140) DEBUG: name = flip last_ts = 153.841965 last_received_ts = 153.841354 last_seq = 3444 current_ts = 153.858597 current_received_ts = 153.857971 current_seq = 3445 count = 349 seq_step = 1 [153.446072] (kms_flip:7140) DEBUG: Vblank took 18us [153.462700] (kms_flip:7140) DEBUG: name = flip last_ts = 153.858597 last_received_ts = 153.857971 last_seq = 3445 current_ts = 153.875229 current_received_ts = 153.874634 current_seq = 3446 count = 350 seq_step = 1 [153.462718] (kms_flip:7140) DEBUG: Vblank took 8us [153.479341] (kms_flip:7140) DEBUG: name = flip last_ts = 153.875229 last_received_ts = 153.874634 last_seq = 3446 current_ts = 153.891861 current_received_ts = 153.891266 current_seq = 3447 count = 351 seq_step = 1 [153.479360] (kms_flip:7140) DEBUG: Vblank took 9us [153.495954] (kms_flip:7140) DEBUG: name = flip last_ts = 153.891861 last_received_ts = 153.891266 last_seq = 3447 current_ts = 153.908493 current_received_ts = 153.907883 current_seq = 3448 count = 352 seq_step = 1 [153.495971] (kms_flip:7140) DEBUG: Vblank took 8us [153.512590] (kms_flip:7140) DEBUG: name = flip last_ts = 153.908493 last_received_ts = 153.907883 last_seq = 3448 current_ts = 153.925125 current_received_ts = 153.924515 current_seq = 3449 count = 353 seq_step = 1 [153.512609] (kms_flip:7140) DEBUG: Vblank took 10us [153.529215] (kms_flip:7140) DEBUG: name = flip last_ts = 153.925125 last_received_ts = 153.924515 last_seq = 3449 current_ts = 153.941757 current_received_ts = 153.941132 current_seq = 3450 count = 354 seq_step = 1 [153.529232] (kms_flip:7140) DEBUG: Vblank took 9us [153.545868] (kms_flip:7140) DEBUG: name = flip last_ts = 153.941757 last_received_ts = 153.941132 last_seq = 3450 current_ts = 153.958374 current_received_ts = 153.957794 current_seq = 3451 count = 355 seq_step = 1 [153.545886] (kms_flip:7140) DEBUG: Vblank took 8us [153.562495] (kms_flip:7140) DEBUG: name = flip last_ts = 153.958374 last_received_ts = 153.957794 last_seq = 3451 current_ts = 153.975021 current_received_ts = 153.974411 current_seq = 3452 count = 356 seq_step = 1 [153.562513] (kms_flip:7140) DEBUG: Vblank took 8us [153.579123] (kms_flip:7140) DEBUG: name = flip last_ts = 153.975021 last_received_ts = 153.974411 last_seq = 3452 current_ts = 153.991653 current_received_ts = 153.991043 current_seq = 3453 count = 357 seq_step = 1 [153.579141] (kms_flip:7140) DEBUG: Vblank took 8us [153.595766] (kms_flip:7140) DEBUG: name = flip last_ts = 153.991653 last_received_ts = 153.991043 last_seq = 3453 current_ts = 154.008270 current_received_ts = 154.007690 current_seq = 3454 count = 358 seq_step = 1 [153.595784] (kms_flip:7140) DEBUG: Vblank took 9us [153.612394] (kms_flip:7140) DEBUG: name = flip last_ts = 154.008270 last_received_ts = 154.007690 last_seq = 3454 current_ts = 154.024902 current_received_ts = 154.024307 current_seq = 3455 count = 359 seq_step = 1 [153.612410] (kms_flip:7140) DEBUG: Vblank took 8us [153.629018] (kms_flip:7140) DEBUG: name = flip last_ts = 154.024902 last_received_ts = 154.024307 last_seq = 3455 current_ts = 154.041550 current_received_ts = 154.040939 current_seq = 3456 count = 360 seq_step = 1 [153.629035] (kms_flip:7140) DEBUG: Vblank took 8us [153.645661] (kms_flip:7140) DEBUG: name = flip last_ts = 154.041550 last_received_ts = 154.040939 last_seq = 3456 current_ts = 154.058167 current_received_ts = 154.057571 current_seq = 3457 count = 361 seq_step = 1 [153.645680] (kms_flip:7140) DEBUG: Vblank took 9us [153.662287] (kms_flip:7140) DEBUG: name = flip last_ts = 154.058167 last_received_ts = 154.057571 last_seq = 3457 current_ts = 154.074799 current_received_ts = 154.074203 current_seq = 3458 count = 362 seq_step = 1 [153.662303] (kms_flip:7140) DEBUG: Vblank took 7us [153.678933] (kms_flip:7140) DEBUG: name = flip last_ts = 154.074799 last_received_ts = 154.074203 last_seq = 3458 current_ts = 154.091431 current_received_ts = 154.090836 current_seq = 3459 count = 363 seq_step = 1 [153.678949] (kms_flip:7140) DEBUG: Vblank took 8us [153.695565] (kms_flip:7140) DEBUG: name = flip last_ts = 154.091431 last_received_ts = 154.090836 last_seq = 3459 current_ts = 154.108063 current_received_ts = 154.107468 current_seq = 3460 count = 364 seq_step = 1 [153.695582] (kms_flip:7140) DEBUG: Vblank took 8us [153.712167] (kms_flip:7140) DEBUG: name = flip last_ts = 154.108063 last_received_ts = 154.107468 last_seq = 3460 current_ts = 154.124695 current_received_ts = 154.124069 current_seq = 3461 count = 365 seq_step = 1 [153.712183] (kms_flip:7140) DEBUG: Vblank took 8us [153.728887] (kms_flip:7140) DEBUG: name = flip last_ts = 154.124695 last_received_ts = 154.124069 last_seq = 3461 current_ts = 154.141327 current_received_ts = 154.140793 current_seq = 3462 count = 366 seq_step = 1 [153.728903] (kms_flip:7140) DEBUG: Vblank took 8us [153.745440] (kms_flip:7140) DEBUG: name = flip last_ts = 154.141327 last_received_ts = 154.140793 last_seq = 3462 current_ts = 154.157959 current_received_ts = 154.157349 current_seq = 3463 count = 367 seq_step = 1 [153.745456] (kms_flip:7140) DEBUG: Vblank took 8us [153.762074] (kms_flip:7140) DEBUG: name = flip last_ts = 154.157959 last_received_ts = 154.157349 last_seq = 3463 current_ts = 154.174591 current_received_ts = 154.173981 current_seq = 3464 count = 368 seq_step = 1 [153.762101] (kms_flip:7140) DEBUG: Vblank took 20us [153.778729] (kms_flip:7140) DEBUG: name = flip last_ts = 154.174591 last_received_ts = 154.173981 last_seq = 3464 current_ts = 154.191223 current_received_ts = 154.190628 current_seq = 3465 count = 369 seq_step = 1 [153.778745] (kms_flip:7140) DEBUG: Vblank took 8us [153.795348] (kms_flip:7140) DEBUG: name = flip last_ts = 154.191223 last_received_ts = 154.190628 last_seq = 3465 current_ts = 154.207855 current_received_ts = 154.207245 current_seq = 3466 count = 370 seq_step = 1 [153.795366] (kms_flip:7140) DEBUG: Vblank took 9us [153.811980] (kms_flip:7140) DEBUG: name = flip last_ts = 154.207855 last_received_ts = 154.207245 last_seq = 3466 current_ts = 154.224487 current_received_ts = 154.223877 current_seq = 3467 count = 371 seq_step = 1 [153.811998] (kms_flip:7140) DEBUG: Vblank took 9us [153.828630] (kms_flip:7140) DEBUG: name = flip last_ts = 154.224487 last_received_ts = 154.223877 last_seq = 3467 current_ts = 154.241119 current_received_ts = 154.240524 current_seq = 3468 count = 372 seq_step = 1 [153.828647] (kms_flip:7140) DEBUG: Vblank took 8us [153.845297] (kms_flip:7140) DEBUG: name = flip last_ts = 154.241119 last_received_ts = 154.240524 last_seq = 3468 current_ts = 154.257751 current_received_ts = 154.257187 current_seq = 3469 count = 373 seq_step = 1 [153.845314] (kms_flip:7140) DEBUG: Vblank took 8us [153.861871] (kms_flip:7140) DEBUG: name = flip last_ts = 154.257751 last_received_ts = 154.257187 last_seq = 3469 current_ts = 154.274384 current_received_ts = 154.273773 current_seq = 3470 count = 374 seq_step = 1 [153.861888] (kms_flip:7140) DEBUG: Vblank took 9us [153.878501] (kms_flip:7140) DEBUG: name = flip last_ts = 154.274384 last_received_ts = 154.273773 last_seq = 3470 current_ts = 154.291016 current_received_ts = 154.290390 current_seq = 3471 count = 375 seq_step = 1 [153.878518] (kms_flip:7140) DEBUG: Vblank took 7us [153.895141] (kms_flip:7140) DEBUG: name = flip last_ts = 154.291016 last_received_ts = 154.290390 last_seq = 3471 current_ts = 154.307648 current_received_ts = 154.307037 current_seq = 3472 count = 376 seq_step = 1 [153.895157] (kms_flip:7140) DEBUG: Vblank took 8us [153.911762] (kms_flip:7140) DEBUG: name = flip last_ts = 154.307648 last_received_ts = 154.307037 last_seq = 3472 current_ts = 154.324280 current_received_ts = 154.323654 current_seq = 3473 count = 377 seq_step = 1 [153.911778] (kms_flip:7140) DEBUG: Vblank took 7us [153.928392] (kms_flip:7140) DEBUG: name = flip last_ts = 154.324280 last_received_ts = 154.323654 last_seq = 3473 current_ts = 154.340912 current_received_ts = 154.340286 current_seq = 3474 count = 378 seq_step = 1 [153.928407] (kms_flip:7140) DEBUG: Vblank took 7us [153.945034] (kms_flip:7140) DEBUG: name = flip last_ts = 154.340912 last_received_ts = 154.340286 last_seq = 3474 current_ts = 154.357544 current_received_ts = 154.356918 current_seq = 3475 count = 379 seq_step = 1 [153.945049] (kms_flip:7140) DEBUG: Vblank took 8us [153.961667] (kms_flip:7140) DEBUG: name = flip last_ts = 154.357544 last_received_ts = 154.356918 last_seq = 3475 current_ts = 154.374176 current_received_ts = 154.373550 current_seq = 3476 count = 380 seq_step = 1 [153.961683] (kms_flip:7140) DEBUG: Vblank took 7us [153.978298] (kms_flip:7140) DEBUG: name = flip last_ts = 154.374176 last_received_ts = 154.373550 last_seq = 3476 current_ts = 154.390808 current_received_ts = 154.390182 current_seq = 3477 count = 381 seq_step = 1 [153.978313] (kms_flip:7140) DEBUG: Vblank took 7us [153.994949] (kms_flip:7140) DEBUG: name = flip last_ts = 154.390808 last_received_ts = 154.390182 last_seq = 3477 current_ts = 154.407440 current_received_ts = 154.406830 current_seq = 3478 count = 382 seq_step = 1 [153.994965] (kms_flip:7140) DEBUG: Vblank took 8us [154.011730] (kms_flip:7140) DEBUG: name = flip last_ts = 154.407440 last_received_ts = 154.406830 last_seq = 3478 current_ts = 154.424072 current_received_ts = 154.423615 current_seq = 3479 count = 383 seq_step = 1 [154.011748] (kms_flip:7140) DEBUG: Vblank took 9us [154.028218] (kms_flip:7140) DEBUG: name = flip last_ts = 154.424072 last_received_ts = 154.423615 last_seq = 3479 current_ts = 154.440704 current_received_ts = 154.440094 current_seq = 3480 count = 384 seq_step = 1 [154.028234] (kms_flip:7140) DEBUG: Vblank took 8us [154.044827] (kms_flip:7140) DEBUG: name = flip last_ts = 154.440704 last_received_ts = 154.440094 last_seq = 3480 current_ts = 154.457336 current_received_ts = 154.456711 current_seq = 3481 count = 385 seq_step = 1 [154.044842] (kms_flip:7140) DEBUG: Vblank took 7us [154.061462] (kms_flip:7140) DEBUG: name = flip last_ts = 154.457336 last_received_ts = 154.456711 last_seq = 3481 current_ts = 154.473969 current_received_ts = 154.473343 current_seq = 3482 count = 386 seq_step = 1 [154.061478] (kms_flip:7140) DEBUG: Vblank took 7us [154.078096] (kms_flip:7140) DEBUG: name = flip last_ts = 154.473969 last_received_ts = 154.473343 last_seq = 3482 current_ts = 154.490601 current_received_ts = 154.489975 current_seq = 3483 count = 387 seq_step = 1 [154.078653] (kms_flip:7140) DEBUG: Vblank took 549us [154.078658] (kms_flip:7140) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [154.078718] (kms_flip:7140) CRITICAL: Failed assertion: end - start < 500 [154.085750] (kms_flip:7140) igt_core-INFO: Stack trace: [154.106260] (kms_flip:7140) igt_core-INFO: #0 ../lib/igt_core.c:2106 __igt_fail_assert() [154.107713] (kms_flip:7140) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [154.107822] (kms_flip:7140) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [154.107879] (kms_flip:7140) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() [154.107944] (kms_flip:7140) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [154.112602] (kms_flip:7140) igt_core-INFO: #5 [__libc_init_first+0x8a] [154.114796] (kms_flip:7140) igt_core-INFO: #6 [__libc_start_main+0x8b] [154.115349] (kms_flip:7140) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-HDMI-A1: FAIL (7.059s)
Dmesg	<6> [147.515905] [IGT] kms_flip: starting dynamic subtest A-HDMI-A1 <7> [147.516608] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:88] <7> [147.516745] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:91] <7> [147.570586] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:53:pipe A] <7> [147.570926] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:72:pipe B] <7> [147.571241] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.enable (expected yes, found no) <7> [147.572065] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.active (expected yes, found no) <7> [147.572828] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1) <7> [147.573718] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in has_pch_encoder (expected yes, found no) <7> [147.574152] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in fdi_lanes (expected 1, found 0) <7> [147.574508] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] 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> [147.574867] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000) <7> [147.575264] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [147.575622] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0) <7> [147.576018] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0) <7> [147.576375] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0) <7> [147.576756] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0) <7> [147.577146] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0) <7> [147.577502] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0) <7> [147.577858] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0) <7> [147.578251] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0) <7> [147.578570] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0) <7> [147.578923] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0) <7> [147.579329] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0) <7> [147.579702] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0) <7> [147.580114] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0) <7> [147.580494] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0) <7> [147.580850] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0) <7> [147.581245] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0) <7> [147.581617] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0) <7> [147.582022] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0) <7> [147.582378] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0) <7> [147.582734] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0) <7> [147.583121] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0) <7> [147.583494] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0) <7> [147.583850] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0) <7> [147.584246] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0) <7> [147.584603] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [147.585010] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [147.585367] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [147.585725] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pipe_bpp (expected 24, found 0) <7> [147.586126] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0) <7> [147.586484] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0) <7> [147.586839] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in port_clock (expected 64800, found 0) <7> [147.587232] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:72:pipe B] fastset requirement not met, forcing full modeset <7> [147.587605] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:72:pipe B] releasing PCH DPLL A <7> [147.588066] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:72:pipe B] min cdclk: 72000 kHz -> 0 kHz <7> [147.588424] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:72:pipe B] enable: no [modeset] <7> [147.588780] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:primary B] fb: [NOFB], visible: no <7> [147.589336] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B <7> [147.600270] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found <7> [147.600606] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found <7> [147.601190] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found <7> [147.615233] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x2, on? 1) for [CRTC:72:pipe B] <7> [147.615749] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A <7> [147.616533] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:CRT] <7> [147.617274] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:75:HDMI D] <7> [147.618122] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:83:DP D] <7> [147.618510] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:73:VGA-1] <7> [147.618916] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:72:pipe B] <7> [147.619464] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:53:pipe A] <7> [147.619512] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:76:HDMI-A-1] <7> [147.619673] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 12 bpc for HDMI output (pipe bpp: 36) <7> [147.620084] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:53:pipe A] hw max bpp: 36, pipe bpp: 36, dithering: 0 <7> [147.620444] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe A, lanes 3 <7> [147.620796] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.enable (expected no, found yes) <7> [147.621167] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.active (expected no, found yes) <7> [147.621523] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0) <7> [147.621879] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in has_pch_encoder (expected no, found yes) <7> [147.622275] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in fdi_lanes (expected 0, found 3) <7> [147.622645] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in fdi_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6934582/8388608 link 288940/524288) <7> [147.623033] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in lane_count (expected 0, found 4) <7> [147.623391] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040) <7> [147.623749] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [147.624131] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920) <7> [147.624487] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200) <7> [147.624843] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920) <7> [147.625252] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200) <7> [147.625610] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008) <7> [147.625994] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052) <7> [147.626367] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080) <7> [147.626721] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080) <7> [147.627112] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083) <7> [147.627469] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088) <7> [147.627826] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125) <7> [147.628236] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125) <7> [147.628594] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920) <7> [147.628969] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200) <7> [147.629335] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920) <7> [147.629690] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200) <7> [147.630120] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008) <7> [147.630478] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052) <7> [147.630836] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080) <7> [147.631250] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080) <7> [147.631608] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083) <7> [147.631999] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088) <7> [147.632376] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125) <7> [147.632729] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125) <7> [147.633113] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [147.633471] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1) <7> [147.633828] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [147.634239] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in has_hdmi_sink (expected no, found yes) <7> [147.634596] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in has_infoframe (expected no, found yes) <7> [147.634973] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in dpll_hw_state <7> [147.635337] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [147.635689] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09 <7> [147.636074] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [147.636430] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06 <7> [147.636786] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 36) <7> [147.637209] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on <7> [147.637201] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148800) <7> [147.637611] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148800) <7> [147.637985] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in port_clock (expected 0, found 223200) <7> [147.638346] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071) <7> [147.638703] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006) <7> [147.639095] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in avi infoframe <7> [147.639463] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [147.639816] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [147.640224] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [147.640229] i915 0000:00:02.0: colorspace: RGB <7> [147.640233] i915 0000:00:02.0: scan mode: Underscan <7> [147.640236] i915 0000:00:02.0: colorimetry: No Data <7> [147.640240] i915 0000:00:02.0: picture aspect: No Data <7> [147.640244] i915 0000:00:02.0: active aspect: Same as Picture <7> [147.640248] i915 0000:00:02.0: itc: No Data <7> [147.640251] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [147.640255] i915 0000:00:02.0: quantization range: Full <7> [147.640259] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [147.640270] i915 0000:00:02.0: video code: 0 <7> [147.640274] i915 0000:00:02.0: ycc quantization range: Full <7> [147.640277] i915 0000:00:02.0: hdmi content type: Graphics <7> [147.640289] i915 0000:00:02.0: pixel repeat: 0 <7> [147.640300] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [147.640305] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in spd infoframe <7> [147.640669] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [147.641052] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [147.641406] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [147.641410] i915 0000:00:02.0: vendor: Intel <7> [147.641414] i915 0000:00:02.0: product: Integrated gfx <7> [147.641418] i915 0000:00:02.0: source device information: PC General (0x9) <7> [147.641423] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hdmi infoframe <7> [147.641792] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected: <7> [147.642171] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found: <7> [147.642524] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [147.642529] i915 0000:00:02.0: empty frame <7> [147.642533] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:53:pipe A] fastset requirement not met, forcing full modeset <7> [147.642929] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:53:pipe A] min cdclk: 0 kHz -> 165334 kHz <7> [147.643339] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:53:pipe A] allocated PCH DPLL A <7> [147.643693] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:53:pipe A] reserving PCH DPLL A <7> [147.644077] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:53:pipe A] enable: yes [modeset] <7> [147.644433] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB <7> [147.644789] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: A, pipe bpp: 36, dithering: 0 <7> [147.645169] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid> <7> [147.645522] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [147.645876] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0 <7> [147.646285] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0 <7> [147.646655] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fdi: lanes: 3; data_m: 6934582, data_n: 8388608, link_m: 288940, link_n: 524288, tu: 64 <7> [147.647054] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71 <7> [147.647285] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6 <7> [147.647545] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13 <7> [147.647548] i915 0000:00:02.0: colorspace: RGB <7> [147.647550] i915 0000:00:02.0: scan mode: Underscan <7> [147.647552] i915 0000:00:02.0: colorimetry: No Data <7> [147.647554] i915 0000:00:02.0: picture aspect: No Data <7> [147.647556] i915 0000:00:02.0: active aspect: Same as Picture <7> [147.647557] i915 0000:00:02.0: itc: No Data <7> [147.647559] i915 0000:00:02.0: extended colorimetry: xvYCC 601 <7> [147.647561] i915 0000:00:02.0: quantization range: Full <7> [147.647563] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling <7> [147.647565] i915 0000:00:02.0: video code: 0 <7> [147.647567] i915 0000:00:02.0: ycc quantization range: Full <7> [147.647569] i915 0000:00:02.0: hdmi content type: Graphics <7> [147.647571] i915 0000:00:02.0: pixel repeat: 0 <7> [147.647572] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0 <7> [147.647575] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25 <7> [147.647577] i915 0000:00:02.0: vendor: Intel <7> [147.647579] i915 0000:00:02.0: product: Integrated gfx <7> [147.647581] i915 0000:00:02.0: source device information: PC General (0x9) <7> [147.647583] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4 <7> [147.647585] i915 0000:00:02.0: empty frame <7> [147.647587] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 07 00 66 10 00 01 00 00 00 00 00 00 00 00 <7> [147.647817] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 05 e3 cd 0c 32 38 45 38 35 30 09 07 07 00 00 00 <7> [147.648081] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1 <7> [147.648342] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [147.648583] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0 <7> [147.648818] 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> [147.649362] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [147.649600] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 <7> [147.649837] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 <7> [147.650093] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148800, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9 <7> [147.650331] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148800 1920 2008 2052 2200 1080 1083 1088 1125 0x40 0x9 <7> [147.650567] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148800, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9 <7> [147.650803] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 223200, pixel rate 148800, min cdclk 165334, min voltage level 0 <7> [147.651100] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0 <7> [147.651460] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0 <7> [147.651773] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [147.652036] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [147.652284] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0 <7> [147.652514] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06 <7> [147.652743] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [147.652998] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [147.653237] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [147.653544] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [147.653912] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [147.654199] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [147.654429] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:primary A] fb: [FB:88] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes <7> [147.654661] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [147.654890] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0 <7> [147.657352] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on <7> [147.657599] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:CRT] <7> [147.657826] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:75:HDMI D] <7> [147.658149] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:83:DP D] <7> [147.659046] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe A <7> [147.660106] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100 <7> [147.660399] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done. <7> [147.661299] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x600 <7> [147.661528] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done. <7> [147.661795] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done. <7> [147.662163] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x1, on? 0) for [CRTC:53:pipe A] <7> [147.662417] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A <7> [147.730838] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:76:HDMI-A-1][ENCODER:75:HDMI D] Enable audio codec on [CRTC:53:pipe A], 32 bytes ELD <7> [147.747465] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] HDMI audio pixel clock setting for 148800 not found, falling back to defaults <7> [147.747961] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 25200 (0x00010000) <7> [147.748503] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:76:HDMI-A-1] <7> [147.749049] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:53:pipe A] <6> [154.574902] [IGT] kms_flip: finished subtest A-HDMI-A1, FAIL

Detail

Value

Duration

7.06 seconds

Hostname

shard-snb6

Igt-Version

IGT-Version: 2.4-g0e365bfe5 (x86_64) (Linux: 7.1.0-rc5-Patchwork_167481v1-g3561a5c5f9c0+ x86_64)

Out

Starting dynamic subtest: A-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9 
Stack trace:
  #0 ../lib/igt_core.c:2106 __igt_fail_assert()
  #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
  #2 ../tests/kms_flip.c:1920 run_test()
  #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
  #4 ../tests/kms_flip.c:2105 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A1: FAIL (7.059s)

Err

Starting dynamic subtest: A-HDMI-A1
[154.078658] (kms_flip:7140) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[154.078718] (kms_flip:7140) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest A-HDMI-A1 failed.
**** DEBUG ****
[152.065538] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.461548
last_received_ts = 152.460968
last_seq = 3361
current_ts = 152.478165
current_received_ts = 152.477585
current_seq = 3362
count = 266
seq_step = 1
[152.065555] (kms_flip:7140) DEBUG: Vblank took 7us
[152.082143] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.478165
last_received_ts = 152.477585
last_seq = 3362
current_ts = 152.494797
current_received_ts = 152.494186
current_seq = 3363
count = 267
seq_step = 1
[152.082158] (kms_flip:7140) DEBUG: Vblank took 7us
[152.098775] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.494797
last_received_ts = 152.494186
last_seq = 3363
current_ts = 152.511429
current_received_ts = 152.510818
current_seq = 3364
count = 268
seq_step = 1
[152.098794] (kms_flip:7140) DEBUG: Vblank took 9us
[152.115426] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.511429
last_received_ts = 152.510818
last_seq = 3364
current_ts = 152.528076
current_received_ts = 152.527466
current_seq = 3365
count = 269
seq_step = 1
[152.115442] (kms_flip:7140) DEBUG: Vblank took 8us
[152.132079] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.528076
last_received_ts = 152.527466
last_seq = 3365
current_ts = 152.544693
current_received_ts = 152.544128
current_seq = 3366
count = 270
seq_step = 1
[152.132093] (kms_flip:7140) DEBUG: Vblank took 6us
[152.148701] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.544693
last_received_ts = 152.544128
last_seq = 3366
current_ts = 152.561325
current_received_ts = 152.560745
current_seq = 3367
count = 271
seq_step = 1
[152.148712] (kms_flip:7140) DEBUG: Vblank took 6us
[152.165314] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.561325
last_received_ts = 152.560745
last_seq = 3367
current_ts = 152.577957
current_received_ts = 152.577347
current_seq = 3368
count = 272
seq_step = 1
[152.165332] (kms_flip:7140) DEBUG: Vblank took 9us
[152.182017] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.577957
last_received_ts = 152.577347
last_seq = 3368
current_ts = 152.594604
current_received_ts = 152.594040
current_seq = 3369
count = 273
seq_step = 1
[152.182034] (kms_flip:7140) DEBUG: Vblank took 8us
[152.198609] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.594604
last_received_ts = 152.594040
last_seq = 3369
current_ts = 152.611221
current_received_ts = 152.610641
current_seq = 3370
count = 274
seq_step = 1
[152.198624] (kms_flip:7140) DEBUG: Vblank took 7us
[152.215244] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.611221
last_received_ts = 152.610641
last_seq = 3370
current_ts = 152.627853
current_received_ts = 152.627274
current_seq = 3371
count = 275
seq_step = 1
[152.215259] (kms_flip:7140) DEBUG: Vblank took 7us
[152.231892] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.627853
last_received_ts = 152.627274
last_seq = 3371
current_ts = 152.644485
current_received_ts = 152.643921
current_seq = 3372
count = 276
seq_step = 1
[152.231905] (kms_flip:7140) DEBUG: Vblank took 6us
[152.248508] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.644485
last_received_ts = 152.643921
last_seq = 3372
current_ts = 152.661118
current_received_ts = 152.660538
current_seq = 3373
count = 277
seq_step = 1
[152.248527] (kms_flip:7140) DEBUG: Vblank took 8us
[152.265124] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.661118
last_received_ts = 152.660538
last_seq = 3373
current_ts = 152.677750
current_received_ts = 152.677155
current_seq = 3374
count = 278
seq_step = 1
[152.265144] (kms_flip:7140) DEBUG: Vblank took 8us
[152.281747] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.677750
last_received_ts = 152.677155
last_seq = 3374
current_ts = 152.694382
current_received_ts = 152.693771
current_seq = 3375
count = 279
seq_step = 1
[152.281765] (kms_flip:7140) DEBUG: Vblank took 9us
[152.298376] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.694382
last_received_ts = 152.693771
last_seq = 3375
current_ts = 152.711014
current_received_ts = 152.710403
current_seq = 3376
count = 280
seq_step = 1
[152.298392] (kms_flip:7140) DEBUG: Vblank took 8us
[152.315016] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.711014
last_received_ts = 152.710403
last_seq = 3376
current_ts = 152.727631
current_received_ts = 152.727036
current_seq = 3377
count = 281
seq_step = 1
[152.315032] (kms_flip:7140) DEBUG: Vblank took 8us
[152.331632] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.727631
last_received_ts = 152.727036
last_seq = 3377
current_ts = 152.744278
current_received_ts = 152.743652
current_seq = 3378
count = 282
seq_step = 1
[152.331646] (kms_flip:7140) DEBUG: Vblank took 7us
[152.348293] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.744278
last_received_ts = 152.743652
last_seq = 3378
current_ts = 152.760910
current_received_ts = 152.760315
current_seq = 3379
count = 283
seq_step = 1
[152.348309] (kms_flip:7140) DEBUG: Vblank took 8us
[152.364946] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.760910
last_received_ts = 152.760315
last_seq = 3379
current_ts = 152.777542
current_received_ts = 152.776962
current_seq = 3380
count = 284
seq_step = 1
[152.364965] (kms_flip:7140) DEBUG: Vblank took 8us
[152.381549] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.777542
last_received_ts = 152.776962
last_seq = 3380
current_ts = 152.794174
current_received_ts = 152.793564
current_seq = 3381
count = 285
seq_step = 1
[152.381568] (kms_flip:7140) DEBUG: Vblank took 8us
[152.398210] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.794174
last_received_ts = 152.793564
last_seq = 3381
current_ts = 152.810806
current_received_ts = 152.810226
current_seq = 3382
count = 286
seq_step = 1
[152.398229] (kms_flip:7140) DEBUG: Vblank took 9us
[152.414839] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.810806
last_received_ts = 152.810226
last_seq = 3382
current_ts = 152.827438
current_received_ts = 152.826859
current_seq = 3383
count = 287
seq_step = 1
[152.414857] (kms_flip:7140) DEBUG: Vblank took 7us
[152.431468] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.827438
last_received_ts = 152.826859
last_seq = 3383
current_ts = 152.844070
current_received_ts = 152.843475
current_seq = 3384
count = 288
seq_step = 1
[152.431485] (kms_flip:7140) DEBUG: Vblank took 8us
[152.448067] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.844070
last_received_ts = 152.843475
last_seq = 3384
current_ts = 152.860703
current_received_ts = 152.860077
current_seq = 3385
count = 289
seq_step = 1
[152.448085] (kms_flip:7140) DEBUG: Vblank took 9us
[152.464717] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.860703
last_received_ts = 152.860077
last_seq = 3385
current_ts = 152.877335
current_received_ts = 152.876724
current_seq = 3386
count = 290
seq_step = 1
[152.464734] (kms_flip:7140) DEBUG: Vblank took 7us
[152.481350] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.877335
last_received_ts = 152.876724
last_seq = 3386
current_ts = 152.893967
current_received_ts = 152.893356
current_seq = 3387
count = 291
seq_step = 1
[152.481367] (kms_flip:7140) DEBUG: Vblank took 7us
[152.497990] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.893967
last_received_ts = 152.893356
last_seq = 3387
current_ts = 152.910583
current_received_ts = 152.909988
current_seq = 3388
count = 292
seq_step = 1
[152.498008] (kms_flip:7140) DEBUG: Vblank took 7us
[152.514640] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.910583
last_received_ts = 152.909988
last_seq = 3388
current_ts = 152.927216
current_received_ts = 152.926651
current_seq = 3389
count = 293
seq_step = 1
[152.514658] (kms_flip:7140) DEBUG: Vblank took 8us
[152.531268] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.927216
last_received_ts = 152.926651
last_seq = 3389
current_ts = 152.943848
current_received_ts = 152.943268
current_seq = 3390
count = 294
seq_step = 1
[152.531286] (kms_flip:7140) DEBUG: Vblank took 7us
[152.547875] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.943848
last_received_ts = 152.943268
last_seq = 3390
current_ts = 152.960480
current_received_ts = 152.959885
current_seq = 3391
count = 295
seq_step = 1
[152.547892] (kms_flip:7140) DEBUG: Vblank took 8us
[152.564543] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.960480
last_received_ts = 152.959885
last_seq = 3391
current_ts = 152.977127
current_received_ts = 152.976547
current_seq = 3392
count = 296
seq_step = 1
[152.564562] (kms_flip:7140) DEBUG: Vblank took 9us
[152.581149] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.977127
last_received_ts = 152.976547
last_seq = 3392
current_ts = 152.993744
current_received_ts = 152.993149
current_seq = 3393
count = 297
seq_step = 1
[152.581168] (kms_flip:7140) DEBUG: Vblank took 9us
[152.597804] (kms_flip:7140) DEBUG: name = flip
last_ts = 152.993744
last_received_ts = 152.993149
last_seq = 3393
current_ts = 153.010376
current_received_ts = 153.009811
current_seq = 3394
count = 298
seq_step = 1
[152.597820] (kms_flip:7140) DEBUG: Vblank took 7us
[152.614435] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.010376
last_received_ts = 153.009811
last_seq = 3394
current_ts = 153.027008
current_received_ts = 153.026428
current_seq = 3395
count = 299
seq_step = 1
[152.614452] (kms_flip:7140) DEBUG: Vblank took 8us
[152.631047] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.027008
last_received_ts = 153.026428
last_seq = 3395
current_ts = 153.043640
current_received_ts = 153.043045
current_seq = 3396
count = 300
seq_step = 1
[152.631064] (kms_flip:7140) DEBUG: Vblank took 7us
[152.647698] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.043640
last_received_ts = 153.043045
last_seq = 3396
current_ts = 153.060272
current_received_ts = 153.059692
current_seq = 3397
count = 301
seq_step = 1
[152.647716] (kms_flip:7140) DEBUG: Vblank took 8us
[152.664310] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.060272
last_received_ts = 153.059692
last_seq = 3397
current_ts = 153.076904
current_received_ts = 153.076309
current_seq = 3398
count = 302
seq_step = 1
[152.664327] (kms_flip:7140) DEBUG: Vblank took 8us
[152.680931] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.076904
last_received_ts = 153.076309
last_seq = 3398
current_ts = 153.093536
current_received_ts = 153.092926
current_seq = 3399
count = 303
seq_step = 1
[152.680948] (kms_flip:7140) DEBUG: Vblank took 8us
[152.697576] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.093536
last_received_ts = 153.092926
last_seq = 3399
current_ts = 153.110168
current_received_ts = 153.109573
current_seq = 3400
count = 304
seq_step = 1
[152.697593] (kms_flip:7140) DEBUG: Vblank took 7us
[152.714214] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.110168
last_received_ts = 153.109573
last_seq = 3400
current_ts = 153.126801
current_received_ts = 153.126205
current_seq = 3401
count = 305
seq_step = 1
[152.714232] (kms_flip:7140) DEBUG: Vblank took 8us
[152.730897] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.126801
last_received_ts = 153.126205
last_seq = 3401
current_ts = 153.143433
current_received_ts = 153.142883
current_seq = 3402
count = 306
seq_step = 1
[152.730914] (kms_flip:7140) DEBUG: Vblank took 8us
[152.747502] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.143433
last_received_ts = 153.142883
last_seq = 3402
current_ts = 153.160065
current_received_ts = 153.159485
current_seq = 3403
count = 307
seq_step = 1
[152.747520] (kms_flip:7140) DEBUG: Vblank took 8us
[152.764100] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.160065
last_received_ts = 153.159485
last_seq = 3403
current_ts = 153.176697
current_received_ts = 153.176086
current_seq = 3404
count = 308
seq_step = 1
[152.764118] (kms_flip:7140) DEBUG: Vblank took 9us
[152.780728] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.176697
last_received_ts = 153.176086
last_seq = 3404
current_ts = 153.193329
current_received_ts = 153.192703
current_seq = 3405
count = 309
seq_step = 1
[152.780746] (kms_flip:7140) DEBUG: Vblank took 9us
[152.797361] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.193329
last_received_ts = 153.192703
last_seq = 3405
current_ts = 153.209961
current_received_ts = 153.209351
current_seq = 3406
count = 310
seq_step = 1
[152.797379] (kms_flip:7140) DEBUG: Vblank took 8us
[152.814028] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.209961
last_received_ts = 153.209351
last_seq = 3406
current_ts = 153.226593
current_received_ts = 153.225998
current_seq = 3407
count = 311
seq_step = 1
[152.814045] (kms_flip:7140) DEBUG: Vblank took 7us
[152.830650] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.226593
last_received_ts = 153.225998
last_seq = 3407
current_ts = 153.243225
current_received_ts = 153.242630
current_seq = 3408
count = 312
seq_step = 1
[152.830669] (kms_flip:7140) DEBUG: Vblank took 9us
[152.847267] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.243225
last_received_ts = 153.242630
last_seq = 3408
current_ts = 153.259857
current_received_ts = 153.259247
current_seq = 3409
count = 313
seq_step = 1
[152.847285] (kms_flip:7140) DEBUG: Vblank took 9us
[152.863926] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.259857
last_received_ts = 153.259247
last_seq = 3409
current_ts = 153.276489
current_received_ts = 153.275894
current_seq = 3410
count = 314
seq_step = 1
[152.863946] (kms_flip:7140) DEBUG: Vblank took 10us
[152.880538] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.276489
last_received_ts = 153.275894
last_seq = 3410
current_ts = 153.293121
current_received_ts = 153.292511
current_seq = 3411
count = 315
seq_step = 1
[152.880558] (kms_flip:7140) DEBUG: Vblank took 9us
[152.897177] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.293121
last_received_ts = 153.292511
last_seq = 3411
current_ts = 153.309753
current_received_ts = 153.309143
current_seq = 3412
count = 316
seq_step = 1
[152.897196] (kms_flip:7140) DEBUG: Vblank took 9us
[152.913806] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.309753
last_received_ts = 153.309143
last_seq = 3412
current_ts = 153.326385
current_received_ts = 153.325775
current_seq = 3413
count = 317
seq_step = 1
[152.913825] (kms_flip:7140) DEBUG: Vblank took 10us
[152.930430] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.326385
last_received_ts = 153.325775
last_seq = 3413
current_ts = 153.343018
current_received_ts = 153.342407
current_seq = 3414
count = 318
seq_step = 1
[152.930448] (kms_flip:7140) DEBUG: Vblank took 9us
[152.947201] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.343018
last_received_ts = 153.342407
last_seq = 3414
current_ts = 153.359650
current_received_ts = 153.359177
current_seq = 3415
count = 319
seq_step = 1
[152.947218] (kms_flip:7140) DEBUG: Vblank took 9us
[152.963738] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.359650
last_received_ts = 153.359177
last_seq = 3415
current_ts = 153.376282
current_received_ts = 153.375702
current_seq = 3416
count = 320
seq_step = 1
[152.963756] (kms_flip:7140) DEBUG: Vblank took 8us
[152.980354] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.376282
last_received_ts = 153.375702
last_seq = 3416
current_ts = 153.392899
current_received_ts = 153.392319
current_seq = 3417
count = 321
seq_step = 1
[152.980374] (kms_flip:7140) DEBUG: Vblank took 9us
[152.996990] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.392899
last_received_ts = 153.392319
last_seq = 3417
current_ts = 153.409531
current_received_ts = 153.408951
current_seq = 3418
count = 322
seq_step = 1
[152.997008] (kms_flip:7140) DEBUG: Vblank took 8us
[153.013627] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.409531
last_received_ts = 153.408951
last_seq = 3418
current_ts = 153.426178
current_received_ts = 153.425598
current_seq = 3419
count = 323
seq_step = 1
[153.013644] (kms_flip:7140) DEBUG: Vblank took 8us
[153.030238] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.426178
last_received_ts = 153.425598
last_seq = 3419
current_ts = 153.442810
current_received_ts = 153.442200
current_seq = 3420
count = 324
seq_step = 1
[153.030256] (kms_flip:7140) DEBUG: Vblank took 8us
[153.046889] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.442810
last_received_ts = 153.442200
last_seq = 3420
current_ts = 153.459442
current_received_ts = 153.458847
current_seq = 3421
count = 325
seq_step = 1
[153.046905] (kms_flip:7140) DEBUG: Vblank took 8us
[153.063526] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.459442
last_received_ts = 153.458847
last_seq = 3421
current_ts = 153.476074
current_received_ts = 153.475494
current_seq = 3422
count = 326
seq_step = 1
[153.063542] (kms_flip:7140) DEBUG: Vblank took 7us
[153.080166] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.476074
last_received_ts = 153.475494
last_seq = 3422
current_ts = 153.492691
current_received_ts = 153.492126
current_seq = 3423
count = 327
seq_step = 1
[153.080184] (kms_flip:7140) DEBUG: Vblank took 8us
[153.096770] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.492691
last_received_ts = 153.492126
last_seq = 3423
current_ts = 153.509323
current_received_ts = 153.508728
current_seq = 3424
count = 328
seq_step = 1
[153.096787] (kms_flip:7140) DEBUG: Vblank took 7us
[153.113425] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.509323
last_received_ts = 153.508728
last_seq = 3424
current_ts = 153.525955
current_received_ts = 153.525375
current_seq = 3425
count = 329
seq_step = 1
[153.113441] (kms_flip:7140) DEBUG: Vblank took 7us
[153.130073] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.525955
last_received_ts = 153.525375
last_seq = 3425
current_ts = 153.542587
current_received_ts = 153.542023
current_seq = 3426
count = 330
seq_step = 1
[153.130088] (kms_flip:7140) DEBUG: Vblank took 7us
[153.146689] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.542587
last_received_ts = 153.542023
last_seq = 3426
current_ts = 153.559219
current_received_ts = 153.558640
current_seq = 3427
count = 331
seq_step = 1
[153.146705] (kms_flip:7140) DEBUG: Vblank took 8us
[153.163282] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.559219
last_received_ts = 153.558640
last_seq = 3427
current_ts = 153.575851
current_received_ts = 153.575241
current_seq = 3428
count = 332
seq_step = 1
[153.163299] (kms_flip:7140) DEBUG: Vblank took 8us
[153.179991] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.575851
last_received_ts = 153.575241
last_seq = 3428
current_ts = 153.592484
current_received_ts = 153.591934
current_seq = 3429
count = 333
seq_step = 1
[153.180009] (kms_flip:7140) DEBUG: Vblank took 8us
[153.196565] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.592484
last_received_ts = 153.591934
last_seq = 3429
current_ts = 153.609116
current_received_ts = 153.608521
current_seq = 3430
count = 334
seq_step = 1
[153.196580] (kms_flip:7140) DEBUG: Vblank took 7us
[153.213199] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.609116
last_received_ts = 153.608521
last_seq = 3430
current_ts = 153.625748
current_received_ts = 153.625153
current_seq = 3431
count = 335
seq_step = 1
[153.213213] (kms_flip:7140) DEBUG: Vblank took 7us
[153.229831] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.625748
last_received_ts = 153.625153
last_seq = 3431
current_ts = 153.642380
current_received_ts = 153.641785
current_seq = 3432
count = 336
seq_step = 1
[153.229846] (kms_flip:7140) DEBUG: Vblank took 7us
[153.246465] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.642380
last_received_ts = 153.641785
last_seq = 3432
current_ts = 153.659012
current_received_ts = 153.658417
current_seq = 3433
count = 337
seq_step = 1
[153.246479] (kms_flip:7140) DEBUG: Vblank took 6us
[153.263122] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.659012
last_received_ts = 153.658417
last_seq = 3433
current_ts = 153.675644
current_received_ts = 153.675064
current_seq = 3434
count = 338
seq_step = 1
[153.263136] (kms_flip:7140) DEBUG: Vblank took 6us
[153.279755] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.675644
last_received_ts = 153.675064
last_seq = 3434
current_ts = 153.692276
current_received_ts = 153.691696
current_seq = 3435
count = 339
seq_step = 1
[153.279770] (kms_flip:7140) DEBUG: Vblank took 7us
[153.296373] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.692276
last_received_ts = 153.691696
last_seq = 3435
current_ts = 153.708908
current_received_ts = 153.708313
current_seq = 3436
count = 340
seq_step = 1
[153.296389] (kms_flip:7140) DEBUG: Vblank took 8us
[153.312987] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.708908
last_received_ts = 153.708313
last_seq = 3436
current_ts = 153.725540
current_received_ts = 153.724930
current_seq = 3437
count = 341
seq_step = 1
[153.313005] (kms_flip:7140) DEBUG: Vblank took 9us
[153.329632] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.725540
last_received_ts = 153.724930
last_seq = 3437
current_ts = 153.742172
current_received_ts = 153.741577
current_seq = 3438
count = 342
seq_step = 1
[153.329650] (kms_flip:7140) DEBUG: Vblank took 9us
[153.346273] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.742172
last_received_ts = 153.741577
last_seq = 3438
current_ts = 153.758804
current_received_ts = 153.758209
current_seq = 3439
count = 343
seq_step = 1
[153.346290] (kms_flip:7140) DEBUG: Vblank took 8us
[153.362880] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.758804
last_received_ts = 153.758209
last_seq = 3439
current_ts = 153.775436
current_received_ts = 153.774811
current_seq = 3440
count = 344
seq_step = 1
[153.362898] (kms_flip:7140) DEBUG: Vblank took 9us
[153.379641] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.775436
last_received_ts = 153.774811
last_seq = 3440
current_ts = 153.792068
current_received_ts = 153.791580
current_seq = 3441
count = 345
seq_step = 1
[153.379659] (kms_flip:7140) DEBUG: Vblank took 9us
[153.396207] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.792068
last_received_ts = 153.791580
last_seq = 3441
current_ts = 153.808701
current_received_ts = 153.808136
current_seq = 3442
count = 346
seq_step = 1
[153.396225] (kms_flip:7140) DEBUG: Vblank took 8us
[153.412782] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.808701
last_received_ts = 153.808136
last_seq = 3442
current_ts = 153.825333
current_received_ts = 153.824707
current_seq = 3443
count = 347
seq_step = 1
[153.412801] (kms_flip:7140) DEBUG: Vblank took 9us
[153.429432] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.825333
last_received_ts = 153.824707
last_seq = 3443
current_ts = 153.841965
current_received_ts = 153.841354
current_seq = 3444
count = 348
seq_step = 1
[153.429450] (kms_flip:7140) DEBUG: Vblank took 9us
[153.446044] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.841965
last_received_ts = 153.841354
last_seq = 3444
current_ts = 153.858597
current_received_ts = 153.857971
current_seq = 3445
count = 349
seq_step = 1
[153.446072] (kms_flip:7140) DEBUG: Vblank took 18us
[153.462700] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.858597
last_received_ts = 153.857971
last_seq = 3445
current_ts = 153.875229
current_received_ts = 153.874634
current_seq = 3446
count = 350
seq_step = 1
[153.462718] (kms_flip:7140) DEBUG: Vblank took 8us
[153.479341] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.875229
last_received_ts = 153.874634
last_seq = 3446
current_ts = 153.891861
current_received_ts = 153.891266
current_seq = 3447
count = 351
seq_step = 1
[153.479360] (kms_flip:7140) DEBUG: Vblank took 9us
[153.495954] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.891861
last_received_ts = 153.891266
last_seq = 3447
current_ts = 153.908493
current_received_ts = 153.907883
current_seq = 3448
count = 352
seq_step = 1
[153.495971] (kms_flip:7140) DEBUG: Vblank took 8us
[153.512590] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.908493
last_received_ts = 153.907883
last_seq = 3448
current_ts = 153.925125
current_received_ts = 153.924515
current_seq = 3449
count = 353
seq_step = 1
[153.512609] (kms_flip:7140) DEBUG: Vblank took 10us
[153.529215] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.925125
last_received_ts = 153.924515
last_seq = 3449
current_ts = 153.941757
current_received_ts = 153.941132
current_seq = 3450
count = 354
seq_step = 1
[153.529232] (kms_flip:7140) DEBUG: Vblank took 9us
[153.545868] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.941757
last_received_ts = 153.941132
last_seq = 3450
current_ts = 153.958374
current_received_ts = 153.957794
current_seq = 3451
count = 355
seq_step = 1
[153.545886] (kms_flip:7140) DEBUG: Vblank took 8us
[153.562495] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.958374
last_received_ts = 153.957794
last_seq = 3451
current_ts = 153.975021
current_received_ts = 153.974411
current_seq = 3452
count = 356
seq_step = 1
[153.562513] (kms_flip:7140) DEBUG: Vblank took 8us
[153.579123] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.975021
last_received_ts = 153.974411
last_seq = 3452
current_ts = 153.991653
current_received_ts = 153.991043
current_seq = 3453
count = 357
seq_step = 1
[153.579141] (kms_flip:7140) DEBUG: Vblank took 8us
[153.595766] (kms_flip:7140) DEBUG: name = flip
last_ts = 153.991653
last_received_ts = 153.991043
last_seq = 3453
current_ts = 154.008270
current_received_ts = 154.007690
current_seq = 3454
count = 358
seq_step = 1
[153.595784] (kms_flip:7140) DEBUG: Vblank took 9us
[153.612394] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.008270
last_received_ts = 154.007690
last_seq = 3454
current_ts = 154.024902
current_received_ts = 154.024307
current_seq = 3455
count = 359
seq_step = 1
[153.612410] (kms_flip:7140) DEBUG: Vblank took 8us
[153.629018] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.024902
last_received_ts = 154.024307
last_seq = 3455
current_ts = 154.041550
current_received_ts = 154.040939
current_seq = 3456
count = 360
seq_step = 1
[153.629035] (kms_flip:7140) DEBUG: Vblank took 8us
[153.645661] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.041550
last_received_ts = 154.040939
last_seq = 3456
current_ts = 154.058167
current_received_ts = 154.057571
current_seq = 3457
count = 361
seq_step = 1
[153.645680] (kms_flip:7140) DEBUG: Vblank took 9us
[153.662287] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.058167
last_received_ts = 154.057571
last_seq = 3457
current_ts = 154.074799
current_received_ts = 154.074203
current_seq = 3458
count = 362
seq_step = 1
[153.662303] (kms_flip:7140) DEBUG: Vblank took 7us
[153.678933] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.074799
last_received_ts = 154.074203
last_seq = 3458
current_ts = 154.091431
current_received_ts = 154.090836
current_seq = 3459
count = 363
seq_step = 1
[153.678949] (kms_flip:7140) DEBUG: Vblank took 8us
[153.695565] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.091431
last_received_ts = 154.090836
last_seq = 3459
current_ts = 154.108063
current_received_ts = 154.107468
current_seq = 3460
count = 364
seq_step = 1
[153.695582] (kms_flip:7140) DEBUG: Vblank took 8us
[153.712167] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.108063
last_received_ts = 154.107468
last_seq = 3460
current_ts = 154.124695
current_received_ts = 154.124069
current_seq = 3461
count = 365
seq_step = 1
[153.712183] (kms_flip:7140) DEBUG: Vblank took 8us
[153.728887] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.124695
last_received_ts = 154.124069
last_seq = 3461
current_ts = 154.141327
current_received_ts = 154.140793
current_seq = 3462
count = 366
seq_step = 1
[153.728903] (kms_flip:7140) DEBUG: Vblank took 8us
[153.745440] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.141327
last_received_ts = 154.140793
last_seq = 3462
current_ts = 154.157959
current_received_ts = 154.157349
current_seq = 3463
count = 367
seq_step = 1
[153.745456] (kms_flip:7140) DEBUG: Vblank took 8us
[153.762074] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.157959
last_received_ts = 154.157349
last_seq = 3463
current_ts = 154.174591
current_received_ts = 154.173981
current_seq = 3464
count = 368
seq_step = 1
[153.762101] (kms_flip:7140) DEBUG: Vblank took 20us
[153.778729] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.174591
last_received_ts = 154.173981
last_seq = 3464
current_ts = 154.191223
current_received_ts = 154.190628
current_seq = 3465
count = 369
seq_step = 1
[153.778745] (kms_flip:7140) DEBUG: Vblank took 8us
[153.795348] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.191223
last_received_ts = 154.190628
last_seq = 3465
current_ts = 154.207855
current_received_ts = 154.207245
current_seq = 3466
count = 370
seq_step = 1
[153.795366] (kms_flip:7140) DEBUG: Vblank took 9us
[153.811980] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.207855
last_received_ts = 154.207245
last_seq = 3466
current_ts = 154.224487
current_received_ts = 154.223877
current_seq = 3467
count = 371
seq_step = 1
[153.811998] (kms_flip:7140) DEBUG: Vblank took 9us
[153.828630] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.224487
last_received_ts = 154.223877
last_seq = 3467
current_ts = 154.241119
current_received_ts = 154.240524
current_seq = 3468
count = 372
seq_step = 1
[153.828647] (kms_flip:7140) DEBUG: Vblank took 8us
[153.845297] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.241119
last_received_ts = 154.240524
last_seq = 3468
current_ts = 154.257751
current_received_ts = 154.257187
current_seq = 3469
count = 373
seq_step = 1
[153.845314] (kms_flip:7140) DEBUG: Vblank took 8us
[153.861871] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.257751
last_received_ts = 154.257187
last_seq = 3469
current_ts = 154.274384
current_received_ts = 154.273773
current_seq = 3470
count = 374
seq_step = 1
[153.861888] (kms_flip:7140) DEBUG: Vblank took 9us
[153.878501] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.274384
last_received_ts = 154.273773
last_seq = 3470
current_ts = 154.291016
current_received_ts = 154.290390
current_seq = 3471
count = 375
seq_step = 1
[153.878518] (kms_flip:7140) DEBUG: Vblank took 7us
[153.895141] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.291016
last_received_ts = 154.290390
last_seq = 3471
current_ts = 154.307648
current_received_ts = 154.307037
current_seq = 3472
count = 376
seq_step = 1
[153.895157] (kms_flip:7140) DEBUG: Vblank took 8us
[153.911762] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.307648
last_received_ts = 154.307037
last_seq = 3472
current_ts = 154.324280
current_received_ts = 154.323654
current_seq = 3473
count = 377
seq_step = 1
[153.911778] (kms_flip:7140) DEBUG: Vblank took 7us
[153.928392] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.324280
last_received_ts = 154.323654
last_seq = 3473
current_ts = 154.340912
current_received_ts = 154.340286
current_seq = 3474
count = 378
seq_step = 1
[153.928407] (kms_flip:7140) DEBUG: Vblank took 7us
[153.945034] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.340912
last_received_ts = 154.340286
last_seq = 3474
current_ts = 154.357544
current_received_ts = 154.356918
current_seq = 3475
count = 379
seq_step = 1
[153.945049] (kms_flip:7140) DEBUG: Vblank took 8us
[153.961667] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.357544
last_received_ts = 154.356918
last_seq = 3475
current_ts = 154.374176
current_received_ts = 154.373550
current_seq = 3476
count = 380
seq_step = 1
[153.961683] (kms_flip:7140) DEBUG: Vblank took 7us
[153.978298] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.374176
last_received_ts = 154.373550
last_seq = 3476
current_ts = 154.390808
current_received_ts = 154.390182
current_seq = 3477
count = 381
seq_step = 1
[153.978313] (kms_flip:7140) DEBUG: Vblank took 7us
[153.994949] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.390808
last_received_ts = 154.390182
last_seq = 3477
current_ts = 154.407440
current_received_ts = 154.406830
current_seq = 3478
count = 382
seq_step = 1
[153.994965] (kms_flip:7140) DEBUG: Vblank took 8us
[154.011730] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.407440
last_received_ts = 154.406830
last_seq = 3478
current_ts = 154.424072
current_received_ts = 154.423615
current_seq = 3479
count = 383
seq_step = 1
[154.011748] (kms_flip:7140) DEBUG: Vblank took 9us
[154.028218] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.424072
last_received_ts = 154.423615
last_seq = 3479
current_ts = 154.440704
current_received_ts = 154.440094
current_seq = 3480
count = 384
seq_step = 1
[154.028234] (kms_flip:7140) DEBUG: Vblank took 8us
[154.044827] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.440704
last_received_ts = 154.440094
last_seq = 3480
current_ts = 154.457336
current_received_ts = 154.456711
current_seq = 3481
count = 385
seq_step = 1
[154.044842] (kms_flip:7140) DEBUG: Vblank took 7us
[154.061462] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.457336
last_received_ts = 154.456711
last_seq = 3481
current_ts = 154.473969
current_received_ts = 154.473343
current_seq = 3482
count = 386
seq_step = 1
[154.061478] (kms_flip:7140) DEBUG: Vblank took 7us
[154.078096] (kms_flip:7140) DEBUG: name = flip
last_ts = 154.473969
last_received_ts = 154.473343
last_seq = 3482
current_ts = 154.490601
current_received_ts = 154.489975
current_seq = 3483
count = 387
seq_step = 1
[154.078653] (kms_flip:7140) DEBUG: Vblank took 549us
[154.078658] (kms_flip:7140) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[154.078718] (kms_flip:7140) CRITICAL: Failed assertion: end - start < 500
[154.085750] (kms_flip:7140) igt_core-INFO: Stack trace:
[154.106260] (kms_flip:7140) igt_core-INFO:   #0 ../lib/igt_core.c:2106 __igt_fail_assert()
[154.107713] (kms_flip:7140) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[154.107822] (kms_flip:7140) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[154.107879] (kms_flip:7140) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
[154.107944] (kms_flip:7140) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[154.112602] (kms_flip:7140) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[154.114796] (kms_flip:7140) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[154.115349] (kms_flip:7140) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A1: FAIL (7.059s)

Dmesg

<6> [147.515905] [IGT] kms_flip: starting dynamic subtest A-HDMI-A1

<7> [147.516608] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:88]

<7> [147.516745] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:91]

<7> [147.570586] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:53:pipe A]

<7> [147.570926] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:72:pipe B]

<7> [147.571241] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.enable (expected yes, found no)

<7> [147.572065] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.active (expected yes, found no)

<7> [147.572828] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in cpu_transcoder (expected 1, found -1)

<7> [147.573718] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in has_pch_encoder (expected yes, found no)

<7> [147.574152] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in fdi_lanes (expected 1, found 0)

<7> [147.574508] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] 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> [147.574867] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in output_types (expected 0x00000002, found 0x00000000)

<7> [147.575264] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in framestart_delay (expected 1, found 0)

<7> [147.575622] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 1024, found 0)

<7> [147.576018] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 1344, found 0)

<7> [147.576375] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 1024, found 0)

<7> [147.576756] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 1344, found 0)

<7> [147.577146] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 1048, found 0)

<7> [147.577502] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 1184, found 0)

<7> [147.577858] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 768, found 0)

<7> [147.578251] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 768, found 0)

<7> [147.578570] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 771, found 0)

<7> [147.578923] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 777, found 0)

<7> [147.579329] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 806, found 0)

<7> [147.579702] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 806, found 0)

<7> [147.580114] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 1024, found 0)

<7> [147.580494] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 1344, found 0)

<7> [147.580850] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 1024, found 0)

<7> [147.581245] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 1344, found 0)

<7> [147.581617] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 1048, found 0)

<7> [147.582022] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 1184, found 0)

<7> [147.582378] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 768, found 0)

<7> [147.582734] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 768, found 0)

<7> [147.583121] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 771, found 0)

<7> [147.583494] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 777, found 0)

<7> [147.583850] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 806, found 0)

<7> [147.584246] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 806, found 0)

<7> [147.584603] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pixel_multiplier (expected 1, found 0)

<7> [147.585010] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)

<7> [147.585367] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)

<7> [147.585725] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in pipe_bpp (expected 24, found 0)

<7> [147.586126] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 64800, found 0)

<7> [147.586484] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 64800, found 0)

<7> [147.586839] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:72:pipe B] fastset requirement not met in port_clock (expected 64800, found 0)

<7> [147.587232] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:72:pipe B] fastset requirement not met, forcing full modeset

<7> [147.587605] i915 0000:00:02.0: [drm:intel_dpll_crtc_put [i915]] [CRTC:72:pipe B] releasing PCH DPLL A

<7> [147.588066] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:72:pipe B] min cdclk: 72000 kHz -> 0 kHz

<7> [147.588424] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:72:pipe B] enable: no [modeset]

<7> [147.588780] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:54:primary B] fb: [NOFB], visible: no

<7> [147.589336] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe B

<7> [147.600270] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port B found

<7> [147.600606] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port C found

<7> [147.601190] i915 0000:00:02.0: [drm:g4x_dp_port_enabled [i915]] No pipe for DP port D found

<7> [147.615233] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disable PCH DPLL A (active 0x2, on? 1) for [CRTC:72:pipe B]

<7> [147.615749] i915 0000:00:02.0: [drm:intel_dpll_disable [i915]] disabling PCH DPLL A

<7> [147.616533] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:CRT]

<7> [147.617274] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:75:HDMI D]

<7> [147.618122] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:83:DP D]

<7> [147.618510] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:73:VGA-1]

<7> [147.618916] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:72:pipe B]

<7> [147.619464] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:53:pipe A]

<7> [147.619512] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:76:HDMI-A-1]

<7> [147.619673] i915 0000:00:02.0: [drm:intel_hdmi_compute_output_format [i915]] picking 12 bpc for HDMI output (pipe bpp: 36)

<7> [147.620084] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:53:pipe A] hw max bpp: 36, pipe bpp: 36, dithering: 0

<7> [147.620444] i915 0000:00:02.0: [drm:intel_fdi_atomic_check_link [i915]] checking fdi config on pipe A, lanes 3

<7> [147.620796] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.enable (expected no, found yes)

<7> [147.621167] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.active (expected no, found yes)

<7> [147.621523] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0)

<7> [147.621879] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in has_pch_encoder (expected no, found yes)

<7> [147.622275] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in fdi_lanes (expected 0, found 3)

<7> [147.622645] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in fdi_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6934582/8388608 link 288940/524288)

<7> [147.623033] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in lane_count (expected 0, found 4)

<7> [147.623391] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000040)

<7> [147.623749] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1)

<7> [147.624131] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 1920)

<7> [147.624487] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 2200)

<7> [147.624843] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 1920)

<7> [147.625252] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 2200)

<7> [147.625610] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2008)

<7> [147.625994] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2052)

<7> [147.626367] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1080)

<7> [147.626721] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1080)

<7> [147.627112] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1083)

<7> [147.627469] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1088)

<7> [147.627826] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1125)

<7> [147.628236] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1125)

<7> [147.628594] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 1920)

<7> [147.628969] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 2200)

<7> [147.629335] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 1920)

<7> [147.629690] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 2200)

<7> [147.630120] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2008)

<7> [147.630478] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2052)

<7> [147.630836] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1080)

<7> [147.631250] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1080)

<7> [147.631608] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1083)

<7> [147.631999] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1088)

<7> [147.632376] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1125)

<7> [147.632729] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1125)

<7> [147.633113] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1)

<7> [147.633471] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.flags (1) (expected 0, found 1)

<7> [147.633828] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)

<7> [147.634239] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in has_hdmi_sink (expected no, found yes)

<7> [147.634596] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in has_infoframe (expected no, found yes)

<7> [147.634973] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in dpll_hw_state

<7> [147.635337] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [147.635689] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0x84100010, dpll_md: 0x0, fp0: 0x10c09, fp1: 0x10c09

<7> [147.636074] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [147.636430] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06

<7> [147.636786] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 36)

<7> [147.637209] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling always-on

<7> [147.637201] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 148800)

<7> [147.637611] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 148800)

<7> [147.637985] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in port_clock (expected 0, found 223200)

<7> [147.638346] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in infoframes.enable (expected 0x00000000, found 0x00000071)

<7> [147.638703] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in infoframes.gcp (expected 0x00000000, found 0x00000006)

<7> [147.639095] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in avi infoframe

<7> [147.639463] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [147.639816] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [147.640224] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [147.640229] i915 0000:00:02.0: colorspace: RGB

<7> [147.640233] i915 0000:00:02.0: scan mode: Underscan

<7> [147.640236] i915 0000:00:02.0: colorimetry: No Data

<7> [147.640240] i915 0000:00:02.0: picture aspect: No Data

<7> [147.640244] i915 0000:00:02.0: active aspect: Same as Picture

<7> [147.640248] i915 0000:00:02.0: itc: No Data

<7> [147.640251] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [147.640255] i915 0000:00:02.0: quantization range: Full

<7> [147.640259] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [147.640270] i915 0000:00:02.0: video code: 0

<7> [147.640274] i915 0000:00:02.0: ycc quantization range: Full

<7> [147.640277] i915 0000:00:02.0: hdmi content type: Graphics

<7> [147.640289] i915 0000:00:02.0: pixel repeat: 0

<7> [147.640300] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

<7> [147.640305] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in spd infoframe

<7> [147.640669] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [147.641052] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [147.641406] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [147.641410] i915 0000:00:02.0: vendor: Intel

<7> [147.641414] i915 0000:00:02.0: product: Integrated gfx

<7> [147.641418] i915 0000:00:02.0: source device information: PC General (0x9)

<7> [147.641423] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:53:pipe A] fastset requirement not met in hdmi infoframe

<7> [147.641792] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] expected:

<7> [147.642171] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] found:

<7> [147.642524] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [147.642529] i915 0000:00:02.0: empty frame

<7> [147.642533] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:53:pipe A] fastset requirement not met, forcing full modeset

<7> [147.642929] i915 0000:00:02.0: [drm:intel_cdclk_atomic_check [i915]] [CRTC:53:pipe A] min cdclk: 0 kHz -> 165334 kHz

<7> [147.643339] i915 0000:00:02.0: [drm:intel_find_dpll [i915]] [CRTC:53:pipe A] allocated PCH DPLL A

<7> [147.643693] i915 0000:00:02.0: [drm:intel_dpll_crtc_get [i915]] [CRTC:53:pipe A] reserving PCH DPLL A

<7> [147.644077] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:53:pipe A] enable: yes [modeset]

<7> [147.644433] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: HDMI (0x40), output format: RGB, sink format: RGB

<7> [147.644789] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: A, pipe bpp: 36, dithering: 0

<7> [147.645169] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>

<7> [147.645522] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0

<7> [147.645876] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0

<7> [147.646285] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0

<7> [147.646655] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fdi: lanes: 3; data_m: 6934582, data_n: 8388608, link_m: 288940, link_n: 524288, tu: 64

<7> [147.647054] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 1, infoframes: 1, infoframes enabled: 0x71

<7> [147.647285] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] GCP: 0x6

<7> [147.647545] i915 0000:00:02.0: HDMI infoframe: Auxiliary Video Information (AVI), version 2, length 13

<7> [147.647548] i915 0000:00:02.0: colorspace: RGB

<7> [147.647550] i915 0000:00:02.0: scan mode: Underscan

<7> [147.647552] i915 0000:00:02.0: colorimetry: No Data

<7> [147.647554] i915 0000:00:02.0: picture aspect: No Data

<7> [147.647556] i915 0000:00:02.0: active aspect: Same as Picture

<7> [147.647557] i915 0000:00:02.0: itc: No Data

<7> [147.647559] i915 0000:00:02.0: extended colorimetry: xvYCC 601

<7> [147.647561] i915 0000:00:02.0: quantization range: Full

<7> [147.647563] i915 0000:00:02.0: nups: Unknown Non-uniform Scaling

<7> [147.647565] i915 0000:00:02.0: video code: 0

<7> [147.647567] i915 0000:00:02.0: ycc quantization range: Full

<7> [147.647569] i915 0000:00:02.0: hdmi content type: Graphics

<7> [147.647571] i915 0000:00:02.0: pixel repeat: 0

<7> [147.647572] i915 0000:00:02.0: bar top 0, bottom 0, left 0, right 0

<7> [147.647575] i915 0000:00:02.0: HDMI infoframe: Source Product Description (SPD), version 1, length 25

<7> [147.647577] i915 0000:00:02.0: vendor: Intel

<7> [147.647579] i915 0000:00:02.0: product: Integrated gfx

<7> [147.647581] i915 0000:00:02.0: source device information: PC General (0x9)

<7> [147.647583] i915 0000:00:02.0: HDMI infoframe: Vendor, version 1, length 4

<7> [147.647585] i915 0000:00:02.0: empty frame

<7> [147.647587] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 10 00 07 00 66 10 00 01 00 00 00 00 00 00 00 00

<7> [147.647817] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ELD: 05 e3 cd 0c 32 38 45 38 35 30 09 07 07 00 00 00

<7> [147.648081] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1

<7> [147.648342] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] framestart delay: 1, MSA timing delay: 0, set context latency: 0

<7> [147.648583] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, fixed rr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0

<7> [147.648818] 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> [147.649362] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0

<7> [147.649600] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9

<7> [147.649837] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "1920x1080": 60 148500 1920 2008 2052 2200 1080 1083 1088 1125 0x48 0x9

<7> [147.650093] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148800, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9

<7> [147.650331] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "1920x1080": 60 148800 1920 2008 2052 2200 1080 1083 1088 1125 0x40 0x9

<7> [147.650567] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=148800, hd=1920 hb=1920-2200 hs=2008-2052 ht=2200, vd=1080 vb=1080-1125 vs=1083-1088 vt=1125, flags=0x9

<7> [147.650803] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 223200, pixel rate 148800, min cdclk 165334, min voltage level 0

<7> [147.651100] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 0, ips linetime: 0

<7> [147.651460] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe src: 1920x1080+0+0

<7> [147.651773] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no

<7> [147.652036] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0

<7> [147.652284] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0

<7> [147.652514] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0xc4010001, dpll_md: 0x0, fp0: 0x30f06, fp1: 0x30f06

<7> [147.652743] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x3 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0

<7> [147.652998] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries

<7> [147.653237] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000

<7> [147.653544] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [147.653912] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [147.654199] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000

<7> [147.654429] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:35:primary A] fb: [FB:88] 1920x1080 format = XR24 little-endian (0x34325258) modifier = 0x100000000000001, visible: yes

<7> [147.654661] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0

<7> [147.654890] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 1920.000000x1080.000000+0.000000+0.000000 dst: 1920x1080+0+0

<7> [147.657352] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling always-on

<7> [147.657599] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:74:CRT]

<7> [147.657826] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:75:HDMI D]

<7> [147.658149] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:83:DP D]

<7> [147.659046] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe A

<7> [147.660106] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x100

<7> [147.660399] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 1 done.

<7> [147.661299] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI_RX_IIR 0x600

<7> [147.661528] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train 2 done.

<7> [147.661795] i915 0000:00:02.0: [drm:gen6_fdi_link_train [i915]] FDI train done.

<7> [147.662163] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enable PCH DPLL A (active 0x1, on? 0) for [CRTC:53:pipe A]

<7> [147.662417] i915 0000:00:02.0: [drm:intel_dpll_enable [i915]] enabling PCH DPLL A

<7> [147.730838] i915 0000:00:02.0: [drm:intel_audio_codec_enable [i915]] [CONNECTOR:76:HDMI-A-1][ENCODER:75:HDMI D] Enable audio codec on [CRTC:53:pipe A], 32 bytes ELD

<7> [147.747465] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] HDMI audio pixel clock setting for 148800 not found, falling back to defaults

<7> [147.747961] i915 0000:00:02.0: [drm:audio_config_hdmi_pixel_clock [i915]] Configuring HDMI audio for pixel clock 25200 (0x00010000)

<7> [147.748503] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:76:HDMI-A-1]

<7> [147.749049] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:53:pipe A]

<6> [154.574902] [IGT] kms_flip: finished subtest A-HDMI-A1, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank@a-hdmi-a1