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

Machine description: shard-mtlp-4

Result: Fail

git-log-oneline i915_display_info20 igt_runner20 runtimes20 results20.json results20-i915-load.json i915_display_info_post_exec20 boot20 dmesg20

DetailValue
Duration 7.71 seconds
Hostname 
shard-mtlp-4
Igt-Version 
IGT-Version: 1.30-g613e57cba (x86_64) (Linux: 6.14.0-rc5-CI_DRM_16239-gf02ab9f6e182+ x86_64)
Out 
Using IGT_SRANDOM=1741329641 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-eDP1
  2880x1800: 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa 
Expected frametime: 11111us; measured 11257.6us +- 2.851us accuracy 0.08%
vblank interval differs from modeline! expected 11111.1us, measured 11258us +- 2.851us, difference 146.4us (51.4 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __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 A-eDP1: FAIL (7.707s)
Err 
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-eDP1
(kms_flip:3527) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3527) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
(kms_flip:3527) DEBUG: flip ts/seq: last 332.689575/13050, current 332.700806/13051: elapsed=11221.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.700806
last_received_ts = 332.700653
last_seq = 13051
current_ts = 332.712006
current_received_ts = 332.711975
current_seq = 13052
count = 164
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.700806/13051, current 332.712006/13052: elapsed=11227.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.712006
last_received_ts = 332.711975
last_seq = 13052
current_ts = 332.723236
current_received_ts = 332.723145
current_seq = 13053
count = 165
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.712006/13052, current 332.723236/13053: elapsed=11223.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.723236
last_received_ts = 332.723145
last_seq = 13053
current_ts = 332.734467
current_received_ts = 332.734344
current_seq = 13054
count = 166
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.723236/13053, current 332.734467/13054: elapsed=11227.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.734467
last_received_ts = 332.734344
last_seq = 13054
current_ts = 332.745697
current_received_ts = 332.745544
current_seq = 13055
count = 167
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.734467/13054, current 332.745697/13055: elapsed=11224.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.745697
last_received_ts = 332.745544
last_seq = 13055
current_ts = 332.756927
current_received_ts = 332.756836
current_seq = 13056
count = 168
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.745697/13055, current 332.756927/13056: elapsed=11225.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.756927
last_received_ts = 332.756836
last_seq = 13056
current_ts = 332.768127
current_received_ts = 332.768066
current_seq = 13057
count = 169
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.756927/13056, current 332.768127/13057: elapsed=11221.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.768127
last_received_ts = 332.768066
last_seq = 13057
current_ts = 332.779358
current_received_ts = 332.779266
current_seq = 13058
count = 170
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.768127/13057, current 332.779358/13058: elapsed=11229.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.779358
last_received_ts = 332.779266
last_seq = 13058
current_ts = 332.790588
current_received_ts = 332.790405
current_seq = 13059
count = 171
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.779358/13058, current 332.790588/13059: elapsed=11219.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.790588
last_received_ts = 332.790405
last_seq = 13059
current_ts = 332.801819
current_received_ts = 332.801666
current_seq = 13060
count = 172
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.790588/13059, current 332.801819/13060: elapsed=11227.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.801819
last_received_ts = 332.801666
last_seq = 13060
current_ts = 332.813049
current_received_ts = 332.812988
current_seq = 13061
count = 173
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.801819/13060, current 332.813049/13061: elapsed=11223.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.813049
last_received_ts = 332.812988
last_seq = 13061
current_ts = 332.824280
current_received_ts = 332.824097
current_seq = 13062
count = 174
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.813049/13061, current 332.824280/13062: elapsed=11227.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.824280
last_received_ts = 332.824097
last_seq = 13062
current_ts = 332.835480
current_received_ts = 332.835388
current_seq = 13063
count = 175
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.824280/13062, current 332.835480/13063: elapsed=11221.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.835480
last_received_ts = 332.835388
last_seq = 13063
current_ts = 332.846710
current_received_ts = 332.846527
current_seq = 13064
count = 176
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.835480/13063, current 332.846710/13064: elapsed=11226.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.846710
last_received_ts = 332.846527
last_seq = 13064
current_ts = 332.857941
current_received_ts = 332.857910
current_seq = 13065
count = 177
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.846710/13064, current 332.857941/13065: elapsed=11225.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.857941
last_received_ts = 332.857910
last_seq = 13065
current_ts = 332.869171
current_received_ts = 332.869110
current_seq = 13066
count = 178
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.857941/13065, current 332.869171/13066: elapsed=11223.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.869171
last_received_ts = 332.869110
last_seq = 13066
current_ts = 332.880402
current_received_ts = 332.880219
current_seq = 13067
count = 179
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.869171/13066, current 332.880402/13067: elapsed=11227.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.880402
last_received_ts = 332.880219
last_seq = 13067
current_ts = 332.891602
current_received_ts = 332.891724
current_seq = 13068
count = 180
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.880402/13067, current 332.891602/13068: elapsed=11222.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.891602
last_received_ts = 332.891724
last_seq = 13068
current_ts = 332.902832
current_received_ts = 332.902557
current_seq = 13069
count = 181
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.891602/13068, current 332.902832/13069: elapsed=11225.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.902832
last_received_ts = 332.902557
last_seq = 13069
current_ts = 332.914062
current_received_ts = 332.914001
current_seq = 13070
count = 182
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.902832/13069, current 332.914062/13070: elapsed=11225.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.914062
last_received_ts = 332.914001
last_seq = 13070
current_ts = 332.925293
current_received_ts = 332.925171
current_seq = 13071
count = 183
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.914062/13070, current 332.925293/13071: elapsed=11224.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.925293
last_received_ts = 332.925171
last_seq = 13071
current_ts = 332.936493
current_received_ts = 332.936676
current_seq = 13072
count = 184
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.925293/13071, current 332.936493/13072: elapsed=11219.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.936493
last_received_ts = 332.936676
last_seq = 13072
current_ts = 332.947723
current_received_ts = 332.947479
current_seq = 13073
count = 185
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.936493/13072, current 332.947723/13073: elapsed=11227.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.947723
last_received_ts = 332.947479
last_seq = 13073
current_ts = 332.958954
current_received_ts = 332.958771
current_seq = 13074
count = 186
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.947723/13073, current 332.958954/13074: elapsed=11223.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.958954
last_received_ts = 332.958771
last_seq = 13074
current_ts = 332.970184
current_received_ts = 332.970032
current_seq = 13075
count = 187
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.958954/13074, current 332.970184/13075: elapsed=11224.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.970184
last_received_ts = 332.970032
last_seq = 13075
current_ts = 332.981415
current_received_ts = 332.981323
current_seq = 13076
count = 188
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.970184/13075, current 332.981415/13076: elapsed=11225.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.981415
last_received_ts = 332.981323
last_seq = 13076
current_ts = 332.992615
current_received_ts = 332.992462
current_seq = 13077
count = 189
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.981415/13076, current 332.992615/13077: elapsed=11227.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 332.992615
last_received_ts = 332.992462
last_seq = 13077
current_ts = 333.003845
current_received_ts = 333.003815
current_seq = 13078
count = 190
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 332.992615/13077, current 333.003845/13078: elapsed=11225.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.003845
last_received_ts = 333.003815
last_seq = 13078
current_ts = 333.015076
current_received_ts = 333.014984
current_seq = 13079
count = 191
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.003845/13078, current 333.015076/13079: elapsed=11225.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.015076
last_received_ts = 333.014984
last_seq = 13079
current_ts = 333.026306
current_received_ts = 333.026184
current_seq = 13080
count = 192
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.015076/13079, current 333.026306/13080: elapsed=11225.0us expected=11257.6us +- 56.3us, error 0.3%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.026306
last_received_ts = 333.026184
last_seq = 13080
current_ts = 333.037506
current_received_ts = 333.037384
current_seq = 13081
count = 193
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.026306/13080, current 333.037506/13081: elapsed=11215.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.037506
last_received_ts = 333.037384
last_seq = 13081
current_ts = 333.048737
current_received_ts = 333.048553
current_seq = 13082
count = 194
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.037506/13081, current 333.048737/13082: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.048737
last_received_ts = 333.048553
last_seq = 13082
current_ts = 333.059937
current_received_ts = 333.059845
current_seq = 13083
count = 195
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.048737/13082, current 333.059937/13083: elapsed=11216.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.059937
last_received_ts = 333.059845
last_seq = 13083
current_ts = 333.071136
current_received_ts = 333.071136
current_seq = 13084
count = 196
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.059937/13083, current 333.071136/13084: elapsed=11207.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.071136
last_received_ts = 333.071136
last_seq = 13084
current_ts = 333.082367
current_received_ts = 333.082214
current_seq = 13085
count = 197
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.071136/13084, current 333.082367/13085: elapsed=11214.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.082367
last_received_ts = 333.082214
last_seq = 13085
current_ts = 333.093567
current_received_ts = 333.093384
current_seq = 13086
count = 198
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.082367/13085, current 333.093567/13086: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.093567
last_received_ts = 333.093384
last_seq = 13086
current_ts = 333.104797
current_received_ts = 333.104645
current_seq = 13087
count = 199
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.093567/13086, current 333.104797/13087: elapsed=11207.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.104797
last_received_ts = 333.104645
last_seq = 13087
current_ts = 333.115997
current_received_ts = 333.115906
current_seq = 13088
count = 200
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.104797/13087, current 333.115997/13088: elapsed=11214.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.115997
last_received_ts = 333.115906
last_seq = 13088
current_ts = 333.127197
current_received_ts = 333.127106
current_seq = 13089
count = 201
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.115997/13088, current 333.127197/13089: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.127197
last_received_ts = 333.127106
last_seq = 13089
current_ts = 333.138428
current_received_ts = 333.138245
current_seq = 13090
count = 202
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.127197/13089, current 333.138428/13090: elapsed=11208.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.138428
last_received_ts = 333.138245
last_seq = 13090
current_ts = 333.149628
current_received_ts = 333.149414
current_seq = 13091
count = 203
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.138428/13090, current 333.149628/13091: elapsed=11209.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.149628
last_received_ts = 333.149414
last_seq = 13091
current_ts = 333.160828
current_received_ts = 333.160767
current_seq = 13092
count = 204
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.149628/13091, current 333.160828/13092: elapsed=11217.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.160828
last_received_ts = 333.160767
last_seq = 13092
current_ts = 333.172058
current_received_ts = 333.171997
current_seq = 13093
count = 205
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.160828/13092, current 333.172058/13093: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.172058
last_received_ts = 333.171997
last_seq = 13093
current_ts = 333.183258
current_received_ts = 333.183136
current_seq = 13094
count = 206
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.172058/13093, current 333.183258/13094: elapsed=11208.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.183258
last_received_ts = 333.183136
last_seq = 13094
current_ts = 333.194458
current_received_ts = 333.194275
current_seq = 13095
count = 207
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.183258/13094, current 333.194458/13095: elapsed=11209.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.194458
last_received_ts = 333.194275
last_seq = 13095
current_ts = 333.205688
current_received_ts = 333.205505
current_seq = 13096
count = 208
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.194458/13095, current 333.205688/13096: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.205688
last_received_ts = 333.205505
last_seq = 13096
current_ts = 333.216888
current_received_ts = 333.216705
current_seq = 13097
count = 209
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.205688/13096, current 333.216888/13097: elapsed=11214.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.216888
last_received_ts = 333.216705
last_seq = 13097
current_ts = 333.228088
current_received_ts = 333.227936
current_seq = 13098
count = 210
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.216888/13097, current 333.228088/13098: elapsed=11208.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.228088
last_received_ts = 333.227936
last_seq = 13098
current_ts = 333.239319
current_received_ts = 333.239075
current_seq = 13099
count = 211
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.228088/13098, current 333.239319/13099: elapsed=11215.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.239319
last_received_ts = 333.239075
last_seq = 13099
current_ts = 333.250519
current_received_ts = 333.250366
current_seq = 13100
count = 212
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.239319/13099, current 333.250519/13100: elapsed=11212.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.250519
last_received_ts = 333.250366
last_seq = 13100
current_ts = 333.261749
current_received_ts = 333.261566
current_seq = 13101
count = 213
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.250519/13100, current 333.261749/13101: elapsed=11207.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.261749
last_received_ts = 333.261566
last_seq = 13101
current_ts = 333.272949
current_received_ts = 333.272888
current_seq = 13102
count = 214
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.261749/13101, current 333.272949/13102: elapsed=11214.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.272949
last_received_ts = 333.272888
last_seq = 13102
current_ts = 333.284149
current_received_ts = 333.284088
current_seq = 13103
count = 215
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.272949/13102, current 333.284149/13103: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.284149
last_received_ts = 333.284088
last_seq = 13103
current_ts = 333.295380
current_received_ts = 333.295258
current_seq = 13104
count = 216
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.284149/13103, current 333.295380/13104: elapsed=11209.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.295380
last_received_ts = 333.295258
last_seq = 13104
current_ts = 333.306580
current_received_ts = 333.306366
current_seq = 13105
count = 217
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.295380/13104, current 333.306580/13105: elapsed=11212.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.306580
last_received_ts = 333.306366
last_seq = 13105
current_ts = 333.317780
current_received_ts = 333.317719
current_seq = 13106
count = 218
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.306580/13105, current 333.317780/13106: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.317780
last_received_ts = 333.317719
last_seq = 13106
current_ts = 333.329010
current_received_ts = 333.328918
current_seq = 13107
count = 219
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.317780/13106, current 333.329010/13107: elapsed=11214.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.329010
last_received_ts = 333.328918
last_seq = 13107
current_ts = 333.340210
current_received_ts = 333.340149
current_seq = 13108
count = 220
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.329010/13107, current 333.340210/13108: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.340210
last_received_ts = 333.340149
last_seq = 13108
current_ts = 333.351410
current_received_ts = 333.351227
current_seq = 13109
count = 221
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.340210/13108, current 333.351410/13109: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.351410
last_received_ts = 333.351227
last_seq = 13109
current_ts = 333.362640
current_received_ts = 333.362457
current_seq = 13110
count = 222
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.351410/13109, current 333.362640/13110: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.362640
last_received_ts = 333.362457
last_seq = 13110
current_ts = 333.373840
current_received_ts = 333.373749
current_seq = 13111
count = 223
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.362640/13110, current 333.373840/13111: elapsed=11209.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.373840
last_received_ts = 333.373749
last_seq = 13111
current_ts = 333.385040
current_received_ts = 333.385040
current_seq = 13112
count = 224
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.373840/13111, current 333.385040/13112: elapsed=11209.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.385040
last_received_ts = 333.385040
last_seq = 13112
current_ts = 333.396271
current_received_ts = 333.396149
current_seq = 13113
count = 225
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.385040/13112, current 333.396271/13113: elapsed=11214.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.396271
last_received_ts = 333.396149
last_seq = 13113
current_ts = 333.407471
current_received_ts = 333.407257
current_seq = 13114
count = 226
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.396271/13113, current 333.407471/13114: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.407471
last_received_ts = 333.407257
last_seq = 13114
current_ts = 333.418701
current_received_ts = 333.418549
current_seq = 13115
count = 227
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.407471/13114, current 333.418701/13115: elapsed=11207.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.418701
last_received_ts = 333.418549
last_seq = 13115
current_ts = 333.429901
current_received_ts = 333.429810
current_seq = 13116
count = 228
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.418701/13115, current 333.429901/13116: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.429901
last_received_ts = 333.429810
last_seq = 13116
current_ts = 333.441101
current_received_ts = 333.441040
current_seq = 13117
count = 229
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.429901/13116, current 333.441101/13117: elapsed=11216.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.441101
last_received_ts = 333.441040
last_seq = 13117
current_ts = 333.452332
current_received_ts = 333.452148
current_seq = 13118
count = 230
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.441101/13117, current 333.452332/13118: elapsed=11207.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.452332
last_received_ts = 333.452148
last_seq = 13118
current_ts = 333.463531
current_received_ts = 333.463409
current_seq = 13119
count = 231
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.452332/13118, current 333.463531/13119: elapsed=11214.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.463531
last_received_ts = 333.463409
last_seq = 13119
current_ts = 333.474731
current_received_ts = 333.474579
current_seq = 13120
count = 232
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.463531/13119, current 333.474731/13120: elapsed=11209.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.474731
last_received_ts = 333.474579
last_seq = 13120
current_ts = 333.485962
current_received_ts = 333.485870
current_seq = 13121
count = 233
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.474731/13120, current 333.485962/13121: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.485962
last_received_ts = 333.485870
last_seq = 13121
current_ts = 333.497162
current_received_ts = 333.497101
current_seq = 13122
count = 234
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.485962/13121, current 333.497162/13122: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.497162
last_received_ts = 333.497101
last_seq = 13122
current_ts = 333.508362
current_received_ts = 333.508209
current_seq = 13123
count = 235
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.497162/13122, current 333.508362/13123: elapsed=11213.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.508362
last_received_ts = 333.508209
last_seq = 13123
current_ts = 333.519592
current_received_ts = 333.519409
current_seq = 13124
count = 236
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.508362/13123, current 333.519592/13124: elapsed=11209.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.519592
last_received_ts = 333.519409
last_seq = 13124
current_ts = 333.530792
current_received_ts = 333.530670
current_seq = 13125
count = 237
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.519592/13124, current 333.530792/13125: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.530792
last_received_ts = 333.530670
last_seq = 13125
current_ts = 333.541992
current_received_ts = 333.541901
current_seq = 13126
count = 238
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.530792/13125, current 333.541992/13126: elapsed=11209.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.541992
last_received_ts = 333.541901
last_seq = 13126
current_ts = 333.553223
current_received_ts = 333.553131
current_seq = 13127
count = 239
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.541992/13126, current 333.553223/13127: elapsed=11212.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.553223
last_received_ts = 333.553131
last_seq = 13127
current_ts = 333.564423
current_received_ts = 333.564209
current_seq = 13128
count = 240
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.553223/13127, current 333.564423/13128: elapsed=11214.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.564423
last_received_ts = 333.564209
last_seq = 13128
current_ts = 333.575653
current_received_ts = 333.575409
current_seq = 13129
count = 241
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.564423/13128, current 333.575653/13129: elapsed=11208.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.575653
last_received_ts = 333.575409
last_seq = 13129
current_ts = 333.586853
current_received_ts = 333.586670
current_seq = 13130
count = 242
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.575653/13129, current 333.586853/13130: elapsed=11212.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.586853
last_received_ts = 333.586670
last_seq = 13130
current_ts = 333.598053
current_received_ts = 333.597992
current_seq = 13131
count = 243
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.586853/13130, current 333.598053/13131: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.598053
last_received_ts = 333.597992
last_seq = 13131
current_ts = 333.609283
current_received_ts = 333.609131
current_seq = 13132
count = 244
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.598053/13131, current 333.609283/13132: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.609283
last_received_ts = 333.609131
last_seq = 13132
current_ts = 333.620483
current_received_ts = 333.620270
current_seq = 13133
count = 245
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.609283/13132, current 333.620483/13133: elapsed=11213.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.620483
last_received_ts = 333.620270
last_seq = 13133
current_ts = 333.631683
current_received_ts = 333.631531
current_seq = 13134
count = 246
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.620483/13133, current 333.631683/13134: elapsed=11212.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.631683
last_received_ts = 333.631531
last_seq = 13134
current_ts = 333.642914
current_received_ts = 333.642700
current_seq = 13135
count = 247
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.631683/13134, current 333.642914/13135: elapsed=11209.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.642914
last_received_ts = 333.642700
last_seq = 13135
current_ts = 333.654114
current_received_ts = 333.654083
current_seq = 13136
count = 248
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.642914/13135, current 333.654114/13136: elapsed=11212.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.654114
last_received_ts = 333.654083
last_seq = 13136
current_ts = 333.665314
current_received_ts = 333.665222
current_seq = 13137
count = 249
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.654114/13136, current 333.665314/13137: elapsed=11209.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.665314
last_received_ts = 333.665222
last_seq = 13137
current_ts = 333.676544
current_received_ts = 333.676392
current_seq = 13138
count = 250
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.665314/13137, current 333.676544/13138: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.676544
last_received_ts = 333.676392
last_seq = 13138
current_ts = 333.687744
current_received_ts = 333.687592
current_seq = 13139
count = 251
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.676544/13138, current 333.687744/13139: elapsed=11208.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.687744
last_received_ts = 333.687592
last_seq = 13139
current_ts = 333.698975
current_received_ts = 333.698914
current_seq = 13140
count = 252
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.687744/13139, current 333.698975/13140: elapsed=11215.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.698975
last_received_ts = 333.698914
last_seq = 13140
current_ts = 333.710175
current_received_ts = 333.710083
current_seq = 13141
count = 253
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.698975/13140, current 333.710175/13141: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.710175
last_received_ts = 333.710083
last_seq = 13141
current_ts = 333.721375
current_received_ts = 333.721283
current_seq = 13142
count = 254
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.710175/13141, current 333.721375/13142: elapsed=11208.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.721375
last_received_ts = 333.721283
last_seq = 13142
current_ts = 333.732605
current_received_ts = 333.732422
current_seq = 13143
count = 255
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.721375/13142, current 333.732605/13143: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.732605
last_received_ts = 333.732422
last_seq = 13143
current_ts = 333.743805
current_received_ts = 333.743683
current_seq = 13144
count = 256
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.732605/13143, current 333.743805/13144: elapsed=11214.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.743805
last_received_ts = 333.743683
last_seq = 13144
current_ts = 333.755005
current_received_ts = 333.754944
current_seq = 13145
count = 257
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.743805/13144, current 333.755005/13145: elapsed=11208.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.755005
last_received_ts = 333.754944
last_seq = 13145
current_ts = 333.766235
current_received_ts = 333.766144
current_seq = 13146
count = 258
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.755005/13145, current 333.766235/13146: elapsed=11216.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.766235
last_received_ts = 333.766144
last_seq = 13146
current_ts = 333.777435
current_received_ts = 333.777222
current_seq = 13147
count = 259
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.766235/13146, current 333.777435/13147: elapsed=11205.0us expected=11257.6us +- 56.3us, error 0.5%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.777435
last_received_ts = 333.777222
last_seq = 13147
current_ts = 333.788635
current_received_ts = 333.788452
current_seq = 13148
count = 260
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.777435/13147, current 333.788635/13148: elapsed=11215.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.788635
last_received_ts = 333.788452
last_seq = 13148
current_ts = 333.799866
current_received_ts = 333.799805
current_seq = 13149
count = 261
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.788635/13148, current 333.799866/13149: elapsed=11212.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.799866
last_received_ts = 333.799805
last_seq = 13149
current_ts = 333.811066
current_received_ts = 333.811066
current_seq = 13150
count = 262
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.799866/13149, current 333.811066/13150: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.811066
last_received_ts = 333.811066
last_seq = 13150
current_ts = 333.822296
current_received_ts = 333.822144
current_seq = 13151
count = 263
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.811066/13150, current 333.822296/13151: elapsed=11212.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.822296
last_received_ts = 333.822144
last_seq = 13151
current_ts = 333.833496
current_received_ts = 333.833374
current_seq = 13152
count = 264
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.822296/13151, current 333.833496/13152: elapsed=11209.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.833496
last_received_ts = 333.833374
last_seq = 13152
current_ts = 333.844696
current_received_ts = 333.844482
current_seq = 13153
count = 265
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.833496/13152, current 333.844696/13153: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.844696
last_received_ts = 333.844482
last_seq = 13153
current_ts = 333.855896
current_received_ts = 333.855804
current_seq = 13154
count = 266
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.844696/13153, current 333.855896/13154: elapsed=11208.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.855896
last_received_ts = 333.855804
last_seq = 13154
current_ts = 333.867126
current_received_ts = 333.867065
current_seq = 13155
count = 267
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.855896/13154, current 333.867126/13155: elapsed=11213.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.867126
last_received_ts = 333.867065
last_seq = 13155
current_ts = 333.878326
current_received_ts = 333.878235
current_seq = 13156
count = 268
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.867126/13155, current 333.878326/13156: elapsed=11213.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.878326
last_received_ts = 333.878235
last_seq = 13156
current_ts = 333.889557
current_received_ts = 333.889404
current_seq = 13157
count = 269
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.878326/13156, current 333.889557/13157: elapsed=11206.0us expected=11257.6us +- 56.3us, error 0.5%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.889557
last_received_ts = 333.889404
last_seq = 13157
current_ts = 333.900757
current_received_ts = 333.900635
current_seq = 13158
count = 270
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.889557/13157, current 333.900757/13158: elapsed=11214.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.900757
last_received_ts = 333.900635
last_seq = 13158
current_ts = 333.911957
current_received_ts = 333.911896
current_seq = 13159
count = 271
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.900757/13158, current 333.911957/13159: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.911957
last_received_ts = 333.911896
last_seq = 13159
current_ts = 333.923187
current_received_ts = 333.923065
current_seq = 13160
count = 272
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.911957/13159, current 333.923187/13160: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.923187
last_received_ts = 333.923065
last_seq = 13160
current_ts = 333.934387
current_received_ts = 333.934235
current_seq = 13161
count = 273
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.923187/13160, current 333.934387/13161: elapsed=11209.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.934387
last_received_ts = 333.934235
last_seq = 13161
current_ts = 333.945587
current_received_ts = 333.945404
current_seq = 13162
count = 274
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.934387/13161, current 333.945587/13162: elapsed=11214.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.945587
last_received_ts = 333.945404
last_seq = 13162
current_ts = 333.956818
current_received_ts = 333.956635
current_seq = 13163
count = 275
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.945587/13162, current 333.956818/13163: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.956818
last_received_ts = 333.956635
last_seq = 13163
current_ts = 333.968018
current_received_ts = 333.967926
current_seq = 13164
count = 276
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.956818/13163, current 333.968018/13164: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.968018
last_received_ts = 333.967926
last_seq = 13164
current_ts = 333.979218
current_received_ts = 333.979126
current_seq = 13165
count = 277
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.968018/13164, current 333.979218/13165: elapsed=11211.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.979218
last_received_ts = 333.979126
last_seq = 13165
current_ts = 333.990448
current_received_ts = 333.990234
current_seq = 13166
count = 278
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.979218/13165, current 333.990448/13166: elapsed=11212.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 333.990448
last_received_ts = 333.990234
last_seq = 13166
current_ts = 334.001648
current_received_ts = 334.001465
current_seq = 13167
count = 279
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 333.990448/13166, current 334.001648/13167: elapsed=11205.0us expected=11257.6us +- 56.3us, error 0.5%
(kms_flip:3527) DEBUG: name = flip
last_ts = 334.001648
last_received_ts = 334.001465
last_seq = 13167
current_ts = 334.012878
current_received_ts = 334.012756
current_seq = 13168
count = 280
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 334.001648/13167, current 334.012878/13168: elapsed=11217.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 334.012878
last_received_ts = 334.012756
last_seq = 13168
current_ts = 334.024078
current_received_ts = 334.023987
current_seq = 13169
count = 281
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 334.012878/13168, current 334.024078/13169: elapsed=11210.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 334.024078
last_received_ts = 334.023987
last_seq = 13169
current_ts = 334.035278
current_received_ts = 334.035187
current_seq = 13170
count = 282
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 334.024078/13169, current 334.035278/13170: elapsed=11209.0us expected=11257.6us +- 56.3us, error 0.4%
(kms_flip:3527) DEBUG: name = flip
last_ts = 334.035278
last_received_ts = 334.035187
last_seq = 13170
current_ts = 334.046478
current_received_ts = 334.046356
current_seq = 13171
count = 283
seq_step = 1
(kms_flip:3527) DEBUG: flip ts/seq: last 334.035278/13170, current 334.046478/13171: elapsed=11196.0us expected=11257.6us +- 56.3us, error 0.5%
(kms_flip:3527) DEBUG: inconsistent flip ts/seq: last 334.035278/13170, current 334.046478/13171: elapsed=11196.0us expected=11257.6us
(kms_flip:3527) DEBUG: expected 0, counted 283, encoder type 2
(kms_flip:3527) DEBUG: dropped frames, expected 0, counted 283, encoder type 2
(kms_flip:3527) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:3527) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:3527) igt_core-INFO: Stack trace:
(kms_flip:3527) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:3527) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:3527) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:3527) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:3527) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:3527) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:3527) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:3527) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (7.707s)
Dmesg
<6> [343.187933] Console: switching to colour dummy device 80x25
<6> [343.188231] [IGT] kms_flip: executing
<7> [343.192246] i915 0000:00:02.0: [drm:i915_gem_open [i915]]
<7> [343.193585] i915 0000:00:02.0: [drm:i915_drop_caches_set [i915]] Dropping caches: 0x000001dc [0x000001dc]
<7> [343.212264] i915 0000:00:02.0: [drm:i915_gem_open [i915]]
<7> [343.217413] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:250:DP-1]
<7> [343.217429] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:250:DP-1]
<7> [343.221878] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:250:DP-1] disconnected
<7> [343.222148] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:262:HDMI-A-1]
<7> [343.222156] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:262:HDMI-A-1]
<7> [343.226853] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:262:HDMI-A-1] disconnected
<7> [343.227114] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:268:DP-2]
<7> [343.227122] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:268:DP-2]
<7> [343.227369] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port D/TC#1: TC port mode reset (disconnected -> tbt-alt)
<7> [343.227552] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:268:DP-2] disconnected
<7> [343.227827] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:277:HDMI-A-2]
<7> [343.227837] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:277:HDMI-A-2]
<7> [343.228114] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port E/TC#2: TC port mode reset (disconnected -> legacy)
<7> [343.232758] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:277:HDMI-A-2] disconnected
<7> [343.233009] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:281:DP-3]
<7> [343.233016] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:281:DP-3]
<7> [343.233223] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port F/TC#3: TC port mode reset (disconnected -> tbt-alt)
<7> [343.233395] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:281:DP-3] disconnected
<7> [343.233629] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:290:DP-4]
<7> [343.233637] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:290:DP-4]
<7> [343.233871] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port G/TC#4: TC port mode reset (disconnected -> tbt-alt)
<7> [343.234048] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:290:DP-4] disconnected
<7> [343.234350] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:241:eDP-1]
<7> [343.234357] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:241:eDP-1]
<7> [343.235226] i915 0000:00:02.0: [drm:intel_dp_read_dsc_dpcd [i915]] DSC DPCD: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
<7> [343.235912] i915 0000:00:02.0: [drm:intel_dp_print_rates [i915]] source rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000, 675000, 810000
<7> [343.236025] i915 0000:00:02.0: [drm:intel_dp_print_rates [i915]] sink rates: 162000, 216000, 243000, 270000, 324000, 378000, 432000, 540000
<7> [343.236133] i915 0000:00:02.0: [drm:intel_dp_print_rates [i915]] common rates: 162000, 216000, 243000, 270000, 324000, 432000, 540000
<7> [343.236258] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:241:eDP-1] Assigning EDID-1.4 digital sink color depth as 10 bpc.
<7> [343.236264] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:241:eDP-1] ELD monitor
<7> [343.236266] i915 0000:00:02.0: [drm:update_display_info.part.0] [CONNECTOR:241:eDP-1] ELD size 20, SAD count 0
<7> [343.236279] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] [CONNECTOR:241:eDP-1] VRR capable: no
<7> [343.236392] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] [CONNECTOR:241:eDP-1] DFP max bpc 0, max dotclock 0, TMDS clock 0-0, PCON Max FRL BW 0Gbps
<7> [343.237245] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] PCON ENCODER DSC DPCD: 00 00 00 00 00 00 00 00 00 00 00 00 00
<7> [343.237362] i915 0000:00:02.0: [drm:intel_dp_set_edid [i915]] [CONNECTOR:241:eDP-1] RGB->YcbCr conversion? no, YCbCr 4:2:0 allowed? yes, YCbCr 4:4:4->4:2:0 conversion? no
<7> [343.238633] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:241:eDP-1] probed modes:
<7> [343.238642] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] Probed mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa
<7> [343.238659] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:250:DP-1]
<7> [343.238666] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:250:DP-1]
<7> [343.243519] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:250:DP-1] disconnected
<7> [343.243536] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:262:HDMI-A-1]
<7> [343.243544] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:262:HDMI-A-1]
<7> [343.248478] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:262:HDMI-A-1] disconnected
<7> [343.248493] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:268:DP-2]
<7> [343.248501] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:268:DP-2]
<7> [343.248715] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:268:DP-2] disconnected
<7> [343.248728] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:277:HDMI-A-2]
<7> [343.248736] i915 0000:00:02.0: [drm:intel_hdmi_detect [i915]] [CONNECTOR:277:HDMI-A-2]
<7> [343.253399] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:277:HDMI-A-2] disconnected
<7> [343.253420] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:281:DP-3]
<7> [343.253427] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:281:DP-3]
<7> [343.253640] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:281:DP-3] disconnected
<7> [343.253653] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:290:DP-4]
<7> [343.253659] i915 0000:00:02.0: [drm:intel_dp_detect [i915]] [CONNECTOR:290:DP-4]
<7> [343.253863] i915 0000:00:02.0: [drm:drm_helper_probe_single_connector_modes [drm_kms_helper]] [CONNECTOR:290:DP-4] disconnected
<6> [343.254438] [IGT] kms_flip: starting subtest plain-flip-ts-check
<6> [343.256663] [IGT] kms_flip: starting dynamic subtest A-eDP1
<7> [343.256929] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:298]
<7> [343.256968] i915 0000:00:02.0: [drm:drm_mode_addfb2] [FB:301]
<7> [343.266246] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [343.266544] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [343.300323] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [343.300732] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [343.321289] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [343.322083] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [343.346864] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [343.347077] [drm:eb_validate_vma [i915]] EINVAL at eb_validate_vma:509
<7> [343.373332] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:82:pipe A]
<7> [343.373472] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.enable (expected yes, found no)
<7> [343.373657] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.active (expected yes, found no)
<7> [343.373806] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in cpu_transcoder (expected 0, found -1)
<7> [343.373949] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in lane_count (expected 4, found 0)
<7> [343.374087] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in dp_m_n (expected tu 64 data 7483046/8388608 link 498869/524288, found tu 0, data 0/0 link 0/0)
<7> [343.374226] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in output_types (expected 0x00000100, found 0x00000000)
<7> [343.374362] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in framestart_delay (expected 1, found 0)
<7> [343.374497] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 2880, found 0)
<7> [343.374645] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 3040, found 0)
<7> [343.374780] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 2880, found 0)
<7> [343.374915] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 3040, found 0)
<7> [343.375050] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 2928, found 0)
<7> [343.375183] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 2960, found 0)
<7> [343.375318] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 1800, found 0)
<7> [343.375438] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 1800, found 0)
<7> [343.375559] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 1803, found 0)
<7> [343.375682] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 1809, found 0)
<7> [343.375796] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 1878, found 0)
<7> [343.375910] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 1878, found 0)
<7> [343.376022] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 2880, found 0)
<7> [343.376136] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 3040, found 0)
<7> [343.376257] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 2880, found 0)
<7> [343.376404] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 3040, found 0)
<7> [343.376528] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 2928, found 0)
<7> [343.376664] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 2960, found 0)
<7> [343.376787] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 1800, found 0)
<7> [343.376903] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 1800, found 0)
<7> [343.377018] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 1803, found 0)
<7> [343.377141] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 1809, found 0)
<7> [343.377259] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 1878, found 0)
<7> [343.377376] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 1878, found 0)
<7> [343.377493] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pixel_multiplier (expected 1, found 0)
<7> [343.377628] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 2, found 0)
<7> [343.377742] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 8, found 0)
<7> [343.377860] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in enhanced_framing (expected yes, found no)
<7> [343.378008] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pipe_bpp (expected 30, found 0)
<7> [343.378144] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 513820, found 0)
<7> [343.378263] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 513820, found 0)
<7> [343.378389] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in port_clock (expected 540000, found 0)
<7> [343.378517] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] fastset requirement not met, forcing full modeset
<7> [343.378694] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0xf -> 0x1 (total dbuf slices 0xf), mbus joined? yes->no
<7> [343.378810] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:82:pipe A] dbuf slices 0xf -> 0x0, ddb (0 - 4096) -> (0 - 0), active pipes 0x1 -> 0x0
<7> [343.378967] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] ddb ( 0 - 4001) -> ( 0 - 0), size 4001 -> 0
<7> [343.379080] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:77:cursor A] ddb (4001 - 4096) -> ( 0 - 0), size 95 -> 0
<7> [343.379195] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] level *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm -> wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm
<7> [343.379330] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] lines 2, 16, 16, 19, 19, 28, 0, 0, 0, 3, 0 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [343.379459] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] blocks 49, 385, 385, 457, 457, 673, 0, 0, 63, 73, 87 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [343.379627] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] min_ddb 55, 425, 425, 504, 504, 742, 0, 0, 64, 82, 88 -> 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0
<7> [343.379771] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:82:pipe A] data rate 0 num active planes 0
<7> [343.379929] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 0 qgv_peak_bw: 51200
<7> [343.380355] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [343.380818] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [343.381248] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 0 qgv_peak_bw: 51200
<7> [343.381704] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 0
<7> [343.382140] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing
<7> [343.382579] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 172800 kHz, actual 172800 kHz
<7> [343.382996] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [343.383352] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:82:pipe A] enable: no [modeset]
<7> [343.383532] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:plane 1A] fb: [NOFB], visible: no
<7> [343.383694] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:41:plane 2A] fb: [NOFB], visible: no
<7> [343.383852] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:50:plane 3A] fb: [NOFB], visible: no
<7> [343.384010] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:59:plane 4A] fb: [NOFB], visible: no
<7> [343.384171] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:68:plane 5A] fb: [NOFB], visible: no
<7> [343.384331] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:77:cursor A] fb: [NOFB], visible: no
<7> [343.384573] i915 0000:00:02.0: [drm:intel_psr_disable_locked [i915]] Disabling PSR2
<7> [343.385728] i915 0000:00:02.0: [drm:intel_edp_backlight_off [i915]]
<7> [343.586843] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 0
<7> [343.587686] i915 0000:00:02.0: [drm:intel_disable_transcoder [i915]] disabling pipe A
<7> [343.597908] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power off
<7> [343.598291] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x00000089, pins 0x00000010, long 0x00000000
<7> [343.598391] i915 0000:00:02.0: [drm:intel_pps_off_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power off time
<7> [343.598761] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - short
<7> [343.598868] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb0000000 value: 0x00000000 PP_STATUS: 0xa0000002 PP_CONTROL: 0x00000060
<7> [343.648628] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [343.649341] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling AUX_A
<7> [343.649364] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring short hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [343.650018] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A]
<7> [343.650528] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B]
<7> [343.650876] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [343.650981] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A]
<7> [343.651296] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B]
<7> [343.651341] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long
<7> [343.651589] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C]
<7> [343.651765] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 10
<7> [343.651865] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D]
<7> [343.652135] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1]
<7> [343.652322] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A]
<7> [343.652194] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [343.652488] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B]
<7> [343.652645] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C]
<7> [343.652900] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D]
<7> [343.653239] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2]
<7> [343.653451] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3]
<7> [343.653654] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A]
<7> [343.653809] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B]
<7> [343.653970] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C]
<7> [343.654085] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D]
<7> [343.654224] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4]
<7> [343.654414] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A]
<7> [343.654570] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B]
<7> [343.654737] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C]
<7> [343.654868] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D]
<7> [343.654987] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1]
<7> [343.655140] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 2 (mbus joined: no)
<7> [343.655280] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: yes -> no (pipe: *)
<7> [343.655413] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0x1
<7> [343.655645] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling PW_A
<7> [343.655878] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:82:pipe A]
<7> [343.656043] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Post changing CDCLK to 172800 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0
<7> [343.656208] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=432
<7> [343.656396] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:134:pipe B]
<7> [343.656589] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:186:pipe C]
<7> [343.656676] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:238:pipe D]
<7> [343.656780] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CRTC:82:pipe A]
<7> [343.656811] i915 0000:00:02.0: [drm:drm_mode_setcrtc] [CONNECTOR:241:eDP-1]
<7> [343.656903] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CONNECTOR:241:eDP-1] Limiting display bpp to 30 (EDID bpp 30, max requested bpp 36, max platform bpp 36)
<7> [343.657044] i915 0000:00:02.0: [drm:intel_dp_compute_config_limits [i915]] [ENCODER:240:DDI A/PHY A][CRTC:82:pipe A] DP link limits: pixel clock 513820 kHz DSC off max lanes 4 max rate 540000 max pipe_bpp 30 max link_bpp 30.0000
<7> [343.657164] i915 0000:00:02.0: [drm:intel_dp_compute_link_config [i915]] DP lane count 4 clock 540000 bpp input 30 compressed 0.0000 link rate required 1926825 available 2160000
<7> [343.657288] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] hw max bpp: 30, pipe bpp: 30, dithering: 0
<7> [343.657424] i915 0000:00:02.0: [drm:intel_ddi_compute_config_late [i915]] [ENCODER:240:DDI A/PHY A] [CRTC:82:pipe A]
<7> [343.657542] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.enable (expected no, found yes)
<7> [343.657667] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.active (expected no, found yes)
<7> [343.657789] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in cpu_transcoder (expected -1, found 0)
<7> [343.657911] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in lane_count (expected 0, found 4)
<7> [343.658032] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in dp_m_n (expected tu 0 data 0/0 link 0/0, found tu 64, data 7483046/8388608 link 498869/524288)
<7> [343.658153] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in output_types (expected 0x00000000, found 0x00000100)
<7> [343.658278] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in framestart_delay (expected 0, found 1)
<7> [343.658416] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hdisplay (expected 0, found 2880)
<7> [343.658540] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_htotal (expected 0, found 3040)
<7> [343.658652] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_start (expected 0, found 2880)
<7> [343.658767] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hblank_end (expected 0, found 3040)
<7> [343.658881] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_start (expected 0, found 2928)
<7> [343.659000] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_hsync_end (expected 0, found 2960)
<7> [343.659118] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vdisplay (expected 0, found 1800)
<7> [343.659237] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_start (expected 0, found 1800)
<7> [343.659364] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_start (expected 0, found 1803)
<7> [343.659488] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vsync_end (expected 0, found 1809)
<7> [343.659605] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vtotal (expected 0, found 1878)
<7> [343.659723] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_vblank_end (expected 0, found 1878)
<7> [343.659842] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hdisplay (expected 0, found 2880)
<7> [343.659959] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_htotal (expected 0, found 3040)
<7> [343.660078] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_start (expected 0, found 2880)
<7> [343.660196] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hblank_end (expected 0, found 3040)
<7> [343.660319] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_start (expected 0, found 2928)
<7> [343.660438] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_hsync_end (expected 0, found 2960)
<7> [343.660550] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vdisplay (expected 0, found 1800)
<7> [343.660662] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_start (expected 0, found 1800)
<7> [343.660774] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_start (expected 0, found 1803)
<7> [343.660889] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vsync_end (expected 0, found 1809)
<7> [343.661006] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vtotal (expected 0, found 1878)
<7> [343.661123] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_vblank_end (expected 0, found 1878)
<7> [343.661240] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pixel_multiplier (expected 0, found 1)
<7> [343.661366] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (2) (expected 0, found 2)
<7> [343.661485] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.flags (8) (expected 0, found 8)
<7> [343.661606] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in enhanced_framing (expected no, found yes)
<7> [343.661724] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in pipe_bpp (expected 0, found 30)
<7> [343.661842] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.pipe_mode.crtc_clock (expected 0, found 513820)
<7> [343.661959] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in hw.adjusted_mode.crtc_clock (expected 0, found 513820)
<7> [343.662075] i915 0000:00:02.0: [drm:intel_pipe_config_compare [i915]] [CRTC:82:pipe A] fastset requirement not met in port_clock (expected 0, found 540000)
<7> [343.662192] i915 0000:00:02.0: [drm:intel_atomic_check [i915]] [CRTC:82:pipe A] fastset requirement not met, forcing full modeset
<7> [343.662467] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] Enabled dbuf slices 0x1 -> 0xf (total dbuf slices 0xf), mbus joined? no->yes
<7> [343.662639] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [CRTC:82:pipe A] dbuf slices 0x0 -> 0xf, ddb (0 - 0) -> (0 - 4096), active pipes 0x0 -> 0x1
<7> [343.662850] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] ddb ( 0 - 0) -> ( 0 - 4001), size 0 -> 4001
<7> [343.663024] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:77:cursor A] ddb ( 0 - 0) -> (4001 - 4096), size 0 -> 95
<7> [343.663184] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] level wm0, wm1, wm2, wm3, wm4, wm5, wm6, wm7, twm, swm, stwm -> *wm0,*wm1,*wm2,*wm3,*wm4,*wm5, wm6, wm7,*twm,*swm,*stwm
<7> [343.663315] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] lines 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 2, 16, 16, 19, 19, 28, 0, 0, 0, 3, 0
<7> [343.663433] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] blocks 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 49, 385, 385, 457, 457, 673, 0, 0, 63, 73, 87
<7> [343.663543] i915 0000:00:02.0: [drm:skl_compute_wm [i915]] [PLANE:32:plane 1A] min_ddb 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0 -> 55, 425, 425, 504, 504, 742, 0, 0, 64, 82, 88
<7> [343.663654] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] [CRTC:82:pipe A] data rate 2055280 num active planes 1
<7> [343.663773] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 0: max bw 28913 required 2159 qgv_peak_bw: 51200
<7> [343.663891] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 1: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [343.664009] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 2: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [343.664125] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] QGV point 3: max bw 38000 required 2159 qgv_peak_bw: 51200
<7> [343.664252] i915 0000:00:02.0: [drm:intel_bw_atomic_check [i915]] Matching peaks QGV bw: 51200 for required data rate: 2159
<7> [343.664397] i915 0000:00:02.0: [drm:intel_plane_calc_min_cdclk [i915]] [PLANE:32:plane 1A] min cdclk (256910 kHz) > [CRTC:82:pipe A] min cdclk (0 kHz)
<7> [343.664564] i915 0000:00:02.0: [drm:intel_bw_calc_min_cdclk [i915]] new bandwidth min cdclk (40143 kHz) > old min cdclk (0 kHz)
<7> [343.664752] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] Can change cdclk via squashing
<7> [343.664972] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New cdclk calculated to be logical 307200 kHz, actual 307200 kHz
<7> [343.665107] i915 0000:00:02.0: [drm:intel_modeset_calc_cdclk [i915]] New voltage level calculated to be logical 0, actual 0
<7> [343.665259] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [CRTC:82:pipe A] enable: yes [modeset]
<7> [343.665382] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] active: yes, output_types: EDP (0x100), output format: RGB, sink format: RGB
<7> [343.665499] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] cpu_transcoder: A, pipe bpp: 30, dithering: 0
<7> [343.665612] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] MST master transcoder: <invalid>
<7> [343.665725] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port sync: master transcoder: <invalid>, slave transcoder bitmask = 0x0
<7> [343.665837] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] joiner: no, pipes: 0x0
<7> [343.665949] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] splitter: disabled, link count 0, overlap 0
<7> [343.666138] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m_n: lanes: 4; data_m: 7483046, data_n: 8388608, link_m: 498869, link_n: 524288, tu: 64
<7> [343.666362] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dp m2_n2: lanes: 4; data_m: 0, data_n: 0, link_m: 0, link_n: 0, tu: 0
<7> [343.666564] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] fec: disabled, enhanced framing: enabled
<7> [343.666782] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] sdp split: disabled
<7> [343.666925] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] psr: enabled, selective update: enabled, panel replay: disabled, selective fetch: enabled
<7> [343.667040] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] minimum HBlank: 0
<7> [343.667159] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] audio: 0, infoframes: 0, infoframes enabled: 0x4
<7> [343.667292] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] DP SDP: VSC, revision 4, length 14
<7> [343.667406] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pixelformat: RGB
<7> [343.667518] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] colorimetry: sRGB
<7> [343.667630] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] bpc: 0
<7> [343.667740] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dynamic range: VESA range
<7> [343.667850] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] content type: Not defined
<7> [343.667963] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] scanline offset: 1
<7> [343.668075] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vblank delay: 0, framestart delay: 1, MSA timing delay: 0
<7> [343.668201] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: no, vmin: 0, vmax: 0, flipline: 0, pipeline full: 0, guardband: 0 vsync start: 0, vsync end: 0
<7> [343.668320] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] vrr: vmin vblank: 0, vmax vblank: 0, vmin vtotal: 0, vmax vtotal: 0
<7> [343.668431] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] requested mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa
<7> [343.668541] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] adjusted mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x48 0xa
<7> [343.668653] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1878 vs=1803-1809 vt=1878, flags=0xa
<7> [343.668766] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe mode: "2880x1800": 90 513820 2880 2928 2960 3040 1800 1803 1809 1878 0x40 0xa
<7> [343.668877] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] crtc timings: clock=513820, hd=2880 hb=2880-3040 hs=2928-2960 ht=3040, vd=1800 vb=1800-1878 vs=1803-1809 vt=1878, flags=0xa
<7> [343.668988] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] port clock: 540000, pipe src: 2880x1800+0+0, pixel rate 513820
<7> [343.669100] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] linetime: 48, ips linetime: 0
<7> [343.669234] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] num_scalers: 2, scaler_users: 0x0, scaler_id: -1, scaling_filter: 0
<7> [343.669352] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pch pfit: 0x0+0+0, disabled, force thru: no
<7> [343.669464] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] ips: 0, double wide: 0, drrs: 0
<7> [343.669575] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] dpll_hw_state: dpll: 0x83d60, dpll_md: 0xf42110, fp0: 0xf8, fp1: 0x1000000
<7> [343.669687] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] csc_mode: 0x0 gamma_mode: 0x0 gamma_enable: 0 csc_enable: 0
<7> [343.669797] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pre csc lut: 0 entries, post csc lut: 0 entries
<7> [343.669907] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: pre offsets: 0x0000 0x0000 0x0000
<7> [343.670019] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [343.670133] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [343.670312] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: coefficients: 0x0000 0x0000 0x0000
<7> [343.670501] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] output csc: post offsets: 0x0000 0x0000 0x0000
<7> [343.670678] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: pre offsets: 0x0000 0x0000 0x0000
<7> [343.670840] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [343.671004] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [343.671165] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: coefficients: 0x0000 0x0000 0x0000
<7> [343.671286] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] pipe csc: post offsets: 0x0000 0x0000 0x0000
<7> [343.671405] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:32:plane 1A] fb: [FB:298] 2880x1800 format = XR24 little-endian (0x34325258) modifier = 0x0, visible: yes
<7> [343.671524] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] rotation: 0x1, scaler: -1, scaling_filter: 0
<7> [343.671636] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] src: 2880.000000x1800.000000+0.000000+0.000000 dst: 2880x1800+0+0
<7> [343.671748] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:41:plane 2A] fb: [NOFB], visible: no
<7> [343.671860] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:50:plane 3A] fb: [NOFB], visible: no
<7> [343.671970] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:59:plane 4A] fb: [NOFB], visible: no
<7> [343.672081] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:68:plane 5A] fb: [NOFB], visible: no
<7> [343.672245] i915 0000:00:02.0: [drm:intel_crtc_state_dump [i915]] [PLANE:77:cursor A] fb: [NOFB], visible: no
<7> [343.674171] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off
<7> [343.674359] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6
<7> [343.674510] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02
<7> [343.674757] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling DC_off
<7> [343.674885] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 02 to 00
<7> [343.675288] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling PW_A
<7> [343.675486] i915 0000:00:02.0: [drm:intel_set_cdclk [i915]] Pre changing CDCLK to 307200 kHz, VCO 614400 kHz, ref 38400 kHz, bypass 19200 kHz, voltage level 0
<7> [343.675640] i915 0000:00:02.0: [drm:intel_audio_cdclk_change_post.part.0 [i915]] aud_ts_cdclk set to M=60, N=768
<7> [343.675759] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:240:DDI A/PHY A]
<7> [343.675872] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:249:DDI B/PHY B]
<7> [343.675983] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:251:DP-MST A]
<7> [343.676118] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:252:DP-MST B]
<7> [343.676232] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:253:DP-MST C]
<7> [343.676341] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:254:DP-MST D]
<7> [343.676449] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:267:DDI TC1/PHY TC1]
<7> [343.676558] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:269:DP-MST A]
<7> [343.676667] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:270:DP-MST B]
<7> [343.676773] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:271:DP-MST C]
<7> [343.676880] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:272:DP-MST D]
<7> [343.676987] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:276:DDI TC2/PHY TC2]
<7> [343.677132] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:280:DDI TC3/PHY TC3]
<7> [343.677242] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:282:DP-MST A]
<7> [343.677350] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:283:DP-MST B]
<7> [343.677458] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:284:DP-MST C]
<7> [343.677564] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:285:DP-MST D]
<7> [343.677669] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:289:DDI TC4/PHY TC4]
<7> [343.677776] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:291:DP-MST A]
<7> [343.677885] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:292:DP-MST B]
<7> [343.677997] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:293:DP-MST C]
<7> [343.678130] i915 0000:00:02.0: [drm:intel_modeset_verify_disabled [i915]] [ENCODER:294:DP-MST D]
<7> [343.678238] i915 0000:00:02.0: [drm:gen9_dbuf_slices_update [i915]] Updating dbuf slices to 0xf
<7> [343.678454] i915 0000:00:02.0: [drm:intel_dbuf_mbus_join_update [i915]] Changing mbus joined: no -> yes (pipe: *)
<7> [343.678578] i915 0000:00:02.0: [drm:intel_dbuf_mdclk_cdclk_ratio_update [i915]] Updating dbuf ratio to 4 (mbus joined: yes)
<7> [343.678729] i915 0000:00:02.0: [drm:intel_power_well_enable [i915]] enabling AUX_A
<7> [343.680205] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turn panel power on
<7> [343.680350] i915 0000:00:02.0: [drm:wait_panel_power_cycle [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power cycle (469 ms remaining)
<7> [344.147277] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb800000f value: 0x00000000 PP_STATUS: 0x08000001 PP_CONTROL: 0x00000060
<7> [344.223934] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [344.224635] i915 0000:00:02.0: [drm:intel_pps_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 wait for panel power on
<7> [344.225324] i915 0000:00:02.0: [drm:wait_panel_status [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 mask: 0xb000000f value: 0x80000008 PP_STATUS: 0x9000000a PP_CONTROL: 0x00000063
<7> [344.256724] i915 0000:00:02.0: [drm:icp_irq_handler [i915]] hotplug event received, stat 0x00010000, dig 0x0000008a, pins 0x00000010, long 0x00000010
<7> [344.257189] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:240:DDI A/PHY A] - long
<7> [344.257618] i915 0000:00:02.0: [drm:intel_hpd_irq_handler [i915]] Received HPD interrupt on PIN 4 - cnt: 20
<7> [344.258185] i915 0000:00:02.0: [drm:intel_dp_hpd_pulse [i915]] ignoring long hpd on eDP [ENCODER:240:DDI A/PHY A]
<7> [344.296971] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port F/TC#3: TC port mode reset (tbt-alt -> disconnected)
<7> [344.296966] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port G/TC#4: TC port mode reset (tbt-alt -> disconnected)
<7> [344.297186] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port E/TC#2: TC port mode reset (legacy -> disconnected)
<7> [344.297678] i915 0000:00:02.0: [drm:intel_tc_port_reset_mode [i915]] Port D/TC#1: TC port mode reset (tbt-alt -> disconnected)
<7> [344.424880] i915 0000:00:02.0: [drm:wait_panel_status [i915]] Wait complete
<7> [344.427311] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD on
<7> [344.427731] i915 0000:00:02.0: [drm:intel_pps_vdd_on_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x0000006b
<7> [344.431556] i915 0000:00:02.0: [drm:drm_dp_read_dpcd_caps [drm_display_helper]] AUX A/DDI A/PHY A: DPCD: 14 14 c4 41 00 00 01 c0 02 00 00 00 00 0b 80
<7> [344.432419] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Reloading eDP link rates
<7> [344.433462] i915 0000:00:02.0: [drm:intel_dp_start_link_train [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using LINK_RATE_SET value 07
<7> [344.434395] i915 0000:00:02.0: [drm:intel_dp_set_signal_levels [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] 8b/10b, lanes: 4, vswing levels: 0/0/0/0, pre-emphasis levels: 0/0/0/0
<7> [344.435087] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using DP training pattern TPS1
<7> [344.436411] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Clock recovery OK
<7> [344.436553] i915 0000:00:02.0: [drm:intel_dp_program_link_training_pattern [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Using DP training pattern TPS3
<7> [344.438206] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Channel EQ done. DP Training successful
<7> [344.438320] i915 0000:00:02.0: [drm:intel_dp_link_train_phy [i915]] [CONNECTOR:241:eDP-1][ENCODER:240:DDI A/PHY A][DPRX] Link Training passed at link rate = 540000, lane count = 4
<7> [344.438945] i915 0000:00:02.0: [drm:intel_enable_transcoder [i915]] enabling pipe A
<7> [344.439500] i915 0000:00:02.0: [drm:intel_edp_backlight_on [i915]]
<7> [344.439794] i915 0000:00:02.0: [drm:intel_backlight_enable [i915]] pipe A
<7> [344.440004] i915 0000:00:02.0: [drm:intel_backlight_set_pwm_level [i915]] [CONNECTOR:241:eDP-1] set backlight PWM = 13892
<7> [344.450867] i915 0000:00:02.0: [drm:intel_psr_post_plane_update [i915]] Enabling PSR2
<7> [344.452461] i915 0000:00:02.0: [drm:verify_connector_state [i915]] [CONNECTOR:241:eDP-1]
<7> [344.452657] i915 0000:00:02.0: [drm:intel_modeset_verify_crtc [i915]] [CRTC:82:pipe A]
<7> [346.954899] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 turning VDD off
<7> [346.955395] i915 0000:00:02.0: [drm:intel_pps_vdd_off_sync_unlocked [i915]] [ENCODER:240:DDI A/PHY A] PPS 0 PP_STATUS: 0x80000008 PP_CONTROL: 0x00000067
<7> [347.824300] i915 0000:00:02.0: [drm:intel_power_well_disable [i915]] disabling DC_off
<7> [347.824783] i915 0000:00:02.0: [drm:skl_enable_dc6 [i915]] Enabling DC6
<7> [347.825272] i915 0000:00:02.0: [drm:gen9_set_dc_state.part.0 [i915]] Setting DC state from 00 to 02
<6> [350.964538] [IGT] kms_flip: finished subtest A-eDP1, FAIL
Created at 2025-03-07 07:31:05