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

Machine description: shard-lnl-4

Result: Fail

i915_display_info20 igt_runner20 results20.json i915_display_info_post_exec20 boot20 dmesg20

DetailValue
Duration 8.90 seconds
Hostname 
shard-lnl-4
Igt-Version 
IGT-Version: 1.29-NO-GIT (x86_64) (Linux: 6.12.0-rc1-xe x86_64)
Out 
Starting dynamic subtest: B-eDP1
  2880x1800: 60 347710 2880 2928 2960 3040 1800 1803 1809 1906 0x48 0xa 
Expected frametime: 16664us; measured 16848.1us +- 4.856us accuracy 0.09%
vblank interval differs from modeline! expected 16664.0us, measured 16848us +- 4.856us, difference 184.1us (37.9 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (8.898s)
Err 
Starting dynamic subtest: B-eDP1
(kms_flip:2649) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2649) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:2649) DEBUG: flip ts/seq: last 289.449341/484, current 289.466125/485: elapsed=16798.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.466125
last_received_ts = 289.465271
last_seq = 485
current_ts = 289.482910
current_received_ts = 289.482086
current_seq = 486
count = 126
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.466125/485, current 289.482910/486: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.482910
last_received_ts = 289.482086
last_seq = 486
current_ts = 289.499725
current_received_ts = 289.498871
current_seq = 487
count = 127
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.482910/486, current 289.499725/487: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.499725
last_received_ts = 289.498871
last_seq = 487
current_ts = 289.516510
current_received_ts = 289.515656
current_seq = 488
count = 128
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.499725/487, current 289.516510/488: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.516510
last_received_ts = 289.515656
last_seq = 488
current_ts = 289.533295
current_received_ts = 289.532440
current_seq = 489
count = 129
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.516510/488, current 289.533295/489: elapsed=16789.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.533295
last_received_ts = 289.532440
last_seq = 489
current_ts = 289.550079
current_received_ts = 289.549225
current_seq = 490
count = 130
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.533295/489, current 289.550079/490: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.550079
last_received_ts = 289.549225
last_seq = 490
current_ts = 289.566864
current_received_ts = 289.566010
current_seq = 491
count = 131
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.550079/490, current 289.566864/491: elapsed=16791.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.566864
last_received_ts = 289.566010
last_seq = 491
current_ts = 289.583649
current_received_ts = 289.582825
current_seq = 492
count = 132
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.566864/491, current 289.583649/492: elapsed=16783.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.583649
last_received_ts = 289.582825
last_seq = 492
current_ts = 289.600433
current_received_ts = 289.599609
current_seq = 493
count = 133
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.583649/492, current 289.600433/493: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.600433
last_received_ts = 289.599609
last_seq = 493
current_ts = 289.617249
current_received_ts = 289.616394
current_seq = 494
count = 134
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.600433/493, current 289.617249/494: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.617249
last_received_ts = 289.616394
last_seq = 494
current_ts = 289.634033
current_received_ts = 289.633179
current_seq = 495
count = 135
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.617249/494, current 289.634033/495: elapsed=16797.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.634033
last_received_ts = 289.633179
last_seq = 495
current_ts = 289.650818
current_received_ts = 289.649963
current_seq = 496
count = 136
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.634033/495, current 289.650818/496: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.650818
last_received_ts = 289.649963
last_seq = 496
current_ts = 289.667603
current_received_ts = 289.666748
current_seq = 497
count = 137
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.650818/496, current 289.667603/497: elapsed=16791.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.667603
last_received_ts = 289.666748
last_seq = 497
current_ts = 289.684387
current_received_ts = 289.683563
current_seq = 498
count = 138
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.667603/497, current 289.684387/498: elapsed=16789.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.684387
last_received_ts = 289.683563
last_seq = 498
current_ts = 289.701172
current_received_ts = 289.700317
current_seq = 499
count = 139
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.684387/498, current 289.701172/499: elapsed=16783.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.701172
last_received_ts = 289.700317
last_seq = 499
current_ts = 289.717987
current_received_ts = 289.717133
current_seq = 500
count = 140
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.701172/499, current 289.717987/500: elapsed=16796.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.717987
last_received_ts = 289.717133
last_seq = 500
current_ts = 289.734772
current_received_ts = 289.733917
current_seq = 501
count = 141
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.717987/500, current 289.734772/501: elapsed=16791.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.734772
last_received_ts = 289.733917
last_seq = 501
current_ts = 289.751556
current_received_ts = 289.750702
current_seq = 502
count = 142
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.734772/501, current 289.751556/502: elapsed=16791.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.751556
last_received_ts = 289.750702
last_seq = 502
current_ts = 289.768341
current_received_ts = 289.767517
current_seq = 503
count = 143
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.751556/502, current 289.768341/503: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.768341
last_received_ts = 289.767517
last_seq = 503
current_ts = 289.785126
current_received_ts = 289.784302
current_seq = 504
count = 144
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.768341/503, current 289.785126/504: elapsed=16783.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.785126
last_received_ts = 289.784302
last_seq = 504
current_ts = 289.801941
current_received_ts = 289.801086
current_seq = 505
count = 145
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.785126/504, current 289.801941/505: elapsed=16796.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.801941
last_received_ts = 289.801086
last_seq = 505
current_ts = 289.818726
current_received_ts = 289.817871
current_seq = 506
count = 146
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.801941/505, current 289.818726/506: elapsed=16783.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.818726
last_received_ts = 289.817871
last_seq = 506
current_ts = 289.835510
current_received_ts = 289.834656
current_seq = 507
count = 147
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.818726/506, current 289.835510/507: elapsed=16798.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.835510
last_received_ts = 289.834656
last_seq = 507
current_ts = 289.852295
current_received_ts = 289.851440
current_seq = 508
count = 148
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.835510/507, current 289.852295/508: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.852295
last_received_ts = 289.851440
last_seq = 508
current_ts = 289.869080
current_received_ts = 289.868225
current_seq = 509
count = 149
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.852295/508, current 289.869080/509: elapsed=16784.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.869080
last_received_ts = 289.868225
last_seq = 509
current_ts = 289.885895
current_received_ts = 289.885040
current_seq = 510
count = 150
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.869080/509, current 289.885895/510: elapsed=16796.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.885895
last_received_ts = 289.885040
last_seq = 510
current_ts = 289.902679
current_received_ts = 289.901825
current_seq = 511
count = 151
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.885895/510, current 289.902679/511: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.902679
last_received_ts = 289.901825
last_seq = 511
current_ts = 289.919464
current_received_ts = 289.918610
current_seq = 512
count = 152
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.902679/511, current 289.919464/512: elapsed=16789.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.919464
last_received_ts = 289.918610
last_seq = 512
current_ts = 289.936249
current_received_ts = 289.935394
current_seq = 513
count = 153
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.919464/512, current 289.936249/513: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.936249
last_received_ts = 289.935394
last_seq = 513
current_ts = 289.953033
current_received_ts = 289.952179
current_seq = 514
count = 154
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.936249/513, current 289.953033/514: elapsed=16785.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.953033
last_received_ts = 289.952179
last_seq = 514
current_ts = 289.969818
current_received_ts = 289.970459
current_seq = 515
count = 155
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.953033/514, current 289.969818/515: elapsed=16789.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.969818
last_received_ts = 289.970459
last_seq = 515
current_ts = 289.986633
current_received_ts = 289.985779
current_seq = 516
count = 156
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.969818/515, current 289.986633/516: elapsed=16793.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 289.986633
last_received_ts = 289.985779
last_seq = 516
current_ts = 290.003418
current_received_ts = 290.002563
current_seq = 517
count = 157
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 289.986633/516, current 290.003418/517: elapsed=16787.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.003418
last_received_ts = 290.002563
last_seq = 517
current_ts = 290.020203
current_received_ts = 290.019348
current_seq = 518
count = 158
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.003418/517, current 290.020203/518: elapsed=16791.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.020203
last_received_ts = 290.019348
last_seq = 518
current_ts = 290.036987
current_received_ts = 290.036133
current_seq = 519
count = 159
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.020203/518, current 290.036987/519: elapsed=16794.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.036987
last_received_ts = 290.036133
last_seq = 519
current_ts = 290.053772
current_received_ts = 290.052948
current_seq = 520
count = 160
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.036987/519, current 290.053772/520: elapsed=16785.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.053772
last_received_ts = 290.052948
last_seq = 520
current_ts = 290.070557
current_received_ts = 290.069733
current_seq = 521
count = 161
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.053772/520, current 290.070557/521: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.070557
last_received_ts = 290.069733
last_seq = 521
current_ts = 290.087341
current_received_ts = 290.086517
current_seq = 522
count = 162
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.070557/521, current 290.087341/522: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.087341
last_received_ts = 290.086517
last_seq = 522
current_ts = 290.104156
current_received_ts = 290.103302
current_seq = 523
count = 163
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.087341/522, current 290.104156/523: elapsed=16789.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.104156
last_received_ts = 290.103302
last_seq = 523
current_ts = 290.120941
current_received_ts = 290.120178
current_seq = 524
count = 164
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.104156/523, current 290.120941/524: elapsed=16791.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.120941
last_received_ts = 290.120178
last_seq = 524
current_ts = 290.137726
current_received_ts = 290.136963
current_seq = 525
count = 165
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.120941/524, current 290.137726/525: elapsed=16792.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.137726
last_received_ts = 290.136963
last_seq = 525
current_ts = 290.154510
current_received_ts = 290.153717
current_seq = 526
count = 166
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.137726/525, current 290.154510/526: elapsed=16788.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.154510
last_received_ts = 290.153717
last_seq = 526
current_ts = 290.171295
current_received_ts = 290.170471
current_seq = 527
count = 167
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.154510/526, current 290.171295/527: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.171295
last_received_ts = 290.170471
last_seq = 527
current_ts = 290.188110
current_received_ts = 290.187256
current_seq = 528
count = 168
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.171295/527, current 290.188110/528: elapsed=16792.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.188110
last_received_ts = 290.187256
last_seq = 528
current_ts = 290.204895
current_received_ts = 290.204163
current_seq = 529
count = 169
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.188110/528, current 290.204895/529: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.204895
last_received_ts = 290.204163
last_seq = 529
current_ts = 290.221680
current_received_ts = 290.220825
current_seq = 530
count = 170
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.204895/529, current 290.221680/530: elapsed=16789.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.221680
last_received_ts = 290.220825
last_seq = 530
current_ts = 290.238464
current_received_ts = 290.237610
current_seq = 531
count = 171
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.221680/530, current 290.238464/531: elapsed=16789.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.238464
last_received_ts = 290.237610
last_seq = 531
current_ts = 290.255249
current_received_ts = 290.254395
current_seq = 532
count = 172
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.238464/531, current 290.255249/532: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.255249
last_received_ts = 290.254395
last_seq = 532
current_ts = 290.272034
current_received_ts = 290.271210
current_seq = 533
count = 173
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.255249/532, current 290.272034/533: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.272034
last_received_ts = 290.271210
last_seq = 533
current_ts = 290.288849
current_received_ts = 290.287994
current_seq = 534
count = 174
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.272034/533, current 290.288849/534: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.288849
last_received_ts = 290.287994
last_seq = 534
current_ts = 290.305634
current_received_ts = 290.304779
current_seq = 535
count = 175
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.288849/534, current 290.305634/535: elapsed=16798.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.305634
last_received_ts = 290.304779
last_seq = 535
current_ts = 290.322418
current_received_ts = 290.321564
current_seq = 536
count = 176
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.305634/535, current 290.322418/536: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.322418
last_received_ts = 290.321564
last_seq = 536
current_ts = 290.339203
current_received_ts = 290.338348
current_seq = 537
count = 177
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.322418/536, current 290.339203/537: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.339203
last_received_ts = 290.338348
last_seq = 537
current_ts = 290.355988
current_received_ts = 290.355164
current_seq = 538
count = 178
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.339203/537, current 290.355988/538: elapsed=16782.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.355988
last_received_ts = 290.355164
last_seq = 538
current_ts = 290.372772
current_received_ts = 290.371948
current_seq = 539
count = 179
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.355988/538, current 290.372772/539: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.372772
last_received_ts = 290.371948
last_seq = 539
current_ts = 290.389587
current_received_ts = 290.388733
current_seq = 540
count = 180
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.372772/539, current 290.389587/540: elapsed=16791.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.389587
last_received_ts = 290.388733
last_seq = 540
current_ts = 290.406372
current_received_ts = 290.405518
current_seq = 541
count = 181
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.389587/540, current 290.406372/541: elapsed=16791.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.406372
last_received_ts = 290.405518
last_seq = 541
current_ts = 290.423157
current_received_ts = 290.422302
current_seq = 542
count = 182
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.406372/541, current 290.423157/542: elapsed=16788.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.423157
last_received_ts = 290.422302
last_seq = 542
current_ts = 290.439941
current_received_ts = 290.439087
current_seq = 543
count = 183
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.423157/542, current 290.439941/543: elapsed=16790.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.439941
last_received_ts = 290.439087
last_seq = 543
current_ts = 290.456726
current_received_ts = 290.455872
current_seq = 544
count = 184
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.439941/543, current 290.456726/544: elapsed=16792.0us expected=16848.1us +- 84.2us, error 0.3%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.456726
last_received_ts = 290.455872
last_seq = 544
current_ts = 290.473511
current_received_ts = 290.472656
current_seq = 545
count = 185
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.456726/544, current 290.473511/545: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.473511
last_received_ts = 290.472656
last_seq = 545
current_ts = 290.490295
current_received_ts = 290.489441
current_seq = 546
count = 186
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.473511/545, current 290.490295/546: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.490295
last_received_ts = 290.489441
last_seq = 546
current_ts = 290.507050
current_received_ts = 290.506195
current_seq = 547
count = 187
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.490295/546, current 290.507050/547: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.507050
last_received_ts = 290.506195
last_seq = 547
current_ts = 290.523834
current_received_ts = 290.522980
current_seq = 548
count = 188
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.507050/547, current 290.523834/548: elapsed=16776.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.523834
last_received_ts = 290.522980
last_seq = 548
current_ts = 290.540619
current_received_ts = 290.539764
current_seq = 549
count = 189
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.523834/548, current 290.540619/549: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.540619
last_received_ts = 290.539764
last_seq = 549
current_ts = 290.557373
current_received_ts = 290.556549
current_seq = 550
count = 190
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.540619/549, current 290.557373/550: elapsed=16768.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.557373
last_received_ts = 290.556549
last_seq = 550
current_ts = 290.574158
current_received_ts = 290.573303
current_seq = 551
count = 191
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.557373/550, current 290.574158/551: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.574158
last_received_ts = 290.573303
last_seq = 551
current_ts = 290.590942
current_received_ts = 290.590088
current_seq = 552
count = 192
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.574158/551, current 290.590942/552: elapsed=16783.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.590942
last_received_ts = 290.590088
last_seq = 552
current_ts = 290.607727
current_received_ts = 290.606873
current_seq = 553
count = 193
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.590942/552, current 290.607727/553: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.607727
last_received_ts = 290.606873
last_seq = 553
current_ts = 290.624481
current_received_ts = 290.623627
current_seq = 554
count = 194
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.607727/553, current 290.624481/554: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.624481
last_received_ts = 290.623627
last_seq = 554
current_ts = 290.641266
current_received_ts = 290.640503
current_seq = 555
count = 195
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.624481/554, current 290.641266/555: elapsed=16769.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.641266
last_received_ts = 290.640503
last_seq = 555
current_ts = 290.658020
current_received_ts = 290.657196
current_seq = 556
count = 196
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.641266/555, current 290.658020/556: elapsed=16776.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.658020
last_received_ts = 290.657196
last_seq = 556
current_ts = 290.674805
current_received_ts = 290.673981
current_seq = 557
count = 197
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.658020/556, current 290.674805/557: elapsed=16782.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.674805
last_received_ts = 290.673981
last_seq = 557
current_ts = 290.691589
current_received_ts = 290.690735
current_seq = 558
count = 198
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.674805/557, current 290.691589/558: elapsed=16774.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.691589
last_received_ts = 290.690735
last_seq = 558
current_ts = 290.708374
current_received_ts = 290.707520
current_seq = 559
count = 199
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.691589/558, current 290.708374/559: elapsed=16768.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.708374
last_received_ts = 290.707520
last_seq = 559
current_ts = 290.725128
current_received_ts = 290.724274
current_seq = 560
count = 200
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.708374/559, current 290.725128/560: elapsed=16776.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.725128
last_received_ts = 290.724274
last_seq = 560
current_ts = 290.741913
current_received_ts = 290.741058
current_seq = 561
count = 201
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.725128/560, current 290.741913/561: elapsed=16782.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.741913
last_received_ts = 290.741058
last_seq = 561
current_ts = 290.758698
current_received_ts = 290.757843
current_seq = 562
count = 202
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.741913/561, current 290.758698/562: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.758698
last_received_ts = 290.757843
last_seq = 562
current_ts = 290.775452
current_received_ts = 290.774628
current_seq = 563
count = 203
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.758698/562, current 290.775452/563: elapsed=16769.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.775452
last_received_ts = 290.774628
last_seq = 563
current_ts = 290.792236
current_received_ts = 290.791412
current_seq = 564
count = 204
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.775452/563, current 290.792236/564: elapsed=16783.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.792236
last_received_ts = 290.791412
last_seq = 564
current_ts = 290.809021
current_received_ts = 290.808167
current_seq = 565
count = 205
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.792236/564, current 290.809021/565: elapsed=16770.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.809021
last_received_ts = 290.808167
last_seq = 565
current_ts = 290.825806
current_received_ts = 290.824951
current_seq = 566
count = 206
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.809021/565, current 290.825806/566: elapsed=16780.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.825806
last_received_ts = 290.824951
last_seq = 566
current_ts = 290.842560
current_received_ts = 290.841705
current_seq = 567
count = 207
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.825806/566, current 290.842560/567: elapsed=16776.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.842560
last_received_ts = 290.841705
last_seq = 567
current_ts = 290.859344
current_received_ts = 290.858582
current_seq = 568
count = 208
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.842560/567, current 290.859344/568: elapsed=16768.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.859344
last_received_ts = 290.858582
last_seq = 568
current_ts = 290.876099
current_received_ts = 290.875336
current_seq = 569
count = 209
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.859344/568, current 290.876099/569: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.876099
last_received_ts = 290.875336
last_seq = 569
current_ts = 290.892883
current_received_ts = 290.892151
current_seq = 570
count = 210
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.876099/569, current 290.892883/570: elapsed=16783.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.892883
last_received_ts = 290.892151
last_seq = 570
current_ts = 290.909668
current_received_ts = 290.908936
current_seq = 571
count = 211
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.892883/570, current 290.909668/571: elapsed=16771.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.909668
last_received_ts = 290.908936
last_seq = 571
current_ts = 290.926453
current_received_ts = 290.925629
current_seq = 572
count = 212
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.909668/571, current 290.926453/572: elapsed=16774.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.926453
last_received_ts = 290.925629
last_seq = 572
current_ts = 290.943207
current_received_ts = 290.942383
current_seq = 573
count = 213
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.926453/572, current 290.943207/573: elapsed=16773.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.943207
last_received_ts = 290.942383
last_seq = 573
current_ts = 290.959991
current_received_ts = 290.959137
current_seq = 574
count = 214
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.943207/573, current 290.959991/574: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.959991
last_received_ts = 290.959137
last_seq = 574
current_ts = 290.976776
current_received_ts = 290.975922
current_seq = 575
count = 215
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.959991/574, current 290.976776/575: elapsed=16782.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.976776
last_received_ts = 290.975922
last_seq = 575
current_ts = 290.993561
current_received_ts = 290.992706
current_seq = 576
count = 216
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.976776/575, current 290.993561/576: elapsed=16776.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 290.993561
last_received_ts = 290.992706
last_seq = 576
current_ts = 291.010315
current_received_ts = 291.009460
current_seq = 577
count = 217
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 290.993561/576, current 291.010315/577: elapsed=16776.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.010315
last_received_ts = 291.009460
last_seq = 577
current_ts = 291.027100
current_received_ts = 291.026245
current_seq = 578
count = 218
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.010315/577, current 291.027100/578: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.027100
last_received_ts = 291.026245
last_seq = 578
current_ts = 291.043884
current_received_ts = 291.043030
current_seq = 579
count = 219
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.027100/578, current 291.043884/579: elapsed=16776.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.043884
last_received_ts = 291.043030
last_seq = 579
current_ts = 291.060638
current_received_ts = 291.059814
current_seq = 580
count = 220
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.043884/579, current 291.060638/580: elapsed=16767.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.060638
last_received_ts = 291.059814
last_seq = 580
current_ts = 291.077423
current_received_ts = 291.076660
current_seq = 581
count = 221
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.060638/580, current 291.077423/581: elapsed=16776.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.077423
last_received_ts = 291.076660
last_seq = 581
current_ts = 291.094208
current_received_ts = 291.093353
current_seq = 582
count = 222
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.077423/581, current 291.094208/582: elapsed=16782.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.094208
last_received_ts = 291.093353
last_seq = 582
current_ts = 291.110962
current_received_ts = 291.110107
current_seq = 583
count = 223
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.094208/582, current 291.110962/583: elapsed=16768.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.110962
last_received_ts = 291.110107
last_seq = 583
current_ts = 291.127747
current_received_ts = 291.126892
current_seq = 584
count = 224
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.110962/583, current 291.127747/584: elapsed=16782.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.127747
last_received_ts = 291.126892
last_seq = 584
current_ts = 291.144531
current_received_ts = 291.143677
current_seq = 585
count = 225
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.127747/584, current 291.144531/585: elapsed=16770.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.144531
last_received_ts = 291.143677
last_seq = 585
current_ts = 291.161285
current_received_ts = 291.160553
current_seq = 586
count = 226
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.144531/585, current 291.161285/586: elapsed=16774.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.161285
last_received_ts = 291.160553
last_seq = 586
current_ts = 291.178070
current_received_ts = 291.177216
current_seq = 587
count = 227
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.161285/586, current 291.178070/587: elapsed=16783.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.178070
last_received_ts = 291.177216
last_seq = 587
current_ts = 291.194855
current_received_ts = 291.194000
current_seq = 588
count = 228
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.178070/587, current 291.194855/588: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.194855
last_received_ts = 291.194000
last_seq = 588
current_ts = 291.211639
current_received_ts = 291.210785
current_seq = 589
count = 229
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.194855/588, current 291.211639/589: elapsed=16776.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.211639
last_received_ts = 291.210785
last_seq = 589
current_ts = 291.228394
current_received_ts = 291.227539
current_seq = 590
count = 230
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.211639/589, current 291.228394/590: elapsed=16768.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.228394
last_received_ts = 291.227539
last_seq = 590
current_ts = 291.245178
current_received_ts = 291.244324
current_seq = 591
count = 231
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.228394/590, current 291.245178/591: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.245178
last_received_ts = 291.244324
last_seq = 591
current_ts = 291.261963
current_received_ts = 291.261108
current_seq = 592
count = 232
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.245178/591, current 291.261963/592: elapsed=16782.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.261963
last_received_ts = 291.261108
last_seq = 592
current_ts = 291.278717
current_received_ts = 291.277863
current_seq = 593
count = 233
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.261963/592, current 291.278717/593: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.278717
last_received_ts = 291.277863
last_seq = 593
current_ts = 291.295502
current_received_ts = 291.294647
current_seq = 594
count = 234
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.278717/593, current 291.295502/594: elapsed=16776.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.295502
last_received_ts = 291.294647
last_seq = 594
current_ts = 291.312256
current_received_ts = 291.311432
current_seq = 595
count = 235
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.295502/594, current 291.312256/595: elapsed=16768.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.312256
last_received_ts = 291.311432
last_seq = 595
current_ts = 291.329041
current_received_ts = 291.328308
current_seq = 596
count = 236
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.312256/595, current 291.329041/596: elapsed=16779.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.329041
last_received_ts = 291.328308
last_seq = 596
current_ts = 291.345825
current_received_ts = 291.344971
current_seq = 597
count = 237
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.329041/596, current 291.345825/597: elapsed=16772.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.345825
last_received_ts = 291.344971
last_seq = 597
current_ts = 291.362610
current_received_ts = 291.361755
current_seq = 598
count = 238
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.345825/597, current 291.362610/598: elapsed=16775.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.362610
last_received_ts = 291.361755
last_seq = 598
current_ts = 291.379364
current_received_ts = 291.378510
current_seq = 599
count = 239
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.362610/598, current 291.379364/599: elapsed=16782.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.379364
last_received_ts = 291.378510
last_seq = 599
current_ts = 291.396149
current_received_ts = 291.395294
current_seq = 600
count = 240
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.379364/599, current 291.396149/600: elapsed=16776.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.396149
last_received_ts = 291.395294
last_seq = 600
current_ts = 291.412933
current_received_ts = 291.412079
current_seq = 601
count = 241
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.396149/600, current 291.412933/601: elapsed=16776.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.412933
last_received_ts = 291.412079
last_seq = 601
current_ts = 291.429688
current_received_ts = 291.428864
current_seq = 602
count = 242
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.412933/601, current 291.429688/602: elapsed=16767.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.429688
last_received_ts = 291.428864
last_seq = 602
current_ts = 291.446472
current_received_ts = 291.445618
current_seq = 603
count = 243
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.429688/602, current 291.446472/603: elapsed=16783.0us expected=16848.1us +- 84.2us, error 0.4%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.446472
last_received_ts = 291.445618
last_seq = 603
current_ts = 291.463257
current_received_ts = 291.462402
current_seq = 604
count = 244
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.446472/603, current 291.463257/604: elapsed=16768.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: name = flip
last_ts = 291.463257
last_received_ts = 291.462402
last_seq = 604
current_ts = 291.480011
current_received_ts = 291.479248
current_seq = 605
count = 245
seq_step = 1
(kms_flip:2649) DEBUG: flip ts/seq: last 291.463257/604, current 291.480011/605: elapsed=16756.0us expected=16848.1us +- 84.2us, error 0.5%
(kms_flip:2649) DEBUG: inconsistent flip ts/seq: last 291.463257/604, current 291.480011/605: elapsed=16756.0us expected=16848.1us
(kms_flip:2649) DEBUG: expected 131096, counted 245, encoder type 2
(kms_flip:2649) DEBUG: dropped frames, expected 131096, counted 245, encoder type 2
(kms_flip:2649) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2649) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2649) igt_core-INFO: Stack trace:
(kms_flip:2649) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2649) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2649) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2649) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2649) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2649) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2649) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2649) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (8.898s)
Dmesg
<6> [322.376209] [IGT] kms_flip: starting dynamic subtest B-eDP1
<7> [322.378061] xe 0000:00:02.0: [drm:drm_mode_addfb2 [drm]] [FB:190]
<7> [322.379926] xe 0000:00:02.0: [drm:drm_mode_addfb2 [drm]] [FB:230]
<7> [322.454081] xe 0000:00:02.0: [drm:drm_mode_setcrtc [drm]] [CRTC:82:pipe A]
<7> [322.454407] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.enable (expected yes, found no)
<7> [322.454677] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.active (expected yes, found no)
<7> [322.454868] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)
<7> [322.455047] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in lane_count (expected 4, found 0)
<7> [322.455220] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82: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> [322.455383] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)
<7> [322.455543] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [322.455702] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0)
<7> [322.455857] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0)
<7> [322.456006] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0)
<7> [322.456154] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0)
<7> [322.456298] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0)
<7> [322.456444] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0)
<7> [322.456588] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0)
<7> [322.456728] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0)
<7> [322.456865] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0)
<7> [322.457001] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0)
<7> [322.457137] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1906, found 0)
<7> [322.457265] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1906, found 0)
<7> [322.457393] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0)
<7> [322.457520] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0)
<7> [322.457694] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0)
<7> [322.457819] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0)
<7> [322.457943] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0)
<7> [322.458067] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0)
<7> [322.458190] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0)
<7> [322.458308] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0)
<7> [322.458426] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0)
<7> [322.458542] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0)
<7> [322.458657] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1906, found 0)
<7> [322.458769] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1906, found 0)
<7> [322.458881] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [322.458993] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [322.459105] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [322.459215] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0)
<7> [322.459321] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 347710, found 0)
<7> [322.459427] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 347710, found 0)
<7> [322.459534] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:82:pipe A] fastset requirement not met in port_clock (expected 432000, found 0)
<7> [322.459645] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:82:pipe A] fastset requirement not met, forcing full modeset
<7> [322.459819] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no
<7> [322.459915] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:82:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0
<7> [322.460087] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:32:plane 1A] ddb ( 0 - 4054) -> ( 0 - 0), size 4054 -> 0
<7> [322.460171] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:77:cursor A] ddb (4054 - 4096) -> ( 0 - 0), size 42 -> 0
<7> [322.460251] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:32:plane 1A] level *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm
<7> [322.460328] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:32:plane 1A] lines 1, 12, 12, 12, 11, 12, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [322.460406] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:32:plane 1A] blocks 24, 289, 289, 289, 265, 289, 0, 0, 38, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [322.460483] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:32:plane 1A] min_ddb 28, 319, 319, 319, 293, 319, 0, 0, 39, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [322.460562] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:82:pipe A] data rate 0 num active planes 0
<7> [322.460674] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 0 qgv_peak_bw: 38400
<7> [322.460778] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 0 qgv_peak_bw: 38400
<7> [322.460879] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 38400
<7> [322.460975] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 38400
<7> [322.461072] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 0
<7> [322.461175] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] Can change cdclk via squashing
<7> [322.461271] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 153600 kHz, actual 153600 kHz
<7> [322.461366] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 0, actual 0
<7> [322.461497] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:82:pipe A] enable: no [modeset]
<7> [322.461613] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:32:plane 1A] fb: [NOFB], visible: no
<7> [322.461709] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:41:plane 2A] fb: [NOFB], visible: no
<7> [322.461801] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:50:plane 3A] fb: [NOFB], visible: no
<7> [322.461888] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:59:plane 4A] fb: [NOFB], visible: no
<7> [322.461971] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:68:plane 5A] fb: [NOFB], visible: no
<7> [322.462054] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:77:cursor A] fb: [NOFB], visible: no
<7> [322.462218] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off
<7> [322.462312] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00
<7> [322.462454] xe 0000:00:02.0: [drm:intel_psr_disable_locked [xe]] Disabling PSR2
<7> [322.481352] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 turning VDD on
<7> [322.481493] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006f
<7> [322.491000] xe 0000:00:02.0: [drm:intel_edp_backlight_off [xe]]
<7> [322.694677] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:189:eDP-1] set backlight PWM = 0
<7> [322.695386] xe 0000:00:02.0: [drm:intel_disable_transcoder [xe]] disabling pipe A
<7> [322.714766] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 turn panel power off
<7> [322.715239] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000
<7> [322.715617] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:188:DDI A/PHY A] - short
<7> [322.716009] xe 0000:00:02.0: [drm:intel_pps_off_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 wait for panel power off time
<7> [322.716356] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060
<7> [322.768474] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x00000009, pins 0x00000010, long 0x00000000
<7> [322.768773] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:188:DDI A/PHY A] - short
<7> [322.797373] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete
<7> [322.797688] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:188:DDI A/PHY A]
<7> [322.797802] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling AUX_A
<7> [322.798226] xe 0000:00:02.0: [drm:__intel_fbc_disable [xe]] Disabling FBC on [PLANE:32:plane 1A]
<7> [322.798249] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring short hpd on eDP [ENCODER:188:DDI A/PHY A]
<7> [322.798874] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:188:DDI A/PHY A]
<7> [322.799151] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:197:DDI TC1/PHY TC1]
<7> [322.799380] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:199:DP-MST A]
<7> [322.799603] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:200:DP-MST B]
<7> [322.799827] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:201:DP-MST C]
<7> [322.800049] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:209:DDI TC2/PHY TC2]
<7> [322.800272] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:211:DP-MST A]
<7> [322.800497] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:212:DP-MST B]
<7> [322.800718] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DP-MST C]
<7> [322.800939] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DDI TC3/PHY TC3]
<7> [322.801160] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:219:DP-MST A]
<7> [322.801417] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:220:DP-MST B]
<7> [322.801643] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:221:DP-MST C]
<7> [322.801870] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:189:eDP-1]
<7> [322.802146] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)
<7> [322.802387] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: yes -> no (pipe: *)
<7> [322.802618] 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> [322.802970] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)
<7> [322.803228] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=384
<7> [322.803557] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0x1
<7> [322.803983] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling PW_A
<7> [322.804432] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:82:pipe A]
<7> [322.804825] xe 0000:00:02.0: [drm:drm_mode_setcrtc [drm]] [CRTC:134:pipe B]
<7> [322.805522] xe 0000:00:02.0: [drm:drm_mode_setcrtc [drm]] [CRTC:186:pipe C]
<7> [322.805937] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010
<7> [322.806224] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:188:DDI A/PHY A] - long
<7> [322.806479] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 10
<7> [322.806808] xe 0000:00:02.0: [drm:drm_mode_setcrtc [drm]] [CRTC:134:pipe B]
<7> [322.806751] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:188:DDI A/PHY A]
<7> [322.806989] xe 0000:00:02.0: [drm:drm_mode_setcrtc [drm]] [CONNECTOR:189:eDP-1]
<7> [322.807325] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CONNECTOR:189:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36)
<7> [322.807747] xe 0000:00:02.0: [drm:intel_dp_compute_config_link_bpp_limits [xe]] [ENCODER:188:DDI A/PHY A][CRTC:134:pipe B] DP link limits: pixel clock 347710 kHz DSC off max lanes 4 max rate 810000 max pipe_bpp 30 max link_bpp 30.0000
<7> [322.808056] xe 0000:00:02.0: [drm:intel_dp_compute_link_config [xe]] DP lane count 4 clock 432000 bpp input 30 compressed 0.0000 link rate required 1303913 available 1728000
<7> [322.808373] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:134:pipe B] hw max bpp: 30, pipe bpp: 30, dithering: 0
<7> [322.808710] xe 0000:00:02.0: [drm:intel_ddi_compute_config_late [xe]] [ENCODER:188:DDI A/PHY A] [CRTC:134:pipe B]
<7> [322.809042] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.enable (expected no, found yes)
<7> [322.809408] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.active (expected no, found yes)
<7> [322.809724] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in cpu_transcoder (expected -1, found 1)
<7> [322.810034] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in lane_count (expected 0, found 4)
<7> [322.810337] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 6329869/8388608 link 421991/524288)
<7> [322.810620] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)
<7> [322.810900] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [322.811177] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880)
<7> [322.811434] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040)
<7> [322.811686] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880)
<7> [322.811939] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040)
<7> [322.812172] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928)
<7> [322.812401] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960)
<7> [322.812632] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800)
<7> [322.812848] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800)
<7> [322.813059] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803)
<7> [322.813327] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809)
<7> [322.813529] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1906)
<7> [322.813727] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1906)
<7> [322.813919] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880)
<7> [322.814104] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040)
<7> [322.814287] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880)
<7> [322.814460] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040)
<7> [322.814634] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928)
<7> [322.814807] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960)
<7> [322.814970] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800)
<7> [322.815130] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800)
<7> [322.815291] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803)
<7> [322.815452] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809)
<7> [322.815607] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1906)
<7> [322.815759] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1906)
<7> [322.815904] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [322.816049] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [322.816190] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [322.816335] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in pipe_bpp (expected 0, found 30)
<7> [322.816474] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 347710)
<7> [322.816607] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 347710)
<7> [322.816739] xe 0000:00:02.0: [drm:intel_pipe_config_compare [xe]] [CRTC:134:pipe B] fastset requirement not met in port_clock (expected 0, found 432000)
<7> [322.816869] xe 0000:00:02.0: [drm:intel_atomic_check [xe]] [CRTC:134:pipe B] fastset requirement not met, forcing full modeset
<7> [322.817168] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes
<7> [322.817303] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [CRTC:134:pipe B] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x2
<7> [322.817551] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:84:plane 1B] ddb ( 0 - 0) -> ( 0 - 4054), size 0 -> 4054
<7> [322.817659] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:129:cursor B] ddb ( 0 - 0) -> (4054 - 4096), size 0 -> 42
<7> [322.817743] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:84:plane 1B] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm
<7> [322.817820] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:84:plane 1B] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 1, 12, 12, 12, 11, 12, 0, 0, 0, 3, 0
<7> [322.817895] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:84:plane 1B] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 24, 289, 289, 289, 265, 289, 0, 0, 38, 73, 87
<7> [322.817972] xe 0000:00:02.0: [drm:skl_compute_wm [xe]] [PLANE:84:plane 1B] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 28, 319, 319, 319, 293, 319, 0, 0, 39, 82, 88
<7> [322.818053] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] [CRTC:134:pipe B] data rate 1390840 num active planes 1
<7> [322.818168] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 0: max bw 23530 required 1461 qgv_peak_bw: 38400
<7> [322.818272] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 1: max bw 36260 required 1461 qgv_peak_bw: 38400
<7> [322.818370] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 2: max bw 38000 required 1461 qgv_peak_bw: 38400
<7> [322.818466] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] QGV point 3: max bw 38000 required 1461 qgv_peak_bw: 38400
<7> [322.818566] xe 0000:00:02.0: [drm:intel_bw_atomic_check [xe]] Matching peaks QGV bw: 38400 for required data rate: 1461
<7> [322.818670] xe 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [xe]] [PLANE:84:plane 1B] min cdclk (173855 kHz) > [CRTC:134:pipe B] min cdclk (0 kHz)
<7> [322.818769] xe 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [xe]] new bandwidth min cdclk (27165 kHz) > old min cdclk (0 kHz)
<7> [322.818873] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] Can change cdclk via squashing
<7> [322.818969] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New cdclk calculated to be logical 192000 kHz, actual 192000 kHz
<7> [322.819062] xe 0000:00:02.0: [drm:intel_modeset_calc_cdclk [xe]] New voltage level calculated to be logical 0, actual 0
<7> [322.819213] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [CRTC:134:pipe B] enable: yes [modeset]
<7> [322.819333] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB
<7> [322.819440] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] cpu_transcoder: B, pipe bpp: 30, dithering: 0
<7> [322.819544] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] MST master transcoder: <invalid>
<7> [322.819641] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [322.819729] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] joiner: no, pipes: 0x0
<7> [322.819814] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] splitter: disabled, link count 0, overlap 0
<7> [322.819894] 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> [322.819975] 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> [322.820053] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] fec: disabled, enhanced framing: disabled
<7> [322.820132] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] sdp split: disabled
<7> [322.820214] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled
<7> [322.820299] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] framestart delay: 1, MSA timing delay: 0
<7> [322.820386] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] audio: 0, infoframes: 0, infoframes enabled: 0x4
<7> [322.820476] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] DP SDP: VSC, revision 4, length 14
<7> [322.820562] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pixelformat: RGB
<7> [322.820656] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] colorimetry: sRGB
<7> [322.820743] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] bpc: 0
<7> [322.820838] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dynamic range: VESA range
<7> [322.820930] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] content type: Not defined
<7> [322.821047] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] vrr: no, vmin: 1905, vmax: 2859, pipeline full: 0, guardband: 106 flipline: 1906, vmin vblank: 1800, vmax vblank: 2753
<7> [322.821146] 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> [322.821238] 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> [322.821335] 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> [322.821435] 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> [322.821531] 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> [322.821625] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] port clock: 432000, pipe src: 2880x1800+0+0, pixel rate 347710
<7> [322.821717] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] linetime: 70, ips linetime: 0
<7> [322.821808] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0
<7> [322.821901] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [322.821996] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] ips: 0, double wide: 0, drrs: 0
<7> [322.822096] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] dpll_hw_state: dpll: 0x69780, dpll_md: 0x42110, fp0: 0x1a2, fp1: 0x1000000
<7> [322.822195] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [322.822294] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [322.822397] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: pre offsets: 0x0000 0x0000 0x0000
<7> [322.822501] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [322.822605] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [322.822716] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [322.822822] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] output csc: post offsets: 0x0000 0x0000 0x0000
<7> [322.822929] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [322.823038] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [322.823146] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [322.823259] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [322.823365] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] pipe csc: post offsets: 0x0000 0x0000 0x0000
<7> [322.823473] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:84:plane 1B] fb: [FB:190] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x0, visible: yes
<7> [322.823586] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [322.823699] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0
<7> [322.823817] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:93:plane 2B] fb: [NOFB], visible: no
<7> [322.823939] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:102:plane 3B] fb: [NOFB], visible: no
<7> [322.824066] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:111:plane 4B] fb: [NOFB], visible: no
<7> [322.824191] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:120:plane 5B] fb: [NOFB], visible: no
<7> [322.824317] xe 0000:00:02.0: [drm:intel_crtc_state_dump [xe]] [PLANE:129:cursor B] fb: [NOFB], visible: no
<7> [322.826808] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_2
<7> [322.827020] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling PW_B
<7> [322.827232] 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> [322.827373] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 4 (mbus joined: no)
<7> [322.827503] xe 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [xe]] aud_ts_cdclk set to M=60, N=480
<7> [322.827618] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:188:DDI A/PHY A]
<7> [322.827710] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:197:DDI TC1/PHY TC1]
<7> [322.827797] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:199:DP-MST A]
<7> [322.827881] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:200:DP-MST B]
<7> [322.827958] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:201:DP-MST C]
<7> [322.828035] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:209:DDI TC2/PHY TC2]
<7> [322.828113] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:211:DP-MST A]
<7> [322.828188] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:212:DP-MST B]
<7> [322.828263] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:213:DP-MST C]
<7> [322.828338] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:217:DDI TC3/PHY TC3]
<7> [322.828413] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:219:DP-MST A]
<7> [322.828486] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:220:DP-MST B]
<7> [322.828558] xe 0000:00:02.0: [drm:intel_modeset_verify_disabled [xe]] [ENCODER:221:DP-MST C]
<7> [322.828638] xe 0000:00:02.0: [drm:gen9_dbuf_slices_update [xe]] Updating dbuf slices to 0xf
<7> [322.828822] xe 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [xe]] Changing mbus joined: no -> yes (pipe: *)
<7> [322.828916] xe 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [xe]] Updating dbuf ratio to 8 (mbus joined: yes)
<7> [322.829008] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling AUX_A
<7> [322.830345] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 turn panel power on
<7> [322.830451] xe 0000:00:02.0: [drm:wait_panel_power_cycle [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 wait for panel power cycle
<7> [323.426139] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x00000000 PP_CONTROL: 0x00000060
<7> [323.426377] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete
<7> [323.426567] xe 0000:00:02.0: [drm:intel_pps_on_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 wait for panel power on
<7> [323.426771] xe 0000:00:02.0: [drm:wait_panel_status [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063
<7> [323.462907] xe 0000:00:02.0: [drm:icp_irq_handler [xe]] hotplug event received, stat 0x00010000, dig 0x0000000a, pins 0x00000010, long 0x00000010
<7> [323.463265] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] digital hpd on [ENCODER:188:DDI A/PHY A] - long
<7> [323.463555] xe 0000:00:02.0: [drm:intel_hpd_irq_handler [xe]] Received HPD interrupt on PIN 4 - cnt: 20
<7> [323.463844] xe 0000:00:02.0: [drm:intel_dp_hpd_pulse [xe]] ignoring long hpd on eDP [ENCODER:188:DDI A/PHY A]
<7> [323.707439] xe 0000:00:02.0: [drm:wait_panel_status [xe]] Wait complete
<7> [323.709667] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 turning VDD on
<7> [323.709948] xe 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b
<7> [323.712167] 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> [323.713466] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:189:eDP-1][ENCODER:188:DDI A/PHY A][DPRX] Reloading eDP link rates
<7> [323.714467] xe 0000:00:02.0: [drm:intel_dp_start_link_train [xe]] [CONNECTOR:189:eDP-1][ENCODER:188:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 05
<7> [323.715533] xe 0000:00:02.0: [drm:intel_dp_set_signal_levels [xe]] [CONNECTOR:189:eDP-1][ENCODER:188:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0
<7> [323.716573] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:189:eDP-1][ENCODER:188:DDI A/PHY A][DPRX] Using DP training pattern TPS1
<7> [323.717751] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:189:eDP-1][ENCODER:188:DDI A/PHY A][DPRX] Clock recovery OK
<7> [323.717907] xe 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [xe]] [CONNECTOR:189:eDP-1][ENCODER:188:DDI A/PHY A][DPRX] Using DP training pattern TPS4
<7> [323.719599] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:189:eDP-1][ENCODER:188:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful
<7> [323.719739] xe 0000:00:02.0: [drm:intel_dp_link_train_phy [xe]] [CONNECTOR:189:eDP-1][ENCODER:188:DDI A/PHY A][DPRX] Link Training passed at link rate = 432000, lane count = 4
<7> [323.720323] xe 0000:00:02.0: [drm:intel_enable_transcoder [xe]] enabling pipe B
<7> [323.720544] xe 0000:00:02.0: [drm:intel_edp_backlight_on [xe]]
<7> [323.720663] xe 0000:00:02.0: [drm:intel_backlight_enable [xe]] pipe B
<7> [323.720795] xe 0000:00:02.0: [drm:intel_backlight_set_pwm_level [xe]] [CONNECTOR:189:eDP-1] set backlight PWM = 13892
<7> [323.721300] xe 0000:00:02.0: [drm:intel_fbc_update [xe]] reserved 10600448 bytes of contiguous stolen space for FBC, limit: 2
<7> [323.721417] xe 0000:00:02.0: [drm:intel_fbc_update [xe]] Enabling FBC on [PLANE:84:plane 1B]
<7> [323.737309] xe 0000:00:02.0: [drm:intel_psr_post_plane_update [xe]] Enabling PSR2
<7> [323.739144] xe 0000:00:02.0: [drm:verify_connector_state [xe]] [CONNECTOR:189:eDP-1]
<7> [323.739512] xe 0000:00:02.0: [drm:intel_modeset_verify_crtc [xe]] [CRTC:134:pipe B]
<7> [323.766101] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off
<7> [323.766511] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6
<7> [323.766856] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02
<7> [324.023546] xe 0000:00:02.0: [drm:intel_power_well_enable [xe]] enabling DC_off
<7> [324.024070] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 02 to 00
<7> [326.790747] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 turning VDD off
<7> [326.791178] xe 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [xe]] [ENCODER:188:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067
<7> [328.157624] xe 0000:00:02.0: [drm:intel_power_well_disable [xe]] disabling DC_off
<7> [328.158231] xe 0000:00:02.0: [drm:skl_enable_dc6 [xe]] Enabling DC6
<7> [328.158725] xe 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [xe]] Setting DC state from 00 to 02
<6> [331.275257] [IGT] kms_flip: finished subtest B-eDP1, FAIL
Created at 2024-09-30 15:06:11