igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1 on shard-lnl@IGTPW

Detail	Value
Duration	3.10 seconds
Hostname	shard-lnl-3
Igt-Version	IGT-Version: 2.4-g61afca4ff (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5053-8fbb3d48e61c7e68c-debug+ x86_64)
Out	Starting dynamic subtest: B-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:2220 __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 B-eDP1: FAIL (3.100s)
Err	Starting dynamic subtest: B-eDP1 [324.239656] (kms_flip:6213) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [324.239731] (kms_flip:6213) CRITICAL: Failed assertion: end - start < 500 [324.239775] (kms_flip:6213) CRITICAL: Last errno: 4, Interrupted system call Dynamic subtest B-eDP1 failed. ** DEBUG [321.213240] (kms_flip:6213) drmtest-DEBUG: Test requirement passed: is_intel_device(fd) [321.214300] (kms_flip:6213) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=11520) [321.214307] (kms_flip:6213) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) [321.222143] (kms_flip:6213) intel_allocator_simple-DEBUG: Using simple allocator [321.230011] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a9e40, fd: 5> objects: 3, reserved_areas: 0 [321.230013] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a9e40, fd: 5> objects: 3, reserved_areas: 0 [321.246825] (kms_flip:6213) intel_allocator_simple-DEBUG: Using simple allocator [321.250972] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a5560, fd: 5> objects: 3, reserved_areas: 0 [321.250973] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a5560, fd: 5> objects: 3, reserved_areas: 0 [321.255627] (kms_flip:6213) intel_allocator_simple-DEBUG: Using simple allocator [321.260174] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a60f0, fd: 5> objects: 3, reserved_areas: 0 [321.260176] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a60f0, fd: 5> objects: 3, reserved_areas: 0 [321.273342] (kms_flip:6213) intel_allocator_simple-DEBUG: Using simple allocator [321.277240] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a5560, fd: 5> objects: 3, reserved_areas: 0 [321.277242] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a5560, fd: 5> objects: 3, reserved_areas: 0 [321.278660] (kms_flip:6213) igt_kms-INFO: 2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa [321.279880] (kms_flip:6213) DEBUG: No stale events found [322.361755] (kms_flip:6213) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0 [322.362045] (kms_flip:6213) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0 [322.389035] (kms_flip:6213) DEBUG: name = flip last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 323.928925 current_received_ts = 323.928101 current_seq = 75 count = 0 seq_step = 1 [322.389138] (kms_flip:6213) DEBUG: Vblank took 88us [322.405737] (kms_flip:6213) DEBUG: name = flip last_ts = 323.928925 last_received_ts = 323.928101 last_seq = 75 current_ts = 323.945587 current_received_ts = 323.944824 current_seq = 76 count = 1 seq_step = 1 [322.405812] (kms_flip:6213) DEBUG: Vblank took 69us [322.422364] (kms_flip:6213) DEBUG: name = flip last_ts = 323.945587 last_received_ts = 323.944824 last_seq = 76 current_ts = 323.962250 current_received_ts = 323.961456 current_seq = 77 count = 2 seq_step = 1 [322.422416] (kms_flip:6213) DEBUG: Vblank took 50us [322.439044] (kms_flip:6213) DEBUG: name = flip last_ts = 323.962250 last_received_ts = 323.961456 last_seq = 77 current_ts = 323.978943 current_received_ts = 323.978119 current_seq = 78 count = 3 seq_step = 1 [322.439092] (kms_flip:6213) DEBUG: Vblank took 45us [322.455728] (kms_flip:6213) DEBUG: name = flip last_ts = 323.978943 last_received_ts = 323.978119 last_seq = 78 current_ts = 323.995605 current_received_ts = 323.994812 current_seq = 79 count = 4 seq_step = 1 [322.455777] (kms_flip:6213) DEBUG: Vblank took 46us [322.472390] (kms_flip:6213) DEBUG: name = flip last_ts = 323.995605 last_received_ts = 323.994812 last_seq = 79 current_ts = 324.012268 current_received_ts = 324.011475 current_seq = 80 count = 5 seq_step = 1 [322.472440] (kms_flip:6213) DEBUG: Vblank took 47us [322.489028] (kms_flip:6213) DEBUG: name = flip last_ts = 324.012268 last_received_ts = 324.011475 last_seq = 80 current_ts = 324.028931 current_received_ts = 324.028107 current_seq = 81 count = 6 seq_step = 1 [322.489077] (kms_flip:6213) DEBUG: Vblank took 46us [322.505718] (kms_flip:6213) DEBUG: name = flip last_ts = 324.028931 last_received_ts = 324.028107 last_seq = 81 current_ts = 324.045593 current_received_ts = 324.044800 current_seq = 82 count = 7 seq_step = 1 [322.505769] (kms_flip:6213) DEBUG: Vblank took 47us [322.522397] (kms_flip:6213) DEBUG: name = flip last_ts = 324.045593 last_received_ts = 324.044800 last_seq = 82 current_ts = 324.062256 current_received_ts = 324.061493 current_seq = 83 count = 8 seq_step = 1 [322.522446] (kms_flip:6213) DEBUG: Vblank took 46us [322.539029] (kms_flip:6213) DEBUG: name = flip last_ts = 324.062256 last_received_ts = 324.061493 last_seq = 83 current_ts = 324.078918 current_received_ts = 324.078125 current_seq = 84 count = 9 seq_step = 1 [322.539077] (kms_flip:6213) DEBUG: Vblank took 46us [322.555718] (kms_flip:6213) DEBUG: name = flip last_ts = 324.078918 last_received_ts = 324.078125 last_seq = 84 current_ts = 324.095581 current_received_ts = 324.094818 current_seq = 85 count = 10 seq_step = 1 [322.555766] (kms_flip:6213) DEBUG: Vblank took 46us [322.572380] (kms_flip:6213) DEBUG: name = flip last_ts = 324.095581 last_received_ts = 324.094818 last_seq = 85 current_ts = 324.112244 current_received_ts = 324.111481 current_seq = 86 count = 11 seq_step = 1 [322.572427] (kms_flip:6213) DEBUG: Vblank took 45us [322.589011] (kms_flip:6213) DEBUG: name = flip last_ts = 324.112244 last_received_ts = 324.111481 last_seq = 86 current_ts = 324.128906 current_received_ts = 324.128113 current_seq = 87 count = 12 seq_step = 1 [322.589059] (kms_flip:6213) DEBUG: Vblank took 46us [322.605675] (kms_flip:6213) DEBUG: name = flip last_ts = 324.128906 last_received_ts = 324.128113 last_seq = 87 current_ts = 324.145569 current_received_ts = 324.144775 current_seq = 88 count = 13 seq_step = 1 [322.605727] (kms_flip:6213) DEBUG: Vblank took 49us [322.622359] (kms_flip:6213) DEBUG: name = flip last_ts = 324.145569 last_received_ts = 324.144775 last_seq = 88 current_ts = 324.162231 current_received_ts = 324.161438 current_seq = 89 count = 14 seq_step = 1 [322.622424] (kms_flip:6213) DEBUG: Vblank took 63us [322.639005] (kms_flip:6213) DEBUG: name = flip last_ts = 324.162231 last_received_ts = 324.161438 last_seq = 89 current_ts = 324.178894 current_received_ts = 324.178101 current_seq = 90 count = 15 seq_step = 1 [322.639054] (kms_flip:6213) DEBUG: Vblank took 46us [322.655692] (kms_flip:6213) DEBUG: name = flip last_ts = 324.178894 last_received_ts = 324.178101 last_seq = 90 current_ts = 324.195557 current_received_ts = 324.194794 current_seq = 91 count = 16 seq_step = 1 [322.655740] (kms_flip:6213) DEBUG: Vblank took 46us [322.672346] (kms_flip:6213) DEBUG: name = flip last_ts = 324.195557 last_received_ts = 324.194794 last_seq = 91 current_ts = 324.212250 current_received_ts = 324.211426 current_seq = 92 count = 17 seq_step = 1 [322.672393] (kms_flip:6213) DEBUG: Vblank took 44us [322.689000] (kms_flip:6213) DEBUG: name = flip last_ts = 324.212250 last_received_ts = 324.211426 last_seq = 92 current_ts = 324.228912 current_received_ts = 324.228088 current_seq = 93 count = 18 seq_step = 1 [322.689050] (kms_flip:6213) DEBUG: Vblank took 48us [322.705680] (kms_flip:6213) DEBUG: name = flip last_ts = 324.228912 last_received_ts = 324.228088 last_seq = 93 current_ts = 324.245575 current_received_ts = 324.244781 current_seq = 94 count = 19 seq_step = 1 [322.705728] (kms_flip:6213) DEBUG: Vblank took 46us [322.722343] (kms_flip:6213) DEBUG: name = flip last_ts = 324.245575 last_received_ts = 324.244781 last_seq = 94 current_ts = 324.262238 current_received_ts = 324.261444 current_seq = 95 count = 20 seq_step = 1 [322.722383] (kms_flip:6213) DEBUG: Vblank took 37us [322.738989] (kms_flip:6213) DEBUG: name = flip last_ts = 324.262238 last_received_ts = 324.261444 last_seq = 95 current_ts = 324.278900 current_received_ts = 324.278076 current_seq = 96 count = 21 seq_step = 1 [322.739038] (kms_flip:6213) DEBUG: Vblank took 46us [322.755645] (kms_flip:6213) DEBUG: name = flip last_ts = 324.278900 last_received_ts = 324.278076 last_seq = 96 current_ts = 324.295563 current_received_ts = 324.294739 current_seq = 97 count = 22 seq_step = 1 [322.755694] (kms_flip:6213) DEBUG: Vblank took 47us [322.772321] (kms_flip:6213) DEBUG: name = flip last_ts = 324.295563 last_received_ts = 324.294739 last_seq = 97 current_ts = 324.312225 current_received_ts = 324.311432 current_seq = 98 count = 23 seq_step = 1 [322.772369] (kms_flip:6213) DEBUG: Vblank took 45us [322.788979] (kms_flip:6213) DEBUG: name = flip last_ts = 324.312225 last_received_ts = 324.311432 last_seq = 98 current_ts = 324.328888 current_received_ts = 324.328064 current_seq = 99 count = 24 seq_step = 1 [322.789028] (kms_flip:6213) DEBUG: Vblank took 47us [322.805667] (kms_flip:6213) DEBUG: name = flip last_ts = 324.328888 last_received_ts = 324.328064 last_seq = 99 current_ts = 324.345551 current_received_ts = 324.344757 current_seq = 100 count = 25 seq_step = 1 [322.805714] (kms_flip:6213) DEBUG: Vblank took 45us [322.822322] (kms_flip:6213) DEBUG: name = flip last_ts = 324.345551 last_received_ts = 324.344757 last_seq = 100 current_ts = 324.362213 current_received_ts = 324.361420 current_seq = 101 count = 26 seq_step = 1 [322.822370] (kms_flip:6213) DEBUG: Vblank took 46us [322.838974] (kms_flip:6213) DEBUG: name = flip last_ts = 324.362213 last_received_ts = 324.361420 last_seq = 101 current_ts = 324.378876 current_received_ts = 324.378082 current_seq = 102 count = 27 seq_step = 1 [322.839021] (kms_flip:6213) DEBUG: Vblank took 46us [322.855645] (kms_flip:6213) DEBUG: name = flip last_ts = 324.378876 last_received_ts = 324.378082 last_seq = 102 current_ts = 324.395538 current_received_ts = 324.394745 current_seq = 103 count = 28 seq_step = 1 [322.855701] (kms_flip:6213) DEBUG: Vblank took 52us [322.872322] (kms_flip:6213) DEBUG: name = flip last_ts = 324.395538 last_received_ts = 324.394745 last_seq = 103 current_ts = 324.412231 current_received_ts = 324.411438 current_seq = 104 count = 29 seq_step = 1 [322.872375] (kms_flip:6213) DEBUG: Vblank took 50us [322.888972] (kms_flip:6213) DEBUG: name = flip last_ts = 324.412231 last_received_ts = 324.411438 last_seq = 104 current_ts = 324.428894 current_received_ts = 324.428070 current_seq = 105 count = 30 seq_step = 1 [322.889023] (kms_flip:6213) DEBUG: Vblank took 48us [322.905643] (kms_flip:6213) DEBUG: name = flip last_ts = 324.428894 last_received_ts = 324.428070 last_seq = 105 current_ts = 324.445557 current_received_ts = 324.444763 current_seq = 106 count = 31 seq_step = 1 [322.905694] (kms_flip:6213) DEBUG: Vblank took 48us [322.922285] (kms_flip:6213) DEBUG: name = flip last_ts = 324.445557 last_received_ts = 324.444763 last_seq = 106 current_ts = 324.462219 current_received_ts = 324.461395 current_seq = 107 count = 32 seq_step = 1 [322.922333] (kms_flip:6213) DEBUG: Vblank took 45us [322.938959] (kms_flip:6213) DEBUG: name = flip last_ts = 324.462219 last_received_ts = 324.461395 last_seq = 107 current_ts = 324.478882 current_received_ts = 324.478058 current_seq = 108 count = 33 seq_step = 1 [322.939010] (kms_flip:6213) DEBUG: Vblank took 48us [322.955647] (kms_flip:6213) DEBUG: name = flip last_ts = 324.478882 last_received_ts = 324.478058 last_seq = 108 current_ts = 324.495544 current_received_ts = 324.494751 current_seq = 109 count = 34 seq_step = 1 [322.955701] (kms_flip:6213) DEBUG: Vblank took 50us [322.972299] (kms_flip:6213) DEBUG: name = flip last_ts = 324.495544 last_received_ts = 324.494751 last_seq = 109 current_ts = 324.512207 current_received_ts = 324.511414 current_seq = 110 count = 35 seq_step = 1 [322.972342] (kms_flip:6213) DEBUG: Vblank took 40us [322.988958] (kms_flip:6213) DEBUG: name = flip last_ts = 324.512207 last_received_ts = 324.511414 last_seq = 110 current_ts = 324.528870 current_received_ts = 324.528076 current_seq = 111 count = 36 seq_step = 1 [322.989006] (kms_flip:6213) DEBUG: Vblank took 46us [323.005634] (kms_flip:6213) DEBUG: name = flip last_ts = 324.528870 last_received_ts = 324.528076 last_seq = 111 current_ts = 324.545532 current_received_ts = 324.544739 current_seq = 112 count = 37 seq_step = 1 [323.005686] (kms_flip:6213) DEBUG: Vblank took 49us [323.022304] (kms_flip:6213) DEBUG: name = flip last_ts = 324.545532 last_received_ts = 324.544739 last_seq = 112 current_ts = 324.562195 current_received_ts = 324.561401 current_seq = 113 count = 38 seq_step = 1 [323.022351] (kms_flip:6213) DEBUG: Vblank took 44us [323.038947] (kms_flip:6213) DEBUG: name = flip last_ts = 324.562195 last_received_ts = 324.561401 last_seq = 113 current_ts = 324.578857 current_received_ts = 324.578064 current_seq = 114 count = 39 seq_step = 1 [323.038999] (kms_flip:6213) DEBUG: Vblank took 49us [323.055625] (kms_flip:6213) DEBUG: name = flip last_ts = 324.578857 last_received_ts = 324.578064 last_seq = 114 current_ts = 324.595520 current_received_ts = 324.594727 current_seq = 115 count = 40 seq_step = 1 [323.055681] (kms_flip:6213) DEBUG: Vblank took 53us [323.072260] (kms_flip:6213) DEBUG: name = flip last_ts = 324.595520 last_received_ts = 324.594727 last_seq = 115 current_ts = 324.612183 current_received_ts = 324.611389 current_seq = 116 count = 41 seq_step = 1 [323.072308] (kms_flip:6213) DEBUG: Vblank took 46us [323.088962] (kms_flip:6213) DEBUG: name = flip last_ts = 324.612183 last_received_ts = 324.611389 last_seq = 116 current_ts = 324.628845 current_received_ts = 324.628082 current_seq = 117 count = 42 seq_step = 1 [323.089011] (kms_flip:6213) DEBUG: Vblank took 48us [323.105617] (kms_flip:6213) DEBUG: name = flip last_ts = 324.628845 last_received_ts = 324.628082 last_seq = 117 current_ts = 324.645508 current_received_ts = 324.644745 current_seq = 118 count = 43 seq_step = 1 [323.105664] (kms_flip:6213) DEBUG: Vblank took 46us [323.122272] (kms_flip:6213) DEBUG: name = flip last_ts = 324.645508 last_received_ts = 324.644745 last_seq = 118 current_ts = 324.662201 current_received_ts = 324.661377 current_seq = 119 count = 44 seq_step = 1 [323.122322] (kms_flip:6213) DEBUG: Vblank took 47us [323.138941] (kms_flip:6213) DEBUG: name = flip last_ts = 324.662201 last_received_ts = 324.661377 last_seq = 119 current_ts = 324.678864 current_received_ts = 324.678070 current_seq = 120 count = 45 seq_step = 1 [323.138995] (kms_flip:6213) DEBUG: Vblank took 50us [323.155608] (kms_flip:6213) DEBUG: name = flip last_ts = 324.678864 last_received_ts = 324.678070 last_seq = 120 current_ts = 324.695526 current_received_ts = 324.694733 current_seq = 121 count = 46 seq_step = 1 [323.155657] (kms_flip:6213) DEBUG: Vblank took 47us [323.172274] (kms_flip:6213) DEBUG: name = flip last_ts = 324.695526 last_received_ts = 324.694733 last_seq = 121 current_ts = 324.712189 current_received_ts = 324.711395 current_seq = 122 count = 47 seq_step = 1 [323.172325] (kms_flip:6213) DEBUG: Vblank took 48us [323.188933] (kms_flip:6213) DEBUG: name = flip last_ts = 324.712189 last_received_ts = 324.711395 last_seq = 122 current_ts = 324.728851 current_received_ts = 324.728058 current_seq = 123 count = 48 seq_step = 1 [323.188984] (kms_flip:6213) DEBUG: Vblank took 49us [323.205601] (kms_flip:6213) DEBUG: name = flip last_ts = 324.728851 last_received_ts = 324.728058 last_seq = 123 current_ts = 324.745514 current_received_ts = 324.744720 current_seq = 124 count = 49 seq_step = 1 [323.205651] (kms_flip:6213) DEBUG: Vblank took 46us [323.222235] (kms_flip:6213) DEBUG: name = flip last_ts = 324.745514 last_received_ts = 324.744720 last_seq = 124 current_ts = 324.762177 current_received_ts = 324.761353 current_seq = 125 count = 50 seq_step = 1 [323.222287] (kms_flip:6213) DEBUG: Vblank took 48us [323.238912] (kms_flip:6213) DEBUG: name = flip last_ts = 324.762177 last_received_ts = 324.761353 last_seq = 125 current_ts = 324.778839 current_received_ts = 324.778046 current_seq = 126 count = 51 seq_step = 1 [323.238962] (kms_flip:6213) DEBUG: Vblank took 46us [323.255595] (kms_flip:6213) DEBUG: name = flip last_ts = 324.778839 last_received_ts = 324.778046 last_seq = 126 current_ts = 324.795502 current_received_ts = 324.794708 current_seq = 127 count = 52 seq_step = 1 [323.255643] (kms_flip:6213) DEBUG: Vblank took 45us [323.272254] (kms_flip:6213) DEBUG: name = flip last_ts = 324.795502 last_received_ts = 324.794708 last_seq = 127 current_ts = 324.812164 current_received_ts = 324.811371 current_seq = 128 count = 53 seq_step = 1 [323.272309] (kms_flip:6213) DEBUG: Vblank took 51us [323.288937] (kms_flip:6213) DEBUG: name = flip last_ts = 324.812164 last_received_ts = 324.811371 last_seq = 128 current_ts = 324.828827 current_received_ts = 324.828064 current_seq = 129 count = 54 seq_step = 1 [323.288993] (kms_flip:6213) DEBUG: Vblank took 53us [323.305595] (kms_flip:6213) DEBUG: name = flip last_ts = 324.828827 last_received_ts = 324.828064 last_seq = 129 current_ts = 324.845490 current_received_ts = 324.844727 current_seq = 130 count = 55 seq_step = 1 [323.305640] (kms_flip:6213) DEBUG: Vblank took 44us [323.322248] (kms_flip:6213) DEBUG: name = flip last_ts = 324.845490 last_received_ts = 324.844727 last_seq = 130 current_ts = 324.862183 current_received_ts = 324.861389 current_seq = 131 count = 56 seq_step = 1 [323.322294] (kms_flip:6213) DEBUG: Vblank took 44us [323.338920] (kms_flip:6213) DEBUG: name = flip last_ts = 324.862183 last_received_ts = 324.861389 last_seq = 131 current_ts = 324.878845 current_received_ts = 324.878052 current_seq = 132 count = 57 seq_step = 1 [323.338969] (kms_flip:6213) DEBUG: Vblank took 46us [323.355573] (kms_flip:6213) DEBUG: name = flip last_ts = 324.878845 last_received_ts = 324.878052 last_seq = 132 current_ts = 324.895508 current_received_ts = 324.894714 current_seq = 133 count = 58 seq_step = 1 [323.355620] (kms_flip:6213) DEBUG: Vblank took 44us [323.372232] (kms_flip:6213) DEBUG: name = flip last_ts = 324.895508 last_received_ts = 324.894714 last_seq = 133 current_ts = 324.912170 current_received_ts = 324.911377 current_seq = 134 count = 59 seq_step = 1 [323.372280] (kms_flip:6213) DEBUG: Vblank took 45us [323.388895] (kms_flip:6213) DEBUG: name = flip last_ts = 324.912170 last_received_ts = 324.911377 last_seq = 134 current_ts = 324.928833 current_received_ts = 324.928040 current_seq = 135 count = 60 seq_step = 1 [323.388947] (kms_flip:6213) DEBUG: Vblank took 50us [323.405587] (kms_flip:6213) DEBUG: name = flip last_ts = 324.928833 last_received_ts = 324.928040 last_seq = 135 current_ts = 324.945496 current_received_ts = 324.944733 current_seq = 136 count = 61 seq_step = 1 [323.405638] (kms_flip:6213) DEBUG: Vblank took 49us [323.422226] (kms_flip:6213) DEBUG: name = flip last_ts = 324.945496 last_received_ts = 324.944733 last_seq = 136 current_ts = 324.962158 current_received_ts = 324.961365 current_seq = 137 count = 62 seq_step = 1 [323.422277] (kms_flip:6213) DEBUG: Vblank took 47us [323.438911] (kms_flip:6213) DEBUG: name = flip last_ts = 324.962158 last_received_ts = 324.961365 last_seq = 137 current_ts = 324.978821 current_received_ts = 324.978058 current_seq = 138 count = 63 seq_step = 1 [323.438962] (kms_flip:6213) DEBUG: Vblank took 48us [323.455567] (kms_flip:6213) DEBUG: name = flip last_ts = 324.978821 last_received_ts = 324.978058 last_seq = 138 current_ts = 324.995483 current_received_ts = 324.994690 current_seq = 139 count = 64 seq_step = 1 [323.455624] (kms_flip:6213) DEBUG: Vblank took 54us [323.472221] (kms_flip:6213) DEBUG: name = flip last_ts = 324.995483 last_received_ts = 324.994690 last_seq = 139 current_ts = 325.012146 current_received_ts = 325.011353 current_seq = 140 count = 65 seq_step = 1 [323.472272] (kms_flip:6213) DEBUG: Vblank took 47us [323.488908] (kms_flip:6213) DEBUG: name = flip last_ts = 325.012146 last_received_ts = 325.011353 last_seq = 140 current_ts = 325.028809 current_received_ts = 325.028046 current_seq = 141 count = 66 seq_step = 1 [323.488959] (kms_flip:6213) DEBUG: Vblank took 48us [323.505553] (kms_flip:6213) DEBUG: name = flip last_ts = 325.028809 last_received_ts = 325.028046 last_seq = 141 current_ts = 325.045471 current_received_ts = 325.044678 current_seq = 142 count = 67 seq_step = 1 [323.505602] (kms_flip:6213) DEBUG: Vblank took 47us [323.522201] (kms_flip:6213) DEBUG: name = flip last_ts = 325.045471 last_received_ts = 325.044678 last_seq = 142 current_ts = 325.062134 current_received_ts = 325.061340 current_seq = 143 count = 68 seq_step = 1 [323.522256] (kms_flip:6213) DEBUG: Vblank took 51us [323.538854] (kms_flip:6213) DEBUG: name = flip last_ts = 325.062134 last_received_ts = 325.061340 last_seq = 143 current_ts = 325.078796 current_received_ts = 325.078003 current_seq = 144 count = 69 seq_step = 1 [323.538925] (kms_flip:6213) DEBUG: Vblank took 68us [323.555521] (kms_flip:6213) DEBUG: name = flip last_ts = 325.078796 last_received_ts = 325.078003 last_seq = 144 current_ts = 325.095459 current_received_ts = 325.094666 current_seq = 145 count = 70 seq_step = 1 [323.555569] (kms_flip:6213) DEBUG: Vblank took 46us [323.572183] (kms_flip:6213) DEBUG: name = flip last_ts = 325.095459 last_received_ts = 325.094666 last_seq = 145 current_ts = 325.112152 current_received_ts = 325.111328 current_seq = 146 count = 71 seq_step = 1 [323.572231] (kms_flip:6213) DEBUG: Vblank took 45us [323.588881] (kms_flip:6213) DEBUG: name = flip last_ts = 325.112152 last_received_ts = 325.111328 last_seq = 146 current_ts = 325.128815 current_received_ts = 325.128021 current_seq = 147 count = 72 seq_step = 1 [323.588925] (kms_flip:6213) DEBUG: Vblank took 42us [323.605542] (kms_flip:6213) DEBUG: name = flip last_ts = 325.128815 last_received_ts = 325.128021 last_seq = 147 current_ts = 325.145477 current_received_ts = 325.144684 current_seq = 148 count = 73 seq_step = 1 [323.605598] (kms_flip:6213) DEBUG: Vblank took 52us [323.622179] (kms_flip:6213) DEBUG: name = flip last_ts = 325.145477 last_received_ts = 325.144684 last_seq = 148 current_ts = 325.162140 current_received_ts = 325.161316 current_seq = 149 count = 74 seq_step = 1 [323.622233] (kms_flip:6213) DEBUG: Vblank took 52us [323.638886] (kms_flip:6213) DEBUG: name = flip last_ts = 325.162140 last_received_ts = 325.161316 last_seq = 149 current_ts = 325.178802 current_received_ts = 325.178040 current_seq = 150 count = 75 seq_step = 1 [323.638930] (kms_flip:6213) DEBUG: Vblank took 41us [323.655529] (kms_flip:6213) DEBUG: name = flip last_ts = 325.178802 last_received_ts = 325.178040 last_seq = 150 current_ts = 325.195465 current_received_ts = 325.194672 current_seq = 151 count = 76 seq_step = 1 [323.655573] (kms_flip:6213) DEBUG: Vblank took 41us [323.672189] (kms_flip:6213) DEBUG: name = flip last_ts = 325.195465 last_received_ts = 325.194672 last_seq = 151 current_ts = 325.212128 current_received_ts = 325.211334 current_seq = 152 count = 77 seq_step = 1 [323.672238] (kms_flip:6213) DEBUG: Vblank took 48us [323.688871] (kms_flip:6213) DEBUG: name = flip last_ts = 325.212128 last_received_ts = 325.211334 last_seq = 152 current_ts = 325.228790 current_received_ts = 325.227997 current_seq = 153 count = 78 seq_step = 1 [323.688924] (kms_flip:6213) DEBUG: Vblank took 49us [323.705498] (kms_flip:6213) DEBUG: name = flip last_ts = 325.228790 last_received_ts = 325.227997 last_seq = 153 current_ts = 325.245453 current_received_ts = 325.244659 current_seq = 154 count = 79 seq_step = 1 [323.705555] (kms_flip:6213) DEBUG: Vblank took 54us [323.722159] (kms_flip:6213) DEBUG: name = flip last_ts = 325.245453 last_received_ts = 325.244659 last_seq = 154 current_ts = 325.262115 current_received_ts = 325.261322 current_seq = 155 count = 80 seq_step = 1 [323.722210] (kms_flip:6213) DEBUG: Vblank took 49us [323.738858] (kms_flip:6213) DEBUG: name = flip last_ts = 325.262115 last_received_ts = 325.261322 last_seq = 155 current_ts = 325.278778 current_received_ts = 325.277985 current_seq = 156 count = 81 seq_step = 1 [323.738900] (kms_flip:6213) DEBUG: Vblank took 39us [323.755521] (kms_flip:6213) DEBUG: name = flip last_ts = 325.278778 last_received_ts = 325.277985 last_seq = 156 current_ts = 325.295441 current_received_ts = 325.294678 current_seq = 157 count = 82 seq_step = 1 [323.755567] (kms_flip:6213) DEBUG: Vblank took 44us [323.772165] (kms_flip:6213) DEBUG: name = flip last_ts = 325.295441 last_received_ts = 325.294678 last_seq = 157 current_ts = 325.312134 current_received_ts = 325.311310 current_seq = 158 count = 83 seq_step = 1 [323.772216] (kms_flip:6213) DEBUG: Vblank took 48us [323.788863] (kms_flip:6213) DEBUG: name = flip last_ts = 325.312134 last_received_ts = 325.311310 last_seq = 158 current_ts = 325.328796 current_received_ts = 325.328003 current_seq = 159 count = 84 seq_step = 1 [323.788914] (kms_flip:6213) DEBUG: Vblank took 47us [323.805508] (kms_flip:6213) DEBUG: name = flip last_ts = 325.328796 last_received_ts = 325.328003 last_seq = 159 current_ts = 325.345459 current_received_ts = 325.344666 current_seq = 160 count = 85 seq_step = 1 [323.805558] (kms_flip:6213) DEBUG: Vblank took 48us [323.822142] (kms_flip:6213) DEBUG: name = flip last_ts = 325.345459 last_received_ts = 325.344666 last_seq = 160 current_ts = 325.362122 current_received_ts = 325.361298 current_seq = 161 count = 86 seq_step = 1 [323.822193] (kms_flip:6213) DEBUG: Vblank took 48us [323.838833] (kms_flip:6213) DEBUG: name = flip last_ts = 325.362122 last_received_ts = 325.361298 last_seq = 161 current_ts = 325.378784 current_received_ts = 325.377991 current_seq = 162 count = 87 seq_step = 1 [323.838900] (kms_flip:6213) DEBUG: Vblank took 64us [323.855469] (kms_flip:6213) DEBUG: name = flip last_ts = 325.378784 last_received_ts = 325.377991 last_seq = 162 current_ts = 325.395447 current_received_ts = 325.394623 current_seq = 163 count = 88 seq_step = 1 [323.855521] (kms_flip:6213) DEBUG: Vblank took 49us [323.872157] (kms_flip:6213) DEBUG: name = flip last_ts = 325.395447 last_received_ts = 325.394623 last_seq = 163 current_ts = 325.412109 current_received_ts = 325.411316 current_seq = 164 count = 89 seq_step = 1 [323.872213] (kms_flip:6213) DEBUG: Vblank took 53us [323.888823] (kms_flip:6213) DEBUG: name = flip last_ts = 325.412109 last_received_ts = 325.411316 last_seq = 164 current_ts = 325.428772 current_received_ts = 325.427979 current_seq = 165 count = 90 seq_step = 1 [323.888898] (kms_flip:6213) DEBUG: Vblank took 71us [323.905500] (kms_flip:6213) DEBUG: name = flip last_ts = 325.428772 last_received_ts = 325.427979 last_seq = 165 current_ts = 325.445435 current_received_ts = 325.444672 current_seq = 166 count = 91 seq_step = 1 [323.905546] (kms_flip:6213) DEBUG: Vblank took 44us [323.922128] (kms_flip:6213) DEBUG: name = flip last_ts = 325.445435 last_received_ts = 325.444672 last_seq = 166 current_ts = 325.462097 current_received_ts = 325.461273 current_seq = 167 count = 92 seq_step = 1 [323.922179] (kms_flip:6213) DEBUG: Vblank took 48us [323.938819] (kms_flip:6213) DEBUG: name = flip last_ts = 325.462097 last_received_ts = 325.461273 last_seq = 167 current_ts = 325.478760 current_received_ts = 325.477966 current_seq = 168 count = 93 seq_step = 1 [323.938882] (kms_flip:6213) DEBUG: Vblank took 60us [323.955485] (kms_flip:6213) DEBUG: name = flip last_ts = 325.478760 last_received_ts = 325.477966 last_seq = 168 current_ts = 325.495422 current_received_ts = 325.494659 current_seq = 169 count = 94 seq_step = 1 [323.955536] (kms_flip:6213) DEBUG: Vblank took 48us [323.972122] (kms_flip:6213) DEBUG: name = flip last_ts = 325.495422 last_received_ts = 325.494659 last_seq = 169 current_ts = 325.512085 current_received_ts = 325.511292 current_seq = 170 count = 95 seq_step = 1 [323.972173] (kms_flip:6213) DEBUG: Vblank took 48us [323.988818] (kms_flip:6213) DEBUG: name = flip last_ts = 325.512085 last_received_ts = 325.511292 last_seq = 170 current_ts = 325.528748 current_received_ts = 325.527985 current_seq = 171 count = 96 seq_step = 1 [323.988883] (kms_flip:6213) DEBUG: Vblank took 61us [324.005450] (kms_flip:6213) DEBUG: name = flip last_ts = 325.528748 last_received_ts = 325.527985 last_seq = 171 current_ts = 325.545441 current_received_ts = 325.544617 current_seq = 172 count = 97 seq_step = 1 [324.005503] (kms_flip:6213) DEBUG: Vblank took 50us [324.022114] (kms_flip:6213) DEBUG: name = flip last_ts = 325.545441 last_received_ts = 325.544617 last_seq = 172 current_ts = 325.562103 current_received_ts = 325.561279 current_seq = 173 count = 98 seq_step = 1 [324.022167] (kms_flip:6213) DEBUG: Vblank took 48us [324.038809] (kms_flip:6213) DEBUG: name = flip last_ts = 325.562103 last_received_ts = 325.561279 last_seq = 173 current_ts = 325.578766 current_received_ts = 325.577972 current_seq = 174 count = 99 seq_step = 1 [324.038876] (kms_flip:6213) DEBUG: Vblank took 63us [324.055475] (kms_flip:6213) DEBUG: name = flip last_ts = 325.578766 last_received_ts = 325.577972 last_seq = 174 current_ts = 325.595428 current_received_ts = 325.594635 current_seq = 175 count = 100 seq_step = 1 [324.055531] (kms_flip:6213) DEBUG: Vblank took 53us [324.072111] (kms_flip:6213) DEBUG: name = flip last_ts = 325.595428 last_received_ts = 325.594635 last_seq = 175 current_ts = 325.612091 current_received_ts = 325.611267 current_seq = 176 count = 101 seq_step = 1 [324.072173] (kms_flip:6213) DEBUG: Vblank took 58us [324.088797] (kms_flip:6213) DEBUG: name = flip last_ts = 325.612091 last_received_ts = 325.611267 last_seq = 176 current_ts = 325.628754 current_received_ts = 325.627960 current_seq = 177 count = 102 seq_step = 1 [324.088860] (kms_flip:6213) DEBUG: Vblank took 61us [324.105453] (kms_flip:6213) DEBUG: name = flip last_ts = 325.628754 last_received_ts = 325.627960 last_seq = 177 current_ts = 325.645416 current_received_ts = 325.644623 current_seq = 178 count = 103 seq_step = 1 [324.105504] (kms_flip:6213) DEBUG: Vblank took 48us [324.122098] (kms_flip:6213) DEBUG: name = flip last_ts = 325.645416 last_received_ts = 325.644623 last_seq = 178 current_ts = 325.662079 current_received_ts = 325.661255 current_seq = 179 count = 104 seq_step = 1 [324.122149] (kms_flip:6213) DEBUG: Vblank took 48us [324.138793] (kms_flip:6213) DEBUG: name = flip last_ts = 325.662079 last_received_ts = 325.661255 last_seq = 179 current_ts = 325.678741 current_received_ts = 325.677948 current_seq = 180 count = 105 seq_step = 1 [324.138867] (kms_flip:6213) DEBUG: Vblank took 71us [324.155450] (kms_flip:6213) DEBUG: name = flip last_ts = 325.678741 last_received_ts = 325.677948 last_seq = 180 current_ts = 325.695404 current_received_ts = 325.694611 current_seq = 181 count = 106 seq_step = 1 [324.155499] (kms_flip:6213) DEBUG: Vblank took 46us [324.172088] (kms_flip:6213) DEBUG: name = flip last_ts = 325.695404 last_received_ts = 325.694611 last_seq = 181 current_ts = 325.712067 current_received_ts = 325.711273 current_seq = 182 count = 107 seq_step = 1 [324.172133] (kms_flip:6213) DEBUG: Vblank took 43us [324.188781] (kms_flip:6213) DEBUG: name = flip last_ts = 325.712067 last_received_ts = 325.711273 last_seq = 182 current_ts = 325.728729 current_received_ts = 325.727966 current_seq = 183 count = 108 seq_step = 1 [324.188837] (kms_flip:6213) DEBUG: Vblank took 52us [324.205449] (kms_flip:6213) DEBUG: name = flip last_ts = 325.728729 last_received_ts = 325.727966 last_seq = 183 current_ts = 325.745392 current_received_ts = 325.744629 current_seq = 184 count = 109 seq_step = 1 [324.205500] (kms_flip:6213) DEBUG: Vblank took 48us [324.222082] (kms_flip:6213) DEBUG: name = flip last_ts = 325.745392 last_received_ts = 325.744629 last_seq = 184 current_ts = 325.762085 current_received_ts = 325.761261 current_seq = 185 count = 110 seq_step = 1 [324.222132] (kms_flip:6213) DEBUG: Vblank took 47us [324.238775] (kms_flip:6213) DEBUG: name = flip last_ts = 325.762085 last_received_ts = 325.761261 last_seq = 185 current_ts = 325.778748 current_received_ts = 325.777954 current_seq = 186 count = 111 seq_step = 1 [324.239650] (kms_flip:6213) DEBUG: Vblank took 871us [324.239656] (kms_flip:6213) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931: [324.239731] (kms_flip:6213) CRITICAL: Failed assertion: end - start < 500 [324.239775] (kms_flip:6213) CRITICAL: Last errno: 4, Interrupted system call [324.253048] (kms_flip:6213) igt_core-INFO: Stack trace: [324.266227] (kms_flip:6213) igt_core-INFO: #0 ../lib/igt_core.c:2074 __igt_fail_assert() [324.267691] (kms_flip:6213) igt_core-INFO: #1 ../tests/kms_flip.c:926 run_test_on_crtc_set() [324.267761] (kms_flip:6213) igt_core-INFO: #2 ../tests/kms_flip.c:1920 run_test() [324.267810] (kms_flip:6213) igt_core-INFO: #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105() [324.267849] (kms_flip:6213) igt_core-INFO: #4 ../tests/kms_flip.c:2105 main() [324.271772] (kms_flip:6213) igt_core-INFO: #5 [__libc_init_first+0x8a] [324.272682] (kms_flip:6213) igt_core-INFO: #6 [__libc_start_main+0x8b] [324.272917] (kms_flip:6213) igt_core-INFO: #7 [_start+0x25] END ** Dynamic subtest B-eDP1: FAIL (3.100s)
Dmesg	<6> [322.937553] [IGT] kms_flip: starting dynamic subtest B-eDP1 <7> [322.939421] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430] <7> [322.940662] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:450] <7> [322.952419] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [322.952695] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [322.952905] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <7> [323.006190] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:151:pipe A] <7> [323.006268] 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> [323.006510] 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> [323.006637] 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> [323.006746] 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> [323.006852] 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> [323.006957] 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> [323.007057] 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> [323.007157] 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> [323.007256] 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> [323.007413] 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> [323.007537] 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> [323.007647] 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> [323.007749] 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> [323.007847] 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> [323.007945] 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> [323.008040] 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> [323.008133] 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> [323.008222] 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> [323.008312] 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> [323.008421] 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> [323.008526] 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> [323.008628] 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> [323.008717] 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> [323.008803] 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> [323.008902] 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> [323.009004] 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> [323.009108] 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> [323.009210] 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> [323.009293] 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> [323.009395] 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> [323.009499] 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> [323.009601] 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> [323.009687] 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> [323.009773] 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> [323.009859] 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> [323.009944] 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> [323.010029] 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> [323.010109] 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> [323.010188] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset <7> [323.010269] xe 0000:00:02.0: [drm:intel_dpll_crtc_put [xe]] [CRTC:151:pipe A] releasing DPLL 0 <7> [323.010538] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no <7> [323.010635] 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> [323.010731] 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> [323.010818] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz <7> [323.010937] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [323.011045] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz <7> [323.011133] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [323.011263] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:151:pipe A] enable: no [modeset] <7> [323.011398] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:35:plane 1A] fb: [NOFB], visible: no <7> [323.011537] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:65:plane 2A] fb: [NOFB], visible: no <7> [323.011648] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:95:plane 3A] fb: [NOFB], visible: no <7> [323.011746] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:125:plane 4A] fb: [NOFB], visible: no <7> [323.011837] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:135:plane 5A] fb: [NOFB], visible: no <7> [323.011927] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:145:cursor A] fb: [NOFB], visible: no <7> [323.012076] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off <7> [323.012179] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00 <7> [323.012418] xe 0000:00:02.0: [drm:intel_alpm_disable [xe]] Disabling ALPM <7> [323.012540] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]] <7> [323.214572] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 0 <7> [323.215048] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A <7> [323.218588] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power off <7> [323.218964] 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> [323.219388] 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> [323.270438] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [323.270775] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disable DPLL 0 (active 0x1, on? 1) for [CRTC:151:pipe A] <7> [323.271637] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000 <7> [323.272082] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - short <7> [323.272172] xe 0000:00:02.0: [drm:intel_dpll_disable [xe]] disabling DPLL 0 <7> [323.272507] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [323.272581] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A <7> [323.273419] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [323.273694] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [323.273939] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [323.274191] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [323.274474] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [323.274717] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [323.274968] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [323.275255] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [323.275564] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [323.275820] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [323.276144] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [323.276468] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [323.276739] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [323.277034] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [323.277416] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [323.277683] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: ) <7> [323.277940] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1 <7> [323.278494] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A <7> [323.278870] 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> [323.279335] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A] <7> [323.279663] 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> [323.280107] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [323.280432] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384 <7> [323.281333] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [323.281709] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:389:pipe C] <7> [323.282004] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:270:pipe B] <7> [323.282070] xe 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:393:eDP-1] <7> [323.282258] 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> [323.282694] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:270:pipe B] 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> [323.283025] 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> [323.283377] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0 <7> [323.283696] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:392:DDI A/PHY A] [CRTC:270:pipe B] <7> [323.283991] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.enable (expected no, found yes) <7> [323.284301] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.active (expected no, found yes) <7> [323.284576] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1) <7> [323.284880] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in lane_count (expected 0, found 4) <7> [323.285143] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] 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> [323.285413] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100) <7> [323.285648] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1) <7> [323.285876] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880) <7> [323.286106] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040) <7> [323.286354] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880) <7> [323.286558] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040) <7> [323.286757] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928) <7> [323.286951] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960) <7> [323.287141] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800) <7> [323.287333] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800) <7> [323.287513] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803) <7> [323.287693] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809) <7> [323.287860] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906) <7> [323.288025] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906) <7> [323.288210] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880) <7> [323.288398] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040) <7> [323.288551] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880) <7> [323.288714] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040) <7> [323.288858] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928) <7> [323.288999] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960) <7> [323.289138] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800) <7> [323.289275] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800) <7> [323.289426] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803) <7> [323.289573] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809) <7> [323.289699] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906) <7> [323.289825] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906) <7> [323.289944] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1) <7> [323.290069] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2) <7> [323.290191] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8) <7> [323.290375] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30) <7> [323.290494] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710) <7> [323.290607] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710) <7> [323.290717] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in port_clock (expected 0, found 432000) <7> [323.290832] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset <7> [323.290983] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes <7> [323.291080] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:270:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2 <7> [323.291203] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051 <7> [323.291299] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:264:cursor B] ddb ( 0 - 0) -> (4051 - 4096), size 0 -> 45 <7> [323.291375] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> wm0,wm1,wm2,wm3,wm4,wm5, wm6, wm7,twm,swm,stwm <7> [323.291447] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0 <7> [323.291519] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197 <7> [323.291589] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] 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> [323.291668] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1 <7> [323.291792] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400 <7> [323.291900] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400 <7> [323.291999] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [323.292105] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400 <7> [323.292212] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461 <7> [323.292331] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz <7> [323.292466] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] Can change cdclk via squashing <7> [323.292586] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz <7> [323.292682] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] New voltage level calculated to be logical 0, actual 0 <7> [323.292794] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0 <7> [323.292890] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0 <7> [323.292981] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset] <7> [323.293072] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB <7> [323.293162] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0 <7> [323.293252] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid> <7> [323.293365] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0 <7> [323.293471] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0 <7> [323.293576] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0 <7> [323.293657] 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> [323.293742] 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> [323.293838] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled <7> [323.293932] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled <7> [323.294019] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled <7> [323.294107] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] minimum hblank: 0 <7> [323.294193] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4 <7> [323.294284] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14 <7> [323.294386] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB <7> [323.294488] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB <7> [323.294584] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0 <7> [323.294666] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range <7> [323.294752] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined <7> [323.294835] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] scanline offset: 1 <7> [323.294919] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0, set context latency: 0 <7> [323.295014] 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> [323.295114] 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> [323.295212] 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> [323.295316] 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> [323.295417] 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> [323.295515] 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> [323.295607] 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> [323.295681] 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> [323.295756] 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> [323.295838] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0 <7> [323.295925] 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> [323.296007] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0 <7> [323.296088] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no <7> [323.296168] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sharpness strength: 0, sharpness tap size: 0, sharpness enable: 0 <7> [323.296247] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0 <7> [323.296351] 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> [323.296448] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no, <7> [323.296541] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] multiplier: 225, tx_clk_div: 1. <7> [323.296630] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_rawhw_state: <7> [323.296707] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] tx: 0x10, cmn: 0x21 <7> [323.296794] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[0] = 0x4, pll[1] = 0x0, pll[2] = 0xa2, pll[3] = 0x1 <7> [323.296884] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[4] = 0x0, pll[5] = 0x0, pll[6] = 0x0, pll[7] = 0x0 <7> [323.296969] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[8] = 0x0, pll[9] = 0x1, pll[10] = 0x0, pll[11] = 0x0 <7> [323.297053] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[12] = 0x0, pll[13] = 0x0, pll[14] = 0x0, pll[15] = 0x1 <7> [323.297151] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pll[16] = 0x85, pll[17] = 0xf, pll[18] = 0xe6, pll[19] = 0x23 <7> [323.297260] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0 <7> [323.297380] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries <7> [323.297480] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000 <7> [323.297574] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [323.297649] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [323.297725] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000 <7> [323.297813] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000 <7> [323.297899] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000 <7> [323.297982] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [323.298062] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [323.298143] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000 <7> [323.298223] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000 <7> [323.298321] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:154:plane 1B] fb: [FB:430] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x100000000000009, visible: yes <7> [323.298421] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0 <7> [323.298518] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0 <7> [323.298611] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no <7> [323.298698] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no <7> [323.298780] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no <7> [323.298872] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no <7> [323.298976] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no <7> [323.299328] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2 <7> [323.299488] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B <7> [323.299655] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000) <7> [323.299782] 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> [323.299890] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no) <7> [323.299985] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480 <7> [323.300079] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:392:DDI A/PHY A] <7> [323.300157] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:401:DDI TC1/PHY TC1] <7> [323.300228] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:403:DP-MST A] <7> [323.300308] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:404:DP-MST B] <7> [323.300398] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:405:DP-MST C] <7> [323.300489] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:413:DDI TC2/PHY TC2] <7> [323.300580] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:415:DP-MST A] <7> [323.300653] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:416:DP-MST B] <7> [323.300724] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:417:DP-MST C] <7> [323.300795] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:421:DDI TC3/PHY TC3] <7> [323.300865] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:423:DP-MST A] <7> [323.300934] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:424:DP-MST B] <7> [323.301004] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:425:DP-MST C] <7> [323.301093] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf <7> [323.301254] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *) <7> [323.301350] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes) <7> [323.301481] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A <7> [323.302333] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B] <7> [323.302456] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enabling DPLL 0 <7> [323.304494] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turn panel power on <7> [323.304606] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 wait for panel power cycle (467 ms remaining) <7> [323.310722] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [323.310867] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [323.310964] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10 <7> [323.311068] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [323.774495] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060 <7> [323.825662] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [323.826220] 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> [323.826756] 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> [323.862948] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010 <7> [323.863325] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:392:DDI A/PHY A] - long <7> [323.863658] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20 <7> [323.864020] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:392:DDI A/PHY A] <7> [324.035573] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete <7> [324.036009] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:392:DDI A/PHY A] PPS 0 turning VDD on <7> [324.036453] 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> [324.038561] 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> [324.040113] 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> [324.041020] 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> [324.042303] 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> [324.043749] 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> [324.044915] 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> [324.045326] 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> [324.046819] 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> [324.047186] 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> [324.048084] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B <7> [324.048596] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]] <7> [324.048952] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B <7> [324.049383] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:393:eDP-1] set backlight PWM = 4518 <7> [324.082001] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2 <7> [324.083733] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:393:eDP-1] <7> [324.084213] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B] <7> [325.982188] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off <7> [325.982749] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6 <7> [325.983250] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02 <6> [326.038172] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Detail

Value

Duration

3.10 seconds

Hostname

shard-lnl-3

Igt-Version

IGT-Version: 2.4-g61afca4ff (x86_64) (Linux: 7.1.0-rc3-lgci-xe-xe-5053-8fbb3d48e61c7e68c-debug+ x86_64)

Out

Starting dynamic subtest: B-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:2220 __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 B-eDP1: FAIL (3.100s)

Err

Starting dynamic subtest: B-eDP1
[324.239656] (kms_flip:6213) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[324.239731] (kms_flip:6213) CRITICAL: Failed assertion: end - start < 500
[324.239775] (kms_flip:6213) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
[321.213240] (kms_flip:6213) drmtest-DEBUG: Test requirement passed: is_intel_device(fd)
[321.214300] (kms_flip:6213) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=11520)
[321.214307] (kms_flip:6213) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
[321.222143] (kms_flip:6213) intel_allocator_simple-DEBUG: Using simple allocator
[321.230011] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a9e40, fd: 5> objects: 3, reserved_areas: 0
[321.230013] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a9e40, fd: 5> objects: 3, reserved_areas: 0
[321.246825] (kms_flip:6213) intel_allocator_simple-DEBUG: Using simple allocator
[321.250972] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a5560, fd: 5> objects: 3, reserved_areas: 0
[321.250973] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a5560, fd: 5> objects: 3, reserved_areas: 0
[321.255627] (kms_flip:6213) intel_allocator_simple-DEBUG: Using simple allocator
[321.260174] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a60f0, fd: 5> objects: 3, reserved_areas: 0
[321.260176] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a60f0, fd: 5> objects: 3, reserved_areas: 0
[321.273342] (kms_flip:6213) intel_allocator_simple-DEBUG: Using simple allocator
[321.277240] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a5560, fd: 5> objects: 3, reserved_areas: 0
[321.277242] (kms_flip:6213) intel_allocator_simple-DEBUG: <ial: 0x56d5cb4a5560, fd: 5> objects: 3, reserved_areas: 0
[321.278660] (kms_flip:6213) igt_kms-INFO:   2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
[321.279880] (kms_flip:6213) DEBUG: No stale events found
[322.361755] (kms_flip:6213) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
[322.362045] (kms_flip:6213) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
[322.389035] (kms_flip:6213) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 323.928925
current_received_ts = 323.928101
current_seq = 75
count = 0
seq_step = 1
[322.389138] (kms_flip:6213) DEBUG: Vblank took 88us
[322.405737] (kms_flip:6213) DEBUG: name = flip
last_ts = 323.928925
last_received_ts = 323.928101
last_seq = 75
current_ts = 323.945587
current_received_ts = 323.944824
current_seq = 76
count = 1
seq_step = 1
[322.405812] (kms_flip:6213) DEBUG: Vblank took 69us
[322.422364] (kms_flip:6213) DEBUG: name = flip
last_ts = 323.945587
last_received_ts = 323.944824
last_seq = 76
current_ts = 323.962250
current_received_ts = 323.961456
current_seq = 77
count = 2
seq_step = 1
[322.422416] (kms_flip:6213) DEBUG: Vblank took 50us
[322.439044] (kms_flip:6213) DEBUG: name = flip
last_ts = 323.962250
last_received_ts = 323.961456
last_seq = 77
current_ts = 323.978943
current_received_ts = 323.978119
current_seq = 78
count = 3
seq_step = 1
[322.439092] (kms_flip:6213) DEBUG: Vblank took 45us
[322.455728] (kms_flip:6213) DEBUG: name = flip
last_ts = 323.978943
last_received_ts = 323.978119
last_seq = 78
current_ts = 323.995605
current_received_ts = 323.994812
current_seq = 79
count = 4
seq_step = 1
[322.455777] (kms_flip:6213) DEBUG: Vblank took 46us
[322.472390] (kms_flip:6213) DEBUG: name = flip
last_ts = 323.995605
last_received_ts = 323.994812
last_seq = 79
current_ts = 324.012268
current_received_ts = 324.011475
current_seq = 80
count = 5
seq_step = 1
[322.472440] (kms_flip:6213) DEBUG: Vblank took 47us
[322.489028] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.012268
last_received_ts = 324.011475
last_seq = 80
current_ts = 324.028931
current_received_ts = 324.028107
current_seq = 81
count = 6
seq_step = 1
[322.489077] (kms_flip:6213) DEBUG: Vblank took 46us
[322.505718] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.028931
last_received_ts = 324.028107
last_seq = 81
current_ts = 324.045593
current_received_ts = 324.044800
current_seq = 82
count = 7
seq_step = 1
[322.505769] (kms_flip:6213) DEBUG: Vblank took 47us
[322.522397] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.045593
last_received_ts = 324.044800
last_seq = 82
current_ts = 324.062256
current_received_ts = 324.061493
current_seq = 83
count = 8
seq_step = 1
[322.522446] (kms_flip:6213) DEBUG: Vblank took 46us
[322.539029] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.062256
last_received_ts = 324.061493
last_seq = 83
current_ts = 324.078918
current_received_ts = 324.078125
current_seq = 84
count = 9
seq_step = 1
[322.539077] (kms_flip:6213) DEBUG: Vblank took 46us
[322.555718] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.078918
last_received_ts = 324.078125
last_seq = 84
current_ts = 324.095581
current_received_ts = 324.094818
current_seq = 85
count = 10
seq_step = 1
[322.555766] (kms_flip:6213) DEBUG: Vblank took 46us
[322.572380] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.095581
last_received_ts = 324.094818
last_seq = 85
current_ts = 324.112244
current_received_ts = 324.111481
current_seq = 86
count = 11
seq_step = 1
[322.572427] (kms_flip:6213) DEBUG: Vblank took 45us
[322.589011] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.112244
last_received_ts = 324.111481
last_seq = 86
current_ts = 324.128906
current_received_ts = 324.128113
current_seq = 87
count = 12
seq_step = 1
[322.589059] (kms_flip:6213) DEBUG: Vblank took 46us
[322.605675] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.128906
last_received_ts = 324.128113
last_seq = 87
current_ts = 324.145569
current_received_ts = 324.144775
current_seq = 88
count = 13
seq_step = 1
[322.605727] (kms_flip:6213) DEBUG: Vblank took 49us
[322.622359] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.145569
last_received_ts = 324.144775
last_seq = 88
current_ts = 324.162231
current_received_ts = 324.161438
current_seq = 89
count = 14
seq_step = 1
[322.622424] (kms_flip:6213) DEBUG: Vblank took 63us
[322.639005] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.162231
last_received_ts = 324.161438
last_seq = 89
current_ts = 324.178894
current_received_ts = 324.178101
current_seq = 90
count = 15
seq_step = 1
[322.639054] (kms_flip:6213) DEBUG: Vblank took 46us
[322.655692] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.178894
last_received_ts = 324.178101
last_seq = 90
current_ts = 324.195557
current_received_ts = 324.194794
current_seq = 91
count = 16
seq_step = 1
[322.655740] (kms_flip:6213) DEBUG: Vblank took 46us
[322.672346] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.195557
last_received_ts = 324.194794
last_seq = 91
current_ts = 324.212250
current_received_ts = 324.211426
current_seq = 92
count = 17
seq_step = 1
[322.672393] (kms_flip:6213) DEBUG: Vblank took 44us
[322.689000] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.212250
last_received_ts = 324.211426
last_seq = 92
current_ts = 324.228912
current_received_ts = 324.228088
current_seq = 93
count = 18
seq_step = 1
[322.689050] (kms_flip:6213) DEBUG: Vblank took 48us
[322.705680] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.228912
last_received_ts = 324.228088
last_seq = 93
current_ts = 324.245575
current_received_ts = 324.244781
current_seq = 94
count = 19
seq_step = 1
[322.705728] (kms_flip:6213) DEBUG: Vblank took 46us
[322.722343] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.245575
last_received_ts = 324.244781
last_seq = 94
current_ts = 324.262238
current_received_ts = 324.261444
current_seq = 95
count = 20
seq_step = 1
[322.722383] (kms_flip:6213) DEBUG: Vblank took 37us
[322.738989] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.262238
last_received_ts = 324.261444
last_seq = 95
current_ts = 324.278900
current_received_ts = 324.278076
current_seq = 96
count = 21
seq_step = 1
[322.739038] (kms_flip:6213) DEBUG: Vblank took 46us
[322.755645] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.278900
last_received_ts = 324.278076
last_seq = 96
current_ts = 324.295563
current_received_ts = 324.294739
current_seq = 97
count = 22
seq_step = 1
[322.755694] (kms_flip:6213) DEBUG: Vblank took 47us
[322.772321] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.295563
last_received_ts = 324.294739
last_seq = 97
current_ts = 324.312225
current_received_ts = 324.311432
current_seq = 98
count = 23
seq_step = 1
[322.772369] (kms_flip:6213) DEBUG: Vblank took 45us
[322.788979] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.312225
last_received_ts = 324.311432
last_seq = 98
current_ts = 324.328888
current_received_ts = 324.328064
current_seq = 99
count = 24
seq_step = 1
[322.789028] (kms_flip:6213) DEBUG: Vblank took 47us
[322.805667] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.328888
last_received_ts = 324.328064
last_seq = 99
current_ts = 324.345551
current_received_ts = 324.344757
current_seq = 100
count = 25
seq_step = 1
[322.805714] (kms_flip:6213) DEBUG: Vblank took 45us
[322.822322] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.345551
last_received_ts = 324.344757
last_seq = 100
current_ts = 324.362213
current_received_ts = 324.361420
current_seq = 101
count = 26
seq_step = 1
[322.822370] (kms_flip:6213) DEBUG: Vblank took 46us
[322.838974] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.362213
last_received_ts = 324.361420
last_seq = 101
current_ts = 324.378876
current_received_ts = 324.378082
current_seq = 102
count = 27
seq_step = 1
[322.839021] (kms_flip:6213) DEBUG: Vblank took 46us
[322.855645] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.378876
last_received_ts = 324.378082
last_seq = 102
current_ts = 324.395538
current_received_ts = 324.394745
current_seq = 103
count = 28
seq_step = 1
[322.855701] (kms_flip:6213) DEBUG: Vblank took 52us
[322.872322] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.395538
last_received_ts = 324.394745
last_seq = 103
current_ts = 324.412231
current_received_ts = 324.411438
current_seq = 104
count = 29
seq_step = 1
[322.872375] (kms_flip:6213) DEBUG: Vblank took 50us
[322.888972] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.412231
last_received_ts = 324.411438
last_seq = 104
current_ts = 324.428894
current_received_ts = 324.428070
current_seq = 105
count = 30
seq_step = 1
[322.889023] (kms_flip:6213) DEBUG: Vblank took 48us
[322.905643] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.428894
last_received_ts = 324.428070
last_seq = 105
current_ts = 324.445557
current_received_ts = 324.444763
current_seq = 106
count = 31
seq_step = 1
[322.905694] (kms_flip:6213) DEBUG: Vblank took 48us
[322.922285] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.445557
last_received_ts = 324.444763
last_seq = 106
current_ts = 324.462219
current_received_ts = 324.461395
current_seq = 107
count = 32
seq_step = 1
[322.922333] (kms_flip:6213) DEBUG: Vblank took 45us
[322.938959] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.462219
last_received_ts = 324.461395
last_seq = 107
current_ts = 324.478882
current_received_ts = 324.478058
current_seq = 108
count = 33
seq_step = 1
[322.939010] (kms_flip:6213) DEBUG: Vblank took 48us
[322.955647] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.478882
last_received_ts = 324.478058
last_seq = 108
current_ts = 324.495544
current_received_ts = 324.494751
current_seq = 109
count = 34
seq_step = 1
[322.955701] (kms_flip:6213) DEBUG: Vblank took 50us
[322.972299] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.495544
last_received_ts = 324.494751
last_seq = 109
current_ts = 324.512207
current_received_ts = 324.511414
current_seq = 110
count = 35
seq_step = 1
[322.972342] (kms_flip:6213) DEBUG: Vblank took 40us
[322.988958] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.512207
last_received_ts = 324.511414
last_seq = 110
current_ts = 324.528870
current_received_ts = 324.528076
current_seq = 111
count = 36
seq_step = 1
[322.989006] (kms_flip:6213) DEBUG: Vblank took 46us
[323.005634] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.528870
last_received_ts = 324.528076
last_seq = 111
current_ts = 324.545532
current_received_ts = 324.544739
current_seq = 112
count = 37
seq_step = 1
[323.005686] (kms_flip:6213) DEBUG: Vblank took 49us
[323.022304] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.545532
last_received_ts = 324.544739
last_seq = 112
current_ts = 324.562195
current_received_ts = 324.561401
current_seq = 113
count = 38
seq_step = 1
[323.022351] (kms_flip:6213) DEBUG: Vblank took 44us
[323.038947] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.562195
last_received_ts = 324.561401
last_seq = 113
current_ts = 324.578857
current_received_ts = 324.578064
current_seq = 114
count = 39
seq_step = 1
[323.038999] (kms_flip:6213) DEBUG: Vblank took 49us
[323.055625] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.578857
last_received_ts = 324.578064
last_seq = 114
current_ts = 324.595520
current_received_ts = 324.594727
current_seq = 115
count = 40
seq_step = 1
[323.055681] (kms_flip:6213) DEBUG: Vblank took 53us
[323.072260] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.595520
last_received_ts = 324.594727
last_seq = 115
current_ts = 324.612183
current_received_ts = 324.611389
current_seq = 116
count = 41
seq_step = 1
[323.072308] (kms_flip:6213) DEBUG: Vblank took 46us
[323.088962] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.612183
last_received_ts = 324.611389
last_seq = 116
current_ts = 324.628845
current_received_ts = 324.628082
current_seq = 117
count = 42
seq_step = 1
[323.089011] (kms_flip:6213) DEBUG: Vblank took 48us
[323.105617] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.628845
last_received_ts = 324.628082
last_seq = 117
current_ts = 324.645508
current_received_ts = 324.644745
current_seq = 118
count = 43
seq_step = 1
[323.105664] (kms_flip:6213) DEBUG: Vblank took 46us
[323.122272] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.645508
last_received_ts = 324.644745
last_seq = 118
current_ts = 324.662201
current_received_ts = 324.661377
current_seq = 119
count = 44
seq_step = 1
[323.122322] (kms_flip:6213) DEBUG: Vblank took 47us
[323.138941] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.662201
last_received_ts = 324.661377
last_seq = 119
current_ts = 324.678864
current_received_ts = 324.678070
current_seq = 120
count = 45
seq_step = 1
[323.138995] (kms_flip:6213) DEBUG: Vblank took 50us
[323.155608] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.678864
last_received_ts = 324.678070
last_seq = 120
current_ts = 324.695526
current_received_ts = 324.694733
current_seq = 121
count = 46
seq_step = 1
[323.155657] (kms_flip:6213) DEBUG: Vblank took 47us
[323.172274] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.695526
last_received_ts = 324.694733
last_seq = 121
current_ts = 324.712189
current_received_ts = 324.711395
current_seq = 122
count = 47
seq_step = 1
[323.172325] (kms_flip:6213) DEBUG: Vblank took 48us
[323.188933] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.712189
last_received_ts = 324.711395
last_seq = 122
current_ts = 324.728851
current_received_ts = 324.728058
current_seq = 123
count = 48
seq_step = 1
[323.188984] (kms_flip:6213) DEBUG: Vblank took 49us
[323.205601] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.728851
last_received_ts = 324.728058
last_seq = 123
current_ts = 324.745514
current_received_ts = 324.744720
current_seq = 124
count = 49
seq_step = 1
[323.205651] (kms_flip:6213) DEBUG: Vblank took 46us
[323.222235] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.745514
last_received_ts = 324.744720
last_seq = 124
current_ts = 324.762177
current_received_ts = 324.761353
current_seq = 125
count = 50
seq_step = 1
[323.222287] (kms_flip:6213) DEBUG: Vblank took 48us
[323.238912] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.762177
last_received_ts = 324.761353
last_seq = 125
current_ts = 324.778839
current_received_ts = 324.778046
current_seq = 126
count = 51
seq_step = 1
[323.238962] (kms_flip:6213) DEBUG: Vblank took 46us
[323.255595] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.778839
last_received_ts = 324.778046
last_seq = 126
current_ts = 324.795502
current_received_ts = 324.794708
current_seq = 127
count = 52
seq_step = 1
[323.255643] (kms_flip:6213) DEBUG: Vblank took 45us
[323.272254] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.795502
last_received_ts = 324.794708
last_seq = 127
current_ts = 324.812164
current_received_ts = 324.811371
current_seq = 128
count = 53
seq_step = 1
[323.272309] (kms_flip:6213) DEBUG: Vblank took 51us
[323.288937] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.812164
last_received_ts = 324.811371
last_seq = 128
current_ts = 324.828827
current_received_ts = 324.828064
current_seq = 129
count = 54
seq_step = 1
[323.288993] (kms_flip:6213) DEBUG: Vblank took 53us
[323.305595] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.828827
last_received_ts = 324.828064
last_seq = 129
current_ts = 324.845490
current_received_ts = 324.844727
current_seq = 130
count = 55
seq_step = 1
[323.305640] (kms_flip:6213) DEBUG: Vblank took 44us
[323.322248] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.845490
last_received_ts = 324.844727
last_seq = 130
current_ts = 324.862183
current_received_ts = 324.861389
current_seq = 131
count = 56
seq_step = 1
[323.322294] (kms_flip:6213) DEBUG: Vblank took 44us
[323.338920] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.862183
last_received_ts = 324.861389
last_seq = 131
current_ts = 324.878845
current_received_ts = 324.878052
current_seq = 132
count = 57
seq_step = 1
[323.338969] (kms_flip:6213) DEBUG: Vblank took 46us
[323.355573] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.878845
last_received_ts = 324.878052
last_seq = 132
current_ts = 324.895508
current_received_ts = 324.894714
current_seq = 133
count = 58
seq_step = 1
[323.355620] (kms_flip:6213) DEBUG: Vblank took 44us
[323.372232] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.895508
last_received_ts = 324.894714
last_seq = 133
current_ts = 324.912170
current_received_ts = 324.911377
current_seq = 134
count = 59
seq_step = 1
[323.372280] (kms_flip:6213) DEBUG: Vblank took 45us
[323.388895] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.912170
last_received_ts = 324.911377
last_seq = 134
current_ts = 324.928833
current_received_ts = 324.928040
current_seq = 135
count = 60
seq_step = 1
[323.388947] (kms_flip:6213) DEBUG: Vblank took 50us
[323.405587] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.928833
last_received_ts = 324.928040
last_seq = 135
current_ts = 324.945496
current_received_ts = 324.944733
current_seq = 136
count = 61
seq_step = 1
[323.405638] (kms_flip:6213) DEBUG: Vblank took 49us
[323.422226] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.945496
last_received_ts = 324.944733
last_seq = 136
current_ts = 324.962158
current_received_ts = 324.961365
current_seq = 137
count = 62
seq_step = 1
[323.422277] (kms_flip:6213) DEBUG: Vblank took 47us
[323.438911] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.962158
last_received_ts = 324.961365
last_seq = 137
current_ts = 324.978821
current_received_ts = 324.978058
current_seq = 138
count = 63
seq_step = 1
[323.438962] (kms_flip:6213) DEBUG: Vblank took 48us
[323.455567] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.978821
last_received_ts = 324.978058
last_seq = 138
current_ts = 324.995483
current_received_ts = 324.994690
current_seq = 139
count = 64
seq_step = 1
[323.455624] (kms_flip:6213) DEBUG: Vblank took 54us
[323.472221] (kms_flip:6213) DEBUG: name = flip
last_ts = 324.995483
last_received_ts = 324.994690
last_seq = 139
current_ts = 325.012146
current_received_ts = 325.011353
current_seq = 140
count = 65
seq_step = 1
[323.472272] (kms_flip:6213) DEBUG: Vblank took 47us
[323.488908] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.012146
last_received_ts = 325.011353
last_seq = 140
current_ts = 325.028809
current_received_ts = 325.028046
current_seq = 141
count = 66
seq_step = 1
[323.488959] (kms_flip:6213) DEBUG: Vblank took 48us
[323.505553] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.028809
last_received_ts = 325.028046
last_seq = 141
current_ts = 325.045471
current_received_ts = 325.044678
current_seq = 142
count = 67
seq_step = 1
[323.505602] (kms_flip:6213) DEBUG: Vblank took 47us
[323.522201] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.045471
last_received_ts = 325.044678
last_seq = 142
current_ts = 325.062134
current_received_ts = 325.061340
current_seq = 143
count = 68
seq_step = 1
[323.522256] (kms_flip:6213) DEBUG: Vblank took 51us
[323.538854] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.062134
last_received_ts = 325.061340
last_seq = 143
current_ts = 325.078796
current_received_ts = 325.078003
current_seq = 144
count = 69
seq_step = 1
[323.538925] (kms_flip:6213) DEBUG: Vblank took 68us
[323.555521] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.078796
last_received_ts = 325.078003
last_seq = 144
current_ts = 325.095459
current_received_ts = 325.094666
current_seq = 145
count = 70
seq_step = 1
[323.555569] (kms_flip:6213) DEBUG: Vblank took 46us
[323.572183] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.095459
last_received_ts = 325.094666
last_seq = 145
current_ts = 325.112152
current_received_ts = 325.111328
current_seq = 146
count = 71
seq_step = 1
[323.572231] (kms_flip:6213) DEBUG: Vblank took 45us
[323.588881] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.112152
last_received_ts = 325.111328
last_seq = 146
current_ts = 325.128815
current_received_ts = 325.128021
current_seq = 147
count = 72
seq_step = 1
[323.588925] (kms_flip:6213) DEBUG: Vblank took 42us
[323.605542] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.128815
last_received_ts = 325.128021
last_seq = 147
current_ts = 325.145477
current_received_ts = 325.144684
current_seq = 148
count = 73
seq_step = 1
[323.605598] (kms_flip:6213) DEBUG: Vblank took 52us
[323.622179] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.145477
last_received_ts = 325.144684
last_seq = 148
current_ts = 325.162140
current_received_ts = 325.161316
current_seq = 149
count = 74
seq_step = 1
[323.622233] (kms_flip:6213) DEBUG: Vblank took 52us
[323.638886] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.162140
last_received_ts = 325.161316
last_seq = 149
current_ts = 325.178802
current_received_ts = 325.178040
current_seq = 150
count = 75
seq_step = 1
[323.638930] (kms_flip:6213) DEBUG: Vblank took 41us
[323.655529] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.178802
last_received_ts = 325.178040
last_seq = 150
current_ts = 325.195465
current_received_ts = 325.194672
current_seq = 151
count = 76
seq_step = 1
[323.655573] (kms_flip:6213) DEBUG: Vblank took 41us
[323.672189] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.195465
last_received_ts = 325.194672
last_seq = 151
current_ts = 325.212128
current_received_ts = 325.211334
current_seq = 152
count = 77
seq_step = 1
[323.672238] (kms_flip:6213) DEBUG: Vblank took 48us
[323.688871] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.212128
last_received_ts = 325.211334
last_seq = 152
current_ts = 325.228790
current_received_ts = 325.227997
current_seq = 153
count = 78
seq_step = 1
[323.688924] (kms_flip:6213) DEBUG: Vblank took 49us
[323.705498] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.228790
last_received_ts = 325.227997
last_seq = 153
current_ts = 325.245453
current_received_ts = 325.244659
current_seq = 154
count = 79
seq_step = 1
[323.705555] (kms_flip:6213) DEBUG: Vblank took 54us
[323.722159] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.245453
last_received_ts = 325.244659
last_seq = 154
current_ts = 325.262115
current_received_ts = 325.261322
current_seq = 155
count = 80
seq_step = 1
[323.722210] (kms_flip:6213) DEBUG: Vblank took 49us
[323.738858] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.262115
last_received_ts = 325.261322
last_seq = 155
current_ts = 325.278778
current_received_ts = 325.277985
current_seq = 156
count = 81
seq_step = 1
[323.738900] (kms_flip:6213) DEBUG: Vblank took 39us
[323.755521] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.278778
last_received_ts = 325.277985
last_seq = 156
current_ts = 325.295441
current_received_ts = 325.294678
current_seq = 157
count = 82
seq_step = 1
[323.755567] (kms_flip:6213) DEBUG: Vblank took 44us
[323.772165] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.295441
last_received_ts = 325.294678
last_seq = 157
current_ts = 325.312134
current_received_ts = 325.311310
current_seq = 158
count = 83
seq_step = 1
[323.772216] (kms_flip:6213) DEBUG: Vblank took 48us
[323.788863] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.312134
last_received_ts = 325.311310
last_seq = 158
current_ts = 325.328796
current_received_ts = 325.328003
current_seq = 159
count = 84
seq_step = 1
[323.788914] (kms_flip:6213) DEBUG: Vblank took 47us
[323.805508] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.328796
last_received_ts = 325.328003
last_seq = 159
current_ts = 325.345459
current_received_ts = 325.344666
current_seq = 160
count = 85
seq_step = 1
[323.805558] (kms_flip:6213) DEBUG: Vblank took 48us
[323.822142] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.345459
last_received_ts = 325.344666
last_seq = 160
current_ts = 325.362122
current_received_ts = 325.361298
current_seq = 161
count = 86
seq_step = 1
[323.822193] (kms_flip:6213) DEBUG: Vblank took 48us
[323.838833] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.362122
last_received_ts = 325.361298
last_seq = 161
current_ts = 325.378784
current_received_ts = 325.377991
current_seq = 162
count = 87
seq_step = 1
[323.838900] (kms_flip:6213) DEBUG: Vblank took 64us
[323.855469] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.378784
last_received_ts = 325.377991
last_seq = 162
current_ts = 325.395447
current_received_ts = 325.394623
current_seq = 163
count = 88
seq_step = 1
[323.855521] (kms_flip:6213) DEBUG: Vblank took 49us
[323.872157] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.395447
last_received_ts = 325.394623
last_seq = 163
current_ts = 325.412109
current_received_ts = 325.411316
current_seq = 164
count = 89
seq_step = 1
[323.872213] (kms_flip:6213) DEBUG: Vblank took 53us
[323.888823] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.412109
last_received_ts = 325.411316
last_seq = 164
current_ts = 325.428772
current_received_ts = 325.427979
current_seq = 165
count = 90
seq_step = 1
[323.888898] (kms_flip:6213) DEBUG: Vblank took 71us
[323.905500] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.428772
last_received_ts = 325.427979
last_seq = 165
current_ts = 325.445435
current_received_ts = 325.444672
current_seq = 166
count = 91
seq_step = 1
[323.905546] (kms_flip:6213) DEBUG: Vblank took 44us
[323.922128] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.445435
last_received_ts = 325.444672
last_seq = 166
current_ts = 325.462097
current_received_ts = 325.461273
current_seq = 167
count = 92
seq_step = 1
[323.922179] (kms_flip:6213) DEBUG: Vblank took 48us
[323.938819] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.462097
last_received_ts = 325.461273
last_seq = 167
current_ts = 325.478760
current_received_ts = 325.477966
current_seq = 168
count = 93
seq_step = 1
[323.938882] (kms_flip:6213) DEBUG: Vblank took 60us
[323.955485] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.478760
last_received_ts = 325.477966
last_seq = 168
current_ts = 325.495422
current_received_ts = 325.494659
current_seq = 169
count = 94
seq_step = 1
[323.955536] (kms_flip:6213) DEBUG: Vblank took 48us
[323.972122] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.495422
last_received_ts = 325.494659
last_seq = 169
current_ts = 325.512085
current_received_ts = 325.511292
current_seq = 170
count = 95
seq_step = 1
[323.972173] (kms_flip:6213) DEBUG: Vblank took 48us
[323.988818] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.512085
last_received_ts = 325.511292
last_seq = 170
current_ts = 325.528748
current_received_ts = 325.527985
current_seq = 171
count = 96
seq_step = 1
[323.988883] (kms_flip:6213) DEBUG: Vblank took 61us
[324.005450] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.528748
last_received_ts = 325.527985
last_seq = 171
current_ts = 325.545441
current_received_ts = 325.544617
current_seq = 172
count = 97
seq_step = 1
[324.005503] (kms_flip:6213) DEBUG: Vblank took 50us
[324.022114] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.545441
last_received_ts = 325.544617
last_seq = 172
current_ts = 325.562103
current_received_ts = 325.561279
current_seq = 173
count = 98
seq_step = 1
[324.022167] (kms_flip:6213) DEBUG: Vblank took 48us
[324.038809] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.562103
last_received_ts = 325.561279
last_seq = 173
current_ts = 325.578766
current_received_ts = 325.577972
current_seq = 174
count = 99
seq_step = 1
[324.038876] (kms_flip:6213) DEBUG: Vblank took 63us
[324.055475] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.578766
last_received_ts = 325.577972
last_seq = 174
current_ts = 325.595428
current_received_ts = 325.594635
current_seq = 175
count = 100
seq_step = 1
[324.055531] (kms_flip:6213) DEBUG: Vblank took 53us
[324.072111] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.595428
last_received_ts = 325.594635
last_seq = 175
current_ts = 325.612091
current_received_ts = 325.611267
current_seq = 176
count = 101
seq_step = 1
[324.072173] (kms_flip:6213) DEBUG: Vblank took 58us
[324.088797] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.612091
last_received_ts = 325.611267
last_seq = 176
current_ts = 325.628754
current_received_ts = 325.627960
current_seq = 177
count = 102
seq_step = 1
[324.088860] (kms_flip:6213) DEBUG: Vblank took 61us
[324.105453] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.628754
last_received_ts = 325.627960
last_seq = 177
current_ts = 325.645416
current_received_ts = 325.644623
current_seq = 178
count = 103
seq_step = 1
[324.105504] (kms_flip:6213) DEBUG: Vblank took 48us
[324.122098] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.645416
last_received_ts = 325.644623
last_seq = 178
current_ts = 325.662079
current_received_ts = 325.661255
current_seq = 179
count = 104
seq_step = 1
[324.122149] (kms_flip:6213) DEBUG: Vblank took 48us
[324.138793] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.662079
last_received_ts = 325.661255
last_seq = 179
current_ts = 325.678741
current_received_ts = 325.677948
current_seq = 180
count = 105
seq_step = 1
[324.138867] (kms_flip:6213) DEBUG: Vblank took 71us
[324.155450] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.678741
last_received_ts = 325.677948
last_seq = 180
current_ts = 325.695404
current_received_ts = 325.694611
current_seq = 181
count = 106
seq_step = 1
[324.155499] (kms_flip:6213) DEBUG: Vblank took 46us
[324.172088] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.695404
last_received_ts = 325.694611
last_seq = 181
current_ts = 325.712067
current_received_ts = 325.711273
current_seq = 182
count = 107
seq_step = 1
[324.172133] (kms_flip:6213) DEBUG: Vblank took 43us
[324.188781] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.712067
last_received_ts = 325.711273
last_seq = 182
current_ts = 325.728729
current_received_ts = 325.727966
current_seq = 183
count = 108
seq_step = 1
[324.188837] (kms_flip:6213) DEBUG: Vblank took 52us
[324.205449] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.728729
last_received_ts = 325.727966
last_seq = 183
current_ts = 325.745392
current_received_ts = 325.744629
current_seq = 184
count = 109
seq_step = 1
[324.205500] (kms_flip:6213) DEBUG: Vblank took 48us
[324.222082] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.745392
last_received_ts = 325.744629
last_seq = 184
current_ts = 325.762085
current_received_ts = 325.761261
current_seq = 185
count = 110
seq_step = 1
[324.222132] (kms_flip:6213) DEBUG: Vblank took 47us
[324.238775] (kms_flip:6213) DEBUG: name = flip
last_ts = 325.762085
last_received_ts = 325.761261
last_seq = 185
current_ts = 325.778748
current_received_ts = 325.777954
current_seq = 186
count = 111
seq_step = 1
[324.239650] (kms_flip:6213) DEBUG: Vblank took 871us
[324.239656] (kms_flip:6213) CRITICAL: Test assertion failure function run_test_step, file ../tests/kms_flip.c:931:
[324.239731] (kms_flip:6213) CRITICAL: Failed assertion: end - start < 500
[324.239775] (kms_flip:6213) CRITICAL: Last errno: 4, Interrupted system call
[324.253048] (kms_flip:6213) igt_core-INFO: Stack trace:
[324.266227] (kms_flip:6213) igt_core-INFO:   #0 ../lib/igt_core.c:2074 __igt_fail_assert()
[324.267691] (kms_flip:6213) igt_core-INFO:   #1 ../tests/kms_flip.c:926 run_test_on_crtc_set()
[324.267761] (kms_flip:6213) igt_core-INFO:   #2 ../tests/kms_flip.c:1920 run_test()
[324.267810] (kms_flip:6213) igt_core-INFO:   #3 ../tests/kms_flip.c:2220 __igt_unique____real_main2105()
[324.267849] (kms_flip:6213) igt_core-INFO:   #4 ../tests/kms_flip.c:2105 main()
[324.271772] (kms_flip:6213) igt_core-INFO:   #5 [__libc_init_first+0x8a]
[324.272682] (kms_flip:6213) igt_core-INFO:   #6 [__libc_start_main+0x8b]
[324.272917] (kms_flip:6213) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (3.100s)

Dmesg

<6> [322.937553] [IGT] kms_flip: starting dynamic subtest B-eDP1

<7> [322.939421] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:430]

<7> [322.940662] xe 0000:00:02.0: [drm:drm_mode_addfb2] [FB:450]

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

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

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

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

<7> [323.006268] 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> [323.006510] 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> [323.006637] 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> [323.006746] 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> [323.006852] 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> [323.006957] 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> [323.007057] 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> [323.007157] 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> [323.007256] 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> [323.007413] 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> [323.007537] 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> [323.007647] 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> [323.007749] 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> [323.007847] 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> [323.007945] 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> [323.008040] 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> [323.008133] 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> [323.008222] 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> [323.008312] 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> [323.008421] 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> [323.008526] 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> [323.008628] 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> [323.008717] 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> [323.008803] 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> [323.008902] 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> [323.009004] 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> [323.009108] 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> [323.009210] 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> [323.009293] 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> [323.009395] 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> [323.009499] 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> [323.009601] 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> [323.009687] 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> [323.009773] 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> [323.009859] 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> [323.009944] 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> [323.010029] 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> [323.010109] 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> [323.010188] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:151:pipe A] fastset requirement not met, forcing full modeset

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

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

<7> [323.010635] 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> [323.010731] 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> [323.010818] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:151:pipe A] min cdclk: 173855 kHz -> 0 kHz

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [323.218964] 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> [323.219388] 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> [323.270438] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [323.278870] 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> [323.279335] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:151:pipe A]

<7> [323.279663] 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> [323.280107] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

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

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

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

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

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

<7> [323.282258] 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> [323.282694] xe 0000:00:02.0: [drm:intel_dp_compute_config_limits [xe]] [ENCODER:392:DDI A/PHY A][CRTC:270:pipe B] 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> [323.283025] 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> [323.283377] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0

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

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

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

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

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

<7> [323.285143] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] 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> [323.285413] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:270:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [323.290832] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:270:pipe B] fastset requirement not met, forcing full modeset

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

<7> [323.291080] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:270:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2

<7> [323.291203] xe 0000:00:02.0: [drm:skl_print_plane_ddb_changes [xe]] [PLANE:154:plane 1B] ddb ( 0 - 0) -> ( 0 - 4051), size 0 -> 4051

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

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

<7> [323.291447] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 4, 13, 13, 13, 13, 13, 0, 0, 0, 4, 0

<7> [323.291519] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 92, 297, 297, 297, 297, 297, 0, 0, 197, 92, 197

<7> [323.291589] xe 0000:00:02.0: [drm:skl_print_plane_wm_changes [xe]] [PLANE:154:plane 1B] 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> [323.291668] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:270:pipe B] data rate 1390840 num active planes 1

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

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

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

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

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

<7> [323.292331] xe 0000:00:02.0: [drm:intel_cdclk_atomic_check [xe]] [CRTC:270:pipe B] min cdclk: 0 kHz -> 173855 kHz

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

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

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

<7> [323.292794] xe 0000:00:02.0: [drm:intel_find_dpll [xe]] [CRTC:270:pipe B] allocated DPLL 0

<7> [323.292890] xe 0000:00:02.0: [drm:intel_dpll_crtc_get [xe]] [CRTC:270:pipe B] reserving DPLL 0

<7> [323.292981] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:270:pipe B] enable: yes [modeset]

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

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

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

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

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

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

<7> [323.293657] 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> [323.293742] 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> [323.293838] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled

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

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

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

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

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

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

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

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

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

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

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

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

<7> [323.295014] 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> [323.295114] 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> [323.295212] 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> [323.295316] 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> [323.295417] 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> [323.295515] 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> [323.295607] 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> [323.295681] 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> [323.295756] 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> [323.295838] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0

<7> [323.295925] 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> [323.296007] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe src: 2880x1800+0+0

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

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

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

<7> [323.296351] 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> [323.296448] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] c10pll_hw_state: fracen: no,

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [323.298611] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:184:plane 2B] fb: [NOFB], visible: no

<7> [323.298698] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:214:plane 3B] fb: [NOFB], visible: no

<7> [323.298780] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:244:plane 4B] fb: [NOFB], visible: no

<7> [323.298872] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:254:plane 5B] fb: [NOFB], visible: no

<7> [323.298976] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:264:cursor B] fb: [NOFB], visible: no

<7> [323.299328] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2

<7> [323.299488] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B

<7> [323.299655] xe 0000:00:02.0: [drm:dss_pipe_gating_enable_disable [xe]] DSS clock gating enabled for pipe_mask=0x2 (CLKGATE_DIS_DSSDSC=0xa2000000)

<7> [323.299782] 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> [323.299890] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

<7> [323.302333] xe 0000:00:02.0: [drm:intel_dpll_enable [xe]] enable DPLL 0 (active 0x2, on? 0) for [CRTC:270:pipe B]

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

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

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

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

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

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

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

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

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

<7> [323.826220] 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> [323.826756] 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> [323.862948] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010

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

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

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

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

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

<7> [324.036453] 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> [324.038561] 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> [324.040113] 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> [324.041020] 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> [324.042303] 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> [324.043749] 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> [324.044915] 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> [324.045326] 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> [324.046819] 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> [324.047186] 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> [324.048084] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B

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

<7> [324.048952] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B

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

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

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

<7> [324.084213] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:270:pipe B]

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

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

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

<6> [326.038172] [IGT] kms_flip: finished subtest B-eDP1, FAIL

Results for igt@kms_flip@flip-vs-expired-vblank-interruptible@b-edp1