IGT-Version: 1.16-g54f8a3f (x86_64) (Linux: 4.8.0-drm-intel-nightly-ww42-commit-15dfed2+ x86_64)
Using monotonic timestamps
Beginning plain-flip-fb-recreate-interruptible on pipe A, connector eDP-1
  3200x1800 60 3200 3248 3280 3316 1800 1802 1807 1816 0xa 0x48 361310
....................................................(kms_flip:25130) CRITICAL: Test assertion failure function check_state, file kms_flip.c:699:
(kms_flip:25130) CRITICAL: Failed assertion: fabs((usec_diff - usec_interflip) / usec_interflip) <= 0.005
(kms_flip:25130) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:25130) CRITICAL: inconsistent flip ts/seq: last 13339.683526/691007, current 13339.700277/691008
Stack trace:
  #0 [__igt_fail_assert+0x101]
  #1 [check_state+0x3ac]
  #2 [<unknown>+0x3ac]
Subtest plain-flip-fb-recreate-interruptible failed.
**** DEBUG ****
(kms_flip:25130) DEBUG: Test requirement passed: (flags & TEST_HANG) == 0 || !is_wedged(drm_fd)
(kms_flip:25130) DEBUG: Test requirement passed: modes
(kms_flip:25130) INFO: Beginning plain-flip-fb-recreate-interruptible on pipe A, connector eDP-1
(kms_flip:25130) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=3200, height=1800, format=0x34325258, tiling=0x0, size=0)
(kms_flip:25130) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=12800)
(kms_flip:25130) igt-fb-DEBUG: igt_create_fb_with_bo_size(width=3200, height=1800, format=0x34325258, tiling=0x0, size=0)
(kms_flip:25130) igt-fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=12800)
(kms_flip:25130) igt-kms-INFO:   3200x1800 60 3200 3248 3280 3316 1800 1802 1807 1816 0xa 0x48 361310
(kms_flip:25130) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 13338.846375
current_received_ts = 13338.846481
current_seq = 690957
count = 0
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13338.846375
last_received_ts = 13338.846481
last_seq = 690957
current_ts = 13338.863117
current_received_ts = 13338.863195
current_seq = 690958
count = 1
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13338.863117
last_received_ts = 13338.863195
last_seq = 690958
current_ts = 13338.879859
current_received_ts = 13338.879890
current_seq = 690959
count = 2
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13338.879859
last_received_ts = 13338.879890
last_seq = 690959
current_ts = 13338.896604
current_received_ts = 13338.896684
current_seq = 690960
count = 3
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13338.896604
last_received_ts = 13338.896684
last_seq = 690960
current_ts = 13338.913348
current_received_ts = 13338.913353
current_seq = 690961
count = 4
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13338.913348
last_received_ts = 13338.913353
last_seq = 690961
current_ts = 13338.930089
current_received_ts = 13338.930167
current_seq = 690962
count = 5
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13338.930089
last_received_ts = 13338.930167
last_seq = 690962
current_ts = 13338.946827
current_received_ts = 13338.946846
current_seq = 690963
count = 6
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13338.946827
last_received_ts = 13338.946846
last_seq = 690963
current_ts = 13338.963573
current_received_ts = 13338.963652
current_seq = 690964
count = 7
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13338.963573
last_received_ts = 13338.963652
last_seq = 690964
current_ts = 13338.980315
current_received_ts = 13338.980343
current_seq = 690965
count = 8
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13338.980315
last_received_ts = 13338.980343
last_seq = 690965
current_ts = 13338.997060
current_received_ts = 13338.997159
current_seq = 690966
count = 9
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13338.997060
last_received_ts = 13338.997159
last_seq = 690966
current_ts = 13339.013802
current_received_ts = 13339.013882
current_seq = 690967
count = 10
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.013802
last_received_ts = 13339.013882
last_seq = 690967
current_ts = 13339.030548
current_received_ts = 13339.030637
current_seq = 690968
count = 11
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.030548
last_received_ts = 13339.030637
last_seq = 690968
current_ts = 13339.047295
current_received_ts = 13339.047387
current_seq = 690969
count = 12
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.047295
last_received_ts = 13339.047387
last_seq = 690969
current_ts = 13339.064037
current_received_ts = 13339.064116
current_seq = 690970
count = 13
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.064037
last_received_ts = 13339.064116
last_seq = 690970
current_ts = 13339.080781
current_received_ts = 13339.080872
current_seq = 690971
count = 14
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.080781
last_received_ts = 13339.080872
last_seq = 690971
current_ts = 13339.097517
current_received_ts = 13339.097526
current_seq = 690972
count = 15
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.097517
last_received_ts = 13339.097526
last_seq = 690972
current_ts = 13339.114264
current_received_ts = 13339.114345
current_seq = 690973
count = 16
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.114264
last_received_ts = 13339.114345
last_seq = 690973
current_ts = 13339.131003
current_received_ts = 13339.131104
current_seq = 690974
count = 17
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.131003
last_received_ts = 13339.131104
last_seq = 690974
current_ts = 13339.147751
current_received_ts = 13339.147815
current_seq = 690975
count = 18
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.147751
last_received_ts = 13339.147815
last_seq = 690975
current_ts = 13339.164496
current_received_ts = 13339.164584
current_seq = 690976
count = 19
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.164496
last_received_ts = 13339.164584
last_seq = 690976
current_ts = 13339.181239
current_received_ts = 13339.181331
current_seq = 690977
count = 20
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.181239
last_received_ts = 13339.181331
last_seq = 690977
current_ts = 13339.197982
current_received_ts = 13339.198068
current_seq = 690978
count = 21
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.197982
last_received_ts = 13339.198068
last_seq = 690978
current_ts = 13339.214721
current_received_ts = 13339.214833
current_seq = 690979
count = 22
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.214721
last_received_ts = 13339.214833
last_seq = 690979
current_ts = 13339.231461
current_received_ts = 13339.231541
current_seq = 690980
count = 23
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.231461
last_received_ts = 13339.231541
last_seq = 690980
current_ts = 13339.248211
current_received_ts = 13339.248323
current_seq = 690981
count = 24
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.248211
last_received_ts = 13339.248323
last_seq = 690981
current_ts = 13339.264954
current_received_ts = 13339.265041
current_seq = 690982
count = 25
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.264954
last_received_ts = 13339.265041
last_seq = 690982
current_ts = 13339.281693
current_received_ts = 13339.281837
current_seq = 690983
count = 26
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.281693
last_received_ts = 13339.281837
last_seq = 690983
current_ts = 13339.298435
current_received_ts = 13339.298521
current_seq = 690984
count = 27
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.298435
last_received_ts = 13339.298521
last_seq = 690984
current_ts = 13339.315181
current_received_ts = 13339.315296
current_seq = 690985
count = 28
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.315181
last_received_ts = 13339.315296
last_seq = 690985
current_ts = 13339.331922
current_received_ts = 13339.332060
current_seq = 690986
count = 29
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.331922
last_received_ts = 13339.332060
last_seq = 690986
current_ts = 13339.348665
current_received_ts = 13339.348691
current_seq = 690987
count = 30
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.348665
last_received_ts = 13339.348691
last_seq = 690987
current_ts = 13339.365407
current_received_ts = 13339.365494
current_seq = 690988
count = 31
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.365407
last_received_ts = 13339.365494
last_seq = 690988
current_ts = 13339.382150
current_received_ts = 13339.382164
current_seq = 690989
count = 32
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.382150
last_received_ts = 13339.382164
last_seq = 690989
current_ts = 13339.398894
current_received_ts = 13339.398983
current_seq = 690990
count = 33
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.398894
last_received_ts = 13339.398983
last_seq = 690990
current_ts = 13339.415639
current_received_ts = 13339.415646
current_seq = 690991
count = 34
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.415639
last_received_ts = 13339.415646
last_seq = 690991
current_ts = 13339.432381
current_received_ts = 13339.432400
current_seq = 690992
count = 35
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.432381
last_received_ts = 13339.432400
last_seq = 690992
current_ts = 13339.449125
current_received_ts = 13339.449207
current_seq = 690993
count = 36
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.449125
last_received_ts = 13339.449207
last_seq = 690993
current_ts = 13339.465874
current_received_ts = 13339.465959
current_seq = 690994
count = 37
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.465874
last_received_ts = 13339.465959
last_seq = 690994
current_ts = 13339.482611
current_received_ts = 13339.482691
current_seq = 690995
count = 38
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.482611
last_received_ts = 13339.482691
last_seq = 690995
current_ts = 13339.499354
current_received_ts = 13339.499456
current_seq = 690996
count = 39
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.499354
last_received_ts = 13339.499456
last_seq = 690996
current_ts = 13339.516101
current_received_ts = 13339.516158
current_seq = 690997
count = 40
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.516101
last_received_ts = 13339.516158
last_seq = 690997
current_ts = 13339.532839
current_received_ts = 13339.532960
current_seq = 690998
count = 41
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.532839
last_received_ts = 13339.532960
last_seq = 690998
current_ts = 13339.549589
current_received_ts = 13339.549668
current_seq = 690999
count = 42
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.549589
last_received_ts = 13339.549668
last_seq = 690999
current_ts = 13339.566325
current_received_ts = 13339.566356
current_seq = 691000
count = 43
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.566325
last_received_ts = 13339.566356
last_seq = 691000
current_ts = 13339.583069
current_received_ts = 13339.583151
current_seq = 691001
count = 44
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.583069
last_received_ts = 13339.583151
last_seq = 691001
current_ts = 13339.599815
current_received_ts = 13339.599758
current_seq = 691002
count = 45
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.599815
last_received_ts = 13339.599758
last_seq = 691002
current_ts = 13339.616559
current_received_ts = 13339.616663
current_seq = 691003
count = 46
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.616559
last_received_ts = 13339.616663
last_seq = 691003
current_ts = 13339.633302
current_received_ts = 13339.633284
current_seq = 691004
count = 47
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.633302
last_received_ts = 13339.633284
last_seq = 691004
current_ts = 13339.650043
current_received_ts = 13339.650128
current_seq = 691005
count = 48
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.650043
last_received_ts = 13339.650128
last_seq = 691005
current_ts = 13339.666790
current_received_ts = 13339.666891
current_seq = 691006
count = 49
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.666790
last_received_ts = 13339.666891
last_seq = 691006
current_ts = 13339.683526
current_received_ts = 13339.683618
current_seq = 691007
count = 50
seq_step = 1
(kms_flip:25130) DEBUG: name = flip
last_ts = 13339.683526
last_received_ts = 13339.683618
last_seq = 691007
current_ts = 13339.700277
current_received_ts = 13339.700249
current_seq = 691008
count = 51
seq_step = 1
(kms_flip:25130) CRITICAL: Test assertion failure function check_state, file kms_flip.c:699:
(kms_flip:25130) CRITICAL: Failed assertion: fabs((usec_diff - usec_interflip) / usec_interflip) <= 0.005
(kms_flip:25130) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:25130) CRITICAL: inconsistent flip ts/seq: last 13339.683526/691007, current 13339.700277/691008
****  END  ****
Subtest plain-flip-fb-recreate-interruptible: FAIL (2.040s)