Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

persistent.tests.test_timestamp.PyAndCComparisonTests.test_strs_equal fails #86

Closed
mcepl opened this issue Aug 14, 2018 · 52 comments

Comments

Projects
None yet
3 participants
@mcepl
Copy link

commented Aug 14, 2018

[   15s] ======================================================================
[   15s] FAIL: test_strs_equal (persistent.tests.test_timestamp.PyAndCComparisonTests)
[   15s] ----------------------------------------------------------------------
[   15s] Traceback (most recent call last):
[   15s]   File "/home/abuild/rpmbuild/BUILD/persistent-4.2.4.2/persistent/tests/test_timestamp.py", line 253, in test_strs_equal
[   15s]     self.assertEqual(str(c), str(py))
[   15s] AssertionError: '2008-12-22 15:20:-11.700000' != '2008-12-22 15:20:48.300000'
[   15s] - 2008-12-22 15:20:-11.700000
[   15s] ?                  ^^^ ^
[   15s] + 2008-12-22 15:20:48.300000
[   15s] ?                  ^^ ^

Build log

This is running on completely normal run-of-the-mill Lenovo Thinkpad T480 with openSUSE Tumbleweed, so of course it is x86_64 architecture. Using persistent-4.2.4.2.tar.gz.

Replacing my comment in #41.

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 14, 2018

I haven't been able to reproduce this either, but all my test machines are debian based.

This looks to be the compiler invocation:

[   13s] gcc -pthread -Wno-unused-result -Wsign-compare -DNDEBUG -fmessage-length=0 -grecord-gcc-switches -O2 -Wall -D_FORTIFY_SOURCE=2 -fstack-protector-strong -funwind-tables -fasynchronous-unwind-tables -fstack-clash-protection -g -DOPENSSL_LOAD_CONF -fmessage-length=0 -grecord-gcc-switches -O2 -Wall -D_FORTIFY_SOURCE=2 -fstack-protector-strong -funwind-tables -fasynchronous-unwind-tables -fstack-clash-protection -g -fmessage-length=0 -grecord-gcc-switches -O2 -Wall -D_FORTIFY_SOURCE=2 -fstack-protector-strong -funwind-tables -fasynchronous-unwind-tables -fstack-clash-protection -g -fPIC -I/usr/include/python3.6m -c persistent/_timestamp.c -o build/temp.linux-x86_64-3.6/persistent/_timestamp.o
[   14s] gcc -pthread -shared -flto -fuse-linker-plugin -ffat-lto-objects -flto-partition=none build/temp.linux-x86_64-3.6/persistent/_timestamp.o -L/usr/lib64 -lpython3.6m -o build/lib.linux-x86_64-3.6/persistent/_timestamp.cpython-36m-x86_64-linux-gnu.so

Some of those switches I'm not familiar with. We may be doing some things that aren't strictly defined? (I'm not sure) So possibly the switches might make a difference? (There aren't any warnings, but compilers are fickle; I know that -ffast-math changes the results.) Can you try compiling with just '-O2'?

Also, do you get the same behaviour on master and with #83? Master fixed at least one case of undefined behaviour, and #83 I'm just curious about :) I wouldn't expect either of them to actually make a difference, though. EDIT: But the added tests in #83 might tell us something.

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 14, 2018

The seconds value we're working with is 48.299999952316284 so we may be looking at some math precision issues in C world. FWIW, my C implementation matches the Python example above, so the C example above is (obviously) wrong.

The C version uses sprintf with a format string of "%4.4d-%2.2d-%2.2d %2.2d:%2.2d:%09.6f", it's possible we could also be looking at a libc sprintf or locale issue in the final '%09.6f' part.

@mcepl

This comment has been minimized.

Copy link
Author

commented Aug 14, 2018

Using gcc-8-2.1.x86_64 and glibc-2.27-6.1.x86_64, but I don't how to build with different CFLAGS.

When I try CFLAGS="-O2" python3 setup.py build I still get build with the standard openSUSE CFLAGS. And no, we don't patch setup.py in any way.

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 14, 2018

Yeah, it usually takes patching distutils itself to change the CFLAGS for all modules, or using a custom build command. (There's a file somewhere in the standard library that records the build flags of when Python was built and that's what distutils uses.) So not an easy ask 😄

TIL that Python's %f format is implemented in code shipped with Python, either in dtoa.c, which uses some specific details of IEEE floating point format, or more generically in PyOS_double_to_string from pystrod.c. The C implementation, obviously, doesn't use that, going directly to the libc sprintf function. So I still think we're looking at either a math precision issue, or a difference in the way sprintf works on this platform. I'm curious what a simple C program that uses that sprintf format string and the arguments (especially seconds) outputs on your platform?

It's possible the fix might be to convert the C implementation to use the same string formatting as Python does.

@mcepl

This comment has been minimized.

Copy link
Author

commented Aug 14, 2018

Suggest me some test C program and I will report results promptly.

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 14, 2018

This would be the most direct C test, going straight to the end result and holding the full precision of the literal:

#include <stdio.h>

int main(void)
{
    char buf[128];
    sprintf(buf, "%4.4d-%2.2d-%2.2d %2.2d:%2.2d:%09.6f",
	    2008, 12, 22, 920 / 60, 920 % 60,
	    48.299999952316284);
    printf("%s\n", buf);
    return 0;
}

Replace that last constant with 48.29999994020909 to get the actual value its using (on my machine) once the rounding has taken place. (I suggest compiling with all the same flags as the python module.) Both produce "2008-12-22 15:20:48.300000" as expected here. If you get something different, it's an sprintf issue.

You could also adjust test_strs_equal to have it print c.second() before the assertEqual. On my machine, it's returning that 48.29999994020909 value; if you get something different it's the precision issue.

@mgedmin

This comment has been minimized.

Copy link
Member

commented Aug 14, 2018

This is an amazing issue and I love it!

The negative value returned by TimeStamp_sec, well, let's see:

static double
TimeStamp_sec(TimeStamp *self)
{
    unsigned int v;

    v = (self->data[4] * 16777216 + self->data[5] * 65536
     + self->data[6] * 256 + self->data[7]);
    return SCONV * v;
}

On a 32-bit platform unsigned int is 32 bits. self->data[4] is an unsigned char. 255 * 16777216 should still fit in an unsigned int, hm.

What happens, according to the C standard, when you multiply a double and an unsigned int?

@mcepl

This comment has been minimized.

Copy link
Author

commented Aug 14, 2018

c.seconds() = -11.70000005979091

======================================================================
FAIL: test_strs_equal (persistent.tests.test_timestamp.PyAndCComparisonTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/matej/build/python/python-persistent/persistent-4.3.0/persistent/tests/test_timestamp.py", line 255, in test_strs_equal
    self.assertEqual(str(c), str(py))
AssertionError: '2008-12-22 15:20:-11.700000' != '2008-12-22 15:20:48.300000'
- 2008-12-22 15:20:-11.700000
?                  ^^^ ^
+ 2008-12-22 15:20:48.300000
?                  ^^ ^

and the testing program

matej@stitny: tmp$ cat test-persistent-86.c
#include <stdio.h>

int main(void)
{
    char buf[128];
    sprintf(buf, "%4.4d-%2.2d-%2.2d %2.2d:%2.2d:%09.6f",
	    2008, 12, 22, 920 / 60, 920 % 60,
	    -11.70000005979091);
    printf("%s\n", buf);
    return 0;
}
matej@stitny: tmp$ gcc -O2 -o test-persistent-86 test-persistent-86.c 
matej@stitny: tmp$ ./test-persistent-86 
2008-12-22 15:20:-11.700000
matej@stitny: tmp$
@mgedmin

This comment has been minimized.

Copy link
Member

commented Aug 14, 2018

Hey, the 16777216 constant is an int! There you have it, 32-bit signed overflow is undefined.

@mgedmin

This comment has been minimized.

Copy link
Member

commented Aug 14, 2018

So, would changing that to 16777216U improve things? I'm not a native C speaker.

(Can we get a 32-bit Linux platform on Travis?)

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 14, 2018

I think using standard sized types like uint _64 would be good. Except Windows may have a problem with that.

@mcepl

This comment has been minimized.

Copy link
Author

commented Aug 14, 2018

(Can we get a 32-bit Linux platform on Travis?)

openSUSE builds on i586 as well https://build.opensuse.org/package/show/devel:languages:python/python-persistent

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 14, 2018

We have a 32 bit platform thanks to manylinux. But we don’t run the tests there, perhaps we should.

@mcepl

This comment has been minimized.

Copy link
Author

commented Aug 14, 2018

We have a 32 bit platform thanks to manylinux. But we don’t run the tests there, perhaps we should.

After switching to working for SUSE I have completely turned around (Saul to Paul kind of) … everybody should run all tests possible.

@mgedmin

This comment has been minimized.

Copy link
Member

commented Aug 14, 2018

I don't think we need a 64-bit int here, we just need to force the arithmetic to be unsigned.

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 14, 2018

Hmm. I have a 32-bit raspberry pi running raspbian, and on Python 3.4 and 2.7, I get the expected results:

Python 3.4.2 (default, Oct 19 2014, 13:31:11)
[GCC 4.9.1] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import platform
>>> platform.architecture()
('32bit', 'ELF')
>>> import struct
>>> struct.calcsize('P') * 8
32
>>> from persistent import timestamp
>>> timestamp.TimeStamp
<built-in function TimeStamp>
>>> c = timestamp.TimeStamp(*(2008, 12, 22, 15, 20, 48.299999952316284))
>>> c.second()
48.299999952316284
>>> str(c)
'2008-12-22 15:20:48.300000'

I even recompiled with all the same flags as above (except -fstack-clash-protection, which isn't supported) and got the same results.

So I don't think we're looking at just a 32-bit linux thing. (If it was just a 32-bit thing, wouldn't the Windows builds, which do test, have failed?) Has GCC changed it's behaviour with regards to int constants in double expressions between 4.9.2 and gcc-8-2.1?

Wait a minute, the reported compiler was gcc-8-2.1.x86_64 and glibc-2.27-6.1.x86_64, meaning we're on a 64-bit platform. (I'm not sure how relevant that is, in C, integer literals without a suffix have the smallest type that will hold them, the constant 16777216 fits in 24 bits, so it takes a 32-bit int---it would be more clear written 0x1000000).

@mgedmin

This comment has been minimized.

Copy link
Member

commented Aug 16, 2018

Yeah, I fail reading comprehension again:

This is running on completely normal run-of-the-mill Lenovo Thinkpad T480 with openSUSE Tumbleweed, so of course it is x86_64 architecture.

How can one get a negative number out of this on x86_64???

@mcepl since you're currently the only one who can reproduce this, would you mind adding some extra debug printfs like

static double
TimeStamp_sec(TimeStamp *self)
{
    unsigned int v;

    v = (self->data[4] * 16777216 + self->data[5] * 65536
     + self->data[6] * 256 + self->data[7]);
    printf("DEBUG: v = %u, SCONV = %f, result = %f\n", v, SCONV, SCONV * v);   /* <----- */
    return SCONV * v;
}

?

jamadden added a commit that referenced this issue Aug 18, 2018

Use unsigned constants for second arithmetic in C timestamp
This might fix #86

I also find that it makes the data derivation/reconstruction more
clear by making the powers-of-two factors more obvious.

jamadden added a commit that referenced this issue Aug 18, 2018

Use unsigned constants for second arithmetic in C timestamp
This might fix #86

I also find that it makes the data derivation/reconstruction more
clear by making the powers-of-two factors more obvious.

@jamadden jamadden closed this in #87 Aug 18, 2018

@jamadden jamadden reopened this Aug 18, 2018

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 18, 2018

After the merge of #87 I have high hopes that this would be fixed in master now. All the arithmetic is explicitly unsigned after that.

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 20, 2018

@mcepl I would like to release master as 4.4.0 soon. Do you expect to have time to look at this more soon? Or would it be easier if the changes were released?

clrpackages pushed a commit to clearlinux-pkgs/persistent that referenced this issue Aug 22, 2018

[update to 4.4.0] Add support for subclasses to implement _p_repr. Fi…
…xes #11

Jason Madden (40):
      Preparing release 4.3.0
      Back to development: 4.3.1
      Add support for Python 3.7 and drop 3.3
      Try 3.7.0 for macpython.
      Merge pull request #74 from zopefoundation/py37
      Switch to zope.testrunner from 'python setup.py test' and 'nose'.
      Updates for appveyor.
      Merge pull request #78 from zopefoundation/zope-testrunner
      Build CFFI modules the modern way. Fixes #75 and fixes #43
      Add links to the change note with details [skip ci]
      Merge pull request #79 from zopefoundation/issue75
      Test the docs on Python 2 and 3 using manuel. This gets a lot of coverage of tests.attrhooks, tests.cucumbers and tests.utils.
      Fix the no cover pragmas.
      100% coverage for the test_* files.
      100% coverage for attrhooks.py
      100% coverage for tests/utils.py by removing unused methods.
      100% coverage for timestamp.py
      100% coverage for persistence.py.
      100% coverage for list.py
      Simplify __init__.py to not repeat itself three times.
      Enable coveralls
      Exclude _ring_build.py; it's only used from setup.py.
      Add change note and coverage badge to README [skip ci]
      Merge pull request #80 from zopefoundation/coverage
      Remove unneeded _compat._b/_u/_native.
      Merge pull request #82 from zopefoundation/issue81
      Simplify test exclusion in test_persistence.py
      Tests and Python implementation.
      C implementation, and add tests that BaseException isn't caught.
      Add support for subclasses to implement _p_repr. Fixes #11
      Merge pull request #84 from zopefoundation/issue11
      Make the C and Python TimeStamp round the same way.
      Merge pull request #83 from zopefoundation/issue41
      Use unsigned constants for second arithmetic in C timestamp
      Use names and 'functions' for the various constants and packing/unpacking operations for better readability.
      whitespace
      Comments, and rename SCONV to TS_SECOND_BYTES_BIAS
      Rename SCONV in timestamp.py too, and change _UNSIGNED_ into _UINT32_ in C to better express the expected range.
      Merge pull request #87 from zopefoundation/use-unsigned-hex-consts-in-timestamp
      Preparing release 4.4.0

4.4.0 (2018-08-22)
------------------

- Use unsigned constants when doing arithmetic on C timestamps,
  possibly avoiding some overflow issues with some compilers or
  compiler settings. See `issue 86
  <https://github.com/zopefoundation/persistent/issues/86>`_.

- Change the default representation of ``Persistent`` objects to
  include the representation of their OID and jar, if set. Also add
  the ability for subclasses to implement ``_p_repr()`` instead of
  overriding ``__repr__`` for better exception handling. See `issue 11
  <https://github.com/zopefoundation/persistent/issues/11>`_.

- Reach and maintain 100% test coverage.

(NEWS truncated at 15 lines)
@mcepl

This comment has been minimized.

Copy link
Author

commented Aug 25, 2018

@jamadden sorry, I am on vacations so I don't follow my GitHub issues that often. There are the debug prints here (that's just explicitly WITHOUT #87; if you want me to test that, could you please provide me a patch against persistent-4.3.0.tar.gz, please?):

[   37s] ======================================================================
[   37s] FAIL: test_strs_equal (persistent.tests.test_timestamp.PyAndCComparisonTests)
[   37s] ----------------------------------------------------------------------
[   37s] Traceback (most recent call last):
[   37s]   File "/home/abuild/rpmbuild/BUILD/persistent-4.3.0/persistent/tests/test_timestamp.py", line 254, in test_strs_equal
[   37s]     self.assertEqual(str(c), str(py))
[   37s] AssertionError: '2008-12-22 15:20:-11.700000' != '2008-12-22 15:20:48.300000'
[   37s] - 2008-12-22 15:20:-11.700000
[   37s] ?                  ^^^ ^
[   37s] + 2008-12-22 15:20:48.300000
[   37s] ?                  ^^ ^
[   37s] 
[   37s] 
[   37s] ----------------------------------------------------------------------
[   37s] Ran 475 tests in 0.304s
[   37s] 
[   37s] FAILED (failures=1)
[   37s] Test failed: <unittest.runner.TextTestResult run=475 errors=0 failures=1>
[   37s] DEBUG: v = 1968526677, SCONV = 0.000000, result = 27.500000
[   37s] DEBUG: v = 1968526677, SCONV = 0.000000, result = 27.500000
[   37s] DEBUG: v = 1968526677, SCONV = 0.000000, result = 27.500000
[   37s] DEBUG: v = 1968526677, SCONV = 0.000000, result = 27.500000
[   37s] DEBUG: v = 1968526677, SCONV = 0.000000, result = 27.500000
[   37s] DEBUG: v = 1968526677, SCONV = 0.000000, result = 27.500000
[   37s] DEBUG: v = 1968526677, SCONV = 0.000000, result = 27.500000
[   37s] DEBUG: v = 1968526677, SCONV = 0.000000, result = 27.500000
[   37s] DEBUG: v = 3457448669, SCONV = 0.000000, result = -11.700000
[   37s] DEBUG: v = 0, SCONV = 0.000000, result = 0.000000
[   37s] DEBUG: v = 0, SCONV = 0.000000, result = 0.000000
[   37s] DEBUG: v = 0, SCONV = 0.000000, result = 0.000000
[   37s] DEBUG: v = 0, SCONV = 0.000000, result = 0.000000
[   37s] DEBUG: v = 1632476982, SCONV = 0.000000, result = 22.805440
[   37s] error: Test failed: <unittest.runner.TextTestResult run=475 errors=0 failures=1>
[   37s] error: Bad exit status from /var/tmp/rpm-tmp.0Q0Hjp (%check)
[   37s] 
[   37s] 
[   37s] RPM build errors:
[   37s]     Bad exit status from /var/tmp/rpm-tmp.0Q0Hjp (%check)
[   37s] 
[   37s] stitny failed "build python-persistent.spec" at Sat Aug 25 11:52:02 UTC 2018.
[   37s]
@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 25, 2018

@mcepl 4.4.0 has been released. Do you still have the problem there? (I will guess that you do.)

[ 37s] DEBUG: v = 3457448669, SCONV = 0.000000, result = -11.700000

SCONV requires more than the default %f formatting to see; something like %1.12f ought to do it. (and %2.12f for result).

The value of v is correct here. The value for SCONV (renamed to TS_SECOND_BYTES_BIAS in 4.4.0 should print as 0.000000013970, and the result should be 48.299999940209, but you're wrapping around. Even if I explicitly type v as uint32_t and SCONV as float, I still don't wraparound, nor would I expect to. Now I'm getting curious as to what instructions the compiler is generating for your function.

One difference between the working values (1968526677) and the failing value (3457448669) is that bit 31 (high-order bit of a 32-bit number) is set.

@mcepl

This comment has been minimized.

Copy link
Author

commented Aug 25, 2018

Withi this patch I get this (full build log):

[   13s] ======================================================================
[   13s] FAIL: test_strs_equal (persistent.tests.test_timestamp.PyAndCComparisonTests)
[   13s] ----------------------------------------------------------------------
[   13s] Traceback (most recent call last):
[   13s]   File "/home/abuild/rpmbuild/BUILD/persistent-4.3.0/persistent/tests/test_timestamp.py", line 253, in test_strs_equal
[   13s]     self.assertEqual(str(c), str(py))
[   13s] AssertionError: '2008-12-22 15:20:-11.700000' != '2008-12-22 15:20:48.300000'
[   13s] - 2008-12-22 15:20:-11.700000
[   13s] ?                  ^^^ ^
[   13s] + 2008-12-22 15:20:48.300000
[   13s] ?                  ^^ ^
[   13s] 
[   13s] 
[   13s] ----------------------------------------------------------------------
[   13s] Ran 475 tests in 0.301s
[   13s] 
[   13s] FAILED (failures=1)
[   13s] Test failed: <unittest.runner.TextTestResult run=475 errors=0 failures=1>
[   13s] DEBUG: v = 3457448669, TS_SECOND_BYTES_BIAS = 0.000000, result = -11.700000
[   13s] DEBUG: v = 0, TS_SECOND_BYTES_BIAS = 0.000000, result = 0.000000
[   13s] DEBUG: v = 0, TS_SECOND_BYTES_BIAS = 0.000000, result = 0.000000
[   13s] DEBUG: v = 0, TS_SECOND_BYTES_BIAS = 0.000000, result = 0.000000
[   13s] DEBUG: v = 0, TS_SECOND_BYTES_BIAS = 0.000000, result = 0.000000
[   13s] DEBUG: v = 1632476982, TS_SECOND_BYTES_BIAS = 0.000000, result = 22.805440
[   13s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   13s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   13s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   13s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   13s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   13s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   13s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   13s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   13s] error: Test failed: <unittest.runner.TextTestResult run=475 errors=0 failures=1>
[   13s] error: Bad exit status from /var/tmp/rpm-tmp.AestvU (%check)
@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 25, 2018

Can you modify the format strings to be %2.12f?

@mcepl

This comment has been minimized.

Copy link
Author

commented Aug 25, 2018

With patch just adding printf() on the top of 4.4.0 I get:

[   13s] 
[   13s] ======================================================================
[   13s] ERROR: persistent.tests.test_docs (unittest.loader.ModuleImportFailure)
[   13s] ----------------------------------------------------------------------
[   13s] ImportError: Failed to import test module: persistent.tests.test_docs
[   13s] Traceback (most recent call last):
[   13s]   File "/usr/lib64/python2.7/unittest/loader.py", line 254, in _find_tests
[   13s]     module = self._get_module_from_name(name)
[   13s]   File "/usr/lib64/python2.7/unittest/loader.py", line 232, in _get_module_from_name
[   13s]     __import__(name)
[   13s]   File "/home/abuild/rpmbuild/BUILD/persistent-4.4.0/persistent/tests/test_docs.py", line 30, in <module>
[   13s]     import manuel.capture
[   13s] ImportError: No module named manuel.capture
[   13s] 
[   13s] 
[   13s] ----------------------------------------------------------------------
[   13s] Ran 515 tests in 0.336s
[   13s] 
[   13s] FAILED (errors=1)
[   13s] Test failed: <unittest.runner.TextTestResult run=515 errors=1 failures=0>
[   13s] 0013970, result = 48.679999946617
[   13s] DEBUG: v = 3485365957, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.689999948256
[   13s] DEBUG: v = 3486081785, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.699999949895
[   13s] DEBUG: v = 3486797613, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.709999951534
[   13s] DEBUG: v = 3487513440, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.719999939203
[   13s] DEBUG: v = 3488229268, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.729999940842
[   13s] DEBUG: v = 3488945096, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.739999942482
[   13s] DEBUG: v = 3489660924, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.749999944121
[   13s] DEBUG: v = 3490376752, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.759999945760
[   13s] DEBUG: v = 3491092580, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.769999947399
[   13s] DEBUG: v = 3491808408, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.779999949038
[   13s] DEBUG: v = 3492524236, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.789999950677
[   13s] DEBUG: v = 3493240064, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.799999952316
[   13s] DEBUG: v = 3493955891, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.809999939986
[   13s] DEBUG: v = 3494671719, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.819999941625
[   13s] DEBUG: v = 3495387547, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.829999943264
[   13s] DEBUG: v = 3496103375, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.839999944903
[   13s] DEBUG: v = 3496819203, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.849999946542
[   13s] DEBUG: v = 3497535031, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.859999948181
[   13s] DEBUG: v = 3498250859, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.869999949820
[   13s] DEBUG: v = 3498966687, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.879999951459
[   13s] DEBUG: v = 3499682514, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.889999939129
[   13s] DEBUG: v = 3457448669, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.299999940209
[   13s] DEBUG: v = 3458164497, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.309999941848
[   13s] DEBUG: v = 3458880325, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.319999943487
[   13s] DEBUG: v = 3459596153, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.329999945126
[   13s] DEBUG: v = 3460311981, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.339999946766
[   13s] DEBUG: v = 3461027809, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.349999948405
[   13s] DEBUG: v = 3461743637, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.359999950044
[   13s] DEBUG: v = 3462459465, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.369999951683
[   13s] DEBUG: v = 3463175292, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.379999939352
[   13s] DEBUG: v = 3463891120, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.389999940991
[   13s] DEBUG: v = 3464606948, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.399999942631
[   13s] DEBUG: v = 3465322776, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.409999944270
[   13s] DEBUG: v = 3466038604, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.419999945909
[   13s] DEBUG: v = 3466754432, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.429999947548
[   13s] DEBUG: v = 3467470260, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.439999949187
[   13s] DEBUG: v = 3468186088, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.449999950826
[   13s] DEBUG: v = 3468901915, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.459999938495
[   13s] DEBUG: v = 3469617743, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.469999940135
[   13s] DEBUG: v = 3470333571, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.479999941774
[   13s] DEBUG: v = 3471049399, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.489999943413
[   13s] DEBUG: v = 0, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 0.000000000000
[   13s] DEBUG: v = 0, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 0.000000000000
[   13s] DEBUG: v = 0, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 0.000000000000
[   13s] DEBUG: v = 0, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 0.000000000000
[   13s] DEBUG: v = 1632476982, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 22.805439988151
[   13s] error: Test failed: <unittest.runner.TextTestResult run=515 errors=1 failures=0>
[   13s] error: Bad exit status from /var/tmp/rpm-tmp.cEmlxZ (%check)

Full build log

@mcepl

This comment has been minimized.

Copy link
Author

commented Aug 25, 2018

Not completely. Passes under python2, but not under python3:

[   14s] 
[   14s] ======================================================================
[   14s] FAIL: test_strs_equal (persistent.tests.test_timestamp.PyAndCComparisonTests)
[   14s] ----------------------------------------------------------------------
[   14s] Traceback (most recent call last):
[   14s]   File "/home/abuild/rpmbuild/BUILD/persistent-4.4.1/persistent/tests/test_timestamp.py", line 252, in test_strs_equal
[   14s]     self.assertEqual(str(c), str(py))
[   14s] AssertionError: '2008-12-22 15:20:-11.700000' != '2008-12-22 15:20:48.300000'
[   14s] - 2008-12-22 15:20:-11.700000
[   14s] ?                  ^^^ ^
[   14s] + 2008-12-22 15:20:48.300000
[   14s] ?                  ^^ ^
[   14s] 
[   14s] 
[   14s] ----------------------------------------------------------------------
[   14s] Ran 524 tests in 0.322s
[   14s] 
[   14s] FAILED (failures=1)
[   14s] Test failed: <unittest.runner.TextTestResult run=524 errors=0 failures=1>
[   14s] DEBUG: v = 438334110, TS_SECOND_BYTES_BIAS = 0.000000, result = 6.123457
[   14s] DEBUG: v = 465288123, TS_SECOND_BYTES_BIAS = 0.000000, result = 6.500000
[   14s] DEBUG: v = 468867263, TS_SECOND_BYTES_BIAS = 0.000000, result = 6.550000
[   14s] DEBUG: v = 469225177, TS_SECOND_BYTES_BIAS = 0.000000, result = 6.555000
[   14s] DEBUG: v = 469260968, TS_SECOND_BYTES_BIAS = 0.000000, result = 6.555500
[   14s] DEBUG: v = 469264547, TS_SECOND_BYTES_BIAS = 0.000000, result = 6.555550
[   14s] DEBUG: v = 469264905, TS_SECOND_BYTES_BIAS = 0.000000, result = 6.555555
[   14s] DEBUG: v = 469264941, TS_SECOND_BYTES_BIAS = 0.000000, result = 6.555555
[   14s] DEBUG: v = 469264944, TS_SECOND_BYTES_BIAS = 0.000000, result = 6.555556
[   14s] DEBUG: v = 469264945, TS_SECOND_BYTES_BIAS = 0.000000, result = 6.555556
[   14s] DEBUG: v = 3457448669, TS_SECOND_BYTES_BIAS = 0.000000, result = -11.700000
[   14s] DEBUG: v = 0, TS_SECOND_BYTES_BIAS = 0.000000, result = 0.000000
[   14s] DEBUG: v = 0, TS_SECOND_BYTES_BIAS = 0.000000, result = 0.000000
[   14s] DEBUG: v = 0, TS_SECOND_BYTES_BIAS = 0.000000, result = 0.000000
[   14s] DEBUG: v = 0, TS_SECOND_BYTES_BIAS = 0.000000, result = 0.000000
[   14s] DEBUG: v = 1632476982, TS_SECOND_BYTES_BIAS = 0.000000, result = 22.805440
[   14s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   14s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   14s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   14s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   14s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   14s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   14s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   14s] DEBUG: v = 1968526677, TS_SECOND_BYTES_BIAS = 0.000000, result = 27.500000
[   14s] error: Test failed: <unittest.runner.TextTestResult run=524 errors=0 failures=1>
[   14s] error: Bad exit status from /var/tmp/rpm-tmp.6fty47 (%check)
[   14s]

osc-build-log.txt

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 25, 2018

Interesting. That function and the interior printing does not use the Python API at all. So I think we're looking at a difference in the compiler and/or compiler flags. (Could we see that output with the %2.12f format?)

@mcepl

This comment has been minimized.

Copy link
Author

commented Aug 25, 2018

Here you are.

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 25, 2018

Thanks!

The failing line:

DEBUG: v = 3457448669, TS_SECOND_BYTES_BIAS = 0.000000013970, result = -11.700000059791

A successful line from earlier in the file:

DEBUG: v = 3458880325, TS_SECOND_BYTES_BIAS = 0.000000013970, result = 48.319999943487

The TS_SECOND_BYTES_BIAS value is correct. Both of the v values need 32 bits and begin with 0b110011..... So two very close values are yielding very different results.

Here's the bad (-11) value in binary:

11000000 00100111 01100110 01100110 01101000 01101000 00000000 00110011

And the correct (48.2999) value in binary:

01000000 01001000 00100110 01100110 01100101 11100101 11111111 11110011

If there's some pattern in the difference, I don't see it.

The compiler args for 2.7 (edited to remove duplicates):

gcc -pthread -fno-strict-aliasing -fmessage-length=0 -grecord-gcc-switches -O2 -Wall -D_FORTIFY_SOURCE=2 -fstack-protector-strong -funwind-tables -fasynchronous-unwind-tables -fstack-clash-protection -g -DNDEBUG  -DOPENSSL_LOAD_CONF -fwrapv -fPIC -I/usr/include/python2.7 -c persistent/_timestamp.c -o build/temp.linux-x86_64-2.7/persistent/_timestamp.o
[   15s] gcc -pthread -shared build/temp.linux-x86_64-2.7/persistent/_timestamp.o -L/usr/lib64 -lpython2.7 -o build/lib.linux-x86_64-2.7/persistent/_timestamp.so

And 3.6:

 gcc -pthread -Wno-unused-result -Wsign-compare -DNDEBUG -fmessage-length=0 -grecord-gcc-switches -O2 -Wall -D_FORTIFY_SOURCE=2 -fstack-protector-strong -funwind-tables -fasynchronous-unwind-tables -fstack-clash-protection -g -DOPENSSL_LOAD_CONF -g   -fPIC -I/usr/include/python3.6m -c persistent/_timestamp.c -o build/temp.linux-x86_64-3.6/persistent/_timestamp.o
[   17s] gcc -pthread -shared -flto -fuse-linker-plugin -ffat-lto-objects -flto-partition=none build/temp.linux-x86_64-3.6/persistent/_timestamp.o -L/usr/lib64 -lpython3.6m -o build/lib.linux-x86_64-3.6/persistent/_timestamp.cpython-36m-x86_64-linux-gnu.so

Two major things are different that I notice:

  1. Under 2.7, the argument -fwrapv is given, which "instructs the compiler to assume that signed arithmetic overflow of addition, subtraction and multiplication wraps around using twos-complement representation. This flag enables some optimizations and disables others." 3.6 does not have that option. I don't think we'd be hitting that case, but maybe? It should be pretty easy to compile 3.6 with "-fwrapv" by setting CFLAGS if you want to try that.
  2. 3.6 is being linked with LTO, while 2.7 is not. That could change things, though I would think it unlikely. (Then again, I would have thought this whole scenario is unlikely.)
@mgedmin

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

>>> (3457448669 - 2**32) * 0.000000013970
-11.70013521919

which is close to -11.700000059791, but not exact, so maybe SCONV is not precisely 0.000000013970?

Yeah:

>>> >>> 60.0 / (1<<16) / (1<<16)
1.3969838619232178e-08

>>> (3457448669 - 2**32) * (60.0 / 2**32)
-11.70000005979091

(still, how on Earth do you get a 32-bit overflow on a 64-bit machine with 64-bit types?)

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

Depending on the compiler and options, double can be using the Intel x86 math unit, which internally uses 80-bit precision. Or it can be using the SSE instructions, which have variants that specify precision (and 'single' and 'double' mean what you think they do).

On my machine, gcc 8 with -O2 -march=native generates SSE (actually AVX, I think) code, something like this:

double convert(unsigned int v)
{
    return v * TS_SECOND_BYTES_BIAS;
}
_convert:
	movl	%edi, %edi
	vxorps	%xmm0, %xmm0, %xmm0 ; zero xmm0
	vmovss	lC1(%rip), %xmm1 ; Copy in TS_BYTES_BIAS?
	vcvtsi2ssq	%rdi, %xmm0, %xmm0 ; convert `v` to a single precision float
	vmulss	lC0(%rip), %xmm0, %xmm0 ; multiply SINGLE PRECISION
	vmulss	%xmm1, %xmm0, %xmm0
	vmulss	%xmm1, %xmm0, %xmm0
	vcvtss2sd	%xmm0, %xmm0, %xmm0 ;  Convert Scalar Single-Precision Floating-Point Value to Scalar Double-Precision Floating-Point Value
	ret

Interestingly, vmulss is defined as "single precision", and the last step of the process widens from single precision to double precision. If I don't use -march=native, I get the plain SSE instructions, mulss and cvtss2sd. Either way, I still get the correct result.

I would be curious to see the code the compiler is generating here. @mcepl can you provide the timestamp.o file from your Python 3.6 build? (EDIT: Even better would be to run the compiler command from above, but add -S to get the .s assembler file and send that.)

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

WHOOPS: Above, I had TS_SECOND_BYTES_BIAS defined as ((float)60) / ((float)(1<<16)) / ((float)(1<<16)), which explains the single precision. If I redefine it as it is in timestamp.c (#define TS_SECOND_BYTES_BIAS ((double)60) / ((double)(1<<16)) / ((double)(1<<16))), I get the expected double precision instructions (still though, I got the expected result using single precision)

_convert:
LFB4:
	movl	%edi, %edi
	pxor	%xmm0, %xmm0
	movsd	lC1(%rip), %xmm1
	cvtsi2sdq	%rdi, %xmm0
	mulsd	lC0(%rip), %xmm0
	mulsd	%xmm1, %xmm0
	mulsd	%xmm1, %xmm0
	ret
@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

maybe SCONV is not precisely 0.000000013970?

It's not. Printing 24 bits of precision shows 0.000000013969838619232178 and

>>> (3457448669 - 2**32) * 0.000000013969838619232178
-11.70000005979091
@mgedmin

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

So, objdump -d ./build/lib.linux-x86_64-2.7/persistent/_timestamp.so gives me

0000000000001410 <TimeStamp_second>:
    1410:	0f b6 47 14          	movzbl 0x14(%rdi),%eax
    1414:	0f b6 57 15          	movzbl 0x15(%rdi),%edx
    1418:	66 0f ef c0          	pxor   %xmm0,%xmm0
    141c:	c1 e0 08             	shl    $0x8,%eax
    141f:	01 d0                	add    %edx,%eax
    1421:	0f b6 57 16          	movzbl 0x16(%rdi),%edx
    1425:	c1 e0 08             	shl    $0x8,%eax
    1428:	01 d0                	add    %edx,%eax
    142a:	0f b6 57 17          	movzbl 0x17(%rdi),%edx
    142e:	c1 e0 08             	shl    $0x8,%eax
    1431:	01 d0                	add    %edx,%eax
    1433:	f2 48 0f 2a c0       	cvtsi2sd %rax,%xmm0
    1438:	f2 0f 59 05 98 0c 00 	mulsd  0xc98(%rip),%xmm0        # 20d8 <month_len+0x1c8>
    143f:	00 
    1440:	e9 bb fa ff ff       	jmpq   f00 <PyFloat_FromDouble@plt>
    1445:	90                   	nop
    1446:	66 2e 0f 1f 84 00 00 	nopw   %cs:0x0(%rax,%rax,1)
    144d:	00 00 00 

(as you can see, the TimeStamp_sec was inlined). AFAIU all the 32-bit operations on %eax implicitly zero-extend the results to full 64-bits in %rax, so there's no possibility of overflow in this function as compiled by my compliler.

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

I get very similar results on macOS with both clang (the default compiler) and gcc 8 with no CFLAGS; if I use my usual optimizing CFLAGS, I get the AVX variants instead of the SSE instructions.

@mgedmin

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

I couldn't find how to download any of the built binary RPMs from https://build.opensuse.org/package/show/devel:languages:python/python-persistent, so I tried

docker run -ti --rm opensuse bash
$ zypper install python-persistent binutils  # got me a build of persistent 4.0.9
$ objdump -d /usr/lib64/python2.7/site-packages/persistent/_timestamp.so
...

and ... there are no symbols??? so it's basically gibberish, but I see a familiar sequence of instructions (easier to find if you search for FromDouble):

Disassembly of section .text:

0000000000001130 <TimeStamp_FromString@@Base-0x820>:
...
    1550:	0f b6 47 14          	movzbl 0x14(%rdi),%eax
    1554:	0f b6 57 15          	movzbl 0x15(%rdi),%edx
    1558:	c1 e0 08             	shl    $0x8,%eax
    155b:	01 d0                	add    %edx,%eax
    155d:	0f b6 57 16          	movzbl 0x16(%rdi),%edx
    1561:	c1 e0 08             	shl    $0x8,%eax
    1564:	01 d0                	add    %edx,%eax
    1566:	0f b6 57 17          	movzbl 0x17(%rdi),%edx
    156a:	c1 e0 08             	shl    $0x8,%eax
    156d:	01 d0                	add    %edx,%eax
    156f:	f2 48 0f 2a c0       	cvtsi2sd %rax,%xmm0
    1574:	f2 0f 59 05 5c 0c 00 	mulsd  0xc5c(%rip),%xmm0        # 21d8 <_fini@@Base+0x23c>
    157b:	00 
    157c:	e9 ef fa ff ff       	jmpq   1070 <PyFloat_FromDouble@plt>

Perhaps if I figured out how to docker pull the latest OpenSuSE Tumbleweed instead of whatever-it-is-that-I-got then I could see the assembly of a buggy python-persistent build?

@mgedmin

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

Same from docker run -ti --rm opensuse/tumbleweed bash:

    15d0:	0f b6 47 14          	movzbl 0x14(%rdi),%eax
    15d4:	0f b6 57 15          	movzbl 0x15(%rdi),%edx
    15d8:	66 0f ef c0          	pxor   %xmm0,%xmm0
    15dc:	c1 e0 08             	shl    $0x8,%eax
    15df:	01 d0                	add    %edx,%eax
    15e1:	0f b6 57 16          	movzbl 0x16(%rdi),%edx
    15e5:	c1 e0 08             	shl    $0x8,%eax
    15e8:	01 d0                	add    %edx,%eax
    15ea:	0f b6 57 17          	movzbl 0x17(%rdi),%edx
    15ee:	c1 e0 08             	shl    $0x8,%eax
    15f1:	01 d0                	add    %edx,%eax
    15f3:	f2 48 0f 2a c0       	cvtsi2sd %rax,%xmm0
    15f8:	f2 0f 59 05 18 0c 00 	mulsd  0xc18(%rip),%xmm0        # 2218 <_fini@@Base+0x32c>
    15ff:	00 
    1600:	e9 8b fa ff ff       	jmpq   1090 <PyFloat_FromDouble@plt>
@mgedmin

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

And here's objdump -d /usr/lib64/python3.6/site-packages/persistent/_timestamp.cpython-36m-x86_64-linux-gnu.so (also Tumbleweed, python3-persistent version 4.3.0):

    25c0:	0f b6 47 14          	movzbl 0x14(%rdi),%eax
    25c4:	0f b6 57 15          	movzbl 0x15(%rdi),%edx
    25c8:	66 0f ef c0          	pxor   %xmm0,%xmm0
    25cc:	c1 e0 08             	shl    $0x8,%eax
    25cf:	01 d0                	add    %edx,%eax
    25d1:	0f b6 57 16          	movzbl 0x16(%rdi),%edx
    25d5:	c1 e0 08             	shl    $0x8,%eax
    25d8:	01 d0                	add    %edx,%eax
    25da:	0f b6 57 17          	movzbl 0x17(%rdi),%edx
    25de:	c1 e0 08             	shl    $0x8,%eax
    25e1:	01 d0                	add    %edx,%eax
    25e3:	f2 0f 2a c0          	cvtsi2sd %eax,%xmm0
    25e7:	f2 0f 59 05 29 0c 00 	mulsd  0xc29(%rip),%xmm0        # 3218 <_fini@@Base+0x350>
    25ee:	00 
    25ef:	e9 8c fa ff ff       	jmpq   2080 <PyFloat_FromDouble@plt>
@mgedmin

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

HEY HEY HEY HEY HEY HEEEEYYYYY SPOT THE DIFFERENCE!

    25e3:	f2 0f 2a c0          	cvtsi2sd %eax,%xmm0

This converts a 32-bit %eax, while all the others convert a 64-bit %rax.

BUG FOUND now somebody explain why it gets compiled this way?

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

Thanks for the tip about docker!

I can duplicate the error compiling the file from scratch in a docker image with the compiler args specified above.

If I add -fwrapv, what Python 2.7 compiles with by default, the error goes away. The offending line becomes cvtsi2sdq %rax, %xmm0.

EDIT: Indeed, -fwrapv changes cvtsi2sd %eax, %xmm0 into cvtsi2sdq %rax, %xmm1 in three different places: In TimeStamp_timeTime, TimeStamp_second (this case) and TimeStamp_str.

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

It's the -O2 that triggers it. Without -O2 (and without -fwrapv) the code is "correct".

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

Perhaps we should explicitly add -fwrapv to extra_compile_args for the timestamp extension when we're on Linux?

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 27, 2018

This is looking like it may be a packaging problem with python3 on opensuse itself.

CPython wants to have -fwrapv in its build by default. But, if I'm looking at the right place, the RPM for building CPython on opensuse exports $OPT (line 282) and overrides this check entirely. So unless the RPM variable optflags already has -fwrapv in it, the build of python itself and all its extension modules won't have -fwrapv and will thus be subtlety broken. I don't know where to look for the definition of that variable.

@mgedmin

This comment has been minimized.

Copy link
Member

commented Aug 28, 2018

I've reproduced the miscompilation on https://godbolt.org/z/HtYwXC

Note that if I replace the multiplication by 0x100 etc. with << 8 etc, the code gets compiled correctly.

I think when you multiply an unsigned char by an int constant like 0x1000000, you get an int, and not an unsigned.

So, it's a bug in our code and not a compiler bug.

If I change the constants to have U suffixes like 0x1000000U, the cvtsi2sdq gets %rax again instead of %eax.

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 28, 2018

But in our code, they are not int constants. They are explicitly cast as doubles, and the compiler uses double-precision instructions for that expression. If they are cast as floats, the compiler uses single-precision instructions and then widens to double (see this comment ).

@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 28, 2018

Indeed, if i change the definition of TS_SECOND_BYTES_BIAS to an explicit double constant with the value we expect it to have:

static const double TS_SECOND_BYTES_BIAS =  0.000000013969838619232178;

The code is still miscompiled when given -O2 and not given -fwrapv:

_TimeStamp_second:
LFB87:
	movzbl	20(%rdi), %eax
	pxor	%xmm0, %xmm0
	movzbl	21(%rdi), %edx
	sall	$8, %eax
	addl	%edx, %eax
	movzbl	22(%rdi), %edx
	sall	$8, %eax
	addl	%edx, %eax
	movzbl	23(%rdi), %edx
	sall	$8, %eax
	addl	%edx, %eax
	cvtsi2sd	%eax, %xmm0 ; Still EAX
	mulsd	lC3(%rip), %xmm0
	jmp	_PyFloat_FromDouble
@jamadden

This comment has been minimized.

Copy link
Member

commented Aug 28, 2018

If I remove the static const part so the compiler has to look up the variable, we can see for sure that that the mistake is happening well before the actual multiplication; it's happening in the inlined arithmetic that unpacks the bytes into an unsigned int (and now I think I see what you were saying above, I was thinking about a different constant than you were)

_TimeStamp_second:
LFB87:
	movzbl	20(%rdi), %eax
	pxor	%xmm0, %xmm0
	movzbl	21(%rdi), %edx
	sall	$8, %eax
	addl	%edx, %eax
	movzbl	22(%rdi), %edx
	sall	$8, %eax
	addl	%edx, %eax
	movzbl	23(%rdi), %edx
	sall	$8, %eax
	addl	%edx, %eax
	cvtsi2sd	%eax, %xmm0
	mulsd	_TS_SECOND_BYTES_BIAS(%rip), %xmm0
	jmp	_PyFloat_FromDouble

Sure enough, changing the constants used in TS_UNPACK_UINT32_FROM_BYTES to have the U suffix does change the register usage:

_TimeStamp_second:
LFB87:
	movzbl	20(%rdi), %eax
	pxor	%xmm0, %xmm0
	movzbl	21(%rdi), %edx
	sall	$8, %eax
	addl	%edx, %eax
	movzbl	22(%rdi), %edx
	sall	$8, %eax
	addl	%edx, %eax
	movzbl	23(%rdi), %edx
	sall	$8, %eax
	addl	%edx, %eax
	cvtsi2sdq	%rax, %xmm0
	mulsd	_TS_SECOND_BYTES_BIAS(%rip), %xmm0
	jmp	_PyFloat_FromDouble

I would have sworn that hex literals were unsigned by default, I thought I looked that up before I made the change, but it seems that's not true.

jamadden added a commit that referenced this issue Aug 28, 2018

Explicitly use unsigned hex literals when [un]packing timestamps.
This should fix #86

Run a compiler with wrapv turned off to verify this.

@jamadden jamadden closed this in #91 Aug 28, 2018

@mgedmin

This comment has been minimized.

Copy link
Member

commented Aug 28, 2018

Heh, yeah, sorry for not being sufficiently explicit.

clrpackages pushed a commit to clearlinux-pkgs/persistent that referenced this issue Aug 29, 2018

[update to 4.4.2] Explicitly use unsigned hex literals when [un]packi…
…ng timestamps.

Jason Madden (4):
      Back to development: 4.4.2
      Explicitly use unsigned hex literals when [un]packing timestamps.
      Merge pull request #91 from zopefoundation/issue86
      Preparing release 4.4.2

Marius Gedminas (2):
      Make test pass when run with 'tox'
      Merge pull request #90 from zopefoundation/fix-tox

4.4.2 (2018-08-28)
------------------

- Explicitly use unsigned constants for packing and unpacking C
  timestamps, fixing an arithmetic issue for GCC when optimizations
  are enabled and ``-fwrapv`` is *not* enabled. See `issue 86
  <https://github.com/zopefoundation/persistent/issues/86>`_.
@mcepl

This comment has been minimized.

Copy link
Author

commented Sep 3, 2018

But, if I'm looking at the right place, the RPM for building CPython on opensuse exports $OPT (line 282) and overrides this check entirely.

You are right. It is really strange, but CPython doesn't provide a configuration option to just add building option, you can just completely replace everything, so we had to add -fwrapv to our OPTS manually. Thank you very much, nobody was able to discover this packaging bug for quite some time we have it there.

@jamadden

This comment has been minimized.

Copy link
Member

commented Sep 4, 2018

Cool! For complete circular reference, here is the PR for the build change:
https://build.opensuse.org/request/show/632918

@mcepl

This comment has been minimized.

Copy link
Author

commented Sep 4, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.