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'