https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_246/fi-icl-y/igt@kms_flip@wf_vblank-ts-check.html Starting subtest: wf_vblank-ts-check (kms_flip:2171) CRITICAL: Test assertion failure function check_state, file ../tests/kms_flip.c:519: (kms_flip:2171) CRITICAL: Failed assertion: fabs((elapsed - expected) / expected) <= 0.005 (kms_flip:2171) CRITICAL: Last errno: 25, Inappropriate ioctl for device (kms_flip:2171) CRITICAL: inconsistent vblank ts/seq: last 402.103943/19683, current 402.337280/19693: elapsed=233348.0us expected=166671.2us Subtest wf_vblank-ts-check failed. **** DEBUG **** (kms_flip:2171) DEBUG: Test requirement passed: (flags & TEST_HANG) == 0 || !is_wedged(drm_fd) (kms_flip:2171) DEBUG: Test requirement passed: resources (kms_flip:2171) DEBUG: Test requirement passed: modes (kms_flip:2171) INFO: Beginning wf_vblank-ts-check on pipe A, connector eDP-1 (kms_flip:2171) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0) (kms_flip:2171) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680) (kms_flip:2171) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:2171) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0) (kms_flip:2171) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680) (kms_flip:2171) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd) (kms_flip:2171) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS (kms_flip:2171) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS (kms_flip:2171) igt_kms-INFO: 1920x1080 60 1920 1966 1996 2080 1080 1082 1086 1112 0xa 0x48 138780 (kms_flip:2171) INFO: Expected frametime: 16666us; measured 16667.1us +- 5.340us accuracy 0.10% (kms_flip:2171) DEBUG: name = vblank last_ts = 0.000000 last_received_ts = 0.000000 last_seq = 0 current_ts = 401.270630 current_received_ts = 401.270264 current_seq = 19633 count = 0 seq_step = 10 (kms_flip:2171) DEBUG: name = vblank last_ts = 401.270630 last_received_ts = 401.270264 last_seq = 19633 current_ts = 401.437286 current_received_ts = 401.436981 current_seq = 19643 count = 1 seq_step = 10 (kms_flip:2171) DEBUG: vblank ts/seq: last 401.270630/19633, current 401.437286/19643: elapsed=166676.0us expected=166671.2us +- 833.4us, error 0.0% (kms_flip:2171) DEBUG: name = vblank last_ts = 401.437286 last_received_ts = 401.436981 last_seq = 19643 current_ts = 401.603973 current_received_ts = 401.603607 current_seq = 19653 count = 2 seq_step = 10 (kms_flip:2171) DEBUG: vblank ts/seq: last 401.437286/19643, current 401.603973/19653: elapsed=166661.0us expected=166671.2us +- 833.4us, error 0.0% (kms_flip:2171) DEBUG: name = vblank last_ts = 401.603973 last_received_ts = 401.603607 last_seq = 19653 current_ts = 401.770630 current_received_ts = 401.770233 current_seq = 19663 count = 3 seq_step = 10 (kms_flip:2171) DEBUG: vblank ts/seq: last 401.603973/19653, current 401.770630/19663: elapsed=166661.0us expected=166671.2us +- 833.4us, error 0.0% (kms_flip:2171) DEBUG: name = vblank last_ts = 401.770630 last_received_ts = 401.770233 last_seq = 19663 current_ts = 401.937286 current_received_ts = 401.936981 current_seq = 19673 count = 4 seq_step = 10 (kms_flip:2171) DEBUG: vblank ts/seq: last 401.770630/19663, current 401.937286/19673: elapsed=166667.0us expected=166671.2us +- 833.4us, error 0.0% (kms_flip:2171) DEBUG: name = vblank last_ts = 401.937286 last_received_ts = 401.936981 last_seq = 19673 current_ts = 402.103943 current_received_ts = 402.103638 current_seq = 19683 count = 5 seq_step = 10 (kms_flip:2171) DEBUG: vblank ts/seq: last 401.937286/19673, current 402.103943/19683: elapsed=166656.0us expected=166671.2us +- 833.4us, error 0.0% (kms_flip:2171) DEBUG: name = vblank last_ts = 402.103943 last_received_ts = 402.103638 last_seq = 19683 current_ts = 402.337280 current_received_ts = 402.336945 current_seq = 19693 count = 6 seq_step = 10 (kms_flip:2171) DEBUG: vblank ts/seq: last 402.103943/19683, current 402.337280/19693: elapsed=233348.0us expected=166671.2us +- 833.4us, error 40.0% (kms_flip:2171) CRITICAL: Test assertion failure function check_state, file ../tests/kms_flip.c:519: (kms_flip:2171) CRITICAL: Failed assertion: fabs((elapsed - expected) / expected) <= 0.005 (kms_flip:2171) CRITICAL: Last errno: 25, Inappropriate ioctl for device (kms_flip:2171) CRITICAL: inconsistent vblank ts/seq: last 402.103943/19683, current 402.337280/19693: elapsed=233348.0us expected=166671.2us (kms_flip:2171) igt_core-INFO: Stack trace: (kms_flip:2171) igt_core-INFO: #0 ../lib/igt_core.c:1474 __igt_fail_assert() (kms_flip:2171) igt_core-INFO: #1 ../tests/kms_flip.c:521 check_state() (kms_flip:2171) igt_core-INFO: #2 ../tests/kms_flip.c:568 check_all_state() (kms_flip:2171) igt_core-INFO: #3 ../tests/kms_flip.c:1051 event_loop() (kms_flip:2171) igt_core-INFO: #4 ../tests/kms_flip.c:1291 run_test_on_crtc_set() (kms_flip:2171) igt_core-INFO: #5 ../tests/kms_flip.c:1346 run_test() (kms_flip:2171) igt_core-INFO: #6 ../tests/kms_flip.c:1558 main() (kms_flip:2171) igt_core-INFO: #7 ../csu/libc-start.c:344 __libc_start_main() (kms_flip:2171) igt_core-INFO: #8 [_start+0x2a] **** END **** Subtest wf_vblank-ts-check: FAIL (2.917s)
The CI Bug Log issue associated to this bug has been updated. ### New filters associated * ICL: igt@kms_flip@wf_vblank-ts-check.* - Failed assertion: fabs((elapsed - expected) / expected) <= 0.005 - https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_243/fi-icl-y/igt@kms_flip@wf_vblank-ts-check-interruptible.html - https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_244/fi-icl-y/igt@kms_flip@wf_vblank-ts-check.html - https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_245/fi-icl-y/igt@kms_flip@wf_vblank-ts-check-interruptible.html - https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_245/fi-icl-y/igt@kms_flip@wf_vblank-ts-check.html - https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_246/fi-icl-y/igt@kms_flip@wf_vblank-ts-check.html
A CI Bug Log filter associated to this bug has been updated: {- ICL: igt@kms_flip@wf_vblank-ts-check.* - Failed assertion: fabs((elapsed - expected) / expected) <= 0.005 -} {+ ICL: igt@kms_flip@wf_vblank-ts-check.* -fail - Failed assertion: fabs((elapsed - expected) / expected) <= 0.005 +} No new failures caught with the new filter
A CI Bug Log filter associated to this bug has been updated: {- ICL: igt@kms_flip@wf_vblank-ts-check.* -fail - Failed assertion: fabs((elapsed - expected) / expected) <= 0.005 -} {+ ICL: igt@kms_flip@wf_vblank-ts-check.* -fail - Failed assertion: fabs((elapsed - expected) / expected) <= 0.005 +} No new failures caught with the new filter
This is occurring on every drmtip run since drmtip-243 and occurring only on fi-icl-y.
A CI Bug Log filter associated to this bug has been updated: {- ICL: igt@kms_flip@wf_vblank-ts-check.* -fail - Failed assertion: fabs((elapsed - expected) / expected) <= 0.005 -} {+ ICL: igt@kms_flip@*wf_vblank* -fail - Failed assertion: fabs((elapsed - expected) / expected) <= 0.005 +} New failures caught by the filter: * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_248/fi-icl-y/igt@kms_flip@blocking-wf_vblank.html * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_249/fi-icl-y/igt@kms_flip@blocking-wf_vblank.html * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_250/fi-icl-y/igt@kms_flip@blocking-wf_vblank.html
Could we close this one? Based on CI logs, the bug haven't been seen for over 3 months now.
(In reply to Mika Kahola from comment #6) > Could we close this one? Based on CI logs, the bug haven't been seen for > over 3 months now. Yes. Reproduction rate of this issue used to be 100% and last seen drmtip_311 (3 months, 3 weeks old) and current drmtip run is 385. Closing and archiving this issue.
The CI Bug Log issue associated to this bug has been archived. New failures matching the above filters will not be associated to this bug anymore.
Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.