Results for igt@kms_flip@plain-flip-fb-recreate-interruptible

IGT-Version: 2.1-g8a840cd64 (x86_64) (Linux: 6.17.0-rc3-lgci-xe-xe-3643-99f4b32d88cb9718c+ x86_64)

Using IGT_SRANDOM=1756524237 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-fb-recreate-interruptible
Starting dynamic subtest: A-eDP1
  2560x1600: 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x48 0xa 
Expected frametime: 4167us; measured 4166.7us +- 0.793us accuracy 0.06%
Event flip: expected 2401, counted 1217, passrate = 2.71%, encoder type 2
Expected frametime: 4167us; measured 4166.8us +- 1.065us accuracy 0.08%
Event flip: expected 2400, counted 1214, passrate = 2.31%, encoder type 2
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1884 run_test()
  #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (25.881s)
Starting dynamic subtest: B-eDP1
  2560x1600: 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x48 0xa 
Expected frametime: 4167us; measured 4166.8us +- 0.911us accuracy 0.07%
Event flip: expected 2400, counted 1215, passrate = 2.39%, encoder type 2
Expected frametime: 4167us; measured 4166.6us +- 1.025us accuracy 0.07%
Event flip: expected 2401, counted 1218, passrate = 2.96%, encoder type 2
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1884 run_test()
  #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (25.870s)
Starting dynamic subtest: C-eDP1
  2560x1600: 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x48 0xa 
Expected frametime: 4167us; measured 4166.7us +- 0.775us accuracy 0.06%
Event flip: expected 2399, counted 1209, passrate = 1.57%, encoder type 2
Expected frametime: 4167us; measured 4166.7us +- 1.065us accuracy 0.08%
Event flip: expected 2401, counted 1212, passrate = 1.90%, encoder type 2
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1884 run_test()
  #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-eDP1: FAIL (25.858s)
Subtest plain-flip-fb-recreate-interruptible: FAIL (77.619s)
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2247 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2961 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2416 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: plain-flip-fb-recreate-interruptible
Starting dynamic subtest: A-eDP1
(kms_flip:2551) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2551) CRITICAL: Failed assertion: !retried
(kms_flip:2551) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
(kms_flip:2551) DEBUG: unexpected flip seq 10226, expected 10225
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.083344
last_received_ts = 307.082916
last_seq = 10226
current_ts = 307.091675
current_received_ts = 307.091278
current_seq = 10228
count = 1134
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.083344/10226, current 307.091675/10228: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10228, expected 10227
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.091675
last_received_ts = 307.091278
last_seq = 10228
current_ts = 307.100006
current_received_ts = 307.099579
current_seq = 10230
count = 1135
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.091675/10228, current 307.100006/10230: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10230, expected 10229
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.100006
last_received_ts = 307.099579
last_seq = 10230
current_ts = 307.108337
current_received_ts = 307.107910
current_seq = 10232
count = 1136
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.100006/10230, current 307.108337/10232: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10232, expected 10231
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.108337
last_received_ts = 307.107910
last_seq = 10232
current_ts = 307.116669
current_received_ts = 307.116241
current_seq = 10234
count = 1137
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.108337/10232, current 307.116669/10234: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10234, expected 10233
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.116669
last_received_ts = 307.116241
last_seq = 10234
current_ts = 307.125000
current_received_ts = 307.124664
current_seq = 10236
count = 1138
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.116669/10234, current 307.125000/10236: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10236, expected 10235
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.125000
last_received_ts = 307.124664
last_seq = 10236
current_ts = 307.133331
current_received_ts = 307.132996
current_seq = 10238
count = 1139
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.125000/10236, current 307.133331/10238: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10238, expected 10237
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.133331
last_received_ts = 307.132996
last_seq = 10238
current_ts = 307.141663
current_received_ts = 307.141266
current_seq = 10240
count = 1140
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.133331/10238, current 307.141663/10240: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10240, expected 10239
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.141663
last_received_ts = 307.141266
last_seq = 10240
current_ts = 307.149994
current_received_ts = 307.149658
current_seq = 10242
count = 1141
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.141663/10240, current 307.149994/10242: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10242, expected 10241
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.149994
last_received_ts = 307.149658
last_seq = 10242
current_ts = 307.158325
current_received_ts = 307.157990
current_seq = 10244
count = 1142
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.149994/10242, current 307.158325/10244: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10244, expected 10243
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.158325
last_received_ts = 307.157990
last_seq = 10244
current_ts = 307.166656
current_received_ts = 307.166260
current_seq = 10246
count = 1143
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.158325/10244, current 307.166656/10246: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10246, expected 10245
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.166656
last_received_ts = 307.166260
last_seq = 10246
current_ts = 307.174988
current_received_ts = 307.174652
current_seq = 10248
count = 1144
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.166656/10246, current 307.174988/10248: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10248, expected 10247
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.174988
last_received_ts = 307.174652
last_seq = 10248
current_ts = 307.183319
current_received_ts = 307.182983
current_seq = 10250
count = 1145
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.174988/10248, current 307.183319/10250: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10250, expected 10249
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.183319
last_received_ts = 307.182983
last_seq = 10250
current_ts = 307.191650
current_received_ts = 307.191254
current_seq = 10252
count = 1146
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.183319/10250, current 307.191650/10252: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10252, expected 10251
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.191650
last_received_ts = 307.191254
last_seq = 10252
current_ts = 307.200012
current_received_ts = 307.199646
current_seq = 10254
count = 1147
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.191650/10252, current 307.200012/10254: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10254, expected 10253
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.200012
last_received_ts = 307.199646
last_seq = 10254
current_ts = 307.208344
current_received_ts = 307.207977
current_seq = 10256
count = 1148
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.200012/10254, current 307.208344/10256: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10256, expected 10255
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.208344
last_received_ts = 307.207977
last_seq = 10256
current_ts = 307.216675
current_received_ts = 307.216248
current_seq = 10258
count = 1149
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.208344/10256, current 307.216675/10258: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10258, expected 10257
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.216675
last_received_ts = 307.216248
last_seq = 10258
current_ts = 307.225006
current_received_ts = 307.224640
current_seq = 10260
count = 1150
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.216675/10258, current 307.225006/10260: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10260, expected 10259
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.225006
last_received_ts = 307.224640
last_seq = 10260
current_ts = 307.233337
current_received_ts = 307.232971
current_seq = 10262
count = 1151
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.225006/10260, current 307.233337/10262: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10262, expected 10261
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.233337
last_received_ts = 307.232971
last_seq = 10262
current_ts = 307.241669
current_received_ts = 307.241272
current_seq = 10264
count = 1152
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.233337/10262, current 307.241669/10264: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10264, expected 10263
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.241669
last_received_ts = 307.241272
last_seq = 10264
current_ts = 307.250000
current_received_ts = 307.249664
current_seq = 10266
count = 1153
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.241669/10264, current 307.250000/10266: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10266, expected 10265
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.250000
last_received_ts = 307.249664
last_seq = 10266
current_ts = 307.258331
current_received_ts = 307.257965
current_seq = 10268
count = 1154
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.250000/10266, current 307.258331/10268: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10268, expected 10267
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.258331
last_received_ts = 307.257965
last_seq = 10268
current_ts = 307.266663
current_received_ts = 307.266266
current_seq = 10270
count = 1155
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.258331/10268, current 307.266663/10270: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10270, expected 10269
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.266663
last_received_ts = 307.266266
last_seq = 10270
current_ts = 307.274994
current_received_ts = 307.274658
current_seq = 10272
count = 1156
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.266663/10270, current 307.274994/10272: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10272, expected 10271
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.274994
last_received_ts = 307.274658
last_seq = 10272
current_ts = 307.283325
current_received_ts = 307.282990
current_seq = 10274
count = 1157
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.274994/10272, current 307.283325/10274: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10274, expected 10273
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.283325
last_received_ts = 307.282990
last_seq = 10274
current_ts = 307.291656
current_received_ts = 307.291260
current_seq = 10276
count = 1158
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.283325/10274, current 307.291656/10276: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10276, expected 10275
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.291656
last_received_ts = 307.291260
last_seq = 10276
current_ts = 307.299988
current_received_ts = 307.299652
current_seq = 10278
count = 1159
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.291656/10276, current 307.299988/10278: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10278, expected 10277
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.299988
last_received_ts = 307.299652
last_seq = 10278
current_ts = 307.308350
current_received_ts = 307.307983
current_seq = 10280
count = 1160
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.299988/10278, current 307.308350/10280: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10280, expected 10279
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.308350
last_received_ts = 307.307983
last_seq = 10280
current_ts = 307.316681
current_received_ts = 307.316254
current_seq = 10282
count = 1161
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.308350/10280, current 307.316681/10282: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10282, expected 10281
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.316681
last_received_ts = 307.316254
last_seq = 10282
current_ts = 307.325012
current_received_ts = 307.324646
current_seq = 10284
count = 1162
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.316681/10282, current 307.325012/10284: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10284, expected 10283
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.325012
last_received_ts = 307.324646
last_seq = 10284
current_ts = 307.333344
current_received_ts = 307.332977
current_seq = 10286
count = 1163
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.325012/10284, current 307.333344/10286: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10286, expected 10285
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.333344
last_received_ts = 307.332977
last_seq = 10286
current_ts = 307.341675
current_received_ts = 307.341248
current_seq = 10288
count = 1164
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.333344/10286, current 307.341675/10288: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10288, expected 10287
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.341675
last_received_ts = 307.341248
last_seq = 10288
current_ts = 307.350006
current_received_ts = 307.349640
current_seq = 10290
count = 1165
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.341675/10288, current 307.350006/10290: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10290, expected 10289
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.350006
last_received_ts = 307.349640
last_seq = 10290
current_ts = 307.358337
current_received_ts = 307.357971
current_seq = 10292
count = 1166
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.350006/10290, current 307.358337/10292: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10292, expected 10291
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.358337
last_received_ts = 307.357971
last_seq = 10292
current_ts = 307.366669
current_received_ts = 307.366272
current_seq = 10294
count = 1167
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.358337/10292, current 307.366669/10294: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10294, expected 10293
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.366669
last_received_ts = 307.366272
last_seq = 10294
current_ts = 307.375000
current_received_ts = 307.374664
current_seq = 10296
count = 1168
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.366669/10294, current 307.375000/10296: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10296, expected 10295
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.375000
last_received_ts = 307.374664
last_seq = 10296
current_ts = 307.383331
current_received_ts = 307.382996
current_seq = 10298
count = 1169
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.375000/10296, current 307.383331/10298: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10298, expected 10297
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.383331
last_received_ts = 307.382996
last_seq = 10298
current_ts = 307.391663
current_received_ts = 307.391266
current_seq = 10300
count = 1170
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.383331/10298, current 307.391663/10300: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10300, expected 10299
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.391663
last_received_ts = 307.391266
last_seq = 10300
current_ts = 307.399994
current_received_ts = 307.399628
current_seq = 10302
count = 1171
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.391663/10300, current 307.399994/10302: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10302, expected 10301
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.399994
last_received_ts = 307.399628
last_seq = 10302
current_ts = 307.408325
current_received_ts = 307.407990
current_seq = 10304
count = 1172
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.399994/10302, current 307.408325/10304: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10304, expected 10303
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.408325
last_received_ts = 307.407990
last_seq = 10304
current_ts = 307.416656
current_received_ts = 307.416260
current_seq = 10306
count = 1173
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.408325/10304, current 307.416656/10306: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10306, expected 10305
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.416656
last_received_ts = 307.416260
last_seq = 10306
current_ts = 307.424988
current_received_ts = 307.424652
current_seq = 10308
count = 1174
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.416656/10306, current 307.424988/10308: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10308, expected 10307
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.424988
last_received_ts = 307.424652
last_seq = 10308
current_ts = 307.433350
current_received_ts = 307.432983
current_seq = 10310
count = 1175
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.424988/10308, current 307.433350/10310: elapsed=8336.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10310, expected 10309
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.433350
last_received_ts = 307.432983
last_seq = 10310
current_ts = 307.441681
current_received_ts = 307.441254
current_seq = 10312
count = 1176
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.433350/10310, current 307.441681/10312: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10312, expected 10311
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.441681
last_received_ts = 307.441254
last_seq = 10312
current_ts = 307.450012
current_received_ts = 307.449646
current_seq = 10314
count = 1177
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.441681/10312, current 307.450012/10314: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10314, expected 10313
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.450012
last_received_ts = 307.449646
last_seq = 10314
current_ts = 307.458344
current_received_ts = 307.457977
current_seq = 10316
count = 1178
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.450012/10314, current 307.458344/10316: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10316, expected 10315
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.458344
last_received_ts = 307.457977
last_seq = 10316
current_ts = 307.466675
current_received_ts = 307.466248
current_seq = 10318
count = 1179
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.458344/10316, current 307.466675/10318: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10318, expected 10317
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.466675
last_received_ts = 307.466248
last_seq = 10318
current_ts = 307.475006
current_received_ts = 307.474640
current_seq = 10320
count = 1180
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.466675/10318, current 307.475006/10320: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10320, expected 10319
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.475006
last_received_ts = 307.474640
last_seq = 10320
current_ts = 307.483337
current_received_ts = 307.482971
current_seq = 10322
count = 1181
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.475006/10320, current 307.483337/10322: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10322, expected 10321
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.483337
last_received_ts = 307.482971
last_seq = 10322
current_ts = 307.491669
current_received_ts = 307.491272
current_seq = 10324
count = 1182
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.483337/10322, current 307.491669/10324: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10324, expected 10323
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.491669
last_received_ts = 307.491272
last_seq = 10324
current_ts = 307.500000
current_received_ts = 307.499634
current_seq = 10326
count = 1183
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.491669/10324, current 307.500000/10326: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10326, expected 10325
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.500000
last_received_ts = 307.499634
last_seq = 10326
current_ts = 307.508331
current_received_ts = 307.507996
current_seq = 10328
count = 1184
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.500000/10326, current 307.508331/10328: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10328, expected 10327
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.508331
last_received_ts = 307.507996
last_seq = 10328
current_ts = 307.516663
current_received_ts = 307.516266
current_seq = 10330
count = 1185
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.508331/10328, current 307.516663/10330: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10330, expected 10329
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.516663
last_received_ts = 307.516266
last_seq = 10330
current_ts = 307.524994
current_received_ts = 307.524658
current_seq = 10332
count = 1186
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.516663/10330, current 307.524994/10332: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10332, expected 10331
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.524994
last_received_ts = 307.524658
last_seq = 10332
current_ts = 307.533325
current_received_ts = 307.532990
current_seq = 10334
count = 1187
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.524994/10332, current 307.533325/10334: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10334, expected 10333
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.533325
last_received_ts = 307.532990
last_seq = 10334
current_ts = 307.541687
current_received_ts = 307.541260
current_seq = 10336
count = 1188
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.533325/10334, current 307.541687/10336: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10336, expected 10335
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.541687
last_received_ts = 307.541260
last_seq = 10336
current_ts = 307.550018
current_received_ts = 307.549652
current_seq = 10338
count = 1189
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.541687/10336, current 307.550018/10338: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10338, expected 10337
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.550018
last_received_ts = 307.549652
last_seq = 10338
current_ts = 307.558350
current_received_ts = 307.557983
current_seq = 10340
count = 1190
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.550018/10338, current 307.558350/10340: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10340, expected 10339
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.558350
last_received_ts = 307.557983
last_seq = 10340
current_ts = 307.566681
current_received_ts = 307.566254
current_seq = 10342
count = 1191
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.558350/10340, current 307.566681/10342: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10342, expected 10341
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.566681
last_received_ts = 307.566254
last_seq = 10342
current_ts = 307.575012
current_received_ts = 307.574646
current_seq = 10344
count = 1192
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.566681/10342, current 307.575012/10344: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10344, expected 10343
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.575012
last_received_ts = 307.574646
last_seq = 10344
current_ts = 307.583344
current_received_ts = 307.582916
current_seq = 10346
count = 1193
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.575012/10344, current 307.583344/10346: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10346, expected 10345
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.583344
last_received_ts = 307.582916
last_seq = 10346
current_ts = 307.591675
current_received_ts = 307.591248
current_seq = 10348
count = 1194
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.583344/10346, current 307.591675/10348: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10348, expected 10347
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.591675
last_received_ts = 307.591248
last_seq = 10348
current_ts = 307.600006
current_received_ts = 307.599579
current_seq = 10350
count = 1195
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.591675/10348, current 307.600006/10350: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10350, expected 10349
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.600006
last_received_ts = 307.599579
last_seq = 10350
current_ts = 307.608337
current_received_ts = 307.607941
current_seq = 10352
count = 1196
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.600006/10350, current 307.608337/10352: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10352, expected 10351
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.608337
last_received_ts = 307.607941
last_seq = 10352
current_ts = 307.616669
current_received_ts = 307.616272
current_seq = 10354
count = 1197
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.608337/10352, current 307.616669/10354: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10354, expected 10353
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.616669
last_received_ts = 307.616272
last_seq = 10354
current_ts = 307.625000
current_received_ts = 307.624695
current_seq = 10356
count = 1198
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.616669/10354, current 307.625000/10356: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10356, expected 10355
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.625000
last_received_ts = 307.624695
last_seq = 10356
current_ts = 307.633331
current_received_ts = 307.632996
current_seq = 10358
count = 1199
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.625000/10356, current 307.633331/10358: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10358, expected 10357
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.633331
last_received_ts = 307.632996
last_seq = 10358
current_ts = 307.641663
current_received_ts = 307.641266
current_seq = 10360
count = 1200
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.633331/10358, current 307.641663/10360: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10360, expected 10359
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.641663
last_received_ts = 307.641266
last_seq = 10360
current_ts = 307.649994
current_received_ts = 307.649658
current_seq = 10362
count = 1201
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.641663/10360, current 307.649994/10362: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10362, expected 10361
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.649994
last_received_ts = 307.649658
last_seq = 10362
current_ts = 307.658356
current_received_ts = 307.657990
current_seq = 10364
count = 1202
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.649994/10362, current 307.658356/10364: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10364, expected 10363
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.658356
last_received_ts = 307.657990
last_seq = 10364
current_ts = 307.666687
current_received_ts = 307.666260
current_seq = 10366
count = 1203
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.658356/10364, current 307.666687/10366: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10366, expected 10365
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.666687
last_received_ts = 307.666260
last_seq = 10366
current_ts = 307.675018
current_received_ts = 307.674652
current_seq = 10368
count = 1204
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.666687/10366, current 307.675018/10368: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10368, expected 10367
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.675018
last_received_ts = 307.674652
last_seq = 10368
current_ts = 307.683350
current_received_ts = 307.683014
current_seq = 10370
count = 1205
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.675018/10368, current 307.683350/10370: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10370, expected 10369
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.683350
last_received_ts = 307.683014
last_seq = 10370
current_ts = 307.691681
current_received_ts = 307.691254
current_seq = 10372
count = 1206
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.683350/10370, current 307.691681/10372: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10372, expected 10371
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.691681
last_received_ts = 307.691254
last_seq = 10372
current_ts = 307.700012
current_received_ts = 307.699646
current_seq = 10374
count = 1207
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.691681/10372, current 307.700012/10374: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10374, expected 10373
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.700012
last_received_ts = 307.699646
last_seq = 10374
current_ts = 307.708344
current_received_ts = 307.707977
current_seq = 10376
count = 1208
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.700012/10374, current 307.708344/10376: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10376, expected 10375
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.708344
last_received_ts = 307.707977
last_seq = 10376
current_ts = 307.716675
current_received_ts = 307.716278
current_seq = 10378
count = 1209
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.708344/10376, current 307.716675/10378: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10378, expected 10377
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.716675
last_received_ts = 307.716278
last_seq = 10378
current_ts = 307.725006
current_received_ts = 307.724670
current_seq = 10380
count = 1210
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.716675/10378, current 307.725006/10380: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10380, expected 10379
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.725006
last_received_ts = 307.724670
last_seq = 10380
current_ts = 307.733337
current_received_ts = 307.733002
current_seq = 10382
count = 1211
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.725006/10380, current 307.733337/10382: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10382, expected 10381
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.733337
last_received_ts = 307.733002
last_seq = 10382
current_ts = 307.741669
current_received_ts = 307.741272
current_seq = 10384
count = 1212
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.733337/10382, current 307.741669/10384: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10384, expected 10383
(kms_flip:2551) DEBUG: name = flip
last_ts = 307.741669
last_received_ts = 307.741272
last_seq = 10384
current_ts = 307.750000
current_received_ts = 307.749664
current_seq = 10386
count = 1213
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 307.741669/10384, current 307.750000/10386: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10386, expected 10385
(kms_flip:2551) INFO: Event flip: expected 2400, counted 1214, passrate = 2.31%, encoder type 2
(kms_flip:2551) DEBUG: dropped frames, expected 2400, counted 1214, passrate = 2.31%, encoder type 2
(kms_flip:2551) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2551) CRITICAL: Failed assertion: !retried
(kms_flip:2551) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2551) igt_core-INFO: Stack trace:
(kms_flip:2551) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2551) igt_core-INFO:   #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
(kms_flip:2551) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:2551) igt_core-INFO:   #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
(kms_flip:2551) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:2551) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2551) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2551) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (25.881s)
Starting dynamic subtest: B-eDP1
(kms_flip:2551) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2551) CRITICAL: Failed assertion: !retried
(kms_flip:2551) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:2551) DEBUG: name = flip
last_ts = 332.957123
last_received_ts = 332.956757
last_seq = 9963
current_ts = 332.965454
current_received_ts = 332.965057
current_seq = 9965
count = 1137
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 332.957123/9963, current 332.965454/9965: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9965, expected 9964
(kms_flip:2551) DEBUG: name = flip
last_ts = 332.965454
last_received_ts = 332.965057
last_seq = 9965
current_ts = 332.973785
current_received_ts = 332.973450
current_seq = 9967
count = 1138
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 332.965454/9965, current 332.973785/9967: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9967, expected 9966
(kms_flip:2551) DEBUG: name = flip
last_ts = 332.973785
last_received_ts = 332.973450
last_seq = 9967
current_ts = 332.982117
current_received_ts = 332.981781
current_seq = 9969
count = 1139
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 332.973785/9967, current 332.982117/9969: elapsed=8335.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9969, expected 9968
(kms_flip:2551) DEBUG: name = flip
last_ts = 332.982117
last_received_ts = 332.981781
last_seq = 9969
current_ts = 332.986298
current_received_ts = 332.985931
current_seq = 9970
count = 1140
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 332.982117/9969, current 332.986298/9970: elapsed=4165.0us expected=4166.6us +- 20.8us, error 0.0%
(kms_flip:2551) DEBUG: name = flip
last_ts = 332.986298
last_received_ts = 332.985931
last_seq = 9970
current_ts = 332.990448
current_received_ts = 332.990051
current_seq = 9971
count = 1141
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 332.986298/9970, current 332.990448/9971: elapsed=4168.0us expected=4166.6us +- 20.8us, error 0.0%
(kms_flip:2551) DEBUG: name = flip
last_ts = 332.990448
last_received_ts = 332.990051
last_seq = 9971
current_ts = 332.998779
current_received_ts = 332.998474
current_seq = 9973
count = 1142
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 332.990448/9971, current 332.998779/9973: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9973, expected 9972
(kms_flip:2551) DEBUG: name = flip
last_ts = 332.998779
last_received_ts = 332.998474
last_seq = 9973
current_ts = 333.007111
current_received_ts = 333.006775
current_seq = 9975
count = 1143
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 332.998779/9973, current 333.007111/9975: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9975, expected 9974
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.007111
last_received_ts = 333.006775
last_seq = 9975
current_ts = 333.015442
current_received_ts = 333.015076
current_seq = 9977
count = 1144
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.007111/9975, current 333.015442/9977: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9977, expected 9976
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.015442
last_received_ts = 333.015076
last_seq = 9977
current_ts = 333.023773
current_received_ts = 333.023438
current_seq = 9979
count = 1145
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.015442/9977, current 333.023773/9979: elapsed=8335.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9979, expected 9978
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.023773
last_received_ts = 333.023438
last_seq = 9979
current_ts = 333.032104
current_received_ts = 333.031769
current_seq = 9981
count = 1146
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.023773/9979, current 333.032104/9981: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9981, expected 9980
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.032104
last_received_ts = 333.031769
last_seq = 9981
current_ts = 333.040466
current_received_ts = 333.040070
current_seq = 9983
count = 1147
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.032104/9981, current 333.040466/9983: elapsed=8335.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9983, expected 9982
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.040466
last_received_ts = 333.040070
last_seq = 9983
current_ts = 333.048798
current_received_ts = 333.048431
current_seq = 9985
count = 1148
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.040466/9983, current 333.048798/9985: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9985, expected 9984
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.048798
last_received_ts = 333.048431
last_seq = 9985
current_ts = 333.057129
current_received_ts = 333.056763
current_seq = 9987
count = 1149
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.048798/9985, current 333.057129/9987: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9987, expected 9986
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.057129
last_received_ts = 333.056763
last_seq = 9987
current_ts = 333.065460
current_received_ts = 333.065063
current_seq = 9989
count = 1150
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.057129/9987, current 333.065460/9989: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9989, expected 9988
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.065460
last_received_ts = 333.065063
last_seq = 9989
current_ts = 333.073792
current_received_ts = 333.073425
current_seq = 9991
count = 1151
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.065460/9989, current 333.073792/9991: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9991, expected 9990
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.073792
last_received_ts = 333.073425
last_seq = 9991
current_ts = 333.082123
current_received_ts = 333.081757
current_seq = 9993
count = 1152
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.073792/9991, current 333.082123/9993: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9993, expected 9992
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.082123
last_received_ts = 333.081757
last_seq = 9993
current_ts = 333.090454
current_received_ts = 333.090057
current_seq = 9995
count = 1153
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.082123/9993, current 333.090454/9995: elapsed=8335.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9995, expected 9994
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.090454
last_received_ts = 333.090057
last_seq = 9995
current_ts = 333.098785
current_received_ts = 333.098450
current_seq = 9997
count = 1154
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.090454/9995, current 333.098785/9997: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9997, expected 9996
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.098785
last_received_ts = 333.098450
last_seq = 9997
current_ts = 333.107117
current_received_ts = 333.106781
current_seq = 9999
count = 1155
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.098785/9997, current 333.107117/9999: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 9999, expected 9998
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.107117
last_received_ts = 333.106781
last_seq = 9999
current_ts = 333.115448
current_received_ts = 333.115082
current_seq = 10001
count = 1156
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.107117/9999, current 333.115448/10001: elapsed=8336.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10001, expected 10000
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.115448
last_received_ts = 333.115082
last_seq = 10001
current_ts = 333.123779
current_received_ts = 333.123444
current_seq = 10003
count = 1157
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.115448/10001, current 333.123779/10003: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10003, expected 10002
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.123779
last_received_ts = 333.123444
last_seq = 10003
current_ts = 333.132111
current_received_ts = 333.131775
current_seq = 10005
count = 1158
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.123779/10003, current 333.132111/10005: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10005, expected 10004
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.132111
last_received_ts = 333.131775
last_seq = 10005
current_ts = 333.140442
current_received_ts = 333.140076
current_seq = 10007
count = 1159
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.132111/10005, current 333.140442/10007: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10007, expected 10006
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.140442
last_received_ts = 333.140076
last_seq = 10007
current_ts = 333.148773
current_received_ts = 333.148438
current_seq = 10009
count = 1160
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.140442/10007, current 333.148773/10009: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10009, expected 10008
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.148773
last_received_ts = 333.148438
last_seq = 10009
current_ts = 333.157135
current_received_ts = 333.156769
current_seq = 10011
count = 1161
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.148773/10009, current 333.157135/10011: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10011, expected 10010
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.157135
last_received_ts = 333.156769
last_seq = 10011
current_ts = 333.165466
current_received_ts = 333.165070
current_seq = 10013
count = 1162
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.157135/10011, current 333.165466/10013: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10013, expected 10012
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.165466
last_received_ts = 333.165070
last_seq = 10013
current_ts = 333.173798
current_received_ts = 333.173431
current_seq = 10015
count = 1163
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.165466/10013, current 333.173798/10015: elapsed=8335.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10015, expected 10014
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.173798
last_received_ts = 333.173431
last_seq = 10015
current_ts = 333.182129
current_received_ts = 333.181763
current_seq = 10017
count = 1164
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.173798/10015, current 333.182129/10017: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10017, expected 10016
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.182129
last_received_ts = 333.181763
last_seq = 10017
current_ts = 333.190460
current_received_ts = 333.190094
current_seq = 10019
count = 1165
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.182129/10017, current 333.190460/10019: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10019, expected 10018
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.190460
last_received_ts = 333.190094
last_seq = 10019
current_ts = 333.198792
current_received_ts = 333.198364
current_seq = 10021
count = 1166
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.190460/10019, current 333.198792/10021: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10021, expected 10020
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.198792
last_received_ts = 333.198364
last_seq = 10021
current_ts = 333.207123
current_received_ts = 333.206757
current_seq = 10023
count = 1167
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.198792/10021, current 333.207123/10023: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10023, expected 10022
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.207123
last_received_ts = 333.206757
last_seq = 10023
current_ts = 333.215454
current_received_ts = 333.215027
current_seq = 10025
count = 1168
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.207123/10023, current 333.215454/10025: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10025, expected 10024
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.215454
last_received_ts = 333.215027
last_seq = 10025
current_ts = 333.223785
current_received_ts = 333.223389
current_seq = 10027
count = 1169
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.215454/10025, current 333.223785/10027: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10027, expected 10026
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.223785
last_received_ts = 333.223389
last_seq = 10027
current_ts = 333.232117
current_received_ts = 333.231720
current_seq = 10029
count = 1170
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.223785/10027, current 333.232117/10029: elapsed=8335.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10029, expected 10028
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.232117
last_received_ts = 333.231720
last_seq = 10029
current_ts = 333.240448
current_received_ts = 333.240021
current_seq = 10031
count = 1171
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.232117/10029, current 333.240448/10031: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10031, expected 10030
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.240448
last_received_ts = 333.240021
last_seq = 10031
current_ts = 333.248779
current_received_ts = 333.248383
current_seq = 10033
count = 1172
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.240448/10031, current 333.248779/10033: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10033, expected 10032
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.248779
last_received_ts = 333.248383
last_seq = 10033
current_ts = 333.257111
current_received_ts = 333.256714
current_seq = 10035
count = 1173
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.248779/10033, current 333.257111/10035: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10035, expected 10034
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.257111
last_received_ts = 333.256714
last_seq = 10035
current_ts = 333.265442
current_received_ts = 333.265106
current_seq = 10037
count = 1174
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.257111/10035, current 333.265442/10037: elapsed=8335.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10037, expected 10036
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.265442
last_received_ts = 333.265106
last_seq = 10037
current_ts = 333.273804
current_received_ts = 333.273438
current_seq = 10039
count = 1175
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.265442/10037, current 333.273804/10039: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10039, expected 10038
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.273804
last_received_ts = 333.273438
last_seq = 10039
current_ts = 333.282135
current_received_ts = 333.281769
current_seq = 10041
count = 1176
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.273804/10039, current 333.282135/10041: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10041, expected 10040
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.282135
last_received_ts = 333.281769
last_seq = 10041
current_ts = 333.290466
current_received_ts = 333.290070
current_seq = 10043
count = 1177
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.282135/10041, current 333.290466/10043: elapsed=8335.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10043, expected 10042
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.290466
last_received_ts = 333.290070
last_seq = 10043
current_ts = 333.298798
current_received_ts = 333.298431
current_seq = 10045
count = 1178
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.290466/10043, current 333.298798/10045: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10045, expected 10044
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.298798
last_received_ts = 333.298431
last_seq = 10045
current_ts = 333.307129
current_received_ts = 333.306763
current_seq = 10047
count = 1179
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.298798/10045, current 333.307129/10047: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10047, expected 10046
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.307129
last_received_ts = 333.306763
last_seq = 10047
current_ts = 333.315460
current_received_ts = 333.315094
current_seq = 10049
count = 1180
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.307129/10047, current 333.315460/10049: elapsed=8335.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10049, expected 10048
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.315460
last_received_ts = 333.315094
last_seq = 10049
current_ts = 333.323792
current_received_ts = 333.323425
current_seq = 10051
count = 1181
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.315460/10049, current 333.323792/10051: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10051, expected 10050
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.323792
last_received_ts = 333.323425
last_seq = 10051
current_ts = 333.332123
current_received_ts = 333.331787
current_seq = 10053
count = 1182
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.323792/10051, current 333.332123/10053: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10053, expected 10052
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.332123
last_received_ts = 333.331787
last_seq = 10053
current_ts = 333.340454
current_received_ts = 333.340088
current_seq = 10055
count = 1183
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.332123/10053, current 333.340454/10055: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10055, expected 10054
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.340454
last_received_ts = 333.340088
last_seq = 10055
current_ts = 333.348785
current_received_ts = 333.348450
current_seq = 10057
count = 1184
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.340454/10055, current 333.348785/10057: elapsed=8336.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10057, expected 10056
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.348785
last_received_ts = 333.348450
last_seq = 10057
current_ts = 333.357117
current_received_ts = 333.356781
current_seq = 10059
count = 1185
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.348785/10057, current 333.357117/10059: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10059, expected 10058
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.357117
last_received_ts = 333.356781
last_seq = 10059
current_ts = 333.365448
current_received_ts = 333.365082
current_seq = 10061
count = 1186
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.357117/10059, current 333.365448/10061: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10061, expected 10060
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.365448
last_received_ts = 333.365082
last_seq = 10061
current_ts = 333.373779
current_received_ts = 333.373444
current_seq = 10063
count = 1187
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.365448/10061, current 333.373779/10063: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10063, expected 10062
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.373779
last_received_ts = 333.373444
last_seq = 10063
current_ts = 333.382111
current_received_ts = 333.381775
current_seq = 10065
count = 1188
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.373779/10063, current 333.382111/10065: elapsed=8335.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10065, expected 10064
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.382111
last_received_ts = 333.381775
last_seq = 10065
current_ts = 333.390442
current_received_ts = 333.390076
current_seq = 10067
count = 1189
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.382111/10065, current 333.390442/10067: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10067, expected 10066
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.390442
last_received_ts = 333.390076
last_seq = 10067
current_ts = 333.398804
current_received_ts = 333.398438
current_seq = 10069
count = 1190
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.390442/10067, current 333.398804/10069: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10069, expected 10068
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.398804
last_received_ts = 333.398438
last_seq = 10069
current_ts = 333.407135
current_received_ts = 333.406769
current_seq = 10071
count = 1191
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.398804/10069, current 333.407135/10071: elapsed=8335.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10071, expected 10070
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.407135
last_received_ts = 333.406769
last_seq = 10071
current_ts = 333.415466
current_received_ts = 333.415070
current_seq = 10073
count = 1192
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.407135/10071, current 333.415466/10073: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10073, expected 10072
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.415466
last_received_ts = 333.415070
last_seq = 10073
current_ts = 333.423798
current_received_ts = 333.423431
current_seq = 10075
count = 1193
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.415466/10073, current 333.423798/10075: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10075, expected 10074
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.423798
last_received_ts = 333.423431
last_seq = 10075
current_ts = 333.432129
current_received_ts = 333.431763
current_seq = 10077
count = 1194
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.423798/10075, current 333.432129/10077: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10077, expected 10076
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.432129
last_received_ts = 333.431763
last_seq = 10077
current_ts = 333.440460
current_received_ts = 333.440063
current_seq = 10079
count = 1195
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.432129/10077, current 333.440460/10079: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10079, expected 10078
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.440460
last_received_ts = 333.440063
last_seq = 10079
current_ts = 333.448792
current_received_ts = 333.448425
current_seq = 10081
count = 1196
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.440460/10079, current 333.448792/10081: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10081, expected 10080
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.448792
last_received_ts = 333.448425
last_seq = 10081
current_ts = 333.457123
current_received_ts = 333.456787
current_seq = 10083
count = 1197
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.448792/10081, current 333.457123/10083: elapsed=8336.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10083, expected 10082
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.457123
last_received_ts = 333.456787
last_seq = 10083
current_ts = 333.465454
current_received_ts = 333.465088
current_seq = 10085
count = 1198
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.457123/10083, current 333.465454/10085: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10085, expected 10084
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.465454
last_received_ts = 333.465088
last_seq = 10085
current_ts = 333.473785
current_received_ts = 333.473450
current_seq = 10087
count = 1199
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.465454/10085, current 333.473785/10087: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10087, expected 10086
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.473785
last_received_ts = 333.473450
last_seq = 10087
current_ts = 333.482117
current_received_ts = 333.481781
current_seq = 10089
count = 1200
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.473785/10087, current 333.482117/10089: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10089, expected 10088
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.482117
last_received_ts = 333.481781
last_seq = 10089
current_ts = 333.490448
current_received_ts = 333.490082
current_seq = 10091
count = 1201
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.482117/10089, current 333.490448/10091: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10091, expected 10090
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.490448
last_received_ts = 333.490082
last_seq = 10091
current_ts = 333.498779
current_received_ts = 333.498444
current_seq = 10093
count = 1202
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.490448/10091, current 333.498779/10093: elapsed=8336.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10093, expected 10092
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.498779
last_received_ts = 333.498444
last_seq = 10093
current_ts = 333.507111
current_received_ts = 333.506775
current_seq = 10095
count = 1203
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.498779/10093, current 333.507111/10095: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10095, expected 10094
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.507111
last_received_ts = 333.506775
last_seq = 10095
current_ts = 333.515472
current_received_ts = 333.515076
current_seq = 10097
count = 1204
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.507111/10095, current 333.515472/10097: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10097, expected 10096
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.515472
last_received_ts = 333.515076
last_seq = 10097
current_ts = 333.523804
current_received_ts = 333.523438
current_seq = 10099
count = 1205
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.515472/10097, current 333.523804/10099: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10099, expected 10098
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.523804
last_received_ts = 333.523438
last_seq = 10099
current_ts = 333.532135
current_received_ts = 333.531769
current_seq = 10101
count = 1206
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.523804/10099, current 333.532135/10101: elapsed=8332.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10101, expected 10100
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.532135
last_received_ts = 333.531769
last_seq = 10101
current_ts = 333.540466
current_received_ts = 333.540070
current_seq = 10103
count = 1207
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.532135/10101, current 333.540466/10103: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10103, expected 10102
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.540466
last_received_ts = 333.540070
last_seq = 10103
current_ts = 333.548798
current_received_ts = 333.548431
current_seq = 10105
count = 1208
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.540466/10103, current 333.548798/10105: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10105, expected 10104
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.548798
last_received_ts = 333.548431
last_seq = 10105
current_ts = 333.557129
current_received_ts = 333.556763
current_seq = 10107
count = 1209
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.548798/10105, current 333.557129/10107: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10107, expected 10106
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.557129
last_received_ts = 333.556763
last_seq = 10107
current_ts = 333.565460
current_received_ts = 333.565063
current_seq = 10109
count = 1210
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.557129/10107, current 333.565460/10109: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10109, expected 10108
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.565460
last_received_ts = 333.565063
last_seq = 10109
current_ts = 333.573792
current_received_ts = 333.573456
current_seq = 10111
count = 1211
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.565460/10109, current 333.573792/10111: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10111, expected 10110
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.573792
last_received_ts = 333.573456
last_seq = 10111
current_ts = 333.582123
current_received_ts = 333.581757
current_seq = 10113
count = 1212
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.573792/10111, current 333.582123/10113: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10113, expected 10112
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.582123
last_received_ts = 333.581757
last_seq = 10113
current_ts = 333.590454
current_received_ts = 333.590057
current_seq = 10115
count = 1213
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.582123/10113, current 333.590454/10115: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10115, expected 10114
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.590454
last_received_ts = 333.590057
last_seq = 10115
current_ts = 333.598785
current_received_ts = 333.598450
current_seq = 10117
count = 1214
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.590454/10115, current 333.598785/10117: elapsed=8333.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10117, expected 10116
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.598785
last_received_ts = 333.598450
last_seq = 10117
current_ts = 333.607117
current_received_ts = 333.606781
current_seq = 10119
count = 1215
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.598785/10117, current 333.607117/10119: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10119, expected 10118
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.607117
last_received_ts = 333.606781
last_seq = 10119
current_ts = 333.615448
current_received_ts = 333.615082
current_seq = 10121
count = 1216
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.607117/10119, current 333.615448/10121: elapsed=8334.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10121, expected 10120
(kms_flip:2551) DEBUG: name = flip
last_ts = 333.615448
last_received_ts = 333.615082
last_seq = 10121
current_ts = 333.623779
current_received_ts = 333.623444
current_seq = 10123
count = 1217
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 333.615448/10121, current 333.623779/10123: elapsed=8331.0us expected=8333.2us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 10123, expected 10122
(kms_flip:2551) INFO: Event flip: expected 2401, counted 1218, passrate = 2.96%, encoder type 2
(kms_flip:2551) DEBUG: dropped frames, expected 2401, counted 1218, passrate = 2.96%, encoder type 2
(kms_flip:2551) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2551) CRITICAL: Failed assertion: !retried
(kms_flip:2551) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2551) igt_core-INFO: Stack trace:
(kms_flip:2551) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2551) igt_core-INFO:   #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
(kms_flip:2551) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:2551) igt_core-INFO:   #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
(kms_flip:2551) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:2551) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2551) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2551) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (25.870s)
Starting dynamic subtest: C-eDP1
(kms_flip:2551) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2551) CRITICAL: Failed assertion: !retried
(kms_flip:2551) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest C-eDP1 failed.
**** DEBUG ****
(kms_flip:2551) DEBUG: unexpected flip seq 15069, expected 15068
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.815308
last_received_ts = 358.814911
last_seq = 15069
current_ts = 358.823639
current_received_ts = 358.823212
current_seq = 15071
count = 1132
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.815308/15069, current 358.823639/15071: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15071, expected 15070
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.823639
last_received_ts = 358.823212
last_seq = 15071
current_ts = 358.831970
current_received_ts = 358.831573
current_seq = 15073
count = 1133
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.823639/15071, current 358.831970/15073: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15073, expected 15072
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.831970
last_received_ts = 358.831573
last_seq = 15073
current_ts = 358.840302
current_received_ts = 358.839905
current_seq = 15075
count = 1134
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.831970/15073, current 358.840302/15075: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15075, expected 15074
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.840302
last_received_ts = 358.839905
last_seq = 15075
current_ts = 358.848633
current_received_ts = 358.848206
current_seq = 15077
count = 1135
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.840302/15075, current 358.848633/15077: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15077, expected 15076
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.848633
last_received_ts = 358.848206
last_seq = 15077
current_ts = 358.856964
current_received_ts = 358.856567
current_seq = 15079
count = 1136
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.848633/15077, current 358.856964/15079: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15079, expected 15078
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.856964
last_received_ts = 358.856567
last_seq = 15079
current_ts = 358.865295
current_received_ts = 358.864929
current_seq = 15081
count = 1137
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.856964/15079, current 358.865295/15081: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15081, expected 15080
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.865295
last_received_ts = 358.864929
last_seq = 15081
current_ts = 358.873627
current_received_ts = 358.873230
current_seq = 15083
count = 1138
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.865295/15081, current 358.873627/15083: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15083, expected 15082
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.873627
last_received_ts = 358.873230
last_seq = 15083
current_ts = 358.881958
current_received_ts = 358.881561
current_seq = 15085
count = 1139
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.873627/15083, current 358.881958/15085: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15085, expected 15084
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.881958
last_received_ts = 358.881561
last_seq = 15085
current_ts = 358.890289
current_received_ts = 358.889923
current_seq = 15087
count = 1140
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.881958/15085, current 358.890289/15087: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15087, expected 15086
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.890289
last_received_ts = 358.889923
last_seq = 15087
current_ts = 358.898651
current_received_ts = 358.898224
current_seq = 15089
count = 1141
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.890289/15087, current 358.898651/15089: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15089, expected 15088
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.898651
last_received_ts = 358.898224
last_seq = 15089
current_ts = 358.906982
current_received_ts = 358.906555
current_seq = 15091
count = 1142
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.898651/15089, current 358.906982/15091: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15091, expected 15090
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.906982
last_received_ts = 358.906555
last_seq = 15091
current_ts = 358.915314
current_received_ts = 358.914917
current_seq = 15093
count = 1143
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.906982/15091, current 358.915314/15093: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15093, expected 15092
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.915314
last_received_ts = 358.914917
last_seq = 15093
current_ts = 358.923645
current_received_ts = 358.923218
current_seq = 15095
count = 1144
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.915314/15093, current 358.923645/15095: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15095, expected 15094
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.923645
last_received_ts = 358.923218
last_seq = 15095
current_ts = 358.931976
current_received_ts = 358.931610
current_seq = 15097
count = 1145
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.923645/15095, current 358.931976/15097: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15097, expected 15096
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.931976
last_received_ts = 358.931610
last_seq = 15097
current_ts = 358.940308
current_received_ts = 358.939941
current_seq = 15099
count = 1146
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.931976/15097, current 358.940308/15099: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15099, expected 15098
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.940308
last_received_ts = 358.939941
last_seq = 15099
current_ts = 358.948639
current_received_ts = 358.948242
current_seq = 15101
count = 1147
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.940308/15099, current 358.948639/15101: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15101, expected 15100
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.948639
last_received_ts = 358.948242
last_seq = 15101
current_ts = 358.956970
current_received_ts = 358.956604
current_seq = 15103
count = 1148
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.948639/15101, current 358.956970/15103: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15103, expected 15102
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.956970
last_received_ts = 358.956604
last_seq = 15103
current_ts = 358.965302
current_received_ts = 358.964935
current_seq = 15105
count = 1149
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.956970/15103, current 358.965302/15105: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15105, expected 15104
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.965302
last_received_ts = 358.964935
last_seq = 15105
current_ts = 358.973633
current_received_ts = 358.973236
current_seq = 15107
count = 1150
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.965302/15105, current 358.973633/15107: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15107, expected 15106
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.973633
last_received_ts = 358.973236
last_seq = 15107
current_ts = 358.981964
current_received_ts = 358.981598
current_seq = 15109
count = 1151
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.973633/15107, current 358.981964/15109: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15109, expected 15108
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.981964
last_received_ts = 358.981598
last_seq = 15109
current_ts = 358.990295
current_received_ts = 358.989929
current_seq = 15111
count = 1152
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.981964/15109, current 358.990295/15111: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15111, expected 15110
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.990295
last_received_ts = 358.989929
last_seq = 15111
current_ts = 358.998627
current_received_ts = 358.998230
current_seq = 15113
count = 1153
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.990295/15111, current 358.998627/15113: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15113, expected 15112
(kms_flip:2551) DEBUG: name = flip
last_ts = 358.998627
last_received_ts = 358.998230
last_seq = 15113
current_ts = 359.006958
current_received_ts = 359.006622
current_seq = 15115
count = 1154
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 358.998627/15113, current 359.006958/15115: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15115, expected 15114
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.006958
last_received_ts = 359.006622
last_seq = 15115
current_ts = 359.015289
current_received_ts = 359.014954
current_seq = 15117
count = 1155
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.006958/15115, current 359.015289/15117: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15117, expected 15116
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.015289
last_received_ts = 359.014954
last_seq = 15117
current_ts = 359.023651
current_received_ts = 359.023285
current_seq = 15119
count = 1156
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.015289/15117, current 359.023651/15119: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15119, expected 15118
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.023651
last_received_ts = 359.023285
last_seq = 15119
current_ts = 359.031982
current_received_ts = 359.031616
current_seq = 15121
count = 1157
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.023651/15119, current 359.031982/15121: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15121, expected 15120
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.031982
last_received_ts = 359.031616
last_seq = 15121
current_ts = 359.040314
current_received_ts = 359.039948
current_seq = 15123
count = 1158
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.031982/15121, current 359.040314/15123: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15123, expected 15122
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.040314
last_received_ts = 359.039948
last_seq = 15123
current_ts = 359.048645
current_received_ts = 359.048248
current_seq = 15125
count = 1159
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.040314/15123, current 359.048645/15125: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15125, expected 15124
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.048645
last_received_ts = 359.048248
last_seq = 15125
current_ts = 359.056976
current_received_ts = 359.056641
current_seq = 15127
count = 1160
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.048645/15125, current 359.056976/15127: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15127, expected 15126
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.056976
last_received_ts = 359.056641
last_seq = 15127
current_ts = 359.065308
current_received_ts = 359.064911
current_seq = 15129
count = 1161
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.056976/15127, current 359.065308/15129: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15129, expected 15128
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.065308
last_received_ts = 359.064911
last_seq = 15129
current_ts = 359.073639
current_received_ts = 359.073212
current_seq = 15131
count = 1162
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.065308/15129, current 359.073639/15131: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15131, expected 15130
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.073639
last_received_ts = 359.073212
last_seq = 15131
current_ts = 359.081970
current_received_ts = 359.081543
current_seq = 15133
count = 1163
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.073639/15131, current 359.081970/15133: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15133, expected 15132
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.081970
last_received_ts = 359.081543
last_seq = 15133
current_ts = 359.090302
current_received_ts = 359.089905
current_seq = 15135
count = 1164
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.081970/15133, current 359.090302/15135: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15135, expected 15134
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.090302
last_received_ts = 359.089905
last_seq = 15135
current_ts = 359.098633
current_received_ts = 359.098236
current_seq = 15137
count = 1165
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.090302/15135, current 359.098633/15137: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15137, expected 15136
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.098633
last_received_ts = 359.098236
last_seq = 15137
current_ts = 359.106964
current_received_ts = 359.106567
current_seq = 15139
count = 1166
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.098633/15137, current 359.106964/15139: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15139, expected 15138
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.106964
last_received_ts = 359.106567
last_seq = 15139
current_ts = 359.115295
current_received_ts = 359.114990
current_seq = 15141
count = 1167
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.106964/15139, current 359.115295/15141: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15141, expected 15140
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.115295
last_received_ts = 359.114990
last_seq = 15141
current_ts = 359.123627
current_received_ts = 359.123230
current_seq = 15143
count = 1168
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.115295/15141, current 359.123627/15143: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15143, expected 15142
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.123627
last_received_ts = 359.123230
last_seq = 15143
current_ts = 359.131958
current_received_ts = 359.131653
current_seq = 15145
count = 1169
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.123627/15143, current 359.131958/15145: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15145, expected 15144
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.131958
last_received_ts = 359.131653
last_seq = 15145
current_ts = 359.140320
current_received_ts = 359.139954
current_seq = 15147
count = 1170
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.131958/15145, current 359.140320/15147: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15147, expected 15146
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.140320
last_received_ts = 359.139954
last_seq = 15147
current_ts = 359.148651
current_received_ts = 359.148224
current_seq = 15149
count = 1171
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.140320/15147, current 359.148651/15149: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15149, expected 15148
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.148651
last_received_ts = 359.148224
last_seq = 15149
current_ts = 359.156982
current_received_ts = 359.156616
current_seq = 15151
count = 1172
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.148651/15149, current 359.156982/15151: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15151, expected 15150
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.156982
last_received_ts = 359.156616
last_seq = 15151
current_ts = 359.165314
current_received_ts = 359.164948
current_seq = 15153
count = 1173
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.156982/15151, current 359.165314/15153: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15153, expected 15152
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.165314
last_received_ts = 359.164948
last_seq = 15153
current_ts = 359.173645
current_received_ts = 359.173218
current_seq = 15155
count = 1174
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.165314/15153, current 359.173645/15155: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15155, expected 15154
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.173645
last_received_ts = 359.173218
last_seq = 15155
current_ts = 359.181976
current_received_ts = 359.181610
current_seq = 15157
count = 1175
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.173645/15155, current 359.181976/15157: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15157, expected 15156
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.181976
last_received_ts = 359.181610
last_seq = 15157
current_ts = 359.190308
current_received_ts = 359.189941
current_seq = 15159
count = 1176
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.181976/15157, current 359.190308/15159: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15159, expected 15158
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.190308
last_received_ts = 359.189941
last_seq = 15159
current_ts = 359.198639
current_received_ts = 359.198242
current_seq = 15161
count = 1177
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.190308/15159, current 359.198639/15161: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15161, expected 15160
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.198639
last_received_ts = 359.198242
last_seq = 15161
current_ts = 359.206970
current_received_ts = 359.206604
current_seq = 15163
count = 1178
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.198639/15161, current 359.206970/15163: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15163, expected 15162
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.206970
last_received_ts = 359.206604
last_seq = 15163
current_ts = 359.215302
current_received_ts = 359.214966
current_seq = 15165
count = 1179
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.206970/15163, current 359.215302/15165: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15165, expected 15164
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.215302
last_received_ts = 359.214966
last_seq = 15165
current_ts = 359.223633
current_received_ts = 359.223236
current_seq = 15167
count = 1180
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.215302/15165, current 359.223633/15167: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15167, expected 15166
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.223633
last_received_ts = 359.223236
last_seq = 15167
current_ts = 359.231964
current_received_ts = 359.231628
current_seq = 15169
count = 1181
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.223633/15167, current 359.231964/15169: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15169, expected 15168
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.231964
last_received_ts = 359.231628
last_seq = 15169
current_ts = 359.240295
current_received_ts = 359.239960
current_seq = 15171
count = 1182
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.231964/15169, current 359.240295/15171: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15171, expected 15170
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.240295
last_received_ts = 359.239960
last_seq = 15171
current_ts = 359.248627
current_received_ts = 359.248230
current_seq = 15173
count = 1183
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.240295/15171, current 359.248627/15173: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15173, expected 15172
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.248627
last_received_ts = 359.248230
last_seq = 15173
current_ts = 359.256958
current_received_ts = 359.256622
current_seq = 15175
count = 1184
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.248627/15173, current 359.256958/15175: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15175, expected 15174
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.256958
last_received_ts = 359.256622
last_seq = 15175
current_ts = 359.265320
current_received_ts = 359.264954
current_seq = 15177
count = 1185
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.256958/15175, current 359.265320/15177: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15177, expected 15176
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.265320
last_received_ts = 359.264954
last_seq = 15177
current_ts = 359.273651
current_received_ts = 359.273224
current_seq = 15179
count = 1186
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.265320/15177, current 359.273651/15179: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15179, expected 15178
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.273651
last_received_ts = 359.273224
last_seq = 15179
current_ts = 359.281982
current_received_ts = 359.281616
current_seq = 15181
count = 1187
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.273651/15179, current 359.281982/15181: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15181, expected 15180
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.281982
last_received_ts = 359.281616
last_seq = 15181
current_ts = 359.290314
current_received_ts = 359.289948
current_seq = 15183
count = 1188
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.281982/15181, current 359.290314/15183: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15183, expected 15182
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.290314
last_received_ts = 359.289948
last_seq = 15183
current_ts = 359.298645
current_received_ts = 359.298218
current_seq = 15185
count = 1189
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.290314/15183, current 359.298645/15185: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15185, expected 15184
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.298645
last_received_ts = 359.298218
last_seq = 15185
current_ts = 359.306976
current_received_ts = 359.306641
current_seq = 15187
count = 1190
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.298645/15185, current 359.306976/15187: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15187, expected 15186
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.306976
last_received_ts = 359.306641
last_seq = 15187
current_ts = 359.315308
current_received_ts = 359.314972
current_seq = 15189
count = 1191
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.306976/15187, current 359.315308/15189: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15189, expected 15188
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.315308
last_received_ts = 359.314972
last_seq = 15189
current_ts = 359.323639
current_received_ts = 359.323242
current_seq = 15191
count = 1192
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.315308/15189, current 359.323639/15191: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15191, expected 15190
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.323639
last_received_ts = 359.323242
last_seq = 15191
current_ts = 359.331970
current_received_ts = 359.331635
current_seq = 15193
count = 1193
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.323639/15191, current 359.331970/15193: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15193, expected 15192
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.331970
last_received_ts = 359.331635
last_seq = 15193
current_ts = 359.340302
current_received_ts = 359.339966
current_seq = 15195
count = 1194
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.331970/15193, current 359.340302/15195: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15195, expected 15194
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.340302
last_received_ts = 359.339966
last_seq = 15195
current_ts = 359.348633
current_received_ts = 359.348236
current_seq = 15197
count = 1195
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.340302/15195, current 359.348633/15197: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15197, expected 15196
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.348633
last_received_ts = 359.348236
last_seq = 15197
current_ts = 359.356964
current_received_ts = 359.356628
current_seq = 15199
count = 1196
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.348633/15197, current 359.356964/15199: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15199, expected 15198
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.356964
last_received_ts = 359.356628
last_seq = 15199
current_ts = 359.365295
current_received_ts = 359.364960
current_seq = 15201
count = 1197
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.356964/15199, current 359.365295/15201: elapsed=8331.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15201, expected 15200
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.365295
last_received_ts = 359.364960
last_seq = 15201
current_ts = 359.373627
current_received_ts = 359.373230
current_seq = 15203
count = 1198
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.365295/15201, current 359.373627/15203: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15203, expected 15202
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.373627
last_received_ts = 359.373230
last_seq = 15203
current_ts = 359.381989
current_received_ts = 359.381622
current_seq = 15205
count = 1199
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.373627/15203, current 359.381989/15205: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15205, expected 15204
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.381989
last_received_ts = 359.381622
last_seq = 15205
current_ts = 359.390320
current_received_ts = 359.389954
current_seq = 15207
count = 1200
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.381989/15205, current 359.390320/15207: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15207, expected 15206
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.390320
last_received_ts = 359.389954
last_seq = 15207
current_ts = 359.398651
current_received_ts = 359.398224
current_seq = 15209
count = 1201
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.390320/15207, current 359.398651/15209: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15209, expected 15208
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.398651
last_received_ts = 359.398224
last_seq = 15209
current_ts = 359.406982
current_received_ts = 359.406616
current_seq = 15211
count = 1202
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.398651/15209, current 359.406982/15211: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15211, expected 15210
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.406982
last_received_ts = 359.406616
last_seq = 15211
current_ts = 359.415314
current_received_ts = 359.414948
current_seq = 15213
count = 1203
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.406982/15211, current 359.415314/15213: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15213, expected 15212
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.415314
last_received_ts = 359.414948
last_seq = 15213
current_ts = 359.423645
current_received_ts = 359.423218
current_seq = 15215
count = 1204
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.415314/15213, current 359.423645/15215: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15215, expected 15214
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.423645
last_received_ts = 359.423218
last_seq = 15215
current_ts = 359.431976
current_received_ts = 359.431610
current_seq = 15217
count = 1205
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.423645/15215, current 359.431976/15217: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15217, expected 15216
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.431976
last_received_ts = 359.431610
last_seq = 15217
current_ts = 359.440308
current_received_ts = 359.439972
current_seq = 15219
count = 1206
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.431976/15217, current 359.440308/15219: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15219, expected 15218
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.440308
last_received_ts = 359.439972
last_seq = 15219
current_ts = 359.448639
current_received_ts = 359.448242
current_seq = 15221
count = 1207
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.440308/15219, current 359.448639/15221: elapsed=8332.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15221, expected 15220
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.448639
last_received_ts = 359.448242
last_seq = 15221
current_ts = 359.456970
current_received_ts = 359.456635
current_seq = 15223
count = 1208
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.448639/15221, current 359.456970/15223: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15223, expected 15222
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.456970
last_received_ts = 359.456635
last_seq = 15223
current_ts = 359.465302
current_received_ts = 359.464966
current_seq = 15225
count = 1209
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.456970/15223, current 359.465302/15225: elapsed=8334.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15225, expected 15224
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.465302
last_received_ts = 359.464966
last_seq = 15225
current_ts = 359.473633
current_received_ts = 359.473236
current_seq = 15227
count = 1210
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.465302/15225, current 359.473633/15227: elapsed=8333.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15227, expected 15226
(kms_flip:2551) DEBUG: name = flip
last_ts = 359.473633
last_received_ts = 359.473236
last_seq = 15227
current_ts = 359.481964
current_received_ts = 359.481628
current_seq = 15229
count = 1211
seq_step = 1
(kms_flip:2551) DEBUG: flip ts/seq: last 359.473633/15227, current 359.481964/15229: elapsed=8335.0us expected=8333.5us +- 41.7us, error 0.0%
(kms_flip:2551) DEBUG: unexpected flip seq 15229, expected 15228
(kms_flip:2551) INFO: Event flip: expected 2401, counted 1212, passrate = 1.90%, encoder type 2
(kms_flip:2551) DEBUG: dropped frames, expected 2401, counted 1212, passrate = 1.90%, encoder type 2
(kms_flip:2551) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2551) CRITICAL: Failed assertion: !retried
(kms_flip:2551) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:2551) igt_core-INFO: Stack trace:
(kms_flip:2551) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2551) igt_core-INFO:   #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
(kms_flip:2551) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:2551) igt_core-INFO:   #3 ../tests/kms_flip.c:2153 __igt_unique____real_main2040()
(kms_flip:2551) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:2551) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2551) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2551) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-eDP1: FAIL (25.858s)
Subtest plain-flip-fb-recreate-interruptible: FAIL (77.619s)
(kms_flip:2551) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2247:
(kms_flip:2551) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2551) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2551) igt_kms-CRITICAL: DPMS property not found on 205