Attachment 133147 Details for Bug 96226 – Tests Log (BSW)

Tests Log (BSW)

KmsFlipFam-02.log (text/plain), 149.37 KB, created by Hector Velazquez on 2017-07-31 16:07:43 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Hector Velazquez

Created: 2017-07-31 16:07:43 UTC

Size: 149.37 KB

patch

obsolete

>IGT-Version: 1.19-gf145475 (x86_64) (Linux: 4.13.0-rc2-drm-tip-ww30-commit-1eb8669+ x86_64)
>(kms_flip:1611) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
>(kms_flip:1611) drmtest-DEBUG: Test requirement passed: !(fd<0)
>(kms_flip:1611) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
>(kms_flip:1611) drmtest-DEBUG: Test requirement passed: drmSetMaster(fd) == 0
>(kms_flip:1611) drmtest-DEBUG: Test requirement passed: !(fd<0)
>(kms_flip:1611) igt-kms-DEBUG: VT: graphics mode set (mode was 0x0)
>Using monotonic timestamps
>(kms_flip:1611) igt-core-DEBUG: Starting subtest: plain-flip-fb-recreate-interruptible
>(kms_flip:1611) DEBUG: Test requirement passed: (flags & TEST_HANG) == 0 || !is_wedged(drm_fd)
>(kms_flip:1611) DEBUG: Test requirement passed: modes
>Beginning plain-flip-fb-recreate-interruptible on pipe A, connector DP-1
>(kms_flip:1611) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
>(kms_flip:1611) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
>(kms_flip:1611) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
>(kms_flip:1611) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
>  1920x1080 60 1920 2008 2052 2200 1080 1084 1089 1125 0x5 0x48 148500
>Expected frametime: 16667us; measured 16666.0us +- 6.851us accuracy 0.12%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 0.000000
>last_received_ts = 0.000000
>last_seq = 0
>current_ts = 2618.829904
>current_received_ts = 2618.829716
>current_seq = 156519
>count = 0
>seq_step = 1
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2618.829904
>last_received_ts = 2618.829716
>last_seq = 156519
>current_ts = 2618.846565
>current_received_ts = 2618.846138
>current_seq = 156520
>count = 1
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2618.829904/156519, current 2618.846565/156520: elapsed=16661.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2618.846565
>last_received_ts = 2618.846138
>last_seq = 156520
>current_ts = 2618.863230
>current_received_ts = 2618.863132
>current_seq = 156521
>count = 2
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2618.846565/156520, current 2618.863230/156521: elapsed=16665.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2618.863230
>last_received_ts = 2618.863132
>last_seq = 156521
>current_ts = 2618.879894
>current_received_ts = 2618.879690
>current_seq = 156522
>count = 3
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2618.863230/156521, current 2618.879894/156522: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2618.879894
>last_received_ts = 2618.879690
>last_seq = 156522
>current_ts = 2618.896568
>current_received_ts = 2618.896602
>current_seq = 156523
>count = 4
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2618.879894/156522, current 2618.896568/156523: elapsed=16674.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2618.896568
>last_received_ts = 2618.896602
>last_seq = 156523
>current_ts = 2618.913232
>current_received_ts = 2618.913278
>current_seq = 156524
>count = 5
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2618.896568/156523, current 2618.913232/156524: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2618.913232
>last_received_ts = 2618.913278
>last_seq = 156524
>current_ts = 2618.929903
>current_received_ts = 2618.929772
>current_seq = 156525
>count = 6
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2618.913232/156524, current 2618.929903/156525: elapsed=16671.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2618.929903
>last_received_ts = 2618.929772
>last_seq = 156525
>current_ts = 2618.946570
>current_received_ts = 2618.946547
>current_seq = 156526
>count = 7
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2618.929903/156525, current 2618.946570/156526: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2618.946570
>last_received_ts = 2618.946547
>last_seq = 156526
>current_ts = 2618.963236
>current_received_ts = 2618.962773
>current_seq = 156527
>count = 8
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2618.946570/156526, current 2618.963236/156527: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2618.963236
>last_received_ts = 2618.962773
>last_seq = 156527
>current_ts = 2618.979897
>current_received_ts = 2618.979923
>current_seq = 156528
>count = 9
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2618.963236/156527, current 2618.979897/156528: elapsed=16661.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2618.979897
>last_received_ts = 2618.979923
>last_seq = 156528
>current_ts = 2618.996567
>current_received_ts = 2618.996249
>current_seq = 156529
>count = 10
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2618.979897/156528, current 2618.996567/156529: elapsed=16670.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2618.996567
>last_received_ts = 2618.996249
>last_seq = 156529
>current_ts = 2619.013230
>current_received_ts = 2619.013310
>current_seq = 156530
>count = 11
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2618.996567/156529, current 2619.013230/156530: elapsed=16663.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.013230
>last_received_ts = 2619.013310
>last_seq = 156530
>current_ts = 2619.029905
>current_received_ts = 2619.029733
>current_seq = 156531
>count = 12
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.013230/156530, current 2619.029905/156531: elapsed=16675.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.029905
>last_received_ts = 2619.029733
>last_seq = 156531
>current_ts = 2619.046564
>current_received_ts = 2619.046250
>current_seq = 156532
>count = 13
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.029905/156531, current 2619.046564/156532: elapsed=16659.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.046564
>last_received_ts = 2619.046250
>last_seq = 156532
>current_ts = 2619.063228
>current_received_ts = 2619.063115
>current_seq = 156533
>count = 14
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.046564/156532, current 2619.063228/156533: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.063228
>last_received_ts = 2619.063115
>last_seq = 156533
>current_ts = 2619.079907
>current_received_ts = 2619.079779
>current_seq = 156534
>count = 15
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.063228/156533, current 2619.079907/156534: elapsed=16679.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.079907
>last_received_ts = 2619.079779
>last_seq = 156534
>current_ts = 2619.096570
>current_received_ts = 2619.096860
>current_seq = 156535
>count = 16
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.079907/156534, current 2619.096570/156535: elapsed=16663.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.096570
>last_received_ts = 2619.096860
>last_seq = 156535
>current_ts = 2619.113232
>current_received_ts = 2619.112827
>current_seq = 156536
>count = 17
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.096570/156535, current 2619.113232/156536: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.113232
>last_received_ts = 2619.112827
>last_seq = 156536
>current_ts = 2619.129899
>current_received_ts = 2619.129840
>current_seq = 156537
>count = 18
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.113232/156536, current 2619.129899/156537: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.129899
>last_received_ts = 2619.129840
>last_seq = 156537
>current_ts = 2619.146565
>current_received_ts = 2619.146436
>current_seq = 156538
>count = 19
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.129899/156537, current 2619.146565/156538: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.146565
>last_received_ts = 2619.146436
>last_seq = 156538
>current_ts = 2619.163232
>current_received_ts = 2619.163252
>current_seq = 156539
>count = 20
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.146565/156538, current 2619.163232/156539: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.163232
>last_received_ts = 2619.163252
>last_seq = 156539
>current_ts = 2619.179905
>current_received_ts = 2619.179829
>current_seq = 156540
>count = 21
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.163232/156539, current 2619.179905/156540: elapsed=16673.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.179905
>last_received_ts = 2619.179829
>last_seq = 156540
>current_ts = 2619.196562
>current_received_ts = 2619.196432
>current_seq = 156541
>count = 22
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.179905/156540, current 2619.196562/156541: elapsed=16657.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.196562
>last_received_ts = 2619.196432
>last_seq = 156541
>current_ts = 2619.213228
>current_received_ts = 2619.213305
>current_seq = 156542
>count = 23
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.196562/156541, current 2619.213228/156542: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.213228
>last_received_ts = 2619.213305
>last_seq = 156542
>current_ts = 2619.229898
>current_received_ts = 2619.229719
>current_seq = 156543
>count = 24
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.213228/156542, current 2619.229898/156543: elapsed=16670.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.229898
>last_received_ts = 2619.229719
>last_seq = 156543
>current_ts = 2619.246569
>current_received_ts = 2619.246507
>current_seq = 156544
>count = 25
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.229898/156543, current 2619.246569/156544: elapsed=16671.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.246569
>last_received_ts = 2619.246507
>last_seq = 156544
>current_ts = 2619.263235
>current_received_ts = 2619.263063
>current_seq = 156545
>count = 26
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.246569/156544, current 2619.263235/156545: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.263235
>last_received_ts = 2619.263063
>last_seq = 156545
>current_ts = 2619.279894
>current_received_ts = 2619.279409
>current_seq = 156546
>count = 27
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.263235/156545, current 2619.279894/156546: elapsed=16659.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.279894
>last_received_ts = 2619.279409
>last_seq = 156546
>current_ts = 2619.296569
>current_received_ts = 2619.296439
>current_seq = 156547
>count = 28
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.279894/156546, current 2619.296569/156547: elapsed=16675.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.296569
>last_received_ts = 2619.296439
>last_seq = 156547
>current_ts = 2619.313232
>current_received_ts = 2619.313132
>current_seq = 156548
>count = 29
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.296569/156547, current 2619.313232/156548: elapsed=16663.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.313232
>last_received_ts = 2619.313132
>last_seq = 156548
>current_ts = 2619.329904
>current_received_ts = 2619.329558
>current_seq = 156549
>count = 30
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.313232/156548, current 2619.329904/156549: elapsed=16672.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.329904
>last_received_ts = 2619.329558
>last_seq = 156549
>current_ts = 2619.346565
>current_received_ts = 2619.346429
>current_seq = 156550
>count = 31
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.329904/156549, current 2619.346565/156550: elapsed=16661.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.346565
>last_received_ts = 2619.346429
>last_seq = 156550
>current_ts = 2619.363233
>current_received_ts = 2619.363072
>current_seq = 156551
>count = 32
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.346565/156550, current 2619.363233/156551: elapsed=16668.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.363233
>last_received_ts = 2619.363072
>last_seq = 156551
>current_ts = 2619.379904
>current_received_ts = 2619.379964
>current_seq = 156552
>count = 33
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.363233/156551, current 2619.379904/156552: elapsed=16671.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.379904
>last_received_ts = 2619.379964
>last_seq = 156552
>current_ts = 2619.396571
>current_received_ts = 2619.396370
>current_seq = 156553
>count = 34
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.379904/156552, current 2619.396571/156553: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.396571
>last_received_ts = 2619.396370
>last_seq = 156553
>current_ts = 2619.413239
>current_received_ts = 2619.412781
>current_seq = 156554
>count = 35
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.396571/156553, current 2619.413239/156554: elapsed=16668.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.413239
>last_received_ts = 2619.412781
>last_seq = 156554
>current_ts = 2619.429898
>current_received_ts = 2619.429686
>current_seq = 156555
>count = 36
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.413239/156554, current 2619.429898/156555: elapsed=16659.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.429898
>last_received_ts = 2619.429686
>last_seq = 156555
>current_ts = 2619.446573
>current_received_ts = 2619.446559
>current_seq = 156556
>count = 37
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.429898/156555, current 2619.446573/156556: elapsed=16675.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.446573
>last_received_ts = 2619.446559
>last_seq = 156556
>current_ts = 2619.463240
>current_received_ts = 2619.463174
>current_seq = 156557
>count = 38
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.446573/156556, current 2619.463240/156557: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.463240
>last_received_ts = 2619.463174
>last_seq = 156557
>current_ts = 2619.479906
>current_received_ts = 2619.479716
>current_seq = 156558
>count = 39
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.463240/156557, current 2619.479906/156558: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.479906
>last_received_ts = 2619.479716
>last_seq = 156558
>current_ts = 2619.496572
>current_received_ts = 2619.496282
>current_seq = 156559
>count = 40
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.479906/156558, current 2619.496572/156559: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.496572
>last_received_ts = 2619.496282
>last_seq = 156559
>current_ts = 2619.513238
>current_received_ts = 2619.513195
>current_seq = 156560
>count = 41
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.496572/156559, current 2619.513238/156560: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.513238
>last_received_ts = 2619.513195
>last_seq = 156560
>current_ts = 2619.529898
>current_received_ts = 2619.529833
>current_seq = 156561
>count = 42
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.513238/156560, current 2619.529898/156561: elapsed=16660.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.529898
>last_received_ts = 2619.529833
>last_seq = 156561
>current_ts = 2619.546563
>current_received_ts = 2619.546134
>current_seq = 156562
>count = 43
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.529898/156561, current 2619.546563/156562: elapsed=16665.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.546563
>last_received_ts = 2619.546134
>last_seq = 156562
>current_ts = 2619.563232
>current_received_ts = 2619.562851
>current_seq = 156563
>count = 44
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.546563/156562, current 2619.563232/156563: elapsed=16669.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.563232
>last_received_ts = 2619.562851
>last_seq = 156563
>current_ts = 2619.579903
>current_received_ts = 2619.579561
>current_seq = 156564
>count = 45
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.563232/156563, current 2619.579903/156564: elapsed=16671.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.579903
>last_received_ts = 2619.579561
>last_seq = 156564
>current_ts = 2619.596575
>current_received_ts = 2619.596519
>current_seq = 156565
>count = 46
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.579903/156564, current 2619.596575/156565: elapsed=16672.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.596575
>last_received_ts = 2619.596519
>last_seq = 156565
>current_ts = 2619.613234
>current_received_ts = 2619.612800
>current_seq = 156566
>count = 47
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.596575/156565, current 2619.613234/156566: elapsed=16659.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.613234
>last_received_ts = 2619.612800
>last_seq = 156566
>current_ts = 2619.629900
>current_received_ts = 2619.629563
>current_seq = 156567
>count = 48
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.613234/156566, current 2619.629900/156567: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.629900
>last_received_ts = 2619.629563
>last_seq = 156567
>current_ts = 2619.646562
>current_received_ts = 2619.646495
>current_seq = 156568
>count = 49
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.629900/156567, current 2619.646562/156568: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.646562
>last_received_ts = 2619.646495
>last_seq = 156568
>current_ts = 2619.663235
>current_received_ts = 2619.663119
>current_seq = 156569
>count = 50
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.646562/156568, current 2619.663235/156569: elapsed=16673.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.663235
>last_received_ts = 2619.663119
>last_seq = 156569
>current_ts = 2619.679901
>current_received_ts = 2619.679657
>current_seq = 156570
>count = 51
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.663235/156569, current 2619.679901/156570: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.679901
>last_received_ts = 2619.679657
>last_seq = 156570
>current_ts = 2619.696575
>current_received_ts = 2619.696460
>current_seq = 156571
>count = 52
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.679901/156570, current 2619.696575/156571: elapsed=16674.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.696575
>last_received_ts = 2619.696460
>last_seq = 156571
>current_ts = 2619.713231
>current_received_ts = 2619.712851
>current_seq = 156572
>count = 53
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.696575/156571, current 2619.713231/156572: elapsed=16656.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.713231
>last_received_ts = 2619.712851
>last_seq = 156572
>current_ts = 2619.729909
>current_received_ts = 2619.729809
>current_seq = 156573
>count = 54
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.713231/156572, current 2619.729909/156573: elapsed=16678.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.729909
>last_received_ts = 2619.729809
>last_seq = 156573
>current_ts = 2619.746567
>current_received_ts = 2619.746429
>current_seq = 156574
>count = 55
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.729909/156573, current 2619.746567/156574: elapsed=16658.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.746567
>last_received_ts = 2619.746429
>last_seq = 156574
>current_ts = 2619.763230
>current_received_ts = 2619.763200
>current_seq = 156575
>count = 56
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.746567/156574, current 2619.763230/156575: elapsed=16663.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.763230
>last_received_ts = 2619.763200
>last_seq = 156575
>current_ts = 2619.779896
>current_received_ts = 2619.779534
>current_seq = 156576
>count = 57
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.763230/156575, current 2619.779896/156576: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.779896
>last_received_ts = 2619.779534
>last_seq = 156576
>current_ts = 2619.796570
>current_received_ts = 2619.796576
>current_seq = 156577
>count = 58
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.779896/156576, current 2619.796570/156577: elapsed=16674.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.796570
>last_received_ts = 2619.796576
>last_seq = 156577
>current_ts = 2619.813235
>current_received_ts = 2619.812907
>current_seq = 156578
>count = 59
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.796570/156577, current 2619.813235/156578: elapsed=16665.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.813235
>last_received_ts = 2619.812907
>last_seq = 156578
>current_ts = 2619.829902
>current_received_ts = 2619.829884
>current_seq = 156579
>count = 60
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.813235/156578, current 2619.829902/156579: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.829902
>last_received_ts = 2619.829884
>last_seq = 156579
>current_ts = 2619.846574
>current_received_ts = 2619.846515
>current_seq = 156580
>count = 61
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.829902/156579, current 2619.846574/156580: elapsed=16672.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.846574
>last_received_ts = 2619.846515
>last_seq = 156580
>current_ts = 2619.863231
>current_received_ts = 2619.863172
>current_seq = 156581
>count = 62
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.846574/156580, current 2619.863231/156581: elapsed=16657.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.863231
>last_received_ts = 2619.863172
>last_seq = 156581
>current_ts = 2619.879895
>current_received_ts = 2619.879550
>current_seq = 156582
>count = 63
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.863231/156581, current 2619.879895/156582: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.879895
>last_received_ts = 2619.879550
>last_seq = 156582
>current_ts = 2619.896567
>current_received_ts = 2619.896584
>current_seq = 156583
>count = 64
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.879895/156582, current 2619.896567/156583: elapsed=16672.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.896567
>last_received_ts = 2619.896584
>last_seq = 156583
>current_ts = 2619.913238
>current_received_ts = 2619.913277
>current_seq = 156584
>count = 65
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.896567/156583, current 2619.913238/156584: elapsed=16671.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.913238
>last_received_ts = 2619.913277
>last_seq = 156584
>current_ts = 2619.929905
>current_received_ts = 2619.929748
>current_seq = 156585
>count = 66
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.913238/156584, current 2619.929905/156585: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.929905
>last_received_ts = 2619.929748
>last_seq = 156585
>current_ts = 2619.946571
>current_received_ts = 2619.946585
>current_seq = 156586
>count = 67
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.929905/156585, current 2619.946571/156586: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.946571
>last_received_ts = 2619.946585
>last_seq = 156586
>current_ts = 2619.963241
>current_received_ts = 2619.963229
>current_seq = 156587
>count = 68
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.946571/156586, current 2619.963241/156587: elapsed=16670.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.963241
>last_received_ts = 2619.963229
>last_seq = 156587
>current_ts = 2619.979910
>current_received_ts = 2619.979755
>current_seq = 156588
>count = 69
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.963241/156587, current 2619.979910/156588: elapsed=16669.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.979910
>last_received_ts = 2619.979755
>last_seq = 156588
>current_ts = 2619.996576
>current_received_ts = 2619.996650
>current_seq = 156589
>count = 70
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.979910/156588, current 2619.996576/156589: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2619.996576
>last_received_ts = 2619.996650
>last_seq = 156589
>current_ts = 2620.013240
>current_received_ts = 2620.012849
>current_seq = 156590
>count = 71
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2619.996576/156589, current 2620.013240/156590: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.013240
>last_received_ts = 2620.012849
>last_seq = 156590
>current_ts = 2620.029897
>current_received_ts = 2620.029674
>current_seq = 156591
>count = 72
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.013240/156590, current 2620.029897/156591: elapsed=16657.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.029897
>last_received_ts = 2620.029674
>last_seq = 156591
>current_ts = 2620.046566
>current_received_ts = 2620.046394
>current_seq = 156592
>count = 73
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.029897/156591, current 2620.046566/156592: elapsed=16669.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.046566
>last_received_ts = 2620.046394
>last_seq = 156592
>current_ts = 2620.063237
>current_received_ts = 2620.063201
>current_seq = 156593
>count = 74
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.046566/156592, current 2620.063237/156593: elapsed=16671.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.063237
>last_received_ts = 2620.063201
>last_seq = 156593
>current_ts = 2620.079897
>current_received_ts = 2620.079689
>current_seq = 156594
>count = 75
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.063237/156593, current 2620.079897/156594: elapsed=16660.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.079897
>last_received_ts = 2620.079689
>last_seq = 156594
>current_ts = 2620.096576
>current_received_ts = 2620.096541
>current_seq = 156595
>count = 76
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.079897/156594, current 2620.096576/156595: elapsed=16679.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.096576
>last_received_ts = 2620.096541
>last_seq = 156595
>current_ts = 2620.113244
>current_received_ts = 2620.113170
>current_seq = 156596
>count = 77
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.096576/156595, current 2620.113244/156596: elapsed=16668.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.113244
>last_received_ts = 2620.113170
>last_seq = 156596
>current_ts = 2620.129908
>current_received_ts = 2620.129649
>current_seq = 156597
>count = 78
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.113244/156596, current 2620.129908/156597: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.129908
>last_received_ts = 2620.129649
>last_seq = 156597
>current_ts = 2620.146570
>current_received_ts = 2620.146603
>current_seq = 156598
>count = 79
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.129908/156597, current 2620.146570/156598: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.146570
>last_received_ts = 2620.146603
>last_seq = 156598
>current_ts = 2620.163232
>current_received_ts = 2620.163129
>current_seq = 156599
>count = 80
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.146570/156598, current 2620.163232/156599: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.163232
>last_received_ts = 2620.163129
>last_seq = 156599
>current_ts = 2620.179907
>current_received_ts = 2620.179779
>current_seq = 156600
>count = 81
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.163232/156599, current 2620.179907/156600: elapsed=16675.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.179907
>last_received_ts = 2620.179779
>last_seq = 156600
>current_ts = 2620.196572
>current_received_ts = 2620.196371
>current_seq = 156601
>count = 82
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.179907/156600, current 2620.196572/156601: elapsed=16665.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.196572
>last_received_ts = 2620.196371
>last_seq = 156601
>current_ts = 2620.213239
>current_received_ts = 2620.213273
>current_seq = 156602
>count = 83
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.196572/156601, current 2620.213239/156602: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.213239
>last_received_ts = 2620.213273
>last_seq = 156602
>current_ts = 2620.229898
>current_received_ts = 2620.229413
>current_seq = 156603
>count = 84
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.213239/156602, current 2620.229898/156603: elapsed=16659.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.229898
>last_received_ts = 2620.229413
>last_seq = 156603
>current_ts = 2620.246567
>current_received_ts = 2620.246429
>current_seq = 156604
>count = 85
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.229898/156603, current 2620.246567/156604: elapsed=16669.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.246567
>last_received_ts = 2620.246429
>last_seq = 156604
>current_ts = 2620.263244
>current_received_ts = 2620.263289
>current_seq = 156605
>count = 86
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.246567/156604, current 2620.263244/156605: elapsed=16677.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.263244
>last_received_ts = 2620.263289
>last_seq = 156605
>current_ts = 2620.279906
>current_received_ts = 2620.279602
>current_seq = 156606
>count = 87
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.263244/156605, current 2620.279906/156606: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.279906
>last_received_ts = 2620.279602
>last_seq = 156606
>current_ts = 2620.296571
>current_received_ts = 2620.296490
>current_seq = 156607
>count = 88
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.279906/156606, current 2620.296571/156607: elapsed=16665.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.296571
>last_received_ts = 2620.296490
>last_seq = 156607
>current_ts = 2620.313234
>current_received_ts = 2620.312907
>current_seq = 156608
>count = 89
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.296571/156607, current 2620.313234/156608: elapsed=16663.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.313234
>last_received_ts = 2620.312907
>last_seq = 156608
>current_ts = 2620.329905
>current_received_ts = 2620.329746
>current_seq = 156609
>count = 90
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.313234/156608, current 2620.329905/156609: elapsed=16671.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.329905
>last_received_ts = 2620.329746
>last_seq = 156609
>current_ts = 2620.346572
>current_received_ts = 2620.346726
>current_seq = 156610
>count = 91
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.329905/156609, current 2620.346572/156610: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.346572
>last_received_ts = 2620.346726
>last_seq = 156610
>current_ts = 2620.363242
>current_received_ts = 2620.362835
>current_seq = 156611
>count = 92
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.346572/156610, current 2620.363242/156611: elapsed=16670.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.363242
>last_received_ts = 2620.362835
>last_seq = 156611
>current_ts = 2620.379909
>current_received_ts = 2620.379903
>current_seq = 156612
>count = 93
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.363242/156611, current 2620.379909/156612: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.379909
>last_received_ts = 2620.379903
>last_seq = 156612
>current_ts = 2620.396564
>current_received_ts = 2620.396652
>current_seq = 156613
>count = 94
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.379909/156612, current 2620.396564/156613: elapsed=16655.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.396564
>last_received_ts = 2620.396652
>last_seq = 156613
>current_ts = 2620.413234
>current_received_ts = 2620.413216
>current_seq = 156614
>count = 95
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.396564/156613, current 2620.413234/156614: elapsed=16670.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.413234
>last_received_ts = 2620.413216
>last_seq = 156614
>current_ts = 2620.429912
>current_received_ts = 2620.429922
>current_seq = 156615
>count = 96
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.413234/156614, current 2620.429912/156615: elapsed=16678.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.429912
>last_received_ts = 2620.429922
>last_seq = 156615
>current_ts = 2620.446566
>current_received_ts = 2620.446308
>current_seq = 156616
>count = 97
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.429912/156615, current 2620.446566/156616: elapsed=16654.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.446566
>last_received_ts = 2620.446308
>last_seq = 156616
>current_ts = 2620.463236
>current_received_ts = 2620.463228
>current_seq = 156617
>count = 98
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.446566/156616, current 2620.463236/156617: elapsed=16670.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.463236
>last_received_ts = 2620.463228
>last_seq = 156617
>current_ts = 2620.479905
>current_received_ts = 2620.480825
>current_seq = 156618
>count = 99
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.463236/156617, current 2620.479905/156618: elapsed=16669.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.479905
>last_received_ts = 2620.480825
>last_seq = 156618
>current_ts = 2620.496568
>current_received_ts = 2620.496638
>current_seq = 156619
>count = 100
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.479905/156618, current 2620.496568/156619: elapsed=16663.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.496568
>last_received_ts = 2620.496638
>last_seq = 156619
>current_ts = 2620.513233
>current_received_ts = 2620.513170
>current_seq = 156620
>count = 101
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.496568/156619, current 2620.513233/156620: elapsed=16665.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.513233
>last_received_ts = 2620.513170
>last_seq = 156620
>current_ts = 2620.529900
>current_received_ts = 2620.529772
>current_seq = 156621
>count = 102
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.513233/156620, current 2620.529900/156621: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.529900
>last_received_ts = 2620.529772
>last_seq = 156621
>current_ts = 2620.546576
>current_received_ts = 2620.546124
>current_seq = 156622
>count = 103
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.529900/156621, current 2620.546576/156622: elapsed=16676.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.546576
>last_received_ts = 2620.546124
>last_seq = 156622
>current_ts = 2620.563243
>current_received_ts = 2620.562987
>current_seq = 156623
>count = 104
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.546576/156622, current 2620.563243/156623: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.563243
>last_received_ts = 2620.562987
>last_seq = 156623
>current_ts = 2620.579909
>current_received_ts = 2620.580068
>current_seq = 156624
>count = 105
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.563243/156623, current 2620.579909/156624: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.579909
>last_received_ts = 2620.580068
>last_seq = 156624
>current_ts = 2620.596568
>current_received_ts = 2620.596483
>current_seq = 156625
>count = 106
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.579909/156624, current 2620.596568/156625: elapsed=16659.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.596568
>last_received_ts = 2620.596483
>last_seq = 156625
>current_ts = 2620.613244
>current_received_ts = 2620.613238
>current_seq = 156626
>count = 107
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.596568/156625, current 2620.613244/156626: elapsed=16676.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.613244
>last_received_ts = 2620.613238
>last_seq = 156626
>current_ts = 2620.629899
>current_received_ts = 2620.629579
>current_seq = 156627
>count = 108
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.613244/156626, current 2620.629899/156627: elapsed=16655.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.629899
>last_received_ts = 2620.629579
>last_seq = 156627
>current_ts = 2620.646576
>current_received_ts = 2620.646395
>current_seq = 156628
>count = 109
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.629899/156627, current 2620.646576/156628: elapsed=16677.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.646576
>last_received_ts = 2620.646395
>last_seq = 156628
>current_ts = 2620.663233
>current_received_ts = 2620.663282
>current_seq = 156629
>count = 110
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.646576/156628, current 2620.663233/156629: elapsed=16657.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.663233
>last_received_ts = 2620.663282
>last_seq = 156629
>current_ts = 2620.679911
>current_received_ts = 2620.679697
>current_seq = 156630
>count = 111
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.663233/156629, current 2620.679911/156630: elapsed=16678.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.679911
>last_received_ts = 2620.679697
>last_seq = 156630
>current_ts = 2620.696570
>current_received_ts = 2620.696599
>current_seq = 156631
>count = 112
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.679911/156630, current 2620.696570/156631: elapsed=16659.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.696570
>last_received_ts = 2620.696599
>last_seq = 156631
>current_ts = 2620.713234
>current_received_ts = 2620.713076
>current_seq = 156632
>count = 113
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.696570/156631, current 2620.713234/156632: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.713234
>last_received_ts = 2620.713076
>last_seq = 156632
>current_ts = 2620.729910
>current_received_ts = 2620.729920
>current_seq = 156633
>count = 114
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.713234/156632, current 2620.729910/156633: elapsed=16676.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.729910
>last_received_ts = 2620.729920
>last_seq = 156633
>current_ts = 2620.746573
>current_received_ts = 2620.746421
>current_seq = 156634
>count = 115
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.729910/156633, current 2620.746573/156634: elapsed=16663.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.746573
>last_received_ts = 2620.746421
>last_seq = 156634
>current_ts = 2620.763235
>current_received_ts = 2620.763124
>current_seq = 156635
>count = 116
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.746573/156634, current 2620.763235/156635: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.763235
>last_received_ts = 2620.763124
>last_seq = 156635
>current_ts = 2620.779909
>current_received_ts = 2620.779863
>current_seq = 156636
>count = 117
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.763235/156635, current 2620.779909/156636: elapsed=16674.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.779909
>last_received_ts = 2620.779863
>last_seq = 156636
>current_ts = 2620.796571
>current_received_ts = 2620.796582
>current_seq = 156637
>count = 118
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.779909/156636, current 2620.796571/156637: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.796571
>last_received_ts = 2620.796582
>last_seq = 156637
>current_ts = 2620.813236
>current_received_ts = 2620.813072
>current_seq = 156638
>count = 119
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.796571/156637, current 2620.813236/156638: elapsed=16665.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.813236
>last_received_ts = 2620.813072
>last_seq = 156638
>current_ts = 2620.829901
>current_received_ts = 2620.829718
>current_seq = 156639
>count = 120
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.813236/156638, current 2620.829901/156639: elapsed=16665.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.829901
>last_received_ts = 2620.829718
>last_seq = 156639
>current_ts = 2620.846578
>current_received_ts = 2620.846403
>current_seq = 156640
>count = 121
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.829901/156639, current 2620.846578/156640: elapsed=16677.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.846578
>last_received_ts = 2620.846403
>last_seq = 156640
>current_ts = 2620.863246
>current_received_ts = 2620.863271
>current_seq = 156641
>count = 122
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.846578/156640, current 2620.863246/156641: elapsed=16668.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.863246
>last_received_ts = 2620.863271
>last_seq = 156641
>current_ts = 2620.879911
>current_received_ts = 2620.879813
>current_seq = 156642
>count = 123
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.863246/156641, current 2620.879911/156642: elapsed=16665.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.879911
>last_received_ts = 2620.879813
>last_seq = 156642
>current_ts = 2620.896569
>current_received_ts = 2620.896409
>current_seq = 156643
>count = 124
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.879911/156642, current 2620.896569/156643: elapsed=16658.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.896569
>last_received_ts = 2620.896409
>last_seq = 156643
>current_ts = 2620.913236
>current_received_ts = 2620.913140
>current_seq = 156644
>count = 125
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.896569/156643, current 2620.913236/156644: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.913236
>last_received_ts = 2620.913140
>last_seq = 156644
>current_ts = 2620.929909
>current_received_ts = 2620.929891
>current_seq = 156645
>count = 126
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.913236/156644, current 2620.929909/156645: elapsed=16673.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.929909
>last_received_ts = 2620.929891
>last_seq = 156645
>current_ts = 2620.946571
>current_received_ts = 2620.946561
>current_seq = 156646
>count = 127
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.929909/156645, current 2620.946571/156646: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.946571
>last_received_ts = 2620.946561
>last_seq = 156646
>current_ts = 2620.963236
>current_received_ts = 2620.963358
>current_seq = 156647
>count = 128
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.946571/156646, current 2620.963236/156647: elapsed=16665.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.963236
>last_received_ts = 2620.963358
>last_seq = 156647
>current_ts = 2620.979899
>current_received_ts = 2620.979505
>current_seq = 156648
>count = 129
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.963236/156647, current 2620.979899/156648: elapsed=16663.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.979899
>last_received_ts = 2620.979505
>last_seq = 156648
>current_ts = 2620.996579
>current_received_ts = 2620.996420
>current_seq = 156649
>count = 130
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.979899/156648, current 2620.996579/156649: elapsed=16680.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2620.996579
>last_received_ts = 2620.996420
>last_seq = 156649
>current_ts = 2621.013238
>current_received_ts = 2621.013393
>current_seq = 156650
>count = 131
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2620.996579/156649, current 2621.013238/156650: elapsed=16659.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.013238
>last_received_ts = 2621.013393
>last_seq = 156650
>current_ts = 2621.029906
>current_received_ts = 2621.029712
>current_seq = 156651
>count = 132
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.013238/156650, current 2621.029906/156651: elapsed=16668.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.029906
>last_received_ts = 2621.029712
>last_seq = 156651
>current_ts = 2621.046573
>current_received_ts = 2621.046652
>current_seq = 156652
>count = 133
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.029906/156651, current 2621.046573/156652: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.046573
>last_received_ts = 2621.046652
>last_seq = 156652
>current_ts = 2621.063243
>current_received_ts = 2621.063175
>current_seq = 156653
>count = 134
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.046573/156652, current 2621.063243/156653: elapsed=16670.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.063243
>last_received_ts = 2621.063175
>last_seq = 156653
>current_ts = 2621.079906
>current_received_ts = 2621.079463
>current_seq = 156654
>count = 135
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.063243/156653, current 2621.079906/156654: elapsed=16663.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.079906
>last_received_ts = 2621.079463
>last_seq = 156654
>current_ts = 2621.096567
>current_received_ts = 2621.096407
>current_seq = 156655
>count = 136
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.079906/156654, current 2621.096567/156655: elapsed=16661.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.096567
>last_received_ts = 2621.096407
>last_seq = 156655
>current_ts = 2621.113233
>current_received_ts = 2621.113169
>current_seq = 156656
>count = 137
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.096567/156655, current 2621.113233/156656: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.113233
>last_received_ts = 2621.113169
>last_seq = 156656
>current_ts = 2621.129906
>current_received_ts = 2621.129680
>current_seq = 156657
>count = 138
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.113233/156656, current 2621.129906/156657: elapsed=16673.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.129906
>last_received_ts = 2621.129680
>last_seq = 156657
>current_ts = 2621.146574
>current_received_ts = 2621.146584
>current_seq = 156658
>count = 139
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.129906/156657, current 2621.146574/156658: elapsed=16668.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.146574
>last_received_ts = 2621.146584
>last_seq = 156658
>current_ts = 2621.163235
>current_received_ts = 2621.162891
>current_seq = 156659
>count = 140
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.146574/156658, current 2621.163235/156659: elapsed=16661.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.163235
>last_received_ts = 2621.162891
>last_seq = 156659
>current_ts = 2621.179910
>current_received_ts = 2621.180087
>current_seq = 156660
>count = 141
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.163235/156659, current 2621.179910/156660: elapsed=16675.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.179910
>last_received_ts = 2621.180087
>last_seq = 156660
>current_ts = 2621.196580
>current_received_ts = 2621.196809
>current_seq = 156661
>count = 142
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.179910/156660, current 2621.196580/156661: elapsed=16670.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.196580
>last_received_ts = 2621.196809
>last_seq = 156661
>current_ts = 2621.213244
>current_received_ts = 2621.212832
>current_seq = 156662
>count = 143
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.196580/156661, current 2621.213244/156662: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.213244
>last_received_ts = 2621.212832
>last_seq = 156662
>current_ts = 2621.229901
>current_received_ts = 2621.229953
>current_seq = 156663
>count = 144
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.213244/156662, current 2621.229901/156663: elapsed=16657.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.229901
>last_received_ts = 2621.229953
>last_seq = 156663
>current_ts = 2621.246573
>current_received_ts = 2621.246562
>current_seq = 156664
>count = 145
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.229901/156663, current 2621.246573/156664: elapsed=16672.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.246573
>last_received_ts = 2621.246562
>last_seq = 156664
>current_ts = 2621.263244
>current_received_ts = 2621.262903
>current_seq = 156665
>count = 146
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.246573/156664, current 2621.263244/156665: elapsed=16671.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.263244
>last_received_ts = 2621.262903
>last_seq = 156665
>current_ts = 2621.279908
>current_received_ts = 2621.279510
>current_seq = 156666
>count = 147
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.263244/156665, current 2621.279908/156666: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.279908
>last_received_ts = 2621.279510
>last_seq = 156666
>current_ts = 2621.296579
>current_received_ts = 2621.296259
>current_seq = 156667
>count = 148
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.279908/156666, current 2621.296579/156667: elapsed=16671.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.296579
>last_received_ts = 2621.296259
>last_seq = 156667
>current_ts = 2621.313241
>current_received_ts = 2621.313477
>current_seq = 156668
>count = 149
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.296579/156667, current 2621.313241/156668: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.313241
>last_received_ts = 2621.313477
>last_seq = 156668
>current_ts = 2621.329913
>current_received_ts = 2621.329792
>current_seq = 156669
>count = 150
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.313241/156668, current 2621.329913/156669: elapsed=16672.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.329913
>last_received_ts = 2621.329792
>last_seq = 156669
>current_ts = 2621.346587
>current_received_ts = 2621.346491
>current_seq = 156670
>count = 151
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.329913/156669, current 2621.346587/156670: elapsed=16674.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.346587
>last_received_ts = 2621.346491
>last_seq = 156670
>current_ts = 2621.363241
>current_received_ts = 2621.363255
>current_seq = 156671
>count = 152
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.346587/156670, current 2621.363241/156671: elapsed=16654.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.363241
>last_received_ts = 2621.363255
>last_seq = 156671
>current_ts = 2621.379913
>current_received_ts = 2621.379594
>current_seq = 156672
>count = 153
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.363241/156671, current 2621.379913/156672: elapsed=16672.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.379913
>last_received_ts = 2621.379594
>last_seq = 156672
>current_ts = 2621.396581
>current_received_ts = 2621.396660
>current_seq = 156673
>count = 154
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.379913/156672, current 2621.396581/156673: elapsed=16668.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.396581
>last_received_ts = 2621.396660
>last_seq = 156673
>current_ts = 2621.413246
>current_received_ts = 2621.413159
>current_seq = 156674
>count = 155
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.396581/156673, current 2621.413246/156674: elapsed=16665.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.413246
>last_received_ts = 2621.413159
>last_seq = 156674
>current_ts = 2621.429912
>current_received_ts = 2621.429440
>current_seq = 156675
>count = 156
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.413246/156674, current 2621.429912/156675: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.429912
>last_received_ts = 2621.429440
>last_seq = 156675
>current_ts = 2621.446581
>current_received_ts = 2621.446402
>current_seq = 156676
>count = 157
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.429912/156675, current 2621.446581/156676: elapsed=16669.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.446581
>last_received_ts = 2621.446402
>last_seq = 156676
>current_ts = 2621.463236
>current_received_ts = 2621.462986
>current_seq = 156677
>count = 158
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.446581/156676, current 2621.463236/156677: elapsed=16655.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.463236
>last_received_ts = 2621.462986
>last_seq = 156677
>current_ts = 2621.479909
>current_received_ts = 2621.479711
>current_seq = 156678
>count = 159
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.463236/156677, current 2621.479909/156678: elapsed=16673.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.479909
>last_received_ts = 2621.479711
>last_seq = 156678
>current_ts = 2621.496571
>current_received_ts = 2621.496414
>current_seq = 156679
>count = 160
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.479909/156678, current 2621.496571/156679: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.496571
>last_received_ts = 2621.496414
>last_seq = 156679
>current_ts = 2621.513243
>current_received_ts = 2621.513459
>current_seq = 156680
>count = 161
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.496571/156679, current 2621.513243/156680: elapsed=16672.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.513243
>last_received_ts = 2621.513459
>last_seq = 156680
>current_ts = 2621.529907
>current_received_ts = 2621.529678
>current_seq = 156681
>count = 162
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.513243/156680, current 2621.529907/156681: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.529907
>last_received_ts = 2621.529678
>last_seq = 156681
>current_ts = 2621.546578
>current_received_ts = 2621.546363
>current_seq = 156682
>count = 163
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.529907/156681, current 2621.546578/156682: elapsed=16671.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.546578
>last_received_ts = 2621.546363
>last_seq = 156682
>current_ts = 2621.563237
>current_received_ts = 2621.563096
>current_seq = 156683
>count = 164
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.546578/156682, current 2621.563237/156683: elapsed=16659.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.563237
>last_received_ts = 2621.563096
>last_seq = 156683
>current_ts = 2621.579914
>current_received_ts = 2621.579908
>current_seq = 156684
>count = 165
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.563237/156683, current 2621.579914/156684: elapsed=16677.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.579914
>last_received_ts = 2621.579908
>last_seq = 156684
>current_ts = 2621.596568
>current_received_ts = 2621.596192
>current_seq = 156685
>count = 166
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.579914/156684, current 2621.596568/156685: elapsed=16654.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.596568
>last_received_ts = 2621.596192
>last_seq = 156685
>current_ts = 2621.613245
>current_received_ts = 2621.613319
>current_seq = 156686
>count = 167
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.596568/156685, current 2621.613245/156686: elapsed=16677.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.613245
>last_received_ts = 2621.613319
>last_seq = 156686
>current_ts = 2621.629902
>current_received_ts = 2621.629669
>current_seq = 156687
>count = 168
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.613245/156686, current 2621.629902/156687: elapsed=16657.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.629902
>last_received_ts = 2621.629669
>last_seq = 156687
>current_ts = 2621.646577
>current_received_ts = 2621.646214
>current_seq = 156688
>count = 169
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.629902/156687, current 2621.646577/156688: elapsed=16675.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.646577
>last_received_ts = 2621.646214
>last_seq = 156688
>current_ts = 2621.663236
>current_received_ts = 2621.663318
>current_seq = 156689
>count = 170
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.646577/156688, current 2621.663236/156689: elapsed=16659.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.663236
>last_received_ts = 2621.663318
>last_seq = 156689
>current_ts = 2621.679902
>current_received_ts = 2621.679725
>current_seq = 156690
>count = 171
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.663236/156689, current 2621.679902/156690: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.679902
>last_received_ts = 2621.679725
>last_seq = 156690
>current_ts = 2621.696580
>current_received_ts = 2621.696387
>current_seq = 156691
>count = 172
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.679902/156690, current 2621.696580/156691: elapsed=16678.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.696580
>last_received_ts = 2621.696387
>last_seq = 156691
>current_ts = 2621.713236
>current_received_ts = 2621.713370
>current_seq = 156692
>count = 173
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.696580/156691, current 2621.713236/156692: elapsed=16656.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.713236
>last_received_ts = 2621.713370
>last_seq = 156692
>current_ts = 2621.729912
>current_received_ts = 2621.729579
>current_seq = 156693
>count = 174
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.713236/156692, current 2621.729912/156693: elapsed=16676.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.729912
>last_received_ts = 2621.729579
>last_seq = 156693
>current_ts = 2621.746579
>current_received_ts = 2621.746561
>current_seq = 156694
>count = 175
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.729912/156693, current 2621.746579/156694: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.746579
>last_received_ts = 2621.746561
>last_seq = 156694
>current_ts = 2621.763237
>current_received_ts = 2621.762763
>current_seq = 156695
>count = 176
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.746579/156694, current 2621.763237/156695: elapsed=16658.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.763237
>last_received_ts = 2621.762763
>last_seq = 156695
>current_ts = 2621.779906
>current_received_ts = 2621.779421
>current_seq = 156696
>count = 177
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.763237/156695, current 2621.779906/156696: elapsed=16669.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.779906
>last_received_ts = 2621.779421
>last_seq = 156696
>current_ts = 2621.796580
>current_received_ts = 2621.796481
>current_seq = 156697
>count = 178
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.779906/156696, current 2621.796580/156697: elapsed=16674.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.796580
>last_received_ts = 2621.796481
>last_seq = 156697
>current_ts = 2621.813244
>current_received_ts = 2621.813129
>current_seq = 156698
>count = 179
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.796580/156697, current 2621.813244/156698: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.813244
>last_received_ts = 2621.813129
>last_seq = 156698
>current_ts = 2621.829914
>current_received_ts = 2621.829673
>current_seq = 156699
>count = 180
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.813244/156698, current 2621.829914/156699: elapsed=16670.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.829914
>last_received_ts = 2621.829673
>last_seq = 156699
>current_ts = 2621.846576
>current_received_ts = 2621.846164
>current_seq = 156700
>count = 181
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.829914/156699, current 2621.846576/156700: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.846576
>last_received_ts = 2621.846164
>last_seq = 156700
>current_ts = 2621.863235
>current_received_ts = 2621.863219
>current_seq = 156701
>count = 182
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.846576/156700, current 2621.863235/156701: elapsed=16659.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.863235
>last_received_ts = 2621.863219
>last_seq = 156701
>current_ts = 2621.879914
>current_received_ts = 2621.879734
>current_seq = 156702
>count = 183
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.863235/156701, current 2621.879914/156702: elapsed=16679.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.879914
>last_received_ts = 2621.879734
>last_seq = 156702
>current_ts = 2621.896581
>current_received_ts = 2621.896383
>current_seq = 156703
>count = 184
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.879914/156702, current 2621.896581/156703: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.896581
>last_received_ts = 2621.896383
>last_seq = 156703
>current_ts = 2621.913238
>current_received_ts = 2621.913172
>current_seq = 156704
>count = 185
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.896581/156703, current 2621.913238/156704: elapsed=16657.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.913238
>last_received_ts = 2621.913172
>last_seq = 156704
>current_ts = 2621.929911
>current_received_ts = 2621.929587
>current_seq = 156705
>count = 186
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.913238/156704, current 2621.929911/156705: elapsed=16673.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.929911
>last_received_ts = 2621.929587
>last_seq = 156705
>current_ts = 2621.946573
>current_received_ts = 2621.946442
>current_seq = 156706
>count = 187
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.929911/156705, current 2621.946573/156706: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.946573
>last_received_ts = 2621.946442
>last_seq = 156706
>current_ts = 2621.963248
>current_received_ts = 2621.963196
>current_seq = 156707
>count = 188
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.946573/156706, current 2621.963248/156707: elapsed=16675.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.963248
>last_received_ts = 2621.963196
>last_seq = 156707
>current_ts = 2621.979913
>current_received_ts = 2621.979608
>current_seq = 156708
>count = 189
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.963248/156707, current 2621.979913/156708: elapsed=16665.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.979913
>last_received_ts = 2621.979608
>last_seq = 156708
>current_ts = 2621.996573
>current_received_ts = 2621.996497
>current_seq = 156709
>count = 190
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.979913/156708, current 2621.996573/156709: elapsed=16660.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2621.996573
>last_received_ts = 2621.996497
>last_seq = 156709
>current_ts = 2622.013237
>current_received_ts = 2622.013223
>current_seq = 156710
>count = 191
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2621.996573/156709, current 2622.013237/156710: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.013237
>last_received_ts = 2622.013223
>last_seq = 156710
>current_ts = 2622.029903
>current_received_ts = 2622.029917
>current_seq = 156711
>count = 192
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.013237/156710, current 2622.029903/156711: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.029903
>last_received_ts = 2622.029917
>last_seq = 156711
>current_ts = 2622.046576
>current_received_ts = 2622.046514
>current_seq = 156712
>count = 193
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.029903/156711, current 2622.046576/156712: elapsed=16673.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.046576
>last_received_ts = 2622.046514
>last_seq = 156712
>current_ts = 2622.063240
>current_received_ts = 2622.063142
>current_seq = 156713
>count = 194
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.046576/156712, current 2622.063240/156713: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.063240
>last_received_ts = 2622.063142
>last_seq = 156713
>current_ts = 2622.079902
>current_received_ts = 2622.079808
>current_seq = 156714
>count = 195
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.063240/156713, current 2622.079902/156714: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.079902
>last_received_ts = 2622.079808
>last_seq = 156714
>current_ts = 2622.096580
>current_received_ts = 2622.096508
>current_seq = 156715
>count = 196
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.079902/156714, current 2622.096580/156715: elapsed=16678.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.096580
>last_received_ts = 2622.096508
>last_seq = 156715
>current_ts = 2622.113242
>current_received_ts = 2622.113170
>current_seq = 156716
>count = 197
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.096580/156715, current 2622.113242/156716: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.113242
>last_received_ts = 2622.113170
>last_seq = 156716
>current_ts = 2622.129915
>current_received_ts = 2622.129861
>current_seq = 156717
>count = 198
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.113242/156716, current 2622.129915/156717: elapsed=16673.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.129915
>last_received_ts = 2622.129861
>last_seq = 156717
>current_ts = 2622.146578
>current_received_ts = 2622.146404
>current_seq = 156718
>count = 199
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.129915/156717, current 2622.146578/156718: elapsed=16663.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.146578
>last_received_ts = 2622.146404
>last_seq = 156718
>current_ts = 2622.163240
>current_received_ts = 2622.163168
>current_seq = 156719
>count = 200
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.146578/156718, current 2622.163240/156719: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.163240
>last_received_ts = 2622.163168
>last_seq = 156719
>current_ts = 2622.179902
>current_received_ts = 2622.179932
>current_seq = 156720
>count = 201
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.163240/156719, current 2622.179902/156720: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.179902
>last_received_ts = 2622.179932
>last_seq = 156720
>current_ts = 2622.196576
>current_received_ts = 2622.196461
>current_seq = 156721
>count = 202
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.179902/156720, current 2622.196576/156721: elapsed=16674.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.196576
>last_received_ts = 2622.196461
>last_seq = 156721
>current_ts = 2622.213242
>current_received_ts = 2622.212880
>current_seq = 156722
>count = 203
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.196576/156721, current 2622.213242/156722: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.213242
>last_received_ts = 2622.212880
>last_seq = 156722
>current_ts = 2622.229913
>current_received_ts = 2622.229534
>current_seq = 156723
>count = 204
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.213242/156722, current 2622.229913/156723: elapsed=16671.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.229913
>last_received_ts = 2622.229534
>last_seq = 156723
>current_ts = 2622.246579
>current_received_ts = 2622.246642
>current_seq = 156724
>count = 205
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.229913/156723, current 2622.246579/156724: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.246579
>last_received_ts = 2622.246642
>last_seq = 156724
>current_ts = 2622.263238
>current_received_ts = 2622.263163
>current_seq = 156725
>count = 206
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.246579/156724, current 2622.263238/156725: elapsed=16659.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.263238
>last_received_ts = 2622.263163
>last_seq = 156725
>current_ts = 2622.279917
>current_received_ts = 2622.279812
>current_seq = 156726
>count = 207
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.263238/156725, current 2622.279917/156726: elapsed=16679.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.279917
>last_received_ts = 2622.279812
>last_seq = 156726
>current_ts = 2622.296574
>current_received_ts = 2622.296436
>current_seq = 156727
>count = 208
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.279917/156726, current 2622.296574/156727: elapsed=16657.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.296574
>last_received_ts = 2622.296436
>last_seq = 156727
>current_ts = 2622.313250
>current_received_ts = 2622.312789
>current_seq = 156728
>count = 209
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.296574/156727, current 2622.313250/156728: elapsed=16676.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.313250
>last_received_ts = 2622.312789
>last_seq = 156728
>current_ts = 2622.329904
>current_received_ts = 2622.329993
>current_seq = 156729
>count = 210
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.313250/156728, current 2622.329904/156729: elapsed=16654.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.329904
>last_received_ts = 2622.329993
>last_seq = 156729
>current_ts = 2622.346576
>current_received_ts = 2622.346101
>current_seq = 156730
>count = 211
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.329904/156729, current 2622.346576/156730: elapsed=16672.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.346576
>last_received_ts = 2622.346101
>last_seq = 156730
>current_ts = 2622.363241
>current_received_ts = 2622.363192
>current_seq = 156731
>count = 212
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.346576/156730, current 2622.363241/156731: elapsed=16665.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.363241
>last_received_ts = 2622.363192
>last_seq = 156731
>current_ts = 2622.379907
>current_received_ts = 2622.379637
>current_seq = 156732
>count = 213
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.363241/156731, current 2622.379907/156732: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.379907
>last_received_ts = 2622.379637
>last_seq = 156732
>current_ts = 2622.396571
>current_received_ts = 2622.396640
>current_seq = 156733
>count = 214
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.379907/156732, current 2622.396571/156733: elapsed=16664.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.396571
>last_received_ts = 2622.396640
>last_seq = 156733
>current_ts = 2622.413237
>current_received_ts = 2622.413101
>current_seq = 156734
>count = 215
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.396571/156733, current 2622.413237/156734: elapsed=16666.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.413237
>last_received_ts = 2622.413101
>last_seq = 156734
>current_ts = 2622.429905
>current_received_ts = 2622.429714
>current_seq = 156735
>count = 216
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.413237/156734, current 2622.429905/156735: elapsed=16668.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.429905
>last_received_ts = 2622.429714
>last_seq = 156735
>current_ts = 2622.446575
>current_received_ts = 2622.446738
>current_seq = 156736
>count = 217
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.429905/156735, current 2622.446575/156736: elapsed=16670.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.446575
>last_received_ts = 2622.446738
>last_seq = 156736
>current_ts = 2622.463250
>current_received_ts = 2622.463125
>current_seq = 156737
>count = 218
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.446575/156736, current 2622.463250/156737: elapsed=16675.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.463250
>last_received_ts = 2622.463125
>last_seq = 156737
>current_ts = 2622.479912
>current_received_ts = 2622.479882
>current_seq = 156738
>count = 219
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.463250/156737, current 2622.479912/156738: elapsed=16662.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.479912
>last_received_ts = 2622.479882
>last_seq = 156738
>current_ts = 2622.496583
>current_received_ts = 2622.496263
>current_seq = 156739
>count = 220
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.479912/156738, current 2622.496583/156739: elapsed=16671.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.496583
>last_received_ts = 2622.496263
>last_seq = 156739
>current_ts = 2622.513243
>current_received_ts = 2622.513356
>current_seq = 156740
>count = 221
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.496583/156739, current 2622.513243/156740: elapsed=16660.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.513243
>last_received_ts = 2622.513356
>last_seq = 156740
>current_ts = 2622.529903
>current_received_ts = 2622.529839
>current_seq = 156741
>count = 222
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.513243/156740, current 2622.529903/156741: elapsed=16660.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.529903
>last_received_ts = 2622.529839
>last_seq = 156741
>current_ts = 2622.546582
>current_received_ts = 2622.546399
>current_seq = 156742
>count = 223
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.529903/156741, current 2622.546582/156742: elapsed=16679.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.546582
>last_received_ts = 2622.546399
>last_seq = 156742
>current_ts = 2622.563251
>current_received_ts = 2622.563245
>current_seq = 156743
>count = 224
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.546582/156742, current 2622.563251/156743: elapsed=16669.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.563251
>last_received_ts = 2622.563245
>last_seq = 156743
>current_ts = 2622.579911
>current_received_ts = 2622.579434
>current_seq = 156744
>count = 225
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.563251/156743, current 2622.579911/156744: elapsed=16660.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.579911
>last_received_ts = 2622.579434
>last_seq = 156744
>current_ts = 2622.596585
>current_received_ts = 2622.596306
>current_seq = 156745
>count = 226
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.579911/156744, current 2622.596585/156745: elapsed=16674.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.596585
>last_received_ts = 2622.596306
>last_seq = 156745
>current_ts = 2622.613246
>current_received_ts = 2622.613226
>current_seq = 156746
>count = 227
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.596585/156745, current 2622.613246/156746: elapsed=16661.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.613246
>last_received_ts = 2622.613226
>last_seq = 156746
>current_ts = 2622.629907
>current_received_ts = 2622.629518
>current_seq = 156747
>count = 228
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.613246/156746, current 2622.629907/156747: elapsed=16661.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.629907
>last_received_ts = 2622.629518
>last_seq = 156747
>current_ts = 2622.646581
>current_received_ts = 2622.646653
>current_seq = 156748
>count = 229
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.629907/156747, current 2622.646581/156748: elapsed=16674.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.646581
>last_received_ts = 2622.646653
>last_seq = 156748
>current_ts = 2622.663244
>current_received_ts = 2622.663059
>current_seq = 156749
>count = 230
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.646581/156748, current 2622.663244/156749: elapsed=16663.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.663244
>last_received_ts = 2622.663059
>last_seq = 156749
>current_ts = 2622.679915
>current_received_ts = 2622.679596
>current_seq = 156750
>count = 231
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.663244/156749, current 2622.679915/156750: elapsed=16671.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.679915
>last_received_ts = 2622.679596
>last_seq = 156750
>current_ts = 2622.696570
>current_received_ts = 2622.696384
>current_seq = 156751
>count = 232
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.679915/156750, current 2622.696570/156751: elapsed=16655.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.696570
>last_received_ts = 2622.696384
>last_seq = 156751
>current_ts = 2622.713239
>current_received_ts = 2622.713353
>current_seq = 156752
>count = 233
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.696570/156751, current 2622.713239/156752: elapsed=16669.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.713239
>last_received_ts = 2622.713353
>last_seq = 156752
>current_ts = 2622.729906
>current_received_ts = 2622.729729
>current_seq = 156753
>count = 234
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.713239/156752, current 2622.729906/156753: elapsed=16667.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.729906
>last_received_ts = 2622.729729
>last_seq = 156753
>current_ts = 2622.746583
>current_received_ts = 2622.746523
>current_seq = 156754
>count = 235
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.729906/156753, current 2622.746583/156754: elapsed=16677.0us expected=16666.0us +- 83.3us, error 0.1%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.746583
>last_received_ts = 2622.746523
>last_seq = 156754
>current_ts = 2622.763242
>current_received_ts = 2622.763248
>current_seq = 156755
>count = 236
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.746583/156754, current 2622.763242/156755: elapsed=16659.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.763242
>last_received_ts = 2622.763248
>last_seq = 156755
>current_ts = 2622.779912
>current_received_ts = 2622.779577
>current_seq = 156756
>count = 237
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.763242/156755, current 2622.779912/156756: elapsed=16670.0us expected=16666.0us +- 83.3us, error 0.0%
>(kms_flip:1611) DEBUG: name = flip
>last_ts = 2622.779912
>last_received_ts = 2622.779577
>last_seq = 156756
>current_ts = 2622.913243
>current_received_ts = 2622.913147
>current_seq = 156764
>count = 238
>seq_step = 1
>(kms_flip:1611) DEBUG: flip ts/seq: last 2622.779912/156756, current 2622.913243/156764: elapsed=133331.0us expected=133328.0us +- 666.6us, error 0.0%
>Stack trace:
>  #0 [__igt_fail_assert+0x101]
>  #1 [check_state+0x2d3]
>  #2 [<unknown>+0x2d3]
>Subtest plain-flip-fb-recreate-interruptible: FAIL (4.843s)
>(kms_flip:1611) igt-core-DEBUG: Exiting with status code 99
>(kms_flip:1611) igt-kms-DEBUG: VT: original mode 0x0 restored
>(kms_flip:1611) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
>IGT-Version: 1.19-gf145475 (x86_64) (Linux: 4.13.0-rc2-drm-tip-ww30-commit-1eb8669+ x86_64)
>(kms_flip:1625) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
>(kms_flip:1625) drmtest-DEBUG: Test requirement passed: !(fd<0)
>(kms_flip:1625) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
>(kms_flip:1625) drmtest-DEBUG: Test requirement passed: drmSetMaster(fd) == 0
>(kms_flip:1625) drmtest-DEBUG: Test requirement passed: !(fd<0)
>(kms_flip:1625) igt-kms-DEBUG: VT: graphics mode set (mode was 0x0)
>Using monotonic timestamps
>(kms_flip:1625) igt-core-DEBUG: Starting subtest: flip-vs-expired-vblank-interruptible
>(kms_flip:1625) DEBUG: Test requirement passed: (flags & TEST_HANG) == 0 || !is_wedged(drm_fd)
>(kms_flip:1625) DEBUG: Test requirement passed: modes
>Beginning flip-vs-expired-vblank-interruptible on pipe A, connector DP-1
>(kms_flip:1625) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
>(kms_flip:1625) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
>(kms_flip:1625) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
>(kms_flip:1625) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
>  1920x1080 60 1920 2008 2052 2200 1080 1084 1089 1125 0x5 0x48 148500
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 0.000000
>last_received_ts = 0.000000
>last_seq = 0
>current_ts = 2623.718035
>current_received_ts = 2623.717785
>current_seq = 156810
>count = 0
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.718035
>last_received_ts = 2623.717785
>last_seq = 156810
>current_ts = 2623.734706
>current_received_ts = 2623.734572
>current_seq = 156811
>count = 1
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.734706
>last_received_ts = 2623.734572
>last_seq = 156811
>current_ts = 2623.751377
>current_received_ts = 2623.751540
>current_seq = 156812
>count = 2
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.751377
>last_received_ts = 2623.751540
>last_seq = 156812
>current_ts = 2623.768034
>current_received_ts = 2623.768146
>current_seq = 156813
>count = 3
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.768034
>last_received_ts = 2623.768146
>last_seq = 156813
>current_ts = 2623.784707
>current_received_ts = 2623.785336
>current_seq = 156814
>count = 4
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.784707
>last_received_ts = 2623.785336
>last_seq = 156814
>current_ts = 2623.801378
>current_received_ts = 2623.801716
>current_seq = 156815
>count = 5
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.801378
>last_received_ts = 2623.801716
>last_seq = 156815
>current_ts = 2623.818044
>current_received_ts = 2623.817832
>current_seq = 156816
>count = 6
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.818044
>last_received_ts = 2623.817832
>last_seq = 156816
>current_ts = 2623.834702
>current_received_ts = 2623.834774
>current_seq = 156817
>count = 7
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.834702
>last_received_ts = 2623.834774
>last_seq = 156817
>current_ts = 2623.851374
>current_received_ts = 2623.850950
>current_seq = 156818
>count = 8
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.851374
>last_received_ts = 2623.850950
>last_seq = 156818
>current_ts = 2623.868036
>current_received_ts = 2623.867528
>current_seq = 156819
>count = 9
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.868036
>last_received_ts = 2623.867528
>last_seq = 156819
>current_ts = 2623.884704
>current_received_ts = 2623.884545
>current_seq = 156820
>count = 10
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.884704
>last_received_ts = 2623.884545
>last_seq = 156820
>current_ts = 2623.901377
>current_received_ts = 2623.901555
>current_seq = 156821
>count = 11
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.901377
>last_received_ts = 2623.901555
>last_seq = 156821
>current_ts = 2623.918045
>current_received_ts = 2623.918239
>current_seq = 156822
>count = 12
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.918045
>last_received_ts = 2623.918239
>last_seq = 156822
>current_ts = 2623.934711
>current_received_ts = 2623.934373
>current_seq = 156823
>count = 13
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.934711
>last_received_ts = 2623.934373
>last_seq = 156823
>current_ts = 2623.951375
>current_received_ts = 2623.951314
>current_seq = 156824
>count = 14
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.951375
>last_received_ts = 2623.951314
>last_seq = 156824
>current_ts = 2623.968041
>current_received_ts = 2623.967686
>current_seq = 156825
>count = 15
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.968041
>last_received_ts = 2623.967686
>last_seq = 156825
>current_ts = 2623.984713
>current_received_ts = 2623.984519
>current_seq = 156826
>count = 16
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2623.984713
>last_received_ts = 2623.984519
>last_seq = 156826
>current_ts = 2624.001373
>current_received_ts = 2624.001246
>current_seq = 156827
>count = 17
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.001373
>last_received_ts = 2624.001246
>last_seq = 156827
>current_ts = 2624.018032
>current_received_ts = 2624.017703
>current_seq = 156828
>count = 18
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.018032
>last_received_ts = 2624.017703
>last_seq = 156828
>current_ts = 2624.034709
>current_received_ts = 2624.034736
>current_seq = 156829
>count = 19
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.034709
>last_received_ts = 2624.034736
>last_seq = 156829
>current_ts = 2624.051367
>current_received_ts = 2624.051192
>current_seq = 156830
>count = 20
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.051367
>last_received_ts = 2624.051192
>last_seq = 156830
>current_ts = 2624.068044
>current_received_ts = 2624.067937
>current_seq = 156831
>count = 21
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.068044
>last_received_ts = 2624.067937
>last_seq = 156831
>current_ts = 2624.084700
>current_received_ts = 2624.084484
>current_seq = 156832
>count = 22
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.084700
>last_received_ts = 2624.084484
>last_seq = 156832
>current_ts = 2624.101371
>current_received_ts = 2624.101286
>current_seq = 156833
>count = 23
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.101371
>last_received_ts = 2624.101286
>last_seq = 156833
>current_ts = 2624.118039
>current_received_ts = 2624.117843
>current_seq = 156834
>count = 24
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.118039
>last_received_ts = 2624.117843
>last_seq = 156834
>current_ts = 2624.134707
>current_received_ts = 2624.134555
>current_seq = 156835
>count = 25
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.134707
>last_received_ts = 2624.134555
>last_seq = 156835
>current_ts = 2624.151375
>current_received_ts = 2624.151465
>current_seq = 156836
>count = 26
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.151375
>last_received_ts = 2624.151465
>last_seq = 156836
>current_ts = 2624.168033
>current_received_ts = 2624.167881
>current_seq = 156837
>count = 27
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.168033
>last_received_ts = 2624.167881
>last_seq = 156837
>current_ts = 2624.184702
>current_received_ts = 2624.184644
>current_seq = 156838
>count = 28
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.184702
>last_received_ts = 2624.184644
>last_seq = 156838
>current_ts = 2624.201370
>current_received_ts = 2624.201205
>current_seq = 156839
>count = 29
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.201370
>last_received_ts = 2624.201205
>last_seq = 156839
>current_ts = 2624.218038
>current_received_ts = 2624.217905
>current_seq = 156840
>count = 30
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.218038
>last_received_ts = 2624.217905
>last_seq = 156840
>current_ts = 2624.234713
>current_received_ts = 2624.234847
>current_seq = 156841
>count = 31
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.234713
>last_received_ts = 2624.234847
>last_seq = 156841
>current_ts = 2624.251373
>current_received_ts = 2624.251253
>current_seq = 156842
>count = 32
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.251373
>last_received_ts = 2624.251253
>last_seq = 156842
>current_ts = 2624.268032
>current_received_ts = 2624.268372
>current_seq = 156843
>count = 33
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.268032
>last_received_ts = 2624.268372
>last_seq = 156843
>current_ts = 2624.284700
>current_received_ts = 2624.284531
>current_seq = 156844
>count = 34
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.284700
>last_received_ts = 2624.284531
>last_seq = 156844
>current_ts = 2624.301380
>current_received_ts = 2624.301626
>current_seq = 156845
>count = 35
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.301380
>last_received_ts = 2624.301626
>last_seq = 156845
>current_ts = 2624.318044
>current_received_ts = 2624.318193
>current_seq = 156846
>count = 36
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.318044
>last_received_ts = 2624.318193
>last_seq = 156846
>current_ts = 2624.334702
>current_received_ts = 2624.334925
>current_seq = 156847
>count = 37
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.334702
>last_received_ts = 2624.334925
>last_seq = 156847
>current_ts = 2624.351370
>current_received_ts = 2624.351362
>current_seq = 156848
>count = 38
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.351370
>last_received_ts = 2624.351362
>last_seq = 156848
>current_ts = 2624.368042
>current_received_ts = 2624.368204
>current_seq = 156849
>count = 39
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.368042
>last_received_ts = 2624.368204
>last_seq = 156849
>current_ts = 2624.384700
>current_received_ts = 2624.385652
>current_seq = 156850
>count = 40
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.384700
>last_received_ts = 2624.385652
>last_seq = 156850
>current_ts = 2624.401369
>current_received_ts = 2624.401449
>current_seq = 156851
>count = 41
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.401369
>last_received_ts = 2624.401449
>last_seq = 156851
>current_ts = 2624.418044
>current_received_ts = 2624.418508
>current_seq = 156852
>count = 42
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.418044
>last_received_ts = 2624.418508
>last_seq = 156852
>current_ts = 2624.434702
>current_received_ts = 2624.434721
>current_seq = 156853
>count = 43
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.434702
>last_received_ts = 2624.434721
>last_seq = 156853
>current_ts = 2624.451371
>current_received_ts = 2624.451412
>current_seq = 156854
>count = 44
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.451371
>last_received_ts = 2624.451412
>last_seq = 156854
>current_ts = 2624.468041
>current_received_ts = 2624.468342
>current_seq = 156855
>count = 45
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.468041
>last_received_ts = 2624.468342
>last_seq = 156855
>current_ts = 2624.484704
>current_received_ts = 2624.484480
>current_seq = 156856
>count = 46
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.484704
>last_received_ts = 2624.484480
>last_seq = 156856
>current_ts = 2624.501367
>current_received_ts = 2624.501756
>current_seq = 156857
>count = 47
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.501367
>last_received_ts = 2624.501756
>last_seq = 156857
>current_ts = 2624.518037
>current_received_ts = 2624.518126
>current_seq = 156858
>count = 48
>seq_step = 1
>(kms_flip:1625) DEBUG: name = flip
>last_ts = 2624.518037
>last_received_ts = 2624.518126
>last_seq = 156858
>current_ts = 2624.534714
>current_received_ts = 2624.534922
>current_seq = 156859
>count = 49
>seq_step = 1
>Stack trace:
>  #0 [__igt_fail_assert+0x101]
>  #1 [run_test_on_crtc_set.constprop.14+0x1c13]
>  #2 [run_test+0x26a]
>  #3 [main+0x4e1]
>  #4 [__libc_start_main+0xf1]
>  #5 [_start+0x29]
>  #6 [<unknown>+0x29]
>Subtest flip-vs-expired-vblank-interruptible: FAIL (1.104s)
>(kms_flip:1625) igt-core-DEBUG: Exiting with status code 99
>(kms_flip:1625) igt-kms-DEBUG: VT: original mode 0x0 restored
>(kms_flip:1625) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
>IGT-Version: 1.19-gf145475 (x86_64) (Linux: 4.13.0-rc2-drm-tip-ww30-commit-1eb8669+ x86_64)
>(kms_flip:1636) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
>(kms_flip:1636) drmtest-DEBUG: Test requirement passed: !(fd<0)
>(kms_flip:1636) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
>(kms_flip:1636) drmtest-DEBUG: Test requirement passed: drmSetMaster(fd) == 0
>(kms_flip:1636) drmtest-DEBUG: Test requirement passed: !(fd<0)
>(kms_flip:1636) igt-kms-DEBUG: VT: graphics mode set (mode was 0x0)
>Using monotonic timestamps
>(kms_flip:1636) igt-core-DEBUG: Starting subtest: plain-flip-fb-recreate
>(kms_flip:1636) DEBUG: Test requirement passed: (flags & TEST_HANG) == 0 || !is_wedged(drm_fd)
>(kms_flip:1636) DEBUG: Test requirement passed: modes
>Beginning plain-flip-fb-recreate on pipe A, connector DP-1
>(kms_flip:1636) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
>(kms_flip:1636) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
>(kms_flip:1636) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
>(kms_flip:1636) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
>  1920x1080 60 1920 2008 2052 2200 1080 1084 1089 1125 0x5 0x48 148500
>Expected frametime: 16667us; measured 16666.8us +- 4.973us accuracy 0.09%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 0.000000
>last_received_ts = 0.000000
>last_seq = 0
>current_ts = 2625.585452
>current_received_ts = 2625.585364
>current_seq = 156920
>count = 0
>seq_step = 1
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.585452
>last_received_ts = 2625.585364
>last_seq = 156920
>current_ts = 2625.602127
>current_received_ts = 2625.601956
>current_seq = 156921
>count = 1
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.585452/156920, current 2625.602127/156921: elapsed=16675.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.602127
>last_received_ts = 2625.601956
>last_seq = 156921
>current_ts = 2625.618784
>current_received_ts = 2625.618286
>current_seq = 156922
>count = 2
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.602127/156921, current 2625.618784/156922: elapsed=16657.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.618784
>last_received_ts = 2625.618286
>last_seq = 156922
>current_ts = 2625.635455
>current_received_ts = 2625.635253
>current_seq = 156923
>count = 3
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.618784/156922, current 2625.635455/156923: elapsed=16671.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.635455
>last_received_ts = 2625.635253
>last_seq = 156923
>current_ts = 2625.652121
>current_received_ts = 2625.652152
>current_seq = 156924
>count = 4
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.635455/156923, current 2625.652121/156924: elapsed=16666.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.652121
>last_received_ts = 2625.652152
>last_seq = 156924
>current_ts = 2625.668793
>current_received_ts = 2625.668874
>current_seq = 156925
>count = 5
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.652121/156924, current 2625.668793/156925: elapsed=16672.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.668793
>last_received_ts = 2625.668874
>last_seq = 156925
>current_ts = 2625.685461
>current_received_ts = 2625.685892
>current_seq = 156926
>count = 6
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.668793/156925, current 2625.685461/156926: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.685461
>last_received_ts = 2625.685892
>last_seq = 156926
>current_ts = 2625.702120
>current_received_ts = 2625.702295
>current_seq = 156927
>count = 7
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.685461/156926, current 2625.702120/156927: elapsed=16659.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.702120
>last_received_ts = 2625.702295
>last_seq = 156927
>current_ts = 2625.718782
>current_received_ts = 2625.719097
>current_seq = 156928
>count = 8
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.702120/156927, current 2625.718782/156928: elapsed=16662.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.718782
>last_received_ts = 2625.719097
>last_seq = 156928
>current_ts = 2625.735455
>current_received_ts = 2625.735800
>current_seq = 156929
>count = 9
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.718782/156928, current 2625.735455/156929: elapsed=16673.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.735455
>last_received_ts = 2625.735800
>last_seq = 156929
>current_ts = 2625.752128
>current_received_ts = 2625.752264
>current_seq = 156930
>count = 10
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.735455/156929, current 2625.752128/156930: elapsed=16673.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.752128
>last_received_ts = 2625.752264
>last_seq = 156930
>current_ts = 2625.768794
>current_received_ts = 2625.768914
>current_seq = 156931
>count = 11
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.752128/156930, current 2625.768794/156931: elapsed=16666.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.768794
>last_received_ts = 2625.768914
>last_seq = 156931
>current_ts = 2625.785450
>current_received_ts = 2625.785609
>current_seq = 156932
>count = 12
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.768794/156931, current 2625.785450/156932: elapsed=16656.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.785450
>last_received_ts = 2625.785609
>last_seq = 156932
>current_ts = 2625.802116
>current_received_ts = 2625.802567
>current_seq = 156933
>count = 13
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.785450/156932, current 2625.802116/156933: elapsed=16666.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.802116
>last_received_ts = 2625.802567
>last_seq = 156933
>current_ts = 2625.818790
>current_received_ts = 2625.818922
>current_seq = 156934
>count = 14
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.802116/156933, current 2625.818790/156934: elapsed=16674.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.818790
>last_received_ts = 2625.818922
>last_seq = 156934
>current_ts = 2625.835449
>current_received_ts = 2625.835510
>current_seq = 156935
>count = 15
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.818790/156934, current 2625.835449/156935: elapsed=16659.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.835449
>last_received_ts = 2625.835510
>last_seq = 156935
>current_ts = 2625.852122
>current_received_ts = 2625.852251
>current_seq = 156936
>count = 16
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.835449/156935, current 2625.852122/156936: elapsed=16673.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.852122
>last_received_ts = 2625.852251
>last_seq = 156936
>current_ts = 2625.868787
>current_received_ts = 2625.869099
>current_seq = 156937
>count = 17
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.852122/156936, current 2625.868787/156937: elapsed=16665.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.868787
>last_received_ts = 2625.869099
>last_seq = 156937
>current_ts = 2625.885455
>current_received_ts = 2625.885750
>current_seq = 156938
>count = 18
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.868787/156937, current 2625.885455/156938: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.885455
>last_received_ts = 2625.885750
>last_seq = 156938
>current_ts = 2625.902122
>current_received_ts = 2625.902313
>current_seq = 156939
>count = 19
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.885455/156938, current 2625.902122/156939: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.902122
>last_received_ts = 2625.902313
>last_seq = 156939
>current_ts = 2625.918783
>current_received_ts = 2625.918893
>current_seq = 156940
>count = 20
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.902122/156939, current 2625.918783/156940: elapsed=16661.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.918783
>last_received_ts = 2625.918893
>last_seq = 156940
>current_ts = 2625.935461
>current_received_ts = 2625.935343
>current_seq = 156941
>count = 21
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.918783/156940, current 2625.935461/156941: elapsed=16678.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.935461
>last_received_ts = 2625.935343
>last_seq = 156941
>current_ts = 2625.952116
>current_received_ts = 2625.951878
>current_seq = 156942
>count = 22
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.935461/156941, current 2625.952116/156942: elapsed=16655.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.952116
>last_received_ts = 2625.951878
>last_seq = 156942
>current_ts = 2625.968796
>current_received_ts = 2625.968699
>current_seq = 156943
>count = 23
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.952116/156942, current 2625.968796/156943: elapsed=16680.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.968796
>last_received_ts = 2625.968699
>last_seq = 156943
>current_ts = 2625.985460
>current_received_ts = 2625.985369
>current_seq = 156944
>count = 24
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.968796/156943, current 2625.985460/156944: elapsed=16664.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2625.985460
>last_received_ts = 2625.985369
>last_seq = 156944
>current_ts = 2626.002129
>current_received_ts = 2626.002151
>current_seq = 156945
>count = 25
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2625.985460/156944, current 2626.002129/156945: elapsed=16669.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.002129
>last_received_ts = 2626.002151
>last_seq = 156945
>current_ts = 2626.018789
>current_received_ts = 2626.018681
>current_seq = 156946
>count = 26
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.002129/156945, current 2626.018789/156946: elapsed=16660.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.018789
>last_received_ts = 2626.018681
>last_seq = 156946
>current_ts = 2626.035456
>current_received_ts = 2626.035444
>current_seq = 156947
>count = 27
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.018789/156946, current 2626.035456/156947: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.035456
>last_received_ts = 2626.035444
>last_seq = 156947
>current_ts = 2626.052129
>current_received_ts = 2626.051969
>current_seq = 156948
>count = 28
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.035456/156947, current 2626.052129/156948: elapsed=16673.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.052129
>last_received_ts = 2626.051969
>last_seq = 156948
>current_ts = 2626.068785
>current_received_ts = 2626.068749
>current_seq = 156949
>count = 29
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.052129/156948, current 2626.068785/156949: elapsed=16656.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.068785
>last_received_ts = 2626.068749
>last_seq = 156949
>current_ts = 2626.085458
>current_received_ts = 2626.085320
>current_seq = 156950
>count = 30
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.068785/156949, current 2626.085458/156950: elapsed=16673.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.085458
>last_received_ts = 2626.085320
>last_seq = 156950
>current_ts = 2626.102123
>current_received_ts = 2626.102070
>current_seq = 156951
>count = 31
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.085458/156950, current 2626.102123/156951: elapsed=16665.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.102123
>last_received_ts = 2626.102070
>last_seq = 156951
>current_ts = 2626.118790
>current_received_ts = 2626.118778
>current_seq = 156952
>count = 32
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.102123/156951, current 2626.118790/156952: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.118790
>last_received_ts = 2626.118778
>last_seq = 156952
>current_ts = 2626.135458
>current_received_ts = 2626.135209
>current_seq = 156953
>count = 33
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.118790/156952, current 2626.135458/156953: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.135458
>last_received_ts = 2626.135209
>last_seq = 156953
>current_ts = 2626.152126
>current_received_ts = 2626.152250
>current_seq = 156954
>count = 34
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.135458/156953, current 2626.152126/156954: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.152126
>last_received_ts = 2626.152250
>last_seq = 156954
>current_ts = 2626.168787
>current_received_ts = 2626.168631
>current_seq = 156955
>count = 35
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.152126/156954, current 2626.168787/156955: elapsed=16661.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.168787
>last_received_ts = 2626.168631
>last_seq = 156955
>current_ts = 2626.185463
>current_received_ts = 2626.185328
>current_seq = 156956
>count = 36
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.168787/156955, current 2626.185463/156956: elapsed=16676.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.185463
>last_received_ts = 2626.185328
>last_seq = 156956
>current_ts = 2626.202126
>current_received_ts = 2626.201969
>current_seq = 156957
>count = 37
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.185463/156956, current 2626.202126/156957: elapsed=16663.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.202126
>last_received_ts = 2626.201969
>last_seq = 156957
>current_ts = 2626.218792
>current_received_ts = 2626.218652
>current_seq = 156958
>count = 38
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.202126/156957, current 2626.218792/156958: elapsed=16666.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.218792
>last_received_ts = 2626.218652
>last_seq = 156958
>current_ts = 2626.235453
>current_received_ts = 2626.235513
>current_seq = 156959
>count = 39
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.218792/156958, current 2626.235453/156959: elapsed=16661.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.235453
>last_received_ts = 2626.235513
>last_seq = 156959
>current_ts = 2626.252123
>current_received_ts = 2626.251975
>current_seq = 156960
>count = 40
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.235453/156959, current 2626.252123/156960: elapsed=16670.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.252123
>last_received_ts = 2626.251975
>last_seq = 156960
>current_ts = 2626.268783
>current_received_ts = 2626.268747
>current_seq = 156961
>count = 41
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.252123/156960, current 2626.268783/156961: elapsed=16660.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.268783
>last_received_ts = 2626.268747
>last_seq = 156961
>current_ts = 2626.285459
>current_received_ts = 2626.285230
>current_seq = 156962
>count = 42
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.268783/156961, current 2626.285459/156962: elapsed=16676.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.285459
>last_received_ts = 2626.285230
>last_seq = 156962
>current_ts = 2626.302117
>current_received_ts = 2626.302075
>current_seq = 156963
>count = 43
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.285459/156962, current 2626.302117/156963: elapsed=16658.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.302117
>last_received_ts = 2626.302075
>last_seq = 156963
>current_ts = 2626.318784
>current_received_ts = 2626.318617
>current_seq = 156964
>count = 44
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.302117/156963, current 2626.318784/156964: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.318784
>last_received_ts = 2626.318617
>last_seq = 156964
>current_ts = 2626.335453
>current_received_ts = 2626.335385
>current_seq = 156965
>count = 45
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.318784/156964, current 2626.335453/156965: elapsed=16669.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.335453
>last_received_ts = 2626.335385
>last_seq = 156965
>current_ts = 2626.352120
>current_received_ts = 2626.352130
>current_seq = 156966
>count = 46
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.335453/156965, current 2626.352120/156966: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.352120
>last_received_ts = 2626.352130
>last_seq = 156966
>current_ts = 2626.368791
>current_received_ts = 2626.368506
>current_seq = 156967
>count = 47
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.352120/156966, current 2626.368791/156967: elapsed=16671.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.368791
>last_received_ts = 2626.368506
>last_seq = 156967
>current_ts = 2626.385452
>current_received_ts = 2626.385385
>current_seq = 156968
>count = 48
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.368791/156967, current 2626.385452/156968: elapsed=16661.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.385452
>last_received_ts = 2626.385385
>last_seq = 156968
>current_ts = 2626.402120
>current_received_ts = 2626.402163
>current_seq = 156969
>count = 49
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.385452/156968, current 2626.402120/156969: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.402120
>last_received_ts = 2626.402163
>last_seq = 156969
>current_ts = 2626.418792
>current_received_ts = 2626.418742
>current_seq = 156970
>count = 50
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.402120/156969, current 2626.418792/156970: elapsed=16672.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.418792
>last_received_ts = 2626.418742
>last_seq = 156970
>current_ts = 2626.435452
>current_received_ts = 2626.435284
>current_seq = 156971
>count = 51
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.418792/156970, current 2626.435452/156971: elapsed=16660.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.435452
>last_received_ts = 2626.435284
>last_seq = 156971
>current_ts = 2626.452122
>current_received_ts = 2626.452124
>current_seq = 156972
>count = 52
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.435452/156971, current 2626.452122/156972: elapsed=16670.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.452122
>last_received_ts = 2626.452124
>last_seq = 156972
>current_ts = 2626.468789
>current_received_ts = 2626.468841
>current_seq = 156973
>count = 53
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.452122/156972, current 2626.468789/156973: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.468789
>last_received_ts = 2626.468841
>last_seq = 156973
>current_ts = 2626.485458
>current_received_ts = 2626.485349
>current_seq = 156974
>count = 54
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.468789/156973, current 2626.485458/156974: elapsed=16669.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.485458
>last_received_ts = 2626.485349
>last_seq = 156974
>current_ts = 2626.502124
>current_received_ts = 2626.502235
>current_seq = 156975
>count = 55
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.485458/156974, current 2626.502124/156975: elapsed=16666.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.502124
>last_received_ts = 2626.502235
>last_seq = 156975
>current_ts = 2626.518796
>current_received_ts = 2626.518661
>current_seq = 156976
>count = 56
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.502124/156975, current 2626.518796/156976: elapsed=16672.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.518796
>last_received_ts = 2626.518661
>last_seq = 156976
>current_ts = 2626.535464
>current_received_ts = 2626.535389
>current_seq = 156977
>count = 57
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.518796/156976, current 2626.535464/156977: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.535464
>last_received_ts = 2626.535389
>last_seq = 156977
>current_ts = 2626.552127
>current_received_ts = 2626.552114
>current_seq = 156978
>count = 58
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.535464/156977, current 2626.552127/156978: elapsed=16663.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.552127
>last_received_ts = 2626.552114
>last_seq = 156978
>current_ts = 2626.568797
>current_received_ts = 2626.568678
>current_seq = 156979
>count = 59
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.552127/156978, current 2626.568797/156979: elapsed=16670.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.568797
>last_received_ts = 2626.568678
>last_seq = 156979
>current_ts = 2626.585464
>current_received_ts = 2626.585576
>current_seq = 156980
>count = 60
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.568797/156979, current 2626.585464/156980: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.585464
>last_received_ts = 2626.585576
>last_seq = 156980
>current_ts = 2626.602129
>current_received_ts = 2626.601986
>current_seq = 156981
>count = 61
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.585464/156980, current 2626.602129/156981: elapsed=16665.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.602129
>last_received_ts = 2626.601986
>last_seq = 156981
>current_ts = 2626.618795
>current_received_ts = 2626.618743
>current_seq = 156982
>count = 62
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.602129/156981, current 2626.618795/156982: elapsed=16666.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.618795
>last_received_ts = 2626.618743
>last_seq = 156982
>current_ts = 2626.635456
>current_received_ts = 2626.635318
>current_seq = 156983
>count = 63
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.618795/156982, current 2626.635456/156983: elapsed=16661.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.635456
>last_received_ts = 2626.635318
>last_seq = 156983
>current_ts = 2626.652120
>current_received_ts = 2626.651997
>current_seq = 156984
>count = 64
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.635456/156983, current 2626.652120/156984: elapsed=16664.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.652120
>last_received_ts = 2626.651997
>last_seq = 156984
>current_ts = 2626.668793
>current_received_ts = 2626.668645
>current_seq = 156985
>count = 65
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.652120/156984, current 2626.668793/156985: elapsed=16673.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.668793
>last_received_ts = 2626.668645
>last_seq = 156985
>current_ts = 2626.685453
>current_received_ts = 2626.685315
>current_seq = 156986
>count = 66
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.668793/156985, current 2626.685453/156986: elapsed=16660.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.685453
>last_received_ts = 2626.685315
>last_seq = 156986
>current_ts = 2626.702123
>current_received_ts = 2626.702192
>current_seq = 156987
>count = 67
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.685453/156986, current 2626.702123/156987: elapsed=16670.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.702123
>last_received_ts = 2626.702192
>last_seq = 156987
>current_ts = 2626.718796
>current_received_ts = 2626.718661
>current_seq = 156988
>count = 68
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.702123/156987, current 2626.718796/156988: elapsed=16673.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.718796
>last_received_ts = 2626.718661
>last_seq = 156988
>current_ts = 2626.735460
>current_received_ts = 2626.735417
>current_seq = 156989
>count = 69
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.718796/156988, current 2626.735460/156989: elapsed=16664.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.735460
>last_received_ts = 2626.735417
>last_seq = 156989
>current_ts = 2626.752126
>current_received_ts = 2626.751923
>current_seq = 156990
>count = 70
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.735460/156989, current 2626.752126/156990: elapsed=16666.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.752126
>last_received_ts = 2626.751923
>last_seq = 156990
>current_ts = 2626.768794
>current_received_ts = 2626.768683
>current_seq = 156991
>count = 71
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.752126/156990, current 2626.768794/156991: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.768794
>last_received_ts = 2626.768683
>last_seq = 156991
>current_ts = 2626.785455
>current_received_ts = 2626.785333
>current_seq = 156992
>count = 72
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.768794/156991, current 2626.785455/156992: elapsed=16661.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.785455
>last_received_ts = 2626.785333
>last_seq = 156992
>current_ts = 2626.802122
>current_received_ts = 2626.802116
>current_seq = 156993
>count = 73
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.785455/156992, current 2626.802122/156993: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.802122
>last_received_ts = 2626.802116
>last_seq = 156993
>current_ts = 2626.818793
>current_received_ts = 2626.818839
>current_seq = 156994
>count = 74
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.802122/156993, current 2626.818793/156994: elapsed=16671.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.818793
>last_received_ts = 2626.818839
>last_seq = 156994
>current_ts = 2626.835459
>current_received_ts = 2626.835277
>current_seq = 156995
>count = 75
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.818793/156994, current 2626.835459/156995: elapsed=16666.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.835459
>last_received_ts = 2626.835277
>last_seq = 156995
>current_ts = 2626.852127
>current_received_ts = 2626.852156
>current_seq = 156996
>count = 76
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.835459/156995, current 2626.852127/156996: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.852127
>last_received_ts = 2626.852156
>last_seq = 156996
>current_ts = 2626.868784
>current_received_ts = 2626.868618
>current_seq = 156997
>count = 77
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.852127/156996, current 2626.868784/156997: elapsed=16657.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.868784
>last_received_ts = 2626.868618
>last_seq = 156997
>current_ts = 2626.885452
>current_received_ts = 2626.885312
>current_seq = 156998
>count = 78
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.868784/156997, current 2626.885452/156998: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.885452
>last_received_ts = 2626.885312
>last_seq = 156998
>current_ts = 2626.902126
>current_received_ts = 2626.901982
>current_seq = 156999
>count = 79
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.885452/156998, current 2626.902126/156999: elapsed=16674.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.902126
>last_received_ts = 2626.901982
>last_seq = 156999
>current_ts = 2626.918793
>current_received_ts = 2626.918627
>current_seq = 157000
>count = 80
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.902126/156999, current 2626.918793/157000: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.918793
>last_received_ts = 2626.918627
>last_seq = 157000
>current_ts = 2626.935460
>current_received_ts = 2626.935548
>current_seq = 157001
>count = 81
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.918793/157000, current 2626.935460/157001: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.935460
>last_received_ts = 2626.935548
>last_seq = 157001
>current_ts = 2626.952130
>current_received_ts = 2626.952141
>current_seq = 157002
>count = 82
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.935460/157001, current 2626.952130/157002: elapsed=16670.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.952130
>last_received_ts = 2626.952141
>last_seq = 157002
>current_ts = 2626.968792
>current_received_ts = 2626.968848
>current_seq = 157003
>count = 83
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.952130/157002, current 2626.968792/157003: elapsed=16662.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.968792
>last_received_ts = 2626.968848
>last_seq = 157003
>current_ts = 2626.985457
>current_received_ts = 2626.985405
>current_seq = 157004
>count = 84
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.968792/157003, current 2626.985457/157004: elapsed=16665.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2626.985457
>last_received_ts = 2626.985405
>last_seq = 157004
>current_ts = 2627.002120
>current_received_ts = 2627.002413
>current_seq = 157005
>count = 85
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2626.985457/157004, current 2627.002120/157005: elapsed=16663.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.002120
>last_received_ts = 2627.002413
>last_seq = 157005
>current_ts = 2627.018793
>current_received_ts = 2627.018730
>current_seq = 157006
>count = 86
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.002120/157005, current 2627.018793/157006: elapsed=16673.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.018793
>last_received_ts = 2627.018730
>last_seq = 157006
>current_ts = 2627.035457
>current_received_ts = 2627.035416
>current_seq = 157007
>count = 87
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.018793/157006, current 2627.035457/157007: elapsed=16664.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.035457
>last_received_ts = 2627.035416
>last_seq = 157007
>current_ts = 2627.052124
>current_received_ts = 2627.052228
>current_seq = 157008
>count = 88
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.035457/157007, current 2627.052124/157008: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.052124
>last_received_ts = 2627.052228
>last_seq = 157008
>current_ts = 2627.068797
>current_received_ts = 2627.068694
>current_seq = 157009
>count = 89
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.052124/157008, current 2627.068797/157009: elapsed=16673.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.068797
>last_received_ts = 2627.068694
>last_seq = 157009
>current_ts = 2627.085464
>current_received_ts = 2627.085615
>current_seq = 157010
>count = 90
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.068797/157009, current 2627.085464/157010: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.085464
>last_received_ts = 2627.085615
>last_seq = 157010
>current_ts = 2627.102131
>current_received_ts = 2627.102165
>current_seq = 157011
>count = 91
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.085464/157010, current 2627.102131/157011: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.102131
>last_received_ts = 2627.102165
>last_seq = 157011
>current_ts = 2627.118798
>current_received_ts = 2627.118725
>current_seq = 157012
>count = 92
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.102131/157011, current 2627.118798/157012: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.118798
>last_received_ts = 2627.118725
>last_seq = 157012
>current_ts = 2627.135456
>current_received_ts = 2627.135331
>current_seq = 157013
>count = 93
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.118798/157012, current 2627.135456/157013: elapsed=16658.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.135456
>last_received_ts = 2627.135331
>last_seq = 157013
>current_ts = 2627.152122
>current_received_ts = 2627.152141
>current_seq = 157014
>count = 94
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.135456/157013, current 2627.152122/157014: elapsed=16666.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.152122
>last_received_ts = 2627.152141
>last_seq = 157014
>current_ts = 2627.168791
>current_received_ts = 2627.168907
>current_seq = 157015
>count = 95
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.152122/157014, current 2627.168791/157015: elapsed=16669.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.168791
>last_received_ts = 2627.168907
>last_seq = 157015
>current_ts = 2627.185463
>current_received_ts = 2627.185368
>current_seq = 157016
>count = 96
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.168791/157015, current 2627.185463/157016: elapsed=16672.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.185463
>last_received_ts = 2627.185368
>last_seq = 157016
>current_ts = 2627.202124
>current_received_ts = 2627.202403
>current_seq = 157017
>count = 97
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.185463/157016, current 2627.202124/157017: elapsed=16661.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.202124
>last_received_ts = 2627.202403
>last_seq = 157017
>current_ts = 2627.218788
>current_received_ts = 2627.218656
>current_seq = 157018
>count = 98
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.202124/157017, current 2627.218788/157018: elapsed=16664.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.218788
>last_received_ts = 2627.218656
>last_seq = 157018
>current_ts = 2627.235464
>current_received_ts = 2627.235404
>current_seq = 157019
>count = 99
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.218788/157018, current 2627.235464/157019: elapsed=16676.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.235464
>last_received_ts = 2627.235404
>last_seq = 157019
>current_ts = 2627.252130
>current_received_ts = 2627.251890
>current_seq = 157020
>count = 100
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.235464/157019, current 2627.252130/157020: elapsed=16666.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.252130
>last_received_ts = 2627.251890
>last_seq = 157020
>current_ts = 2627.268795
>current_received_ts = 2627.268419
>current_seq = 157021
>count = 101
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.252130/157020, current 2627.268795/157021: elapsed=16665.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.268795
>last_received_ts = 2627.268419
>last_seq = 157021
>current_ts = 2627.285463
>current_received_ts = 2627.285562
>current_seq = 157022
>count = 102
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.268795/157021, current 2627.285463/157022: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.285463
>last_received_ts = 2627.285562
>last_seq = 157022
>current_ts = 2627.302123
>current_received_ts = 2627.302125
>current_seq = 157023
>count = 103
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.285463/157022, current 2627.302123/157023: elapsed=16660.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.302123
>last_received_ts = 2627.302125
>last_seq = 157023
>current_ts = 2627.318801
>current_received_ts = 2627.318839
>current_seq = 157024
>count = 104
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.302123/157023, current 2627.318801/157024: elapsed=16678.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.318801
>last_received_ts = 2627.318839
>last_seq = 157024
>current_ts = 2627.335465
>current_received_ts = 2627.335371
>current_seq = 157025
>count = 105
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.318801/157024, current 2627.335465/157025: elapsed=16664.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.335465
>last_received_ts = 2627.335371
>last_seq = 157025
>current_ts = 2627.352133
>current_received_ts = 2627.352313
>current_seq = 157026
>count = 106
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.335465/157025, current 2627.352133/157026: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.352133
>last_received_ts = 2627.352313
>last_seq = 157026
>current_ts = 2627.368795
>current_received_ts = 2627.368438
>current_seq = 157027
>count = 107
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.352133/157026, current 2627.368795/157027: elapsed=16662.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.368795
>last_received_ts = 2627.368438
>last_seq = 157027
>current_ts = 2627.385463
>current_received_ts = 2627.385074
>current_seq = 157028
>count = 108
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.368795/157027, current 2627.385463/157028: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.385463
>last_received_ts = 2627.385074
>last_seq = 157028
>current_ts = 2627.402127
>current_received_ts = 2627.401944
>current_seq = 157029
>count = 109
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.385463/157028, current 2627.402127/157029: elapsed=16664.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.402127
>last_received_ts = 2627.401944
>last_seq = 157029
>current_ts = 2627.418785
>current_received_ts = 2627.418622
>current_seq = 157030
>count = 110
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.402127/157029, current 2627.418785/157030: elapsed=16658.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.418785
>last_received_ts = 2627.418622
>last_seq = 157030
>current_ts = 2627.435453
>current_received_ts = 2627.435438
>current_seq = 157031
>count = 111
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.418785/157030, current 2627.435453/157031: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.435453
>last_received_ts = 2627.435438
>last_seq = 157031
>current_ts = 2627.452122
>current_received_ts = 2627.452125
>current_seq = 157032
>count = 112
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.435453/157031, current 2627.452122/157032: elapsed=16669.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.452122
>last_received_ts = 2627.452125
>last_seq = 157032
>current_ts = 2627.468798
>current_received_ts = 2627.468688
>current_seq = 157033
>count = 113
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.452122/157032, current 2627.468798/157033: elapsed=16676.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.468798
>last_received_ts = 2627.468688
>last_seq = 157033
>current_ts = 2627.485461
>current_received_ts = 2627.485373
>current_seq = 157034
>count = 114
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.468798/157033, current 2627.485461/157034: elapsed=16663.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.485461
>last_received_ts = 2627.485373
>last_seq = 157034
>current_ts = 2627.502123
>current_received_ts = 2627.502117
>current_seq = 157035
>count = 115
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.485461/157034, current 2627.502123/157035: elapsed=16662.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.502123
>last_received_ts = 2627.502117
>last_seq = 157035
>current_ts = 2627.518791
>current_received_ts = 2627.518850
>current_seq = 157036
>count = 116
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.502123/157035, current 2627.518791/157036: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.518791
>last_received_ts = 2627.518850
>last_seq = 157036
>current_ts = 2627.535459
>current_received_ts = 2627.535266
>current_seq = 157037
>count = 117
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.518791/157036, current 2627.535459/157037: elapsed=16668.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.535459
>last_received_ts = 2627.535266
>last_seq = 157037
>current_ts = 2627.552124
>current_received_ts = 2627.551751
>current_seq = 157038
>count = 118
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.535459/157037, current 2627.552124/157038: elapsed=16665.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.552124
>last_received_ts = 2627.551751
>last_seq = 157038
>current_ts = 2627.568789
>current_received_ts = 2627.568646
>current_seq = 157039
>count = 119
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.552124/157038, current 2627.568789/157039: elapsed=16665.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.568789
>last_received_ts = 2627.568646
>last_seq = 157039
>current_ts = 2627.585459
>current_received_ts = 2627.585448
>current_seq = 157040
>count = 120
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.568789/157039, current 2627.585459/157040: elapsed=16670.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.585459
>last_received_ts = 2627.585448
>last_seq = 157040
>current_ts = 2627.602130
>current_received_ts = 2627.602170
>current_seq = 157041
>count = 121
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.585459/157040, current 2627.602130/157041: elapsed=16671.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.602130
>last_received_ts = 2627.602170
>last_seq = 157041
>current_ts = 2627.618792
>current_received_ts = 2627.618697
>current_seq = 157042
>count = 122
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.602130/157041, current 2627.618792/157042: elapsed=16662.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.618792
>last_received_ts = 2627.618697
>last_seq = 157042
>current_ts = 2627.635462
>current_received_ts = 2627.635529
>current_seq = 157043
>count = 123
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.618792/157042, current 2627.635462/157043: elapsed=16670.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.635462
>last_received_ts = 2627.635529
>last_seq = 157043
>current_ts = 2627.652123
>current_received_ts = 2627.651985
>current_seq = 157044
>count = 124
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.635462/157043, current 2627.652123/157044: elapsed=16661.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.652123
>last_received_ts = 2627.651985
>last_seq = 157044
>current_ts = 2627.668789
>current_received_ts = 2627.668791
>current_seq = 157045
>count = 125
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.652123/157044, current 2627.668789/157045: elapsed=16666.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.668789
>last_received_ts = 2627.668791
>last_seq = 157045
>current_ts = 2627.685466
>current_received_ts = 2627.685277
>current_seq = 157046
>count = 126
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.668789/157045, current 2627.685466/157046: elapsed=16677.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.685466
>last_received_ts = 2627.685277
>last_seq = 157046
>current_ts = 2627.702132
>current_received_ts = 2627.701984
>current_seq = 157047
>count = 127
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.685466/157046, current 2627.702132/157047: elapsed=16666.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.702132
>last_received_ts = 2627.701984
>last_seq = 157047
>current_ts = 2627.718799
>current_received_ts = 2627.718672
>current_seq = 157048
>count = 128
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.702132/157047, current 2627.718799/157048: elapsed=16667.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.718799
>last_received_ts = 2627.718672
>last_seq = 157048
>current_ts = 2627.735457
>current_received_ts = 2627.735305
>current_seq = 157049
>count = 129
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.718799/157048, current 2627.735457/157049: elapsed=16658.0us expected=16666.8us +- 83.3us, error 0.1%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.735457
>last_received_ts = 2627.735305
>last_seq = 157049
>current_ts = 2627.752122
>current_received_ts = 2627.752185
>current_seq = 157050
>count = 130
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.735457/157049, current 2627.752122/157050: elapsed=16665.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.752122
>last_received_ts = 2627.752185
>last_seq = 157050
>current_ts = 2627.768794
>current_received_ts = 2627.768667
>current_seq = 157051
>count = 131
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.752122/157050, current 2627.768794/157051: elapsed=16672.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.768794
>last_received_ts = 2627.768667
>last_seq = 157051
>current_ts = 2627.785455
>current_received_ts = 2627.785397
>current_seq = 157052
>count = 132
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.768794/157051, current 2627.785455/157052: elapsed=16661.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.785455
>last_received_ts = 2627.785397
>last_seq = 157052
>current_ts = 2627.802124
>current_received_ts = 2627.801975
>current_seq = 157053
>count = 133
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.785455/157052, current 2627.802124/157053: elapsed=16669.0us expected=16666.8us +- 83.3us, error 0.0%
>(kms_flip:1636) DEBUG: name = flip
>last_ts = 2627.802124
>last_received_ts = 2627.801975
>last_seq = 157053
>current_ts = 2627.902132
>current_received_ts = 2627.901770
>current_seq = 157059
>count = 134
>seq_step = 1
>(kms_flip:1636) DEBUG: flip ts/seq: last 2627.802124/157053, current 2627.902132/157059: elapsed=100008.0us expected=100000.5us +- 500.0us, error 0.0%
>Stack trace:
>  #0 [__igt_fail_assert+0x101]
>  #1 [check_state+0x2d3]
>  #2 [<unknown>+0x2d3]
>Subtest plain-flip-fb-recreate: FAIL (2.919s)
>(kms_flip:1636) igt-core-DEBUG: Exiting with status code 99
>(kms_flip:1636) igt-kms-DEBUG: VT: original mode 0x0 restored
>(kms_flip:1636) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
>IGT-Version: 1.19-gf145475 (x86_64) (Linux: 4.13.0-rc2-drm-tip-ww30-commit-1eb8669+ x86_64)
>(kms_flip:1647) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
>(kms_flip:1647) drmtest-DEBUG: Test requirement passed: !(fd<0)
>(kms_flip:1647) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'
>(kms_flip:1647) drmtest-DEBUG: Test requirement passed: drmSetMaster(fd) == 0
>(kms_flip:1647) drmtest-DEBUG: Test requirement passed: !(fd<0)
>(kms_flip:1647) igt-kms-DEBUG: VT: graphics mode set (mode was 0x0)
>Using monotonic timestamps
>rtcwake: assuming RTC uses UTC ...
>rtcwake: wakeup from "mem" using /dev/rtc0 at Mon Jul 31 14:35:18 2017
>rtcwake: assuming RTC uses UTC ...
>rtcwake: wakeup from "mem" using /dev/rtc0 at Mon Jul 31 15:30:47 2017
>(kms_flip:1647) igt-core-DEBUG: Starting subtest: 2x-vblank-vs-suspend-interruptible
>(kms_flip:1647) DEBUG: Test requirement passed: (flags & TEST_HANG) == 0 || !is_wedged(drm_fd)
>(kms_flip:1647) DEBUG: Test requirement passed: modes
>Beginning 2x-vblank-vs-suspend-interruptible on pipe A:C, connector DP-1:DP-3
>(kms_flip:1647) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
>(kms_flip:1647) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
>(kms_flip:1647) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=0x34325258, tiling=0x0, size=0)
>(kms_flip:1647) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
>  1920x1080 60 1920 2008 2052 2200 1080 1084 1089 1125 0x5 0x48 148500
>  1920x1080 60 1920 2008 2052 2200 1080 1084 1089 1125 0xa 0x40 148500
>(kms_flip:1647) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
>(kms_flip:1647) igt-aux-DEBUG: Test requirement passed: (power_dir = open("/sys/power", O_RDONLY)) >= 0
>(kms_flip:1647) igt-aux-DEBUG: Test requirement passed: get_supported_suspend_states(power_dir) & (1 << state)
>(kms_flip:1647) igt-aux-DEBUG: Test requirement passed: test == SUSPEND_TEST_NONE || faccessat(power_dir, "pm_test", R_OK | W_OK, 0) == 0
>(kms_flip:1647) igt-aux-DEBUG: Test requirement passed: system(cmd) == 0
>(kms_flip:1647) DEBUG: name = vblank
>last_ts = 0.000000
>last_received_ts = 0.000000
>last_seq = 0
>current_ts = 2629.131633
>current_received_ts = 2715.440932
>current_seq = 157116
>count = 0
>seq_step = 10
>(kms_flip:1647) igt-core-DEBUG: Test requirement passed: !igt_run_in_simulation()
>(kms_flip:1647) igt-aux-DEBUG: Test requirement passed: (power_dir = open("/sys/power", O_RDONLY)) >= 0
>(kms_flip:1647) igt-aux-DEBUG: Test requirement passed: get_supported_suspend_states(power_dir) & (1 << state)
>(kms_flip:1647) igt-aux-DEBUG: Test requirement passed: test == SUSPEND_TEST_NONE || faccessat(power_dir, "pm_test", R_OK | W_OK, 0) == 0
>(kms_flip:1647) igt-aux-DEBUG: Test requirement passed: system(cmd) == 0
>(kms_flip:1647) DEBUG: name = vblank
>last_ts = 2629.131633
>last_received_ts = 2715.440932
>last_seq = 157116
>current_ts = 2715.599886
>current_received_ts = 6028.129250
>current_seq = 162285
>count = 1
>seq_step = 10
>Stack trace:
>  #0 [__igt_fail_assert+0x101]
>  #1 [check_state+0x331]
>  #2 [<unknown>+0x331]
>Subtest 2x-vblank-vs-suspend-interruptible: FAIL (3399.669s)
>(kms_flip:1647) igt-core-DEBUG: Exiting with status code 99
>(kms_flip:1647) igt-kms-DEBUG: VT: original mode 0x0 restored
>(kms_flip:1647) igt-debugfs-DEBUG: Opening debugfs directory '/sys/kernel/debug/dri/0'

Actions: View

Attachments on bug 96226: 124110 | 126664 | 128985 | 128986 | 133147 | 136341 | 136342 | 137645

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.