Recent versions do not work on Windows

[Kojoley]

Sysinfo:

Windows-7-6.1.7601-SP2
2.7.12 (v2.7.12:d33e0cf91556, Jun 27 2016, 15:19:22) [MSC v.1500 32 bit (Intel)]

Test cmd:

pip install vmprof==%VERSION% && python -m vmprof -o py27-x86.vmprof sometest.py && vmprofshow py27-x86.vmprof 

Log:

0.3.12: Fatal: could not read vmprof profile file 'py27-x86.vmprof': (34882L, "'\\x00'")
0.3.11: Fatal: could not read vmprof profile file 'py27-x86.vmprof': (46491L, '\'"\'')
0.3.10: Could not find a version that satisfies the requirement vmprof==0.3.10
0.3.9: Could not find a version that satisfies the requirement vmprof==0.3.9
0.3.8: Fatal: could not read vmprof profile file 'py27-x86.vmprof': (44071L, '\'"\'')
0.3.7: Fatal: could not read vmprof profile file 'py27-x86.vmprof': (70L, "'\\x00'")
0.3.6: Could not find a version that satisfies the requirement vmprof==0.3.6
0.3.5: Fatal: could not read vmprof profile file 'py27-x86.vmprof':
0.3.4: Could not find a version that satisfies the requirement vmprof==0.3.4
0.3.3: OK
0.3.2: OK
0.3.1: OK
0.3.0: OK

I will try to bisect the commit, but this is sad, something has been broken since 0.3.3-0.3.5 and no one noticed it? Why do not you use Appveyor? I can help you with it if you like.

[Kojoley]

Well, I have bisected it and the first bad commit is #90 merge.

What more strange is that I am recieving different errors every time I run vmprof&vmprofshow:

Fatal: could not read vmprof profile file 'test.vmprof': Error -3 while decompressing: invalid distance too far back
Fatal: could not read vmprof profile file 'test.vmprof':
Fatal: could not read vmprof profile file 'test.vmprof': Error -3 while decompressing: invalid distance too far back
Fatal: could not read vmprof profile file 'test.vmprof': (70L, "':'")
Fatal: could not read vmprof profile file 'test.vmprof': Error -3 while decompressing: invalid code lengths set
Fatal: could not read vmprof profile file 'test.vmprof': (70L, "'F'")

[planrich]

Hi, thanks for tracking this down. No, we do not use appveyor, but I'm now looking into setting it up. Thanks for the hint, I hope I can catch the issue this way. I have a vague idea why this is happening!

[planrich]

I have setup appveyor, but it does not complain in the vmprof tests. Can you maybe post the contents of sometest.py or even write a test that fails reproducing the behaviour?

[Kojoley]

The content of sometest.py:

import time

for _ in xrange(1000):
    time.sleep(.001)

Actually its content does not matter.

After git revert -m 1 8adf8455 the problem goes away, but still not all tests pass.

[planrich]

Well, the test I added did not fail on appveyor. We have several such tests creating a small profile and reading it. Do you have a suggestion why this is working on appveyor?

[Kojoley]

Tests run for me successfully too, I think it is because #90 did not add any test for gzip write&read.

[planrich]

This was implicitly tested. We rely on the machinery to save and load profiles correctly. There are other tests that checked if a correct profile is created.

What I could think of that might cause the problem is that on Windows the subprocess started is not gzip, but python -m gzip

[Kojoley]

I have lied that tests run for me locally, I thought that the fails was in jitlog.

============================= test session starts =============================
platform win32 -- Python 2.7.12, pytest-2.9.2, py-1.4.31, pluggy-0.3.1 -- c:\python27\python.exe
cachedir: .cache
rootdir: C:\Working\Repositories\vmprof-python, inifile: 
plugins: cov-2.3.0, pycharm-0.4.0, xdist-1.14
collecting ... collected 18 items

vmprof/test/test_config.py::test_parser_config PASSED
vmprof/test/test_config.py::test_parser_arg_precedence PASSED
vmprof/test/test_config.py::test_parser_without_section PASSED
vmprof/test/test_reader.py::test_fileobj PASSED
vmprof/test/test_reader.py::test_fileobj_wrapper PASSED
vmprof/test/test_reader.py::test_read_header PASSED
vmprof/test/test_run.py::test_basic FAILED
vmprof/test/test_run.py::test_read_bit_by_bit FAILED
vmprof/test/test_run.py::test_enable_disable FAILED
vmprof/test/test_run.py::test_nested_call FAILED
vmprof/test/test_run.py::test_multithreaded FAILED
vmprof/test/test_run.py::test_memory_measurment SKIPPED
vmprof/test/test_run.py::test_gzip_problem PASSED
vmprof/test/test_run.py::test_line_profiling FAILED
vmprof/test/test_run.py::test_vmprof_show PASSED
vmprof/test/test_stats.py::test_tree_basic PASSED
vmprof/test/test_stats.py::test_tree_jit PASSED
vmprof/test/test_stats.py::test_read_simple SKIPPED
=========================== short test summary info ===========================
SKIP [1] C:\Working\Repositories\vmprof-python\vmprof\test\test_run.py:149: unsupported platform
SKIP [1] C:\Working\Repositories\vmprof-python\vmprof\test\test_stats.py:35: think later

================================== FAILURES ===================================
_________________________________ test_basic __________________________________

    def test_basic():
        tmpfile = tempfile.NamedTemporaryFile(delete=False)
        vmprof.enable(tmpfile.fileno())
        function_foo()
        vmprof.disable()
        tmpfile.close()
>       assert b"function_foo" in gzip.GzipFile(tmpfile.name).read()

vmprof\test\test_run.py:55: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
c:\python27\lib\gzip.py:261: in read
    self._read(readsize)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <gzip open file 'c:\\users\\user\\appdata\\local\\temp\\tmpfpounq', mode 'rb' at 0x0304B498 0x3093f90>
size = 131072

    def _read(self, size=1024):
        if self.fileobj is None:
            raise EOFError, "Reached EOF"

        if self._new_member:
            # If the _new_member flag is set, we have to
            # jump to the next member, if there is one.
            #
            # First, check if we're at the end of the file;
            # if so, it's time to stop; no more members to read.
            pos = self.fileobj.tell()   # Save current position
            self.fileobj.seek(0, 2)     # Seek to end of file
            if pos == self.fileobj.tell():
                raise EOFError, "Reached EOF"
            else:
                self.fileobj.seek( pos ) # Return to original position

            self._init_read()
            self._read_gzip_header()
            self.decompress = zlib.decompressobj(-zlib.MAX_WBITS)
            self._new_member = False

        # Read a chunk of data from the file
        buf = self.fileobj.read(size)

        # If the EOF has been reached, flush the decompression object
        # and mark this object as finished.

        if buf == "":
            uncompress = self.decompress.flush()
            self._read_eof()
            self._add_read_data( uncompress )
            raise EOFError, 'Reached EOF'

>       uncompress = self.decompress.decompress(buf)
E       error: Error -3 while decompressing: invalid literal/lengths set

c:\python27\lib\gzip.py:319: error
____________________________ test_read_bit_by_bit _____________________________

    def test_read_bit_by_bit():
        tmpfile = tempfile.NamedTemporaryFile(delete=False)
        vmprof.enable(tmpfile.fileno())
        function_foo()
        vmprof.disable()
        tmpfile.close()
        with open(tmpfile.name, 'rb') as f:
>           period, profiles, virtual_symbols, interp_name = read_prof_bit_by_bit(f)

vmprof\test\test_run.py:64: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
vmprof\reader.py:207: in read_prof_bit_by_bit
    finished = read_one_marker(fileobj, status, buf)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

fileobj = <vmprof.reader.FileObjWrapper object at 0x0306DF90>
status = <vmprof.reader.ReaderStatus object at 0x03093410>, buffer_so_far = None

    def read_one_marker(fileobj, status, buffer_so_far=None):
        fileobj = FileObjWrapper(fileobj, buffer_so_far)
        marker = fileobj.read(1)
        if marker == MARKER_STACKTRACE:
            count = read_word(fileobj)
            # for now
            assert count == 1
            depth = read_word(fileobj)
            assert depth <= 2**16, 'stack strace depth too high'
            trace = read_trace(fileobj, depth, status.version, status.profile_lines)

            if status.version >= VERSION_THREAD_ID:
                thread_id, = struct.unpack('l', fileobj.read(WORD_SIZE))
            else:
                thread_id = 0
            if status.profile_memory:
                mem_in_kb, = struct.unpack('l', fileobj.read(WORD_SIZE))
            else:
                mem_in_kb = 0
            trace.reverse()
            status.profiles.append((trace, 1, thread_id, mem_in_kb))
        elif marker == MARKER_VIRTUAL_IP:
            unique_id = read_word(fileobj)
            name = read_string(fileobj)
            if PY3:
                name = name.decode()
            status.virtual_ips[unique_id] = name
        elif marker == MARKER_TRAILER:
            return True # finished
        else:
>           raise FileReadError("unexpected marker: %d" % ord(marker))
E           FileReadError: unexpected marker: 55

vmprof\reader.py:188: FileReadError
_____________________________ test_enable_disable _____________________________

    def test_enable_disable():
        prof = vmprof.Profiler()
        with prof.measure():
            function_foo()
>       stats = prof.get_stats()

vmprof\test\test_run.py:72: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
vmprof\profiler.py:57: in get_stats
    res = read_profile(self.ctx.tmpfile.name)
vmprof\profiler.py:34: in read_profile
    period, profiles, virtual_symbols, interp_name = read_prof(prof_file)
vmprof\reader.py:274: in read_prof
    name = read_string(fileobj)
vmshare\binary.py:57: in read_string
    return fileobj.read(lgt)
c:\python27\lib\gzip.py:268: in read
    self._read(readsize)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <gzip open file 'c:\\users\\user\\appdata\\local\\temp\\tmpz9kai3', mode 'rb' at 0x08A600D0 0x8a47630>
size = 16384

    def _read(self, size=1024):
        if self.fileobj is None:
            raise EOFError, "Reached EOF"

        if self._new_member:
            # If the _new_member flag is set, we have to
            # jump to the next member, if there is one.
            #
            # First, check if we're at the end of the file;
            # if so, it's time to stop; no more members to read.
            pos = self.fileobj.tell()   # Save current position
            self.fileobj.seek(0, 2)     # Seek to end of file
            if pos == self.fileobj.tell():
                raise EOFError, "Reached EOF"
            else:
                self.fileobj.seek( pos ) # Return to original position

            self._init_read()
            self._read_gzip_header()
            self.decompress = zlib.decompressobj(-zlib.MAX_WBITS)
            self._new_member = False

        # Read a chunk of data from the file
        buf = self.fileobj.read(size)

        # If the EOF has been reached, flush the decompression object
        # and mark this object as finished.

        if buf == "":
            uncompress = self.decompress.flush()
            self._read_eof()
            self._add_read_data( uncompress )
            raise EOFError, 'Reached EOF'

>       uncompress = self.decompress.decompress(buf)
E       error: Error -3 while decompressing: invalid literal/lengths set

c:\python27\lib\gzip.py:319: error
______________________________ test_nested_call _______________________________

    def test_nested_call():
        prof = vmprof.Profiler()
        with prof.measure():
            function_bar()
        # now jitted, on pypy
        with prof.measure():
            function_bar()
>       stats = prof.get_stats()

vmprof\test\test_run.py:84: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
vmprof\profiler.py:57: in get_stats
    res = read_profile(self.ctx.tmpfile.name)
vmprof\profiler.py:34: in read_profile
    period, profiles, virtual_symbols, interp_name = read_prof(prof_file)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

fileobj = <_io.BufferedReader name='c:\\users\\user\\appdata\\local\\temp\\tmpsqdark'>
virtual_ips_only = False

    def read_prof(fileobj, virtual_ips_only=False):
        fileobj = gunzip(fileobj)

        assert read_word(fileobj) == 0 # header count
        assert read_word(fileobj) == 3 # header size
        assert read_word(fileobj) == 0
        period = read_word(fileobj)
        assert read_word(fileobj) == 0

        virtual_ips = []
        profiles = []
        interp_name = None
        version = 0
        profile_memory = False
        profile_lines = False

        while True:
            marker = fileobj.read(1)
            if marker == MARKER_HEADER:
                assert not version, "multiple headers"
                version, = struct.unpack("!h", fileobj.read(2))
                if version >= VERSION_MODE_AWARE:
                    mode = ord(fileobj.read(1))
                    profile_memory = (mode & PROFILE_MEMORY) != 0
                    profile_lines = (mode & PROFILE_LINES) != 0
                else:
                    profile_memory = version == VERSION_MEMORY
                    profile_lines = False
                lgt = ord(fileobj.read(1))
                interp_name = fileobj.read(lgt)
                if PY3:
                    interp_name = interp_name.decode()
            elif marker == MARKER_STACKTRACE:
                count = read_word(fileobj)
                # for now
                assert count == 1
                depth = read_word(fileobj)
                assert depth <= 2**16, 'stack strace depth too high'
                if virtual_ips_only:
                    fileobj.read(WORD_SIZE * depth)
                    trace = []
                else:
                    trace = read_trace(fileobj, depth, version, profile_lines)
                if version >= VERSION_THREAD_ID:
                    thread_id, = struct.unpack('l', fileobj.read(WORD_SIZE))
                else:
                    thread_id = 0
                if profile_memory:
                    mem_in_kb, = struct.unpack('l', fileobj.read(WORD_SIZE))
                else:
                    mem_in_kb = 0
                trace.reverse()
                profiles.append((trace, 1, thread_id, mem_in_kb))
            elif marker == MARKER_INTERP_NAME:
                assert not version, "multiple headers"
                assert not interp_name, "Dual interpreter name header"
                lgt = ord(fileobj.read(1))
                interp_name = fileobj.read(lgt)
                if PY3:
                    interp_name = interp_name.decode()
            elif marker == MARKER_VIRTUAL_IP:
                unique_id = read_word(fileobj)
                name = read_string(fileobj)
                if PY3:
                    name = name.decode()
                virtual_ips.append((unique_id, name))
            elif marker == MARKER_TRAILER:
                #if not virtual_ips_only:
                #    symmap = read_ranges(fileobj.read())
                break
            else:
>               assert not marker, (fileobj.tell(), repr(marker))
E               AssertionError: (34686618L, "':'")

vmprof\reader.py:283: AssertionError
_____________________________ test_multithreaded ______________________________

    def test_multithreaded():
        if '__pypy__' in sys.builtin_module_names or PY3K:
            py.test.skip("not supported on pypy and python3 just yet")
        import threading
        finished = []

        def f():
            for k in range(1000):
                l = [a for a in xrange(COUNT)]
            finished.append("foo")

        threads = [threading.Thread(target=f), threading.Thread(target=f)]
        prof = vmprof.Profiler()
        with prof.measure():
            for t in threads:
                t.start()
            f()
            for t in threads:
>               t.join()

vmprof\test\test_run.py:133: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
vmprof\profiler.py:25: in __exit__
    vmprof.disable()
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

    def disable():
        try:
>           _vmprof.disable()
E           OSError: [Errno 22] Invalid argument

vmprof\__init__.py:49: OSError
_____________________________ test_line_profiling _____________________________

    def test_line_profiling():
        tmpfile = tempfile.NamedTemporaryFile(delete=False)
        vmprof.enable(tmpfile.fileno(), lines=True)  # enable lines profiling
        function_foo()
        vmprof.disable()
        tmpfile.close()

        def walk(tree):
            assert len(tree.lines) >= len(tree.children)

            for v in six.itervalues(tree.children):
                    walk(v)

        with open(tmpfile.name, 'rb') as f:
>           period, profiles, virtual_symbols, interp_name = read_prof_bit_by_bit(f)

vmprof\test\test_run.py:189: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
vmprof\reader.py:199: in read_prof_bit_by_bit
    status = read_header(fileobj, buf)
vmprof\reader.py:135: in read_header
    assert_error(read_word(fileobj) == 0)
vmshare\binary.py:17: in read_word
    b = fileobj.read(WORD_SIZE)
vmprof\reader.py:106: in read
    s = self._fileobj.read(count)
c:\python27\lib\gzip.py:268: in read
    self._read(readsize)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <gzip closed file 'c:\\users\\user\\appdata\\local\\temp\\tmpxdfr8g', mode 'rb' at 0x08A60700 0x6a96950>
size = 1024

    def _read(self, size=1024):
        if self.fileobj is None:
            raise EOFError, "Reached EOF"

        if self._new_member:
            # If the _new_member flag is set, we have to
            # jump to the next member, if there is one.
            #
            # First, check if we're at the end of the file;
            # if so, it's time to stop; no more members to read.
            pos = self.fileobj.tell()   # Save current position
            self.fileobj.seek(0, 2)     # Seek to end of file
            if pos == self.fileobj.tell():
                raise EOFError, "Reached EOF"
            else:
                self.fileobj.seek( pos ) # Return to original position

            self._init_read()
            self._read_gzip_header()
            self.decompress = zlib.decompressobj(-zlib.MAX_WBITS)
            self._new_member = False

        # Read a chunk of data from the file
        buf = self.fileobj.read(size)

        # If the EOF has been reached, flush the decompression object
        # and mark this object as finished.

        if buf == "":
            uncompress = self.decompress.flush()
            self._read_eof()
            self._add_read_data( uncompress )
            raise EOFError, 'Reached EOF'

>       uncompress = self.decompress.decompress(buf)
E       error: Error -3 while decompressing: invalid literal/lengths set

c:\python27\lib\gzip.py:319: error
=============== 6 failed, 10 passed, 2 skipped in 14.72 seconds ===============

[planrich]

Well, yes I knew that the jitlog is not operatable on windows. But it is currently in a beta stage and only works on windows. That's why I turned it off on appveyor. I'll add a skip for those tests.

Nevertheless, jitlog has nothing todo with vmprof per se. If vmprof tests pass, vmprof is considered functional.

[Kojoley]

If vmprof tests pass, vmprof is considered functional.

Emmm, I did not say it. I have posted the test log from py.test vmprof/ -vra and it clearly does not work.

[planrich]

Ah, right. My bad! I'll have a look at the test failures! Thanks

[planrich]

I setup a virtual machine (win7 SP 1). Cannot reproduce the problem. Unsure how to proceed with this issue.

[planrich]

good news. thanks to a suggestion by armin we narrowed the issue down. python -m gzip outputs in text mode. which lets the reading in the tests fail. It seems not all windows versions are affected (probably depends on the built python)