igt@kms_flip@flip-vs-expired-vblank@a-edp1 on shard-lnl@xe-5065-66af2225d31aa8315b0b9f3c735dba4a53e8d3bf Test details

Detail	Value
Duration	3.26 seconds
Hostname	shard-lnl-7
Igt-Version	IGT-Version: 2.4-g22222b7d9 (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5065-66af2225d31aa8315-debug+ x86_64)
Out	Using IGT_SRANDOM=1778848549 for randomisation Opened device: /dev/dri/card0 Using monotonic timestamps Starting subtest: flip-vs-expired-vblank Starting dynamic subtest: A-eDP1 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa Stack trace: #0 ../lib/igt_core.c:2074 __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-eDP1: FAIL (3.264s)
Err	Starting subtest: flip-vs-expired-vblank Starting dynamic subtest: A-eDP1 [373.742830] (kms_flip:10136) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [373.742909] (kms_flip:10136) CRITICAL: Failed assertion: end - start < 500 Dynamic subtest A-eDP1 failed. ** DEBUG [370.679905] (kms_flip:10136) intel_allocator_simple-DEBUG: <ial: 0x5ea5dbd1c500, fd: 5> objects: 3, reserved_areas: 0 [370.679907] (kms_flip:10136) intel_allocator_simple-DEBUG: <ial: 0x5ea5dbd1c500, fd: 5> objects: 3, reserved_areas: 0 [370.683452] (kms_flip:10136) intel_allocator_simple-DEBUG: Using simple allocator [370.686915] (kms_flip:10136) intel_allocator_simple-DEBUG: <ial: 0x5ea5dbd1f7c0, fd: 5> objects: 3, reserved_areas: 0 [370.686917] (kms_flip:10136) intel_allocator_simple-DEBUG: <ial: 0x5ea5dbd1f7c0, fd: 5> objects: 3, reserved_areas: 0 [370.700106] (kms_flip:10136) intel_allocator_simple-DEBUG: Using simple allocator [370.703086] (kms_flip:10136) intel_allocator_simple-DEBUG: <ial: 0x5ea5dbd1f7c0, fd: 5> objects: 3, reserved_areas: 0 [370.703088] (kms_flip:10136) intel_allocator_simple-DEBUG: <ial: 0x5ea5dbd1f7c0, fd: 5> objects: 3, reserved_areas: 0 [370.704440] (kms_flip:10136) igt_kms-INFO: 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa [370.724551] (kms_flip:10136) DEBUG: No stale events found [371.797517] (kms_flip:10136) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 [371.797788] (kms_flip:10136) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 [371.825336] (kms_flip:10136) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 373.365448 current_received_ts = 373.364624 current_seq = 660 count = 0 seq_step = 1 [371.825395] (kms_flip:10136) DEBUG: Vblank took 48us [371.842138] (kms_flip:10136) DEBUG: name = flip last_ts = 373.365448 last_received_ts = 373.364624 last_seq = 660 current_ts = 373.382111 current_received_ts = 373.381439 current_seq = 661 count = 1 seq_step = 1 [371.842225] (kms_flip:10136) DEBUG: Vblank took 79us [371.858830] (kms_flip:10136) DEBUG: name = flip last_ts = 373.382111 last_received_ts = 373.381439 last_seq = 661 current_ts = 373.398773 current_received_ts = 373.398102 current_seq = 662 count = 2 seq_step = 1 [371.858928] (kms_flip:10136) DEBUG: Vblank took 91us [371.875459] (kms_flip:10136) DEBUG: name = flip last_ts = 373.398773 last_received_ts = 373.398102 last_seq = 662 current_ts = 373.415436 current_received_ts = 373.414734 current_seq = 663 count = 3 seq_step = 1 [371.875576] (kms_flip:10136) DEBUG: Vblank took 108us [371.892234] (kms_flip:10136) DEBUG: name = flip last_ts = 373.415436 last_received_ts = 373.414734 last_seq = 663 current_ts = 373.432098 current_received_ts = 373.431519 current_seq = 664 count = 4 seq_step = 1 [371.892299] (kms_flip:10136) DEBUG: Vblank took 56us [371.908825] (kms_flip:10136) DEBUG: name = flip last_ts = 373.432098 last_received_ts = 373.431519 last_seq = 664 current_ts = 373.448761 current_received_ts = 373.448120 current_seq = 665 count = 5 seq_step = 1 [371.908908] (kms_flip:10136) DEBUG: Vblank took 75us [371.925459] (kms_flip:10136) DEBUG: name = flip last_ts = 373.448761 last_received_ts = 373.448120 last_seq = 665 current_ts = 373.465424 current_received_ts = 373.464752 current_seq = 666 count = 6 seq_step = 1 [371.925557] (kms_flip:10136) DEBUG: Vblank took 90us [371.942100] (kms_flip:10136) DEBUG: name = flip last_ts = 373.465424 last_received_ts = 373.464752 last_seq = 666 current_ts = 373.482086 current_received_ts = 373.481384 current_seq = 667 count = 7 seq_step = 1 [371.942152] (kms_flip:10136) DEBUG: Vblank took 48us [371.958827] (kms_flip:10136) DEBUG: name = flip last_ts = 373.482086 last_received_ts = 373.481384 last_seq = 667 current_ts = 373.498749 current_received_ts = 373.498108 current_seq = 668 count = 8 seq_step = 1 [371.958890] (kms_flip:10136) DEBUG: Vblank took 57us [371.975445] (kms_flip:10136) DEBUG: name = flip last_ts = 373.498749 last_received_ts = 373.498108 last_seq = 668 current_ts = 373.515411 current_received_ts = 373.514740 current_seq = 669 count = 9 seq_step = 1 [371.975561] (kms_flip:10136) DEBUG: Vblank took 109us [371.992083] (kms_flip:10136) DEBUG: name = flip last_ts = 373.515411 last_received_ts = 373.514740 last_seq = 669 current_ts = 373.532074 current_received_ts = 373.531372 current_seq = 670 count = 10 seq_step = 1 [371.992237] (kms_flip:10136) DEBUG: Vblank took 151us [372.008743] (kms_flip:10136) DEBUG: name = flip last_ts = 373.532074 last_received_ts = 373.531372 last_seq = 670 current_ts = 373.548737 current_received_ts = 373.548035 current_seq = 671 count = 11 seq_step = 1 [372.008788] (kms_flip:10136) DEBUG: Vblank took 42us [372.025438] (kms_flip:10136) DEBUG: name = flip last_ts = 373.548737 last_received_ts = 373.548035 last_seq = 671 current_ts = 373.565399 current_received_ts = 373.564728 current_seq = 672 count = 12 seq_step = 1 [372.025541] (kms_flip:10136) DEBUG: Vblank took 95us [372.042172] (kms_flip:10136) DEBUG: name = flip last_ts = 373.565399 last_received_ts = 373.564728 last_seq = 672 current_ts = 373.582062 current_received_ts = 373.581451 current_seq = 673 count = 13 seq_step = 1 [372.042236] (kms_flip:10136) DEBUG: Vblank took 56us [372.058815] (kms_flip:10136) DEBUG: name = flip last_ts = 373.582062 last_received_ts = 373.581451 last_seq = 673 current_ts = 373.598724 current_received_ts = 373.598083 current_seq = 674 count = 14 seq_step = 1 [372.058883] (kms_flip:10136) DEBUG: Vblank took 60us [372.075528] (kms_flip:10136) DEBUG: name = flip last_ts = 373.598724 last_received_ts = 373.598083 last_seq = 674 current_ts = 373.615387 current_received_ts = 373.614807 current_seq = 675 count = 15 seq_step = 1 [372.075587] (kms_flip:10136) DEBUG: Vblank took 51us [372.092142] (kms_flip:10136) DEBUG: name = flip last_ts = 373.615387 last_received_ts = 373.614807 last_seq = 675 current_ts = 373.632050 current_received_ts = 373.631409 current_seq = 676 count = 16 seq_step = 1 [372.092247] (kms_flip:10136) DEBUG: Vblank took 97us [372.108820] (kms_flip:10136) DEBUG: name = flip last_ts = 373.632050 last_received_ts = 373.631409 last_seq = 676 current_ts = 373.648712 current_received_ts = 373.648102 current_seq = 677 count = 17 seq_step = 1 [372.108885] (kms_flip:10136) DEBUG: Vblank took 57us [372.125516] (kms_flip:10136) DEBUG: name = flip last_ts = 373.648712 last_received_ts = 373.648102 last_seq = 677 current_ts = 373.665375 current_received_ts = 373.664795 current_seq = 678 count = 18 seq_step = 1 [372.125574] (kms_flip:10136) DEBUG: Vblank took 51us [372.142103] (kms_flip:10136) DEBUG: name = flip last_ts = 373.665375 last_received_ts = 373.664795 last_seq = 678 current_ts = 373.682037 current_received_ts = 373.681366 current_seq = 679 count = 19 seq_step = 1 [372.142186] (kms_flip:10136) DEBUG: Vblank took 75us [372.158761] (kms_flip:10136) DEBUG: name = flip last_ts = 373.682037 last_received_ts = 373.681366 last_seq = 679 current_ts = 373.698700 current_received_ts = 373.698029 current_seq = 680 count = 20 seq_step = 1 [372.158878] (kms_flip:10136) DEBUG: Vblank took 111us [372.175404] (kms_flip:10136) DEBUG: name = flip last_ts = 373.698700 last_received_ts = 373.698029 last_seq = 680 current_ts = 373.715363 current_received_ts = 373.714691 current_seq = 681 count = 21 seq_step = 1 [372.175460] (kms_flip:10136) DEBUG: Vblank took 52us [372.191996] (kms_flip:10136) DEBUG: name = flip last_ts = 373.715363 last_received_ts = 373.714691 last_seq = 681 current_ts = 373.732025 current_received_ts = 373.731262 current_seq = 682 count = 22 seq_step = 1 [372.192047] (kms_flip:10136) DEBUG: Vblank took 47us [372.208799] (kms_flip:10136) DEBUG: name = flip last_ts = 373.732025 last_received_ts = 373.731262 last_seq = 682 current_ts = 373.748688 current_received_ts = 373.748077 current_seq = 683 count = 23 seq_step = 1 [372.208902] (kms_flip:10136) DEBUG: Vblank took 94us [372.225433] (kms_flip:10136) DEBUG: name = flip last_ts = 373.748688 last_received_ts = 373.748077 last_seq = 683 current_ts = 373.765350 current_received_ts = 373.764709 current_seq = 684 count = 24 seq_step = 1 [372.225545] (kms_flip:10136) DEBUG: Vblank took 103us [372.241996] (kms_flip:10136) DEBUG: name = flip last_ts = 373.765350 last_received_ts = 373.764709 last_seq = 684 current_ts = 373.782013 current_received_ts = 373.781281 current_seq = 685 count = 25 seq_step = 1 [372.242116] (kms_flip:10136) DEBUG: Vblank took 116us [372.258798] (kms_flip:10136) DEBUG: name = flip last_ts = 373.782013 last_received_ts = 373.781281 last_seq = 685 current_ts = 373.798706 current_received_ts = 373.798065 current_seq = 686 count = 26 seq_step = 1 [372.258897] (kms_flip:10136) DEBUG: Vblank took 90us [372.275476] (kms_flip:10136) DEBUG: name = flip last_ts = 373.798706 last_received_ts = 373.798065 last_seq = 686 current_ts = 373.815369 current_received_ts = 373.814758 current_seq = 687 count = 27 seq_step = 1 [372.275537] (kms_flip:10136) DEBUG: Vblank took 53us [372.292074] (kms_flip:10136) DEBUG: name = flip last_ts = 373.815369 last_received_ts = 373.814758 last_seq = 687 current_ts = 373.832001 current_received_ts = 373.831329 current_seq = 688 count = 28 seq_step = 1 [372.292162] (kms_flip:10136) DEBUG: Vblank took 80us [372.308801] (kms_flip:10136) DEBUG: name = flip last_ts = 373.832001 last_received_ts = 373.831329 last_seq = 688 current_ts = 373.848663 current_received_ts = 373.848053 current_seq = 689 count = 29 seq_step = 1 [372.308882] (kms_flip:10136) DEBUG: Vblank took 73us [372.325395] (kms_flip:10136) DEBUG: name = flip last_ts = 373.848663 last_received_ts = 373.848053 last_seq = 689 current_ts = 373.865356 current_received_ts = 373.864655 current_seq = 690 count = 30 seq_step = 1 [372.325507] (kms_flip:10136) DEBUG: Vblank took 104us [372.341981] (kms_flip:10136) DEBUG: name = flip last_ts = 373.865356 last_received_ts = 373.864655 last_seq = 690 current_ts = 373.881989 current_received_ts = 373.881256 current_seq = 691 count = 31 seq_step = 1 [372.342030] (kms_flip:10136) DEBUG: Vblank took 45us [372.358748] (kms_flip:10136) DEBUG: name = flip last_ts = 373.881989 last_received_ts = 373.881256 last_seq = 691 current_ts = 373.898682 current_received_ts = 373.897980 current_seq = 692 count = 32 seq_step = 1 [372.358853] (kms_flip:10136) DEBUG: Vblank took 96us [372.375378] (kms_flip:10136) DEBUG: name = flip last_ts = 373.898682 last_received_ts = 373.897980 last_seq = 692 current_ts = 373.915344 current_received_ts = 373.914642 current_seq = 693 count = 33 seq_step = 1 [372.375490] (kms_flip:10136) DEBUG: Vblank took 104us [372.392006] (kms_flip:10136) DEBUG: name = flip last_ts = 373.915344 last_received_ts = 373.914642 last_seq = 693 current_ts = 373.931976 current_received_ts = 373.931274 current_seq = 694 count = 34 seq_step = 1 [372.392112] (kms_flip:10136) DEBUG: Vblank took 102us [372.408760] (kms_flip:10136) DEBUG: name = flip last_ts = 373.931976 last_received_ts = 373.931274 last_seq = 694 current_ts = 373.948669 current_received_ts = 373.947998 current_seq = 695 count = 35 seq_step = 1 [372.408824] (kms_flip:10136) DEBUG: Vblank took 57us [372.425377] (kms_flip:10136) DEBUG: name = flip last_ts = 373.948669 last_received_ts = 373.947998 last_seq = 695 current_ts = 373.965332 current_received_ts = 373.964630 current_seq = 696 count = 36 seq_step = 1 [372.425483] (kms_flip:10136) DEBUG: Vblank took 99us [372.442015] (kms_flip:10136) DEBUG: name = flip last_ts = 373.965332 last_received_ts = 373.964630 last_seq = 696 current_ts = 373.981995 current_received_ts = 373.981293 current_seq = 697 count = 37 seq_step = 1 [372.442138] (kms_flip:10136) DEBUG: Vblank took 120us [372.458754] (kms_flip:10136) DEBUG: name = flip last_ts = 373.981995 last_received_ts = 373.981293 last_seq = 697 current_ts = 373.998657 current_received_ts = 373.997986 current_seq = 698 count = 38 seq_step = 1 [372.458822] (kms_flip:10136) DEBUG: Vblank took 60us [372.475366] (kms_flip:10136) DEBUG: name = flip last_ts = 373.998657 last_received_ts = 373.997986 last_seq = 698 current_ts = 374.015320 current_received_ts = 374.014618 current_seq = 699 count = 39 seq_step = 1 [372.475469] (kms_flip:10136) DEBUG: Vblank took 95us [372.491927] (kms_flip:10136) DEBUG: name = flip last_ts = 374.015320 last_received_ts = 374.014618 last_seq = 699 current_ts = 374.031982 current_received_ts = 374.031189 current_seq = 700 count = 40 seq_step = 1 [372.491975] (kms_flip:10136) DEBUG: Vblank took 46us [372.508674] (kms_flip:10136) DEBUG: name = flip last_ts = 374.031982 last_received_ts = 374.031189 last_seq = 700 current_ts = 374.048645 current_received_ts = 374.047943 current_seq = 701 count = 41 seq_step = 1 [372.508718] (kms_flip:10136) DEBUG: Vblank took 41us [372.525332] (kms_flip:10136) DEBUG: name = flip last_ts = 374.048645 last_received_ts = 374.047943 last_seq = 701 current_ts = 374.065308 current_received_ts = 374.064606 current_seq = 702 count = 42 seq_step = 1 [372.525373] (kms_flip:10136) DEBUG: Vblank took 38us [372.542118] (kms_flip:10136) DEBUG: name = flip last_ts = 374.065308 last_received_ts = 374.064606 last_seq = 702 current_ts = 374.081970 current_received_ts = 374.081360 current_seq = 703 count = 43 seq_step = 1 [372.542178] (kms_flip:10136) DEBUG: Vblank took 53us [372.558754] (kms_flip:10136) DEBUG: name = flip last_ts = 374.081970 last_received_ts = 374.081360 last_seq = 703 current_ts = 374.098633 current_received_ts = 374.097992 current_seq = 704 count = 44 seq_step = 1 [372.558817] (kms_flip:10136) DEBUG: Vblank took 54us [372.575359] (kms_flip:10136) DEBUG: name = flip last_ts = 374.098633 last_received_ts = 374.097992 last_seq = 704 current_ts = 374.115295 current_received_ts = 374.114624 current_seq = 705 count = 45 seq_step = 1 [372.575448] (kms_flip:10136) DEBUG: Vblank took 80us [372.591946] (kms_flip:10136) DEBUG: name = flip last_ts = 374.115295 last_received_ts = 374.114624 last_seq = 705 current_ts = 374.131958 current_received_ts = 374.131195 current_seq = 706 count = 46 seq_step = 1 [372.592063] (kms_flip:10136) DEBUG: Vblank took 114us [372.608770] (kms_flip:10136) DEBUG: name = flip last_ts = 374.131958 last_received_ts = 374.131195 last_seq = 706 current_ts = 374.148621 current_received_ts = 374.148010 current_seq = 707 count = 47 seq_step = 1 [372.608831] (kms_flip:10136) DEBUG: Vblank took 53us [372.625373] (kms_flip:10136) DEBUG: name = flip last_ts = 374.148621 last_received_ts = 374.148010 last_seq = 707 current_ts = 374.165283 current_received_ts = 374.164612 current_seq = 708 count = 48 seq_step = 1 [372.625474] (kms_flip:10136) DEBUG: Vblank took 93us [372.641983] (kms_flip:10136) DEBUG: name = flip last_ts = 374.165283 last_received_ts = 374.164612 last_seq = 708 current_ts = 374.181946 current_received_ts = 374.181244 current_seq = 709 count = 49 seq_step = 1 [372.642095] (kms_flip:10136) DEBUG: Vblank took 109us [372.658669] (kms_flip:10136) DEBUG: name = flip last_ts = 374.181946 last_received_ts = 374.181244 last_seq = 709 current_ts = 374.198608 current_received_ts = 374.197937 current_seq = 710 count = 50 seq_step = 1 [372.658788] (kms_flip:10136) DEBUG: Vblank took 116us [372.675329] (kms_flip:10136) DEBUG: name = flip last_ts = 374.198608 last_received_ts = 374.197937 last_seq = 710 current_ts = 374.215271 current_received_ts = 374.214600 current_seq = 711 count = 51 seq_step = 1 [372.675375] (kms_flip:10136) DEBUG: Vblank took 43us [372.692078] (kms_flip:10136) DEBUG: name = flip last_ts = 374.215271 last_received_ts = 374.214600 last_seq = 711 current_ts = 374.231934 current_received_ts = 374.231323 current_seq = 712 count = 52 seq_step = 1 [372.692136] (kms_flip:10136) DEBUG: Vblank took 51us [372.708731] (kms_flip:10136) DEBUG: name = flip last_ts = 374.231934 last_received_ts = 374.231323 last_seq = 712 current_ts = 374.248596 current_received_ts = 374.247986 current_seq = 713 count = 53 seq_step = 1 [372.708809] (kms_flip:10136) DEBUG: Vblank took 71us [372.725330] (kms_flip:10136) DEBUG: name = flip last_ts = 374.248596 last_received_ts = 374.247986 last_seq = 713 current_ts = 374.265259 current_received_ts = 374.264587 current_seq = 714 count = 54 seq_step = 1 [372.725424] (kms_flip:10136) DEBUG: Vblank took 87us [372.742045] (kms_flip:10136) DEBUG: name = flip last_ts = 374.265259 last_received_ts = 374.264587 last_seq = 714 current_ts = 374.281921 current_received_ts = 374.281281 current_seq = 715 count = 55 seq_step = 1 [372.742117] (kms_flip:10136) DEBUG: Vblank took 62us [372.758736] (kms_flip:10136) DEBUG: name = flip last_ts = 374.281921 last_received_ts = 374.281281 last_seq = 715 current_ts = 374.298584 current_received_ts = 374.297974 current_seq = 716 count = 56 seq_step = 1 [372.758814] (kms_flip:10136) DEBUG: Vblank took 51us [372.775330] (kms_flip:10136) DEBUG: name = flip last_ts = 374.298584 last_received_ts = 374.297974 last_seq = 716 current_ts = 374.315247 current_received_ts = 374.314575 current_seq = 717 count = 57 seq_step = 1 [372.775439] (kms_flip:10136) DEBUG: Vblank took 102us [372.791968] (kms_flip:10136) DEBUG: name = flip last_ts = 374.315247 last_received_ts = 374.314575 last_seq = 717 current_ts = 374.331909 current_received_ts = 374.331207 current_seq = 718 count = 58 seq_step = 1 [372.792021] (kms_flip:10136) DEBUG: Vblank took 50us [372.808695] (kms_flip:10136) DEBUG: name = flip last_ts = 374.331909 last_received_ts = 374.331207 last_seq = 718 current_ts = 374.348572 current_received_ts = 374.347931 current_seq = 719 count = 59 seq_step = 1 [372.808816] (kms_flip:10136) DEBUG: Vblank took 114us [372.825439] (kms_flip:10136) DEBUG: name = flip last_ts = 374.348572 last_received_ts = 374.347931 last_seq = 719 current_ts = 374.365234 current_received_ts = 374.364685 current_seq = 720 count = 60 seq_step = 1 [372.825529] (kms_flip:10136) DEBUG: Vblank took 80us [372.841986] (kms_flip:10136) DEBUG: name = flip last_ts = 374.365234 last_received_ts = 374.364685 last_seq = 720 current_ts = 374.381897 current_received_ts = 374.381226 current_seq = 721 count = 61 seq_step = 1 [372.842100] (kms_flip:10136) DEBUG: Vblank took 105us [372.858690] (kms_flip:10136) DEBUG: name = flip last_ts = 374.381897 last_received_ts = 374.381226 last_seq = 721 current_ts = 374.398560 current_received_ts = 374.397919 current_seq = 722 count = 62 seq_step = 1 [372.858771] (kms_flip:10136) DEBUG: Vblank took 74us [372.875321] (kms_flip:10136) DEBUG: name = flip last_ts = 374.398560 last_received_ts = 374.397919 last_seq = 722 current_ts = 374.415222 current_received_ts = 374.414551 current_seq = 723 count = 63 seq_step = 1 [372.875418] (kms_flip:10136) DEBUG: Vblank took 90us [372.891945] (kms_flip:10136) DEBUG: name = flip last_ts = 374.415222 last_received_ts = 374.414551 last_seq = 723 current_ts = 374.431885 current_received_ts = 374.431183 current_seq = 724 count = 64 seq_step = 1 [372.892053] (kms_flip:10136) DEBUG: Vblank took 105us [372.908674] (kms_flip:10136) DEBUG: name = flip last_ts = 374.431885 last_received_ts = 374.431183 last_seq = 724 current_ts = 374.448547 current_received_ts = 374.447906 current_seq = 725 count = 65 seq_step = 1 [372.908738] (kms_flip:10136) DEBUG: Vblank took 56us [372.925316] (kms_flip:10136) DEBUG: name = flip last_ts = 374.448547 last_received_ts = 374.447906 last_seq = 725 current_ts = 374.465210 current_received_ts = 374.464569 current_seq = 726 count = 66 seq_step = 1 [372.925410] (kms_flip:10136) DEBUG: Vblank took 86us [372.942057] (kms_flip:10136) DEBUG: name = flip last_ts = 374.465210 last_received_ts = 374.464569 last_seq = 726 current_ts = 374.481873 current_received_ts = 374.481293 current_seq = 727 count = 67 seq_step = 1 [372.942118] (kms_flip:10136) DEBUG: Vblank took 54us [372.958691] (kms_flip:10136) DEBUG: name = flip last_ts = 374.481873 last_received_ts = 374.481293 last_seq = 727 current_ts = 374.498535 current_received_ts = 374.497925 current_seq = 728 count = 68 seq_step = 1 [372.958770] (kms_flip:10136) DEBUG: Vblank took 52us [372.975287] (kms_flip:10136) DEBUG: name = flip last_ts = 374.498535 last_received_ts = 374.497925 last_seq = 728 current_ts = 374.515198 current_received_ts = 374.514526 current_seq = 729 count = 69 seq_step = 1 [372.975390] (kms_flip:10136) DEBUG: Vblank took 96us [372.991997] (kms_flip:10136) DEBUG: name = flip last_ts = 374.515198 last_received_ts = 374.514526 last_seq = 729 current_ts = 374.531860 current_received_ts = 374.531250 current_seq = 730 count = 70 seq_step = 1 [372.992056] (kms_flip:10136) DEBUG: Vblank took 52us [373.008621] (kms_flip:10136) DEBUG: name = flip last_ts = 374.531860 last_received_ts = 374.531250 last_seq = 730 current_ts = 374.548523 current_received_ts = 374.547852 current_seq = 731 count = 71 seq_step = 1 [373.008718] (kms_flip:10136) DEBUG: Vblank took 90us [373.025371] (kms_flip:10136) DEBUG: name = flip last_ts = 374.548523 last_received_ts = 374.547852 last_seq = 731 current_ts = 374.565216 current_received_ts = 374.564606 current_seq = 732 count = 72 seq_step = 1 [373.025430] (kms_flip:10136) DEBUG: Vblank took 51us [373.042034] (kms_flip:10136) DEBUG: name = flip last_ts = 374.565216 last_received_ts = 374.564606 last_seq = 732 current_ts = 374.581848 current_received_ts = 374.581268 current_seq = 733 count = 73 seq_step = 1 [373.042093] (kms_flip:10136) DEBUG: Vblank took 52us [373.058712] (kms_flip:10136) DEBUG: name = flip last_ts = 374.581848 last_received_ts = 374.581268 last_seq = 733 current_ts = 374.598541 current_received_ts = 374.597961 current_seq = 734 count = 74 seq_step = 1 [373.058795] (kms_flip:10136) DEBUG: Vblank took 75us [373.075289] (kms_flip:10136) DEBUG: name = flip last_ts = 374.598541 last_received_ts = 374.597961 last_seq = 734 current_ts = 374.615173 current_received_ts = 374.614532 current_seq = 735 count = 75 seq_step = 1 [373.075416] (kms_flip:10136) DEBUG: Vblank took 120us [373.092022] (kms_flip:10136) DEBUG: name = flip last_ts = 374.615173 last_received_ts = 374.614532 last_seq = 735 current_ts = 374.631836 current_received_ts = 374.631256 current_seq = 736 count = 76 seq_step = 1 [373.092088] (kms_flip:10136) DEBUG: Vblank took 56us [373.108720] (kms_flip:10136) DEBUG: name = flip last_ts = 374.631836 last_received_ts = 374.631256 last_seq = 736 current_ts = 374.648529 current_received_ts = 374.647949 current_seq = 737 count = 77 seq_step = 1 [373.108804] (kms_flip:10136) DEBUG: Vblank took 75us [373.125268] (kms_flip:10136) DEBUG: name = flip last_ts = 374.648529 last_received_ts = 374.647949 last_seq = 737 current_ts = 374.665192 current_received_ts = 374.664490 current_seq = 738 count = 78 seq_step = 1 [373.125384] (kms_flip:10136) DEBUG: Vblank took 108us [373.142008] (kms_flip:10136) DEBUG: name = flip last_ts = 374.665192 last_received_ts = 374.664490 last_seq = 738 current_ts = 374.681824 current_received_ts = 374.681244 current_seq = 739 count = 79 seq_step = 1 [373.142067] (kms_flip:10136) DEBUG: Vblank took 51us [373.158729] (kms_flip:10136) DEBUG: name = flip last_ts = 374.681824 last_received_ts = 374.681244 last_seq = 739 current_ts = 374.698517 current_received_ts = 374.697968 current_seq = 740 count = 80 seq_step = 1 [373.158808] (kms_flip:10136) DEBUG: Vblank took 72us [373.175266] (kms_flip:10136) DEBUG: name = flip last_ts = 374.698517 last_received_ts = 374.697968 last_seq = 740 current_ts = 374.715179 current_received_ts = 374.714508 current_seq = 741 count = 81 seq_step = 1 [373.175366] (kms_flip:10136) DEBUG: Vblank took 93us [373.191943] (kms_flip:10136) DEBUG: name = flip last_ts = 374.715179 last_received_ts = 374.714508 last_seq = 741 current_ts = 374.731842 current_received_ts = 374.731171 current_seq = 742 count = 82 seq_step = 1 [373.192011] (kms_flip:10136) DEBUG: Vblank took 59us [373.208587] (kms_flip:10136) DEBUG: name = flip last_ts = 374.731842 last_received_ts = 374.731171 last_seq = 742 current_ts = 374.748505 current_received_ts = 374.747803 current_seq = 743 count = 83 seq_step = 1 [373.208703] (kms_flip:10136) DEBUG: Vblank took 109us [373.225254] (kms_flip:10136) DEBUG: name = flip last_ts = 374.748505 last_received_ts = 374.747803 last_seq = 743 current_ts = 374.765167 current_received_ts = 374.764496 current_seq = 744 count = 84 seq_step = 1 [373.225365] (kms_flip:10136) DEBUG: Vblank took 103us [373.241955] (kms_flip:10136) DEBUG: name = flip last_ts = 374.765167 last_received_ts = 374.764496 last_seq = 744 current_ts = 374.781830 current_received_ts = 374.781189 current_seq = 745 count = 85 seq_step = 1 [373.242030] (kms_flip:10136) DEBUG: Vblank took 66us [373.258698] (kms_flip:10136) DEBUG: name = flip last_ts = 374.781830 last_received_ts = 374.781189 last_seq = 745 current_ts = 374.798492 current_received_ts = 374.797913 current_seq = 746 count = 86 seq_step = 1 [373.258760] (kms_flip:10136) DEBUG: Vblank took 54us [373.275246] (kms_flip:10136) DEBUG: name = flip last_ts = 374.798492 last_received_ts = 374.797913 last_seq = 746 current_ts = 374.815155 current_received_ts = 374.814484 current_seq = 747 count = 87 seq_step = 1 [373.275355] (kms_flip:10136) DEBUG: Vblank took 102us [373.291974] (kms_flip:10136) DEBUG: name = flip last_ts = 374.815155 last_received_ts = 374.814484 last_seq = 747 current_ts = 374.831818 current_received_ts = 374.831207 current_seq = 748 count = 88 seq_step = 1 [373.292040] (kms_flip:10136) DEBUG: Vblank took 57us [373.308687] (kms_flip:10136) DEBUG: name = flip last_ts = 374.831818 last_received_ts = 374.831207 last_seq = 748 current_ts = 374.848480 current_received_ts = 374.847900 current_seq = 749 count = 89 seq_step = 1 [373.308748] (kms_flip:10136) DEBUG: Vblank took 54us [373.325247] (kms_flip:10136) DEBUG: name = flip last_ts = 374.848480 last_received_ts = 374.847900 last_seq = 749 current_ts = 374.865143 current_received_ts = 374.864471 current_seq = 750 count = 90 seq_step = 1 [373.325336] (kms_flip:10136) DEBUG: Vblank took 83us [373.341943] (kms_flip:10136) DEBUG: name = flip last_ts = 374.865143 last_received_ts = 374.864471 last_seq = 750 current_ts = 374.881805 current_received_ts = 374.881165 current_seq = 751 count = 91 seq_step = 1 [373.342014] (kms_flip:10136) DEBUG: Vblank took 62us [373.358659] (kms_flip:10136) DEBUG: name = flip last_ts = 374.881805 last_received_ts = 374.881165 last_seq = 751 current_ts = 374.898468 current_received_ts = 374.897888 current_seq = 752 count = 92 seq_step = 1 [373.358727] (kms_flip:10136) DEBUG: Vblank took 60us [373.375215] (kms_flip:10136) DEBUG: name = flip last_ts = 374.898468 last_received_ts = 374.897888 last_seq = 752 current_ts = 374.915131 current_received_ts = 374.914429 current_seq = 753 count = 93 seq_step = 1 [373.375328] (kms_flip:10136) DEBUG: Vblank took 106us [373.391950] (kms_flip:10136) DEBUG: name = flip last_ts = 374.915131 last_received_ts = 374.914429 last_seq = 753 current_ts = 374.931793 current_received_ts = 374.931183 current_seq = 754 count = 94 seq_step = 1 [373.392010] (kms_flip:10136) DEBUG: Vblank took 52us [373.408641] (kms_flip:10136) DEBUG: name = flip last_ts = 374.931793 last_received_ts = 374.931183 last_seq = 754 current_ts = 374.948456 current_received_ts = 374.947845 current_seq = 755 count = 95 seq_step = 1 [373.408706] (kms_flip:10136) DEBUG: Vblank took 58us [373.425211] (kms_flip:10136) DEBUG: name = flip last_ts = 374.948456 last_received_ts = 374.947845 last_seq = 755 current_ts = 374.965118 current_received_ts = 374.964417 current_seq = 756 count = 96 seq_step = 1 [373.425310] (kms_flip:10136) DEBUG: Vblank took 92us [373.441960] (kms_flip:10136) DEBUG: name = flip last_ts = 374.965118 last_received_ts = 374.964417 last_seq = 756 current_ts = 374.981781 current_received_ts = 374.981171 current_seq = 757 count = 97 seq_step = 1 [373.442022] (kms_flip:10136) DEBUG: Vblank took 55us [373.458641] (kms_flip:10136) DEBUG: name = flip last_ts = 374.981781 last_received_ts = 374.981171 last_seq = 757 current_ts = 374.998444 current_received_ts = 374.997864 current_seq = 758 count = 98 seq_step = 1 [373.458702] (kms_flip:10136) DEBUG: Vblank took 54us [373.475210] (kms_flip:10136) DEBUG: name = flip last_ts = 374.998444 last_received_ts = 374.997864 last_seq = 758 current_ts = 375.015106 current_received_ts = 375.014435 current_seq = 759 count = 99 seq_step = 1 [373.475322] (kms_flip:10136) DEBUG: Vblank took 104us [373.491933] (kms_flip:10136) DEBUG: name = flip last_ts = 375.015106 last_received_ts = 375.014435 last_seq = 759 current_ts = 375.031769 current_received_ts = 375.031158 current_seq = 760 count = 100 seq_step = 1 [373.492000] (kms_flip:10136) DEBUG: Vblank took 58us [373.508585] (kms_flip:10136) DEBUG: name = flip last_ts = 375.031769 last_received_ts = 375.031158 last_seq = 760 current_ts = 375.048431 current_received_ts = 375.047791 current_seq = 761 count = 101 seq_step = 1 [373.508697] (kms_flip:10136) DEBUG: Vblank took 102us [373.525197] (kms_flip:10136) DEBUG: name = flip last_ts = 375.048431 last_received_ts = 375.047791 last_seq = 761 current_ts = 375.065094 current_received_ts = 375.064423 current_seq = 762 count = 102 seq_step = 1 [373.525254] (kms_flip:10136) DEBUG: Vblank took 53us [373.541919] (kms_flip:10136) DEBUG: name = flip last_ts = 375.065094 last_received_ts = 375.064423 last_seq = 762 current_ts = 375.081757 current_received_ts = 375.081146 current_seq = 763 count = 103 seq_step = 1 [373.541982] (kms_flip:10136) DEBUG: Vblank took 54us [373.558640] (kms_flip:10136) DEBUG: name = flip last_ts = 375.081757 last_received_ts = 375.081146 last_seq = 763 current_ts = 375.098419 current_received_ts = 375.097839 current_seq = 764 count = 104 seq_step = 1 [373.558701] (kms_flip:10136) DEBUG: Vblank took 54us [373.575190] (kms_flip:10136) DEBUG: name = flip last_ts = 375.098419 last_received_ts = 375.097839 last_seq = 764 current_ts = 375.115082 current_received_ts = 375.114410 current_seq = 765 count = 105 seq_step = 1 [373.575303] (kms_flip:10136) DEBUG: Vblank took 106us [373.591892] (kms_flip:10136) DEBUG: name = flip last_ts = 375.115082 last_received_ts = 375.114410 last_seq = 765 current_ts = 375.131744 current_received_ts = 375.131104 current_seq = 766 count = 106 seq_step = 1 [373.591978] (kms_flip:10136) DEBUG: Vblank took 78us [373.608533] (kms_flip:10136) DEBUG: name = flip last_ts = 375.131744 last_received_ts = 375.131104 last_seq = 766 current_ts = 375.148407 current_received_ts = 375.147736 current_seq = 767 count = 107 seq_step = 1 [373.608636] (kms_flip:10136) DEBUG: Vblank took 95us [373.625194] (kms_flip:10136) DEBUG: name = flip last_ts = 375.148407 last_received_ts = 375.147736 last_seq = 767 current_ts = 375.165070 current_received_ts = 375.164398 current_seq = 768 count = 108 seq_step = 1 [373.625314] (kms_flip:10136) DEBUG: Vblank took 112us [373.641900] (kms_flip:10136) DEBUG: name = flip last_ts = 375.165070 last_received_ts = 375.164398 last_seq = 768 current_ts = 375.181732 current_received_ts = 375.181122 current_seq = 769 count = 109 seq_step = 1 [373.641993] (kms_flip:10136) DEBUG: Vblank took 84us [373.658515] (kms_flip:10136) DEBUG: name = flip last_ts = 375.181732 last_received_ts = 375.181122 last_seq = 769 current_ts = 375.198395 current_received_ts = 375.197723 current_seq = 770 count = 110 seq_step = 1 [373.658626] (kms_flip:10136) DEBUG: Vblank took 105us [373.675183] (kms_flip:10136) DEBUG: name = flip last_ts = 375.198395 last_received_ts = 375.197723 last_seq = 770 current_ts = 375.215057 current_received_ts = 375.214386 current_seq = 771 count = 111 seq_step = 1 [373.675320] (kms_flip:10136) DEBUG: Vblank took 130us [373.691896] (kms_flip:10136) DEBUG: name = flip last_ts = 375.215057 last_received_ts = 375.214386 last_seq = 771 current_ts = 375.231720 current_received_ts = 375.231110 current_seq = 772 count = 112 seq_step = 1 [373.691972] (kms_flip:10136) DEBUG: Vblank took 68us [373.708618] (kms_flip:10136) DEBUG: name = flip last_ts = 375.231720 last_received_ts = 375.231110 last_seq = 772 current_ts = 375.248383 current_received_ts = 375.247833 current_seq = 773 count = 113 seq_step = 1 [373.708692] (kms_flip:10136) DEBUG: Vblank took 65us [373.725212] (kms_flip:10136) DEBUG: name = flip last_ts = 375.248383 last_received_ts = 375.247833 last_seq = 773 current_ts = 375.265045 current_received_ts = 375.264404 current_seq = 774 count = 114 seq_step = 1 [373.725318] (kms_flip:10136) DEBUG: Vblank took 96us [373.741871] (kms_flip:10136) DEBUG: name = flip last_ts = 375.265045 last_received_ts = 375.264404 last_seq = 774 current_ts = 375.281708 current_received_ts = 375.281067 current_seq = 775 count = 115 seq_step = 1 [373.742824] (kms_flip:10136) DEBUG: Vblank took 944us [373.742830] (kms_flip:10136) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [373.742909] (kms_flip:10136) CRITICAL: Failed assertion: end - start < 500 [373.756654] (kms_flip:10136) igt_core-INFO: Stack trace: [373.769135] (kms_flip:10136) igt_core-INFO: #0 ../lib/igt_core.c:2074 __igt_fail_assert() [373.770475] (kms_flip:10136) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [373.770575] (kms_flip:10136) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [373.770617] (kms_flip:10136) igt_core-INFO: #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105() [373.770662] (kms_flip:10136) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [373.774882] (kms_flip:10136) igt_core-INFO: #5 [__libc_init_first+0x8a] [373.775813] (kms_flip:10136) igt_core-INFO: #6 [__libc_start_main+0x8b] [373.776048] (kms_flip:10136) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest A-eDP1: FAIL (3.264s)
Dmesg	<6> [417.311004] Console: switching to colour dummy device 80x25 <6> [417.311324] [IGT] kms_flip: executing <7> [417.318159] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [417.318169] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [417.318325] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [417.318533] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [417.318536] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [417.318655] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [417.318949] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [417.318953] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [417.319101] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <7> [417.319310] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] <7> [417.319313] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:393:eDP-1] <7> [417.320292] xe 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [xe]] DSC DPCD: 00 11 00 76 0b 01 01 80 00 01 06 66 08 00 00 00 <7> [417.320626] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000 <7> [417.320832] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] sink rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [417.321011] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000 <7> [417.321203] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Supported Monitor Refresh rate range is 40 Hz - 120 Hz <5> [417.321211] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [417.321215] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [417.321217] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] DisplayID extension version 0x13, primary use 0x00 <7> [417.321221] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc. <5> [417.321225] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [417.321228] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD monitor <5> [417.321233] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [417.321235] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD size 20, SAD count 0 <5> [417.321239] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [417.321259] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] VRR capable: yes <7> [417.321443] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps <7> [417.321602] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no <5> [417.321971] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [417.321974] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <5> [417.321975] [drm] DisplayID checksum invalid, remainder is 248 (ignoring) <7> [417.322030] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] probed modes: <7> [417.322035] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [417.322039] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 120 695310 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [417.322056] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] <7> [417.322061] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1] <7> [417.322235] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected <7> [417.322247] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] <7> [417.322250] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2] <7> [417.322400] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected <7> [417.322411] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] <7> [417.322415] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3] <7> [417.322564] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected <6> [417.323143] [IGT] kms_flip: starting subtest flip-vs-expired-vblank <6> [417.324454] [IGT] kms_flip: starting dynamic subtest A-eDP1 <7> [417.325864] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431] <7> [417.326407] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432] <7> [417.397478] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [417.397680] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected yes, found no) <7> [417.398078] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected yes, found no) <7> [417.398361] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1) <7> [417.398597] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 4, found 0) <7> [417.398795] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0) <7> [417.398976] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000) <7> [417.399146] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0) <7> [417.399313] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0) <7> [417.399480] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0) <7> [417.399640] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0) <7> [417.399814] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0) <7> [417.399967] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0) <7> [417.400116] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0) <7> [417.400263] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0) <7> [417.400407] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0) <7> [417.400547] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0) <7> [417.400688] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0) <7> [417.400879] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0) <7> [417.401013] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0) <7> [417.401143] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0) <7> [417.401272] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0) <7> [417.401400] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0) <7> [417.401527] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0) <7> [417.401651] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0) <7> [417.401788] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0) <7> [417.401910] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0) <7> [417.402032] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0) <7> [417.402152] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0) <7> [417.402269] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0) <7> [417.402382] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0) <7> [417.402495] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0) <7> [417.402605] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0) <7> [417.402718] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0) <7> [417.402823] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0) <7> [417.402928] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0) <7> [417.403031] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0) <7> [417.403130] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0) <7> [417.403226] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0) <7> [417.403326] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [417.403427] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [417.403586] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [417.403661] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0 <7> [417.403776] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0 <7> [417.403864] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0 <7> [417.403952] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm <7> [417.404026] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 1, 13, 13, 13, 13, 13, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [417.404093] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 24, 313, 313, 313, 313, 313, 0, 0, 38, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [417.404159] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 28, 346, 346, 346, 346, 346, 0, 0, 39, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 <7> [417.404246] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0 <7> [417.404347] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400 <7> [417.404445] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400 <7> [417.404549] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [417.404640] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400 <7> [417.404739] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0 <7> [417.404839] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [417.404948] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz <7> [417.405045] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [417.405141] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [417.405225] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [417.405339] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [417.405423] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [417.405506] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [417.405589] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [417.405672] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [417.405775] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [417.405883] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [417.406046] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [417.406766] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [417.406928] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2 <7> [417.407650] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [417.407779] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [417.609886] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [417.610574] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [417.624072] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [417.624437] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time <7> [417.624834] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [417.625174] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [417.625569] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060 <7> [417.677125] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [417.677448] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [417.683850] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [417.684171] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [417.684221] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [417.684665] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [417.685635] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [417.686174] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [417.686687] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [417.687053] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [417.687357] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [417.687682] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [417.687948] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [417.688255] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [417.688516] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [417.688799] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [417.689054] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [417.689344] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [417.689592] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [417.689873] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [417.690122] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [417.690434] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [417.690782] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [417.691030] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [417.691268] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [417.691712] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [417.692056] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000) <7> [417.692475] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [417.692873] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [417.693237] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [417.693486] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [417.694282] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [417.694605] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [417.694918] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [417.694983] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [417.695149] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36) <7> [417.695514] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:151:pipe A] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000 <7> [417.695844] xe 0000:00:02.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000 <7> [417.696157] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [417.696525] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:151:pipe A] <7> [417.696860] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.enable (expected no, found yes) <7> [417.697156] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.active (expected no, found yes) <7> [417.697442] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0) <7> [417.697748] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in lane_count (expected 0, found 4) <7> [417.698064] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288) <7> [417.698322] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [417.698567] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [417.698820] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [417.699084] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [417.699315] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [417.699522] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [417.699738] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [417.699964] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [417.700158] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [417.700337] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [417.700521] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [417.700707] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [417.700877] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [417.701042] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [417.701207] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [417.701385] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [417.701564] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [417.701724] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [417.701872] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [417.702012] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [417.702156] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [417.702314] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [417.702467] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [417.702608] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [417.702762] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [417.702898] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [417.703025] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [417.703151] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [417.703273] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [417.703401] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [417.703526] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [417.703641] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [417.703764] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 0, found 432000) <7> [417.703886] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [417.704041] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [417.704121] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x1 <7> [417.704231] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [417.704309] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [417.704384] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [417.704459] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [417.704534] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [417.704605] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198 <7> [417.704699] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 1390840 num active planes 1 <7> [417.704814] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [417.704917] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [417.705018] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [417.705116] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [417.705210] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [417.705305] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 0 kHz -> 173855 kHz <7> [417.705418] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz <7> [417.705522] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [417.705622] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [417.705733] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [417.705839] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:151:pipe A] allocated DPLL 0 <7> [417.705926] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:151:pipe A] reserving DPLL 0 <7> [417.706012] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: yes [modeset] <7> [417.706102] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [417.706195] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: A, pipe bpp: 30, dithering: 0 <7> [417.706282] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [417.706366] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [417.706453] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [417.706544] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [417.706631] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64 <7> [417.706764] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0 <7> [417.706852] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [417.706938] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [417.707017] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [417.707095] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [417.707179] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [417.707263] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [417.707343] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [417.707422] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [417.707498] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [417.707577] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [417.707652] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [417.707749] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [417.707834] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [417.707916] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97 <7> [417.708001] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906 <7> [417.708087] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0 <7> [417.708165] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [417.708242] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa <7> [417.708317] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [417.708393] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa <7> [417.708468] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa <7> [417.708543] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0 <7> [417.708618] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [417.708701] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0 <7> [417.708783] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [417.708868] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [417.708950] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [417.709032] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [417.709114] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no <7> [417.709196] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [417.709276] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [417.709358] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [417.709438] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [417.709515] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [417.709591] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [417.709674] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [417.709761] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [417.709848] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [417.709932] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [417.710014] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [417.710091] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [417.710166] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [417.710241] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [417.710316] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [417.710391] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [417.710465] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [417.710541] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [417.710617] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [417.710701] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [417.710793] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [417.710887] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [FB:431] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [417.710971] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [417.711054] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [417.711136] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [417.711214] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [417.711287] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [417.711361] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [417.711436] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [417.711823] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_A <7> [417.711997] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xa8000000) <7> [417.712110] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0 <7> [417.712205] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [417.712295] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [417.712380] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [417.712452] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [417.712526] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [417.712612] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [417.712695] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [417.712770] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [417.712844] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [417.712915] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [417.712985] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [417.713050] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [417.713113] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [417.713175] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [417.713236] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [417.713319] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [417.713482] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: ) <7> [417.713555] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [417.713670] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [417.714771] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A] <7> [417.714941] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [417.716961] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [417.717057] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (468 ms remaining) <7> [417.717513] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [417.717590] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [417.717666] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [417.717787] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [418.193861] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x00000000 PP_CONTROL: 0x00000060 <7> [418.204322] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [418.204871] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on <7> [418.205310] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063 <7> [418.241693] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [418.242009] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [418.242286] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [418.242716] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [418.337829] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [418.337811] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [418.337955] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4 <7> [418.419956] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [418.420290] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [418.420561] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b <7> [418.422550] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80 <7> [418.424027] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates <7> [418.424718] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05 <7> [418.425740] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0 <7> [418.427026] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1 <7> [418.428103] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK <7> [418.428506] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4 <7> [418.429918] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful <7> [418.430257] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4 <7> [418.431009] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A <7> [418.431476] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [418.431877] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe A <7> [418.432265] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [418.465028] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [418.466751] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [418.467130] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [420.433759] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [420.434319] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [420.434831] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [420.589910] [IGT] kms_flip: finished subtest A-eDP1, FAIL

Detail

Value

Duration

3.26 seconds

Hostname

shard-lnl-7

Igt-Version

IGT-Version: 2.4-g22222b7d9 (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5065-66af2225d31aa8315-debug+ x86_64)

Out

Using IGT_SRANDOM=1778848549 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Stack trace:
  #0 ../lib/igt_core.c:2074 __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-eDP1: FAIL (3.264s)

Err

Starting subtest: flip-vs-expired-vblank
Starting dynamic subtest: A-eDP1
[373.742830] (kms_flip:10136) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[373.742909] (kms_flip:10136) CRITICAL: Failed assertion: end - start < 500
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
[370.679905] (kms_flip:10136) intel_allocator_simple-DEBUG: <ial: 0x5ea5dbd1c500, fd: 5> objects: 3, reserved_areas: 0
[370.679907] (kms_flip:10136) intel_allocator_simple-DEBUG: <ial: 0x5ea5dbd1c500, fd: 5> objects: 3, reserved_areas: 0
[370.683452] (kms_flip:10136) intel_allocator_simple-DEBUG: Using simple allocator
[370.686915] (kms_flip:10136) intel_allocator_simple-DEBUG: <ial: 0x5ea5dbd1f7c0, fd: 5> objects: 3, reserved_areas: 0
[370.686917] (kms_flip:10136) intel_allocator_simple-DEBUG: <ial: 0x5ea5dbd1f7c0, fd: 5> objects: 3, reserved_areas: 0
[370.700106] (kms_flip:10136) intel_allocator_simple-DEBUG: Using simple allocator
[370.703086] (kms_flip:10136) intel_allocator_simple-DEBUG: <ial: 0x5ea5dbd1f7c0, fd: 5> objects: 3, reserved_areas: 0
[370.703088] (kms_flip:10136) intel_allocator_simple-DEBUG: <ial: 0x5ea5dbd1f7c0, fd: 5> objects: 3, reserved_areas: 0
[370.704440] (kms_flip:10136) igt_kms-INFO:   2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
[370.724551] (kms_flip:10136) DEBUG: No stale events found
[371.797517] (kms_flip:10136) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
[371.797788] (kms_flip:10136) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
[371.825336] (kms_flip:10136) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 373.365448
current_received_ts = 373.364624
current_seq = 660
count = 0
seq_step = 1
[371.825395] (kms_flip:10136) DEBUG: Vblank took 48us
[371.842138] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.365448
last_received_ts = 373.364624
last_seq = 660
current_ts = 373.382111
current_received_ts = 373.381439
current_seq = 661
count = 1
seq_step = 1
[371.842225] (kms_flip:10136) DEBUG: Vblank took 79us
[371.858830] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.382111
last_received_ts = 373.381439
last_seq = 661
current_ts = 373.398773
current_received_ts = 373.398102
current_seq = 662
count = 2
seq_step = 1
[371.858928] (kms_flip:10136) DEBUG: Vblank took 91us
[371.875459] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.398773
last_received_ts = 373.398102
last_seq = 662
current_ts = 373.415436
current_received_ts = 373.414734
current_seq = 663
count = 3
seq_step = 1
[371.875576] (kms_flip:10136) DEBUG: Vblank took 108us
[371.892234] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.415436
last_received_ts = 373.414734
last_seq = 663
current_ts = 373.432098
current_received_ts = 373.431519
current_seq = 664
count = 4
seq_step = 1
[371.892299] (kms_flip:10136) DEBUG: Vblank took 56us
[371.908825] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.432098
last_received_ts = 373.431519
last_seq = 664
current_ts = 373.448761
current_received_ts = 373.448120
current_seq = 665
count = 5
seq_step = 1
[371.908908] (kms_flip:10136) DEBUG: Vblank took 75us
[371.925459] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.448761
last_received_ts = 373.448120
last_seq = 665
current_ts = 373.465424
current_received_ts = 373.464752
current_seq = 666
count = 6
seq_step = 1
[371.925557] (kms_flip:10136) DEBUG: Vblank took 90us
[371.942100] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.465424
last_received_ts = 373.464752
last_seq = 666
current_ts = 373.482086
current_received_ts = 373.481384
current_seq = 667
count = 7
seq_step = 1
[371.942152] (kms_flip:10136) DEBUG: Vblank took 48us
[371.958827] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.482086
last_received_ts = 373.481384
last_seq = 667
current_ts = 373.498749
current_received_ts = 373.498108
current_seq = 668
count = 8
seq_step = 1
[371.958890] (kms_flip:10136) DEBUG: Vblank took 57us
[371.975445] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.498749
last_received_ts = 373.498108
last_seq = 668
current_ts = 373.515411
current_received_ts = 373.514740
current_seq = 669
count = 9
seq_step = 1
[371.975561] (kms_flip:10136) DEBUG: Vblank took 109us
[371.992083] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.515411
last_received_ts = 373.514740
last_seq = 669
current_ts = 373.532074
current_received_ts = 373.531372
current_seq = 670
count = 10
seq_step = 1
[371.992237] (kms_flip:10136) DEBUG: Vblank took 151us
[372.008743] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.532074
last_received_ts = 373.531372
last_seq = 670
current_ts = 373.548737
current_received_ts = 373.548035
current_seq = 671
count = 11
seq_step = 1
[372.008788] (kms_flip:10136) DEBUG: Vblank took 42us
[372.025438] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.548737
last_received_ts = 373.548035
last_seq = 671
current_ts = 373.565399
current_received_ts = 373.564728
current_seq = 672
count = 12
seq_step = 1
[372.025541] (kms_flip:10136) DEBUG: Vblank took 95us
[372.042172] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.565399
last_received_ts = 373.564728
last_seq = 672
current_ts = 373.582062
current_received_ts = 373.581451
current_seq = 673
count = 13
seq_step = 1
[372.042236] (kms_flip:10136) DEBUG: Vblank took 56us
[372.058815] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.582062
last_received_ts = 373.581451
last_seq = 673
current_ts = 373.598724
current_received_ts = 373.598083
current_seq = 674
count = 14
seq_step = 1
[372.058883] (kms_flip:10136) DEBUG: Vblank took 60us
[372.075528] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.598724
last_received_ts = 373.598083
last_seq = 674
current_ts = 373.615387
current_received_ts = 373.614807
current_seq = 675
count = 15
seq_step = 1
[372.075587] (kms_flip:10136) DEBUG: Vblank took 51us
[372.092142] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.615387
last_received_ts = 373.614807
last_seq = 675
current_ts = 373.632050
current_received_ts = 373.631409
current_seq = 676
count = 16
seq_step = 1
[372.092247] (kms_flip:10136) DEBUG: Vblank took 97us
[372.108820] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.632050
last_received_ts = 373.631409
last_seq = 676
current_ts = 373.648712
current_received_ts = 373.648102
current_seq = 677
count = 17
seq_step = 1
[372.108885] (kms_flip:10136) DEBUG: Vblank took 57us
[372.125516] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.648712
last_received_ts = 373.648102
last_seq = 677
current_ts = 373.665375
current_received_ts = 373.664795
current_seq = 678
count = 18
seq_step = 1
[372.125574] (kms_flip:10136) DEBUG: Vblank took 51us
[372.142103] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.665375
last_received_ts = 373.664795
last_seq = 678
current_ts = 373.682037
current_received_ts = 373.681366
current_seq = 679
count = 19
seq_step = 1
[372.142186] (kms_flip:10136) DEBUG: Vblank took 75us
[372.158761] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.682037
last_received_ts = 373.681366
last_seq = 679
current_ts = 373.698700
current_received_ts = 373.698029
current_seq = 680
count = 20
seq_step = 1
[372.158878] (kms_flip:10136) DEBUG: Vblank took 111us
[372.175404] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.698700
last_received_ts = 373.698029
last_seq = 680
current_ts = 373.715363
current_received_ts = 373.714691
current_seq = 681
count = 21
seq_step = 1
[372.175460] (kms_flip:10136) DEBUG: Vblank took 52us
[372.191996] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.715363
last_received_ts = 373.714691
last_seq = 681
current_ts = 373.732025
current_received_ts = 373.731262
current_seq = 682
count = 22
seq_step = 1
[372.192047] (kms_flip:10136) DEBUG: Vblank took 47us
[372.208799] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.732025
last_received_ts = 373.731262
last_seq = 682
current_ts = 373.748688
current_received_ts = 373.748077
current_seq = 683
count = 23
seq_step = 1
[372.208902] (kms_flip:10136) DEBUG: Vblank took 94us
[372.225433] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.748688
last_received_ts = 373.748077
last_seq = 683
current_ts = 373.765350
current_received_ts = 373.764709
current_seq = 684
count = 24
seq_step = 1
[372.225545] (kms_flip:10136) DEBUG: Vblank took 103us
[372.241996] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.765350
last_received_ts = 373.764709
last_seq = 684
current_ts = 373.782013
current_received_ts = 373.781281
current_seq = 685
count = 25
seq_step = 1
[372.242116] (kms_flip:10136) DEBUG: Vblank took 116us
[372.258798] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.782013
last_received_ts = 373.781281
last_seq = 685
current_ts = 373.798706
current_received_ts = 373.798065
current_seq = 686
count = 26
seq_step = 1
[372.258897] (kms_flip:10136) DEBUG: Vblank took 90us
[372.275476] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.798706
last_received_ts = 373.798065
last_seq = 686
current_ts = 373.815369
current_received_ts = 373.814758
current_seq = 687
count = 27
seq_step = 1
[372.275537] (kms_flip:10136) DEBUG: Vblank took 53us
[372.292074] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.815369
last_received_ts = 373.814758
last_seq = 687
current_ts = 373.832001
current_received_ts = 373.831329
current_seq = 688
count = 28
seq_step = 1
[372.292162] (kms_flip:10136) DEBUG: Vblank took 80us
[372.308801] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.832001
last_received_ts = 373.831329
last_seq = 688
current_ts = 373.848663
current_received_ts = 373.848053
current_seq = 689
count = 29
seq_step = 1
[372.308882] (kms_flip:10136) DEBUG: Vblank took 73us
[372.325395] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.848663
last_received_ts = 373.848053
last_seq = 689
current_ts = 373.865356
current_received_ts = 373.864655
current_seq = 690
count = 30
seq_step = 1
[372.325507] (kms_flip:10136) DEBUG: Vblank took 104us
[372.341981] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.865356
last_received_ts = 373.864655
last_seq = 690
current_ts = 373.881989
current_received_ts = 373.881256
current_seq = 691
count = 31
seq_step = 1
[372.342030] (kms_flip:10136) DEBUG: Vblank took 45us
[372.358748] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.881989
last_received_ts = 373.881256
last_seq = 691
current_ts = 373.898682
current_received_ts = 373.897980
current_seq = 692
count = 32
seq_step = 1
[372.358853] (kms_flip:10136) DEBUG: Vblank took 96us
[372.375378] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.898682
last_received_ts = 373.897980
last_seq = 692
current_ts = 373.915344
current_received_ts = 373.914642
current_seq = 693
count = 33
seq_step = 1
[372.375490] (kms_flip:10136) DEBUG: Vblank took 104us
[372.392006] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.915344
last_received_ts = 373.914642
last_seq = 693
current_ts = 373.931976
current_received_ts = 373.931274
current_seq = 694
count = 34
seq_step = 1
[372.392112] (kms_flip:10136) DEBUG: Vblank took 102us
[372.408760] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.931976
last_received_ts = 373.931274
last_seq = 694
current_ts = 373.948669
current_received_ts = 373.947998
current_seq = 695
count = 35
seq_step = 1
[372.408824] (kms_flip:10136) DEBUG: Vblank took 57us
[372.425377] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.948669
last_received_ts = 373.947998
last_seq = 695
current_ts = 373.965332
current_received_ts = 373.964630
current_seq = 696
count = 36
seq_step = 1
[372.425483] (kms_flip:10136) DEBUG: Vblank took 99us
[372.442015] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.965332
last_received_ts = 373.964630
last_seq = 696
current_ts = 373.981995
current_received_ts = 373.981293
current_seq = 697
count = 37
seq_step = 1
[372.442138] (kms_flip:10136) DEBUG: Vblank took 120us
[372.458754] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.981995
last_received_ts = 373.981293
last_seq = 697
current_ts = 373.998657
current_received_ts = 373.997986
current_seq = 698
count = 38
seq_step = 1
[372.458822] (kms_flip:10136) DEBUG: Vblank took 60us
[372.475366] (kms_flip:10136) DEBUG: name = flip
last_ts = 373.998657
last_received_ts = 373.997986
last_seq = 698
current_ts = 374.015320
current_received_ts = 374.014618
current_seq = 699
count = 39
seq_step = 1
[372.475469] (kms_flip:10136) DEBUG: Vblank took 95us
[372.491927] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.015320
last_received_ts = 374.014618
last_seq = 699
current_ts = 374.031982
current_received_ts = 374.031189
current_seq = 700
count = 40
seq_step = 1
[372.491975] (kms_flip:10136) DEBUG: Vblank took 46us
[372.508674] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.031982
last_received_ts = 374.031189
last_seq = 700
current_ts = 374.048645
current_received_ts = 374.047943
current_seq = 701
count = 41
seq_step = 1
[372.508718] (kms_flip:10136) DEBUG: Vblank took 41us
[372.525332] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.048645
last_received_ts = 374.047943
last_seq = 701
current_ts = 374.065308
current_received_ts = 374.064606
current_seq = 702
count = 42
seq_step = 1
[372.525373] (kms_flip:10136) DEBUG: Vblank took 38us
[372.542118] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.065308
last_received_ts = 374.064606
last_seq = 702
current_ts = 374.081970
current_received_ts = 374.081360
current_seq = 703
count = 43
seq_step = 1
[372.542178] (kms_flip:10136) DEBUG: Vblank took 53us
[372.558754] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.081970
last_received_ts = 374.081360
last_seq = 703
current_ts = 374.098633
current_received_ts = 374.097992
current_seq = 704
count = 44
seq_step = 1
[372.558817] (kms_flip:10136) DEBUG: Vblank took 54us
[372.575359] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.098633
last_received_ts = 374.097992
last_seq = 704
current_ts = 374.115295
current_received_ts = 374.114624
current_seq = 705
count = 45
seq_step = 1
[372.575448] (kms_flip:10136) DEBUG: Vblank took 80us
[372.591946] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.115295
last_received_ts = 374.114624
last_seq = 705
current_ts = 374.131958
current_received_ts = 374.131195
current_seq = 706
count = 46
seq_step = 1
[372.592063] (kms_flip:10136) DEBUG: Vblank took 114us
[372.608770] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.131958
last_received_ts = 374.131195
last_seq = 706
current_ts = 374.148621
current_received_ts = 374.148010
current_seq = 707
count = 47
seq_step = 1
[372.608831] (kms_flip:10136) DEBUG: Vblank took 53us
[372.625373] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.148621
last_received_ts = 374.148010
last_seq = 707
current_ts = 374.165283
current_received_ts = 374.164612
current_seq = 708
count = 48
seq_step = 1
[372.625474] (kms_flip:10136) DEBUG: Vblank took 93us
[372.641983] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.165283
last_received_ts = 374.164612
last_seq = 708
current_ts = 374.181946
current_received_ts = 374.181244
current_seq = 709
count = 49
seq_step = 1
[372.642095] (kms_flip:10136) DEBUG: Vblank took 109us
[372.658669] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.181946
last_received_ts = 374.181244
last_seq = 709
current_ts = 374.198608
current_received_ts = 374.197937
current_seq = 710
count = 50
seq_step = 1
[372.658788] (kms_flip:10136) DEBUG: Vblank took 116us
[372.675329] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.198608
last_received_ts = 374.197937
last_seq = 710
current_ts = 374.215271
current_received_ts = 374.214600
current_seq = 711
count = 51
seq_step = 1
[372.675375] (kms_flip:10136) DEBUG: Vblank took 43us
[372.692078] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.215271
last_received_ts = 374.214600
last_seq = 711
current_ts = 374.231934
current_received_ts = 374.231323
current_seq = 712
count = 52
seq_step = 1
[372.692136] (kms_flip:10136) DEBUG: Vblank took 51us
[372.708731] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.231934
last_received_ts = 374.231323
last_seq = 712
current_ts = 374.248596
current_received_ts = 374.247986
current_seq = 713
count = 53
seq_step = 1
[372.708809] (kms_flip:10136) DEBUG: Vblank took 71us
[372.725330] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.248596
last_received_ts = 374.247986
last_seq = 713
current_ts = 374.265259
current_received_ts = 374.264587
current_seq = 714
count = 54
seq_step = 1
[372.725424] (kms_flip:10136) DEBUG: Vblank took 87us
[372.742045] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.265259
last_received_ts = 374.264587
last_seq = 714
current_ts = 374.281921
current_received_ts = 374.281281
current_seq = 715
count = 55
seq_step = 1
[372.742117] (kms_flip:10136) DEBUG: Vblank took 62us
[372.758736] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.281921
last_received_ts = 374.281281
last_seq = 715
current_ts = 374.298584
current_received_ts = 374.297974
current_seq = 716
count = 56
seq_step = 1
[372.758814] (kms_flip:10136) DEBUG: Vblank took 51us
[372.775330] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.298584
last_received_ts = 374.297974
last_seq = 716
current_ts = 374.315247
current_received_ts = 374.314575
current_seq = 717
count = 57
seq_step = 1
[372.775439] (kms_flip:10136) DEBUG: Vblank took 102us
[372.791968] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.315247
last_received_ts = 374.314575
last_seq = 717
current_ts = 374.331909
current_received_ts = 374.331207
current_seq = 718
count = 58
seq_step = 1
[372.792021] (kms_flip:10136) DEBUG: Vblank took 50us
[372.808695] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.331909
last_received_ts = 374.331207
last_seq = 718
current_ts = 374.348572
current_received_ts = 374.347931
current_seq = 719
count = 59
seq_step = 1
[372.808816] (kms_flip:10136) DEBUG: Vblank took 114us
[372.825439] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.348572
last_received_ts = 374.347931
last_seq = 719
current_ts = 374.365234
current_received_ts = 374.364685
current_seq = 720
count = 60
seq_step = 1
[372.825529] (kms_flip:10136) DEBUG: Vblank took 80us
[372.841986] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.365234
last_received_ts = 374.364685
last_seq = 720
current_ts = 374.381897
current_received_ts = 374.381226
current_seq = 721
count = 61
seq_step = 1
[372.842100] (kms_flip:10136) DEBUG: Vblank took 105us
[372.858690] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.381897
last_received_ts = 374.381226
last_seq = 721
current_ts = 374.398560
current_received_ts = 374.397919
current_seq = 722
count = 62
seq_step = 1
[372.858771] (kms_flip:10136) DEBUG: Vblank took 74us
[372.875321] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.398560
last_received_ts = 374.397919
last_seq = 722
current_ts = 374.415222
current_received_ts = 374.414551
current_seq = 723
count = 63
seq_step = 1
[372.875418] (kms_flip:10136) DEBUG: Vblank took 90us
[372.891945] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.415222
last_received_ts = 374.414551
last_seq = 723
current_ts = 374.431885
current_received_ts = 374.431183
current_seq = 724
count = 64
seq_step = 1
[372.892053] (kms_flip:10136) DEBUG: Vblank took 105us
[372.908674] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.431885
last_received_ts = 374.431183
last_seq = 724
current_ts = 374.448547
current_received_ts = 374.447906
current_seq = 725
count = 65
seq_step = 1
[372.908738] (kms_flip:10136) DEBUG: Vblank took 56us
[372.925316] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.448547
last_received_ts = 374.447906
last_seq = 725
current_ts = 374.465210
current_received_ts = 374.464569
current_seq = 726
count = 66
seq_step = 1
[372.925410] (kms_flip:10136) DEBUG: Vblank took 86us
[372.942057] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.465210
last_received_ts = 374.464569
last_seq = 726
current_ts = 374.481873
current_received_ts = 374.481293
current_seq = 727
count = 67
seq_step = 1
[372.942118] (kms_flip:10136) DEBUG: Vblank took 54us
[372.958691] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.481873
last_received_ts = 374.481293
last_seq = 727
current_ts = 374.498535
current_received_ts = 374.497925
current_seq = 728
count = 68
seq_step = 1
[372.958770] (kms_flip:10136) DEBUG: Vblank took 52us
[372.975287] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.498535
last_received_ts = 374.497925
last_seq = 728
current_ts = 374.515198
current_received_ts = 374.514526
current_seq = 729
count = 69
seq_step = 1
[372.975390] (kms_flip:10136) DEBUG: Vblank took 96us
[372.991997] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.515198
last_received_ts = 374.514526
last_seq = 729
current_ts = 374.531860
current_received_ts = 374.531250
current_seq = 730
count = 70
seq_step = 1
[372.992056] (kms_flip:10136) DEBUG: Vblank took 52us
[373.008621] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.531860
last_received_ts = 374.531250
last_seq = 730
current_ts = 374.548523
current_received_ts = 374.547852
current_seq = 731
count = 71
seq_step = 1
[373.008718] (kms_flip:10136) DEBUG: Vblank took 90us
[373.025371] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.548523
last_received_ts = 374.547852
last_seq = 731
current_ts = 374.565216
current_received_ts = 374.564606
current_seq = 732
count = 72
seq_step = 1
[373.025430] (kms_flip:10136) DEBUG: Vblank took 51us
[373.042034] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.565216
last_received_ts = 374.564606
last_seq = 732
current_ts = 374.581848
current_received_ts = 374.581268
current_seq = 733
count = 73
seq_step = 1
[373.042093] (kms_flip:10136) DEBUG: Vblank took 52us
[373.058712] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.581848
last_received_ts = 374.581268
last_seq = 733
current_ts = 374.598541
current_received_ts = 374.597961
current_seq = 734
count = 74
seq_step = 1
[373.058795] (kms_flip:10136) DEBUG: Vblank took 75us
[373.075289] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.598541
last_received_ts = 374.597961
last_seq = 734
current_ts = 374.615173
current_received_ts = 374.614532
current_seq = 735
count = 75
seq_step = 1
[373.075416] (kms_flip:10136) DEBUG: Vblank took 120us
[373.092022] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.615173
last_received_ts = 374.614532
last_seq = 735
current_ts = 374.631836
current_received_ts = 374.631256
current_seq = 736
count = 76
seq_step = 1
[373.092088] (kms_flip:10136) DEBUG: Vblank took 56us
[373.108720] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.631836
last_received_ts = 374.631256
last_seq = 736
current_ts = 374.648529
current_received_ts = 374.647949
current_seq = 737
count = 77
seq_step = 1
[373.108804] (kms_flip:10136) DEBUG: Vblank took 75us
[373.125268] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.648529
last_received_ts = 374.647949
last_seq = 737
current_ts = 374.665192
current_received_ts = 374.664490
current_seq = 738
count = 78
seq_step = 1
[373.125384] (kms_flip:10136) DEBUG: Vblank took 108us
[373.142008] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.665192
last_received_ts = 374.664490
last_seq = 738
current_ts = 374.681824
current_received_ts = 374.681244
current_seq = 739
count = 79
seq_step = 1
[373.142067] (kms_flip:10136) DEBUG: Vblank took 51us
[373.158729] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.681824
last_received_ts = 374.681244
last_seq = 739
current_ts = 374.698517
current_received_ts = 374.697968
current_seq = 740
count = 80
seq_step = 1
[373.158808] (kms_flip:10136) DEBUG: Vblank took 72us
[373.175266] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.698517
last_received_ts = 374.697968
last_seq = 740
current_ts = 374.715179
current_received_ts = 374.714508
current_seq = 741
count = 81
seq_step = 1
[373.175366] (kms_flip:10136) DEBUG: Vblank took 93us
[373.191943] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.715179
last_received_ts = 374.714508
last_seq = 741
current_ts = 374.731842
current_received_ts = 374.731171
current_seq = 742
count = 82
seq_step = 1
[373.192011] (kms_flip:10136) DEBUG: Vblank took 59us
[373.208587] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.731842
last_received_ts = 374.731171
last_seq = 742
current_ts = 374.748505
current_received_ts = 374.747803
current_seq = 743
count = 83
seq_step = 1
[373.208703] (kms_flip:10136) DEBUG: Vblank took 109us
[373.225254] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.748505
last_received_ts = 374.747803
last_seq = 743
current_ts = 374.765167
current_received_ts = 374.764496
current_seq = 744
count = 84
seq_step = 1
[373.225365] (kms_flip:10136) DEBUG: Vblank took 103us
[373.241955] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.765167
last_received_ts = 374.764496
last_seq = 744
current_ts = 374.781830
current_received_ts = 374.781189
current_seq = 745
count = 85
seq_step = 1
[373.242030] (kms_flip:10136) DEBUG: Vblank took 66us
[373.258698] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.781830
last_received_ts = 374.781189
last_seq = 745
current_ts = 374.798492
current_received_ts = 374.797913
current_seq = 746
count = 86
seq_step = 1
[373.258760] (kms_flip:10136) DEBUG: Vblank took 54us
[373.275246] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.798492
last_received_ts = 374.797913
last_seq = 746
current_ts = 374.815155
current_received_ts = 374.814484
current_seq = 747
count = 87
seq_step = 1
[373.275355] (kms_flip:10136) DEBUG: Vblank took 102us
[373.291974] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.815155
last_received_ts = 374.814484
last_seq = 747
current_ts = 374.831818
current_received_ts = 374.831207
current_seq = 748
count = 88
seq_step = 1
[373.292040] (kms_flip:10136) DEBUG: Vblank took 57us
[373.308687] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.831818
last_received_ts = 374.831207
last_seq = 748
current_ts = 374.848480
current_received_ts = 374.847900
current_seq = 749
count = 89
seq_step = 1
[373.308748] (kms_flip:10136) DEBUG: Vblank took 54us
[373.325247] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.848480
last_received_ts = 374.847900
last_seq = 749
current_ts = 374.865143
current_received_ts = 374.864471
current_seq = 750
count = 90
seq_step = 1
[373.325336] (kms_flip:10136) DEBUG: Vblank took 83us
[373.341943] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.865143
last_received_ts = 374.864471
last_seq = 750
current_ts = 374.881805
current_received_ts = 374.881165
current_seq = 751
count = 91
seq_step = 1
[373.342014] (kms_flip:10136) DEBUG: Vblank took 62us
[373.358659] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.881805
last_received_ts = 374.881165
last_seq = 751
current_ts = 374.898468
current_received_ts = 374.897888
current_seq = 752
count = 92
seq_step = 1
[373.358727] (kms_flip:10136) DEBUG: Vblank took 60us
[373.375215] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.898468
last_received_ts = 374.897888
last_seq = 752
current_ts = 374.915131
current_received_ts = 374.914429
current_seq = 753
count = 93
seq_step = 1
[373.375328] (kms_flip:10136) DEBUG: Vblank took 106us
[373.391950] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.915131
last_received_ts = 374.914429
last_seq = 753
current_ts = 374.931793
current_received_ts = 374.931183
current_seq = 754
count = 94
seq_step = 1
[373.392010] (kms_flip:10136) DEBUG: Vblank took 52us
[373.408641] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.931793
last_received_ts = 374.931183
last_seq = 754
current_ts = 374.948456
current_received_ts = 374.947845
current_seq = 755
count = 95
seq_step = 1
[373.408706] (kms_flip:10136) DEBUG: Vblank took 58us
[373.425211] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.948456
last_received_ts = 374.947845
last_seq = 755
current_ts = 374.965118
current_received_ts = 374.964417
current_seq = 756
count = 96
seq_step = 1
[373.425310] (kms_flip:10136) DEBUG: Vblank took 92us
[373.441960] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.965118
last_received_ts = 374.964417
last_seq = 756
current_ts = 374.981781
current_received_ts = 374.981171
current_seq = 757
count = 97
seq_step = 1
[373.442022] (kms_flip:10136) DEBUG: Vblank took 55us
[373.458641] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.981781
last_received_ts = 374.981171
last_seq = 757
current_ts = 374.998444
current_received_ts = 374.997864
current_seq = 758
count = 98
seq_step = 1
[373.458702] (kms_flip:10136) DEBUG: Vblank took 54us
[373.475210] (kms_flip:10136) DEBUG: name = flip
last_ts = 374.998444
last_received_ts = 374.997864
last_seq = 758
current_ts = 375.015106
current_received_ts = 375.014435
current_seq = 759
count = 99
seq_step = 1
[373.475322] (kms_flip:10136) DEBUG: Vblank took 104us
[373.491933] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.015106
last_received_ts = 375.014435
last_seq = 759
current_ts = 375.031769
current_received_ts = 375.031158
current_seq = 760
count = 100
seq_step = 1
[373.492000] (kms_flip:10136) DEBUG: Vblank took 58us
[373.508585] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.031769
last_received_ts = 375.031158
last_seq = 760
current_ts = 375.048431
current_received_ts = 375.047791
current_seq = 761
count = 101
seq_step = 1
[373.508697] (kms_flip:10136) DEBUG: Vblank took 102us
[373.525197] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.048431
last_received_ts = 375.047791
last_seq = 761
current_ts = 375.065094
current_received_ts = 375.064423
current_seq = 762
count = 102
seq_step = 1
[373.525254] (kms_flip:10136) DEBUG: Vblank took 53us
[373.541919] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.065094
last_received_ts = 375.064423
last_seq = 762
current_ts = 375.081757
current_received_ts = 375.081146
current_seq = 763
count = 103
seq_step = 1
[373.541982] (kms_flip:10136) DEBUG: Vblank took 54us
[373.558640] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.081757
last_received_ts = 375.081146
last_seq = 763
current_ts = 375.098419
current_received_ts = 375.097839
current_seq = 764
count = 104
seq_step = 1
[373.558701] (kms_flip:10136) DEBUG: Vblank took 54us
[373.575190] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.098419
last_received_ts = 375.097839
last_seq = 764
current_ts = 375.115082
current_received_ts = 375.114410
current_seq = 765
count = 105
seq_step = 1
[373.575303] (kms_flip:10136) DEBUG: Vblank took 106us
[373.591892] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.115082
last_received_ts = 375.114410
last_seq = 765
current_ts = 375.131744
current_received_ts = 375.131104
current_seq = 766
count = 106
seq_step = 1
[373.591978] (kms_flip:10136) DEBUG: Vblank took 78us
[373.608533] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.131744
last_received_ts = 375.131104
last_seq = 766
current_ts = 375.148407
current_received_ts = 375.147736
current_seq = 767
count = 107
seq_step = 1
[373.608636] (kms_flip:10136) DEBUG: Vblank took 95us
[373.625194] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.148407
last_received_ts = 375.147736
last_seq = 767
current_ts = 375.165070
current_received_ts = 375.164398
current_seq = 768
count = 108
seq_step = 1
[373.625314] (kms_flip:10136) DEBUG: Vblank took 112us
[373.641900] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.165070
last_received_ts = 375.164398
last_seq = 768
current_ts = 375.181732
current_received_ts = 375.181122
current_seq = 769
count = 109
seq_step = 1
[373.641993] (kms_flip:10136) DEBUG: Vblank took 84us
[373.658515] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.181732
last_received_ts = 375.181122
last_seq = 769
current_ts = 375.198395
current_received_ts = 375.197723
current_seq = 770
count = 110
seq_step = 1
[373.658626] (kms_flip:10136) DEBUG: Vblank took 105us
[373.675183] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.198395
last_received_ts = 375.197723
last_seq = 770
current_ts = 375.215057
current_received_ts = 375.214386
current_seq = 771
count = 111
seq_step = 1
[373.675320] (kms_flip:10136) DEBUG: Vblank took 130us
[373.691896] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.215057
last_received_ts = 375.214386
last_seq = 771
current_ts = 375.231720
current_received_ts = 375.231110
current_seq = 772
count = 112
seq_step = 1
[373.691972] (kms_flip:10136) DEBUG: Vblank took 68us
[373.708618] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.231720
last_received_ts = 375.231110
last_seq = 772
current_ts = 375.248383
current_received_ts = 375.247833
current_seq = 773
count = 113
seq_step = 1
[373.708692] (kms_flip:10136) DEBUG: Vblank took 65us
[373.725212] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.248383
last_received_ts = 375.247833
last_seq = 773
current_ts = 375.265045
current_received_ts = 375.264404
current_seq = 774
count = 114
seq_step = 1
[373.725318] (kms_flip:10136) DEBUG: Vblank took 96us
[373.741871] (kms_flip:10136) DEBUG: name = flip
last_ts = 375.265045
last_received_ts = 375.264404
last_seq = 774
current_ts = 375.281708
current_received_ts = 375.281067
current_seq = 775
count = 115
seq_step = 1
[373.742824] (kms_flip:10136) DEBUG: Vblank took 944us
[373.742830] (kms_flip:10136) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[373.742909] (kms_flip:10136) CRITICAL: Failed assertion: end - start < 500
[373.756654] (kms_flip:10136) igt_core-INFO: Stack trace:
[373.769135] (kms_flip:10136) igt_core-INFO:   #0 ../lib/igt_core.c:2074 __igt_fail_assert()
[373.770475] (kms_flip:10136) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[373.770575] (kms_flip:10136) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[373.770617] (kms_flip:10136) igt_core-INFO:   #3 ../tests/kms_flip.c:2184 __igt_unique____real_main2105()
[373.770662] (kms_flip:10136) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[373.774882] (kms_flip:10136) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[373.775813] (kms_flip:10136) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[373.776048] (kms_flip:10136) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (3.264s)

Dmesg

<6> [417.311004] Console: switching to colour dummy device 80x25

<6> [417.311324] [IGT] kms_flip: executing

<7> [417.318159] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1]

<7> [417.318169] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1]

<7> [417.318325] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected

<7> [417.318533] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2]

<7> [417.318536] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2]

<7> [417.318655] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected

<7> [417.318949] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3]

<7> [417.318953] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3]

<7> [417.319101] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected

<7> [417.319310] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1]

<7> [417.319313] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:393:eDP-1]

<7> [417.320292] xe 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [xe]] DSC DPCD: 00 11 00 76 0b 01 01 80 00 01 06 66 08 00 00 00

<7> [417.320626] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000

<7> [417.320832] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] sink rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000

<7> [417.321011] xe 0000:00:02.0: [drm:intel_dp_print_rates [xe]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 810000

<7> [417.321203] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Supported Monitor Refresh rate range is 40 Hz - 120 Hz

<5> [417.321211] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [417.321215] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [417.321217] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] DisplayID extension version 0x13, primary use 0x00

<7> [417.321221] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc.

<5> [417.321225] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [417.321228] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD monitor

<5> [417.321233] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [417.321235] xe 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:393:eDP-1] ELD size 20, SAD count 0

<5> [417.321239] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [417.321259] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] VRR capable: yes

<7> [417.321443] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps

<7> [417.321602] xe 0000:00:02.0: [drm:intel_dp_set_edid [xe]] [CONNECTOR:393:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no

<5> [417.321971] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [417.321974] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<5> [417.321975] [drm] DisplayID checksum invalid, remainder is 248 (ignoring)

<7> [417.322030] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:393:eDP-1] probed modes:

<7> [417.322035] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa

<7> [417.322039] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] Probed mode: "2880x1800": 120 695310 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa

<7> [417.322056] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1]

<7> [417.322061] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:402:DP-1]

<7> [417.322235] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:402:DP-1] disconnected

<7> [417.322247] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2]

<7> [417.322250] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:414:DP-2]

<7> [417.322400] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:414:DP-2] disconnected

<7> [417.322411] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3]

<7> [417.322415] xe 0000:00:02.0: [drm:intel_dp_detect [xe]] [CONNECTOR:422:DP-3]

<7> [417.322564] xe 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes] [CONNECTOR:422:DP-3] disconnected

<6> [417.323143] [IGT] kms_flip: starting subtest flip-vs-expired-vblank

<6> [417.324454] [IGT] kms_flip: starting dynamic subtest A-eDP1

<7> [417.325864] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:431]

<7> [417.326407] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:432]

<7> [417.397478] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]

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

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

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

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

<7> [417.398795] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 6329869/8388608 link 421991/524288, found tu 0, data 0/0 link 0/0)

<7> [417.398976] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)

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

<7> [417.399313] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0)

<7> [417.399480] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0)

<7> [417.399640] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0)

<7> [417.399814] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0)

<7> [417.399967] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0)

<7> [417.400116] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0)

<7> [417.400263] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0)

<7> [417.400407] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0)

<7> [417.400547] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0)

<7> [417.400688] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0)

<7> [417.400879] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0)

<7> [417.401013] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0)

<7> [417.401143] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0)

<7> [417.401272] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0)

<7> [417.401400] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0)

<7> [417.401527] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0)

<7> [417.401651] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0)

<7> [417.401788] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0)

<7> [417.401910] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0)

<7> [417.402032] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0)

<7> [417.402152] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0)

<7> [417.402269] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0)

<7> [417.402382] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0)

<7> [417.402495] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0)

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

<7> [417.402718] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)

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

<7> [417.402928] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0)

<7> [417.403031] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0)

<7> [417.403130] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0)

<7> [417.403226] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 432000, found 0)

<7> [417.403326] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

<7> [417.403427] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0

<7> [417.403586] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no

<7> [417.403661] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0

<7> [417.403776] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 4051) -> ( 0 - 0), size 4051 -> 0

<7> [417.403864] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb (4051 - 4096) -> ( 0 - 0), size 45 -> 0

<7> [417.403952] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm

<7> [417.404026] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 1, 13, 13, 13, 13, 13, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [417.404093] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 24, 313, 313, 313, 313, 313, 0, 0, 38, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [417.404159] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 28, 346, 346, 346, 346, 346, 0, 0, 39, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0

<7> [417.404246] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 0 num active planes 0

<7> [417.404347] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400

<7> [417.404445] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400

<7> [417.404549] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400

<7> [417.404640] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400

<7> [417.404739] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0

<7> [417.404839] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz

<7> [417.404948] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 21732 kHz -> 0 kHz

<7> [417.405045] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing

<7> [417.405141] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz

<7> [417.405225] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0

<7> [417.405339] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset]

<7> [417.405423] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no

<7> [417.405506] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no

<7> [417.405589] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no

<7> [417.405672] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no

<7> [417.405775] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no

<7> [417.405883] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no

<7> [417.406046] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off

<7> [417.406766] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00

<7> [417.406928] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2

<7> [417.407650] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM

<7> [417.407779] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]]

<7> [417.609886] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0

<7> [417.610574] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A

<7> [417.624072] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off

<7> [417.624437] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power off time

<7> [417.624834] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000

<7> [417.625174] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short

<7> [417.625569] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060

<7> [417.677125] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000

<7> [417.677448] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short

<7> [417.683850] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

<7> [417.684171] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A]

<7> [417.684221] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A]

<7> [417.684665] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A]

<7> [417.685635] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0

<7> [417.686174] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A

<7> [417.686687] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A]

<7> [417.687053] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1]

<7> [417.687357] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A]

<7> [417.687682] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B]

<7> [417.687948] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C]

<7> [417.688255] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2]

<7> [417.688516] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A]

<7> [417.688799] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B]

<7> [417.689054] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C]

<7> [417.689344] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3]

<7> [417.689592] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A]

<7> [417.689873] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B]

<7> [417.690122] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C]

<7> [417.690434] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1]

<7> [417.690782] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

<7> [417.691030] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: *)

<7> [417.691268] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1

<7> [417.691712] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A

<7> [417.692056] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating disabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xaa000000)

<7> [417.692475] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A]

<7> [417.692873] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Post changing CDCLK to 153600 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0

<7> [417.693237] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

<7> [417.693486] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384

<7> [417.694282] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B]

<7> [417.694605] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C]

<7> [417.694918] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A]

<7> [417.694983] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1]

<7> [417.695149] xe 0000:00:02.0: [drm:compute_baseline_pipe_bpp [xe]] [CONNECTOR:393:eDP-1] Limiting target display pipe bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36)

<7> [417.695514] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:151:pipe A] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 min link_bpp 18.0000 max link_bpp 30.0000

<7> [417.695844] xe 0000:00:02.0: [drm:intel_dp_compute_output_format [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 HDR no link rate required 1303913 available 1728000

<7> [417.696157] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0

<7> [417.696525] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:151:pipe A]

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

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

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

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

<7> [417.698064] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288)

<7> [417.698322] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)

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

<7> [417.698820] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880)

<7> [417.699084] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040)

<7> [417.699315] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880)

<7> [417.699522] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040)

<7> [417.699738] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928)

<7> [417.699964] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960)

<7> [417.700158] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800)

<7> [417.700337] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800)

<7> [417.700521] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803)

<7> [417.700707] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809)

<7> [417.700877] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906)

<7> [417.701042] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906)

<7> [417.701207] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880)

<7> [417.701385] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040)

<7> [417.701564] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880)

<7> [417.701724] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040)

<7> [417.701872] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928)

<7> [417.702012] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960)

<7> [417.702156] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800)

<7> [417.702314] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800)

<7> [417.702467] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803)

<7> [417.702608] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809)

<7> [417.702762] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906)

<7> [417.702898] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906)

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

<7> [417.703151] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)

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

<7> [417.703401] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 30)

<7> [417.703526] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710)

<7> [417.703641] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710)

<7> [417.703764] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:151:pipe A] fastset requirement not met in port_clock (expected 0, found 432000)

<7> [417.703886] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

<7> [417.704041] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes

<7> [417.704121] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:151:pipe A] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x1

<7> [417.704231] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:35:plane 1A] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051

<7> [417.704309] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:145:cursor A] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45

<7> [417.704384] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm

<7> [417.704459] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0

<7> [417.704534] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197

<7> [417.704605] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:35:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 183, 456, 456, 456, 456, 456, 0, 0, 198, 183, 198

<7> [417.704699] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:151:pipe A] data rate 1390840 num active planes 1

<7> [417.704814] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400

<7> [417.704917] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400

<7> [417.705018] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400

<7> [417.705116] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400

<7> [417.705210] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461

<7> [417.705305] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 0 kHz -> 173855 kHz

<7> [417.705418] xe 0000:00:02.0: [drm:intel_cdclk_update_dbuf_bw_min_cdclk [xe]] dbuf bandwidth min cdclk: 0 kHz -> 21732 kHz

<7> [417.705522] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing

<7> [417.705622] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz

<7> [417.705733] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0

<7> [417.705839] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:151:pipe A] allocated DPLL 0

<7> [417.705926] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:151:pipe A] reserving DPLL 0

<7> [417.706012] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: yes [modeset]

<7> [417.706102] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB

<7> [417.706195] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: A, pipe bpp: 30, dithering: 0

<7> [417.706282] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid>

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

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

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

<7> [417.706631] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m_n: lanes: 4; data_m: 6329869, data_n: 8388608, link_m: 421991, link_n: 524288, tu: 64

<7> [417.706764] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0

<7> [417.706852] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

<7> [417.706938] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled

<7> [417.707017] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled

<7> [417.707095] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0

<7> [417.707179] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4

<7> [417.707263] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14

<7> [417.707343] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB

<7> [417.707422] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB

<7> [417.707498] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0

<7> [417.707577] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range

<7> [417.707652] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined

<7> [417.707749] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1

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

<7> [417.707916] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, fixed rr: yes, vmin: 1906, vmax: 1906, flipline: 1906, pipeline full: 0, guardband: 104 vsync start: 103, vsync end: 97

<7> [417.708001] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: vmin vblank: 1802, vmax vblank: 1802, vmin vtotal: 1906, vmax vtotal: 1906

<7> [417.708087] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: dc balance: no, vmin: 0 vmax: 0 guardband: 0, slope: 0 max increase: 0 max decrease: 0 vblank target: 0

<7> [417.708165] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] requested mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa

<7> [417.708242] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] adjusted mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa

<7> [417.708317] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa

<7> [417.708393] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe mode: "2880x1800": 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x40 0xa

<7> [417.708468] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] crtc timings: clock=347710, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1906 vs=1803-1809 vt=1906, flags=0xa

<7> [417.708543] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pixel rate 347710, min cdclk 173855, min voltage level 0

<7> [417.708618] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0

<7> [417.708701] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0, sharpness_strength: 0

<7> [417.708783] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0

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

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

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

<7> [417.709114] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cx0pll_hw_state: lane_count: 4, ssc_enabled: no, use_c10: yes, tbt_mode: no

<7> [417.709196] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no,

<7> [417.709276] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1.

<7> [417.709358] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state:

<7> [417.709438] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21

<7> [417.709515] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1

<7> [417.709591] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0

<7> [417.709674] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0

<7> [417.709761] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1

<7> [417.709848] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23

<7> [417.709932] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0

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

<7> [417.710091] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000

<7> [417.710166] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [417.710241] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [417.710316] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000

<7> [417.710391] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000

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

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

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

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

<7> [417.710793] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000

<7> [417.710887] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [FB:431] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes

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

<7> [417.711054] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0

<7> [417.711136] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no

<7> [417.711214] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no

<7> [417.711287] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no

<7> [417.711361] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no

<7> [417.711436] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no

<7> [417.711823] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_A

<7> [417.711997] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x1 (CLKGATE_DIS_DSSDSC=0xa8000000)

<7> [417.712110] xe 0000:00:02.0: [drm:intel_set_cdclk [xe]] Pre changing CDCLK to 192000 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0

<7> [417.712205] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

<7> [417.712295] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480

<7> [417.712380] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A]

<7> [417.712452] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1]

<7> [417.712526] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A]

<7> [417.712612] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B]

<7> [417.712695] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C]

<7> [417.712770] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2]

<7> [417.712844] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A]

<7> [417.712915] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B]

<7> [417.712985] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C]

<7> [417.713050] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3]

<7> [417.713113] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A]

<7> [417.713175] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B]

<7> [417.713236] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C]

<7> [417.713319] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf

<7> [417.713482] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *)

<7> [417.713555] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes)

<7> [417.713670] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A

<7> [417.714771] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x1, on? 0) for [CRTC:151:pipe A]

<7> [417.714941] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0

<7> [417.716961] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on

<7> [417.717057] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (468 ms remaining)

<7> [417.717513] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010

<7> [417.717590] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long

<7> [417.717666] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10

<7> [417.717787] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A]

<7> [418.193861] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x00000000 PP_CONTROL: 0x00000060

<7> [418.204322] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

<7> [418.204871] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power on

<7> [418.205310] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063

<7> [418.241693] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010

<7> [418.242009] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long

<7> [418.242286] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20

<7> [418.242716] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A]

<7> [418.337829] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port E/TC#2: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

<7> [418.337811] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

<7> [418.337955] xe 0000:00:02.0: [drm:intel_tc_port_reset_mode [xe]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected) pin assignment: - max lanes: 4

<7> [418.419956] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

<7> [418.420290] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on

<7> [418.420561] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b

<7> [418.422550] xe 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 1e 44 c1 00 00 01 c0 02 00 02 00 00 0b 80

<7> [418.424027] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Reloading eDP link rates

<7> [418.424718] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05

<7> [418.425740] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0

<7> [418.427026] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS1

<7> [418.428103] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Clock recovery OK

<7> [418.428506] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Using DP training pattern TPS4

<7> [418.429918] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful

<7> [418.430257] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:393:eDP-1][ENCODER:392:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4

<7> [418.431009] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe A

<7> [418.431476] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]]

<7> [418.431877] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe A

<7> [418.432265] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518

<7> [418.465028] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2

<7> [418.466751] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1]

<7> [418.467130] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A]

<7> [420.433759] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off

<7> [420.434319] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6

<7> [420.434831] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02

<6> [420.589910] [IGT] kms_flip: finished subtest A-eDP1, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank@a-edp1