Bug 221696 - sysutils/py-diffoscope: Tests run significantly slower on FreeBSD than on other platforms
Summary: sysutils/py-diffoscope: Tests run significantly slower on FreeBSD than on oth...
Status: Closed FIXED
Alias: None
Product: Ports & Packages
Classification: Unclassified
Component: Individual Port(s) (show other bugs)
Version: Latest
Hardware: Any Any
: --- Affects Some People
Assignee: Kubilay Kocak
URL:
Keywords: performance
Depends on: 221700
Blocks:
  Show dependency treegraph
 
Reported: 2017-08-21 16:15 UTC by Guangyuan Yang
Modified: 2019-11-29 11:01 UTC (History)
3 users (show)

See Also:
koobs: maintainer-feedback+


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Guangyuan Yang freebsd_committer freebsd_triage 2017-08-21 16:15:50 UTC
I ran the test suite on both:

Company computer:
i5-3450 8G SSD
FreeBSD 12-CURRENT

My laptop:
i7-5500U 16G SSD
Arch Linux 201706

It takes 260s for the suite to finish on FreeBSD, and just 18s on my Arch Linux.
Comment 1 Guangyuan Yang freebsd_committer freebsd_triage 2017-08-21 16:17:47 UTC
FreeBSD:

== slowest 20 test durations ==
48.89s call     tests/comparators/test_directory.py::test_no_differences_with_extra_slash
48.26s call     tests/comparators/test_directory.py::test_no_differences
18.34s call     tests/comparators/test_ipk.py::test_compare_non_existing
8.14s setup    tests/comparators/test_rlib.py::test_num_items
8.09s setup    tests/comparators/test_rlib.py::test_item1_elf
8.06s setup    tests/comparators/test_rlib.py::test_item0_armap
7.90s setup    tests/comparators/test_rlib.py::test_item2_rust_metadata_bin
6.84s call     tests/comparators/test_elf.py::test_lib_no_differences
6.59s call     tests/comparators/test_elf.py::test_obj_no_differences
6.58s setup    tests/comparators/test_elf.py::test_lib_differences
6.56s setup    tests/comparators/test_elf.py::test_diff
5.99s call     tests/comparators/test_rlib.py::test_compare_non_existing
4.71s call     tests/comparators/test_elf.py::test_obj_compare_non_existing
4.65s call     tests/comparators/test_elf.py::test_lib_compare_non_existing
3.09s setup    tests/comparators/test_ipk.py::test_metadata
3.08s setup    tests/comparators/test_ipk.py::test_compressed_files
2.20s call     tests/comparators/test_deb.py::test_compare_non_existing
2.02s setup    tests/comparators/test_directory.py::test_stat
1.99s setup    tests/comparators/test_directory.py::test_content
1.57s setup    tests/comparators/test_deb.py::test_md5sums
== 1 failed, 259 passed, 100 skipped in 267.14 seconds ==


Arch Linux:

== slowest 20 test durations ==
2.96s call     tests/comparators/test_directory.py::test_no_differences
2.83s call     tests/comparators/test_directory.py::test_no_differences_with_extra_slash
1.12s call     tests/comparators/test_ipk.py::test_compare_non_existing
0.54s setup    tests/test_quines.py::test_differences_deb
0.38s setup    tests/comparators/test_rlib.py::test_item2_rust_metadata_bin
0.37s setup    tests/comparators/test_rlib.py::test_item0_armap
0.37s setup    tests/comparators/test_rlib.py::test_num_items
0.36s setup    tests/comparators/test_rlib.py::test_item1_elf
0.34s setup    tests/comparators/test_ipk.py::test_compressed_files
0.33s setup    tests/comparators/test_ipk.py::test_metadata
0.29s call     tests/comparators/test_elf.py::test_obj_no_differences
0.27s setup    tests/comparators/test_elf.py::test_lib_differences
0.27s call     tests/comparators/test_elf.py::test_lib_no_differences
0.26s setup    tests/comparators/test_elf.py::test_diff
0.26s call     tests/comparators/test_rlib.py::test_compare_non_existing
0.19s call     tests/comparators/test_iso9660.py::test_no_differences
0.18s call     tests/comparators/test_elf.py::test_lib_compare_non_existing
0.18s call     tests/comparators/test_elf.py::test_obj_compare_non_existing
0.17s call     tests/comparators/test_deb.py::test_compare_non_existing
0.14s call     tests/comparators/test_deb.py::test_identification_of_md5sums_in_deb
== 261 passed, 99 skipped in 18.71 seconds ==
Comment 2 Ed Maste freebsd_committer freebsd_triage 2017-08-21 17:58:29 UTC
One problem is python's lack of closefrom: ktrace shows:

  1516 python3.6 CALL  close(0x4)
  1516 python3.6 RET   close -1 errno 9 Bad file descriptor
  1516 python3.6 CALL  close(0x5)
  1516 python3.6 RET   close -1 errno 9 Bad file descriptor
  1516 python3.6 CALL  close(0x6)
  1516 python3.6 RET   close -1 errno 9 Bad file descriptor
  1516 python3.6 CALL  close(0x8)
  1516 python3.6 RET   close -1 errno 9 Bad file descriptor
  1516 python3.6 CALL  close(0x9)
  1516 python3.6 RET   close -1 errno 9 Bad file descriptor
  1516 python3.6 CALL  close(0xa)
  1516 python3.6 RET   close -1 errno 9 Bad file descriptor
...
  1516 python3.6 CALL  close(0x8e344)
  1516 python3.6 RET   close -1 errno 9 Bad file descriptor
  1516 python3.6 CALL  close(0x8e345)
  1516 python3.6 RET   close -1 errno 9 Bad file descriptor
  1516 python3.6 CALL  close(0x8e346)
  1516 python3.6 RET   close -1 errno 9 Bad file descriptor
  1516 python3.6 CALL  close(0x8e347)
  1516 python3.6 RET   close -1 errno 9 Bad file descriptor
  1516 python3.6 CALL  close(0x8e348)
  1516 python3.6 RET   close -1 errno 9 Bad file descriptor
  1516 python3.6 CALL  close(0x8e349)
  1516 python3.6 RET   close -1 errno
Comment 3 Ed Maste freebsd_committer freebsd_triage 2017-08-22 12:58:01 UTC
I ran the slow tests under ktrace and it does complete eventually:

% ktrace -f /tmp/diffoscope.out -i pytest-3.6 tests/comparators/test_directory.py
...
========================= 8 passed in 68469.95 seconds =========================
% ls -lh /tmp/diffoscope.out
-rw-------  1 emaste  wheel   182G Aug 22 08:45 /tmp/diffoscope.out


It appears the issue is likely entirely due to the close_fds issue; with fdescfs mounted it's reasonable on my machine:

% pytest-3.6 --durations=0 tests/comparators/test_directory.py
============================= test session starts ==============================
platform freebsd12 -- Python 3.6.1, pytest-3.1.3, py-1.4.34, pluggy-0.4.0
rootdir: /usr/home/emaste/src/diffoscope, inifile:
collected 8 items 

tests/comparators/test_directory.py ........

============================ slowest test durations ============================
3.02s call     tests/comparators/test_directory.py::test_no_differences_with_extra_slash
3.01s call     tests/comparators/test_directory.py::test_no_differences
0.16s setup    tests/comparators/test_directory.py::test_content
...
=========================== 8 passed in 6.53 seconds ===========================
Comment 4 Ed Maste freebsd_committer freebsd_triage 2018-10-03 14:23:06 UTC
I tried on my laptop just now and the entire test suite completes quite quickly:

% time pytest-3.6
============================= test session starts ==============================
platform freebsd12 -- Python 3.6.5, pytest-3.6.4, py-1.6.0, pluggy-0.6.0
rootdir: /usr/home/emaste/src/diffoscope, inifile:
collected 382 items / 2 errors                                                 

==================================== ERRORS ====================================
________________ ERROR collecting tests/comparators/test_elf.py ________________
tests/comparators/test_elf.py:77: in <module>
    @skip_if_binutils_does_not_support_x86()
tests/utils/tools.py:101: in skip_if_binutils_does_not_support_x86
    'elf64-x86-64' not in get_supported_elf_formats(),
tests/utils/tools.py:109: in get_supported_elf_formats
    ('objdump', '--info'),
/usr/local/lib/python3.6/subprocess.py:336: in check_output
    **kwargs).stdout
/usr/local/lib/python3.6/subprocess.py:418: in run
    output=stdout, stderr=stderr)
E   subprocess.CalledProcessError: Command '('objdump', '--info')' returned non-zero exit status 1.
------------------------------- Captured stderr --------------------------------
objdump: Unknown command line argument '--info'.  Try: 'objdump -help'
objdump: Did you mean '-df'?
_______________ ERROR collecting tests/comparators/test_rlib.py ________________
tests/comparators/test_rlib.py:78: in <module>
    @skip_if_binutils_does_not_support_x86()
tests/utils/tools.py:101: in skip_if_binutils_does_not_support_x86
    'elf64-x86-64' not in get_supported_elf_formats(),
tests/utils/tools.py:109: in get_supported_elf_formats
    ('objdump', '--info'),
/usr/local/lib/python3.6/subprocess.py:336: in check_output
    **kwargs).stdout
/usr/local/lib/python3.6/subprocess.py:418: in run
    output=stdout, stderr=stderr)
E   subprocess.CalledProcessError: Command '('objdump', '--info')' returned non-zero exit status 1.
------------------------------- Captured stderr --------------------------------
objdump: Unknown command line argument '--info'.  Try: 'objdump -help'
objdump: Did you mean '-df'?
!!!!!!!!!!!!!!!!!!! Interrupted: 2 errors during collection !!!!!!!!!!!!!!!!!!!!
=========================== 2 error in 3.18 seconds ============================
pytest-3.6  2.24s user 1.72s system 102% cpu 3.873 total

However ktrace shows that the closefrom issue persists, still millions of close() calls returning EBADF when running
% ktrace -i -f /tmp/diffoscope.out pytest-3.6 tests/comparators/test_directory.py
Comment 5 Ed Maste freebsd_committer freebsd_triage 2018-10-03 17:36:51 UTC
Oh - I think it is reporting the two errors and not actually running tests :(

When PATH prefers /usr/local/bin it is still slow:
% PATH=/usr/local/bin:$PATH /usr/bin/time pytest-3.6
...

============= 8 failed, 272 passed, 120 skipped in 310.55 seconds ==============
      312.16 real       162.52 user       353.22 sys
Comment 6 Kubilay Kocak freebsd_committer freebsd_triage 2019-11-29 11:01:09 UTC
ports r518640 closed dependent bug 221700, which should address the performance issues reported here. Please re-open the issue with additional information if that is not the case