classification
Title: MemoryError in test_strptime
Type: crash Stage: resolved
Components: Extension Modules Versions: Python 3.6, Python 3.5
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: steve.dower Nosy List: David.Edelsohn, belopolsky, eryksun, larry, python-dev, serhiy.storchaka, steve.dower, vstinner
Priority: release blocker Keywords: patch

Created on 2015-09-08 10:30 by serhiy.storchaka, last changed 2015-09-10 20:01 by steve.dower. This issue is now closed.

Files
File name Uploaded Description Edit
25029_1.patch steve.dower, 2015-09-08 15:35 review
Messages (20)
msg250177 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2015-09-08 10:30
All builds on edelsohn-fedora-ppc64 are red starting from build 55 for 3.x and build 41 for 3.5. 3.4 is green.
http://buildbot.python.org/all/builders/PPC64%20Fedora%203.x/builds/55/
http://buildbot.python.org/all/builders/PPC64%20Fedora%203.5/builds/41/

======================================================================
ERROR: test_TimeRE_recreation (test.test_strptime.CacheTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/shager/cpython-buildarea/3.5.edelsohn-fedora-ppc64/build/Lib/test/test_strptime.py", line 565, in test_TimeRE_recreation
    _strptime._strptime_time('10', '%d')
  File "/home/shager/cpython-buildarea/3.5.edelsohn-fedora-ppc64/build/Lib/_strptime.py", line 494, in _strptime_time
    tt = _strptime(data_string, format)[0]
  File "/home/shager/cpython-buildarea/3.5.edelsohn-fedora-ppc64/build/Lib/_strptime.py", line 312, in _strptime
    _TimeRE_cache = TimeRE()
  File "/home/shager/cpython-buildarea/3.5.edelsohn-fedora-ppc64/build/Lib/_strptime.py", line 190, in __init__
    self.locale_time = LocaleTime()
  File "/home/shager/cpython-buildarea/3.5.edelsohn-fedora-ppc64/build/Lib/_strptime.py", line 75, in __init__
    self.__calc_am_pm()
  File "/home/shager/cpython-buildarea/3.5.edelsohn-fedora-ppc64/build/Lib/_strptime.py", line 114, in __calc_am_pm
    am_pm.append(time.strftime("%p", time_tuple).lower())
MemoryError

----------------------------------------------------------------------
msg250190 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2015-09-08 12:28
Any clue here?  Is this unaligned access?
msg250192 - (view) Author: David Edelsohn (David.Edelsohn) * Date: 2015-09-08 12:35
PPC64 is not a strict alignment system.  The system is running a non-recent release of Fedora, so it could be a bad interaction with libc.
msg250197 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-09-08 13:30
I ran test_strptime & test_os with tracemalloc: test_os memory peak is higher than test_strptime memory peak (I ran the two tests independently). So the bug cannot be reproduce on my Fedora 22 (x86_64).
msg250199 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-09-08 13:40
Oh wait, the VmPeak is *much* high when running test_strptime:

* test_os VmPeak: 380 992 kB
* test_strptime VmPeak: 8 608 972 kB (8 GB!?)

1 GB should be enough for everybody:

$ bash -c 'ulimit -v 1000000; ./python -m test -v test_strptime'
..
======================================================================
ERROR: test_TimeRE_recreation (test.test_strptime.CacheTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  ...
  File "/home/haypo/prog/python/default/Lib/_strptime.py", line 75, in __init__
    self.__calc_am_pm()
  File "/home/haypo/prog/python/default/Lib/_strptime.py", line 114, in __calc_am_pm
    am_pm.append(time.strftime("%p", time_tuple).lower())
MemoryError
msg250201 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-09-08 13:48
It's a regression introduced by c31dad22c80d (Issue #24917).
msg250205 - (view) Author: Alexander Belopolsky (belopolsky) * (Python committer) Date: 2015-09-08 14:01
I would blame this change: <https://hg.python.org/cpython/rev/c31dad22c80d/#l3.41>.  The rest should not have any effect on Linux.
msg250206 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-09-08 14:10
Script to reproduce the issue:
---
import time
import locale
import pprint

time_tuple = time.struct_time((1999,3,17,1,44,55,2,76,0))

p1 = time.strftime("%p", time_tuple)
print("current LC_TIME", repr(p1))

locale.setlocale(locale.LC_TIME, ('de_DE', 'UTF8'))
p2 = time.strftime("%p", time_tuple)
print("de_DE (UTF8)", repr(p2))
---

Output:
---
$ python3.4 bug.py
current LC_TIME 'AM'
de_DE (UTF8) ''
---

The problem is that strftime()/wcsftime() *can* return 0, it's not an error. Whereas c31dad22c80d considers that if buflen is 0 but fmtlen is smaller than 5, we must retry with a larger buffer.
msg250207 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-09-08 14:13
Again, this issue remembers me the idea of rewriting strftime() in Python. We already have _strptime.py.
msg250212 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-09-08 15:14
Sorry Larry.

I'll fix it.
msg250215 - (view) Author: Eryk Sun (eryksun) * (Python triager) Date: 2015-09-08 15:25
Steve, it seems to me that for MSVC the EINVAL test should come first:
   
    _Py_BEGIN_SUPPRESS_IPH
    olderr = errno;
    errno = 0;
    buflen = format_time(outbuf, i, fmt, &buf);
    err = errno;
    errno = olderr;
    _Py_END_SUPPRESS_IPH
    
    if (buflen == 0 && err == EINVAL) {
        PyErr_SetString(PyExc_ValueError, "Invalid format string");
        break;
    }

Then the old test could be restored, i.e. (buflen > 0 || i >= 256 * fmtlen).
msg250219 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-09-08 15:35
@eryksun - that's exactly what I've just done :)

Unfortunately, I don't have a _locale module, so I can't do Victor's test. Attached my patch in case Victor is around to test it.
msg250225 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-09-08 15:44
My test runs the following command on Linux (Fedora 22):

make && bash -c 'ulimit -v 1000000; ./python -u -m test -v test_strptime' 

* current default branch (rev 3c0c153d6b02): MemoryError
* with 25029_1.patch: the test pass
msg250266 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-09-08 23:10
Thanks. I'll submit a PR for 3.5.0 later tonight - can't seem to clone Larry's repo successfully at work for some reason.
msg250271 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-09-09 02:14
PR at https://bitbucket.org/larry/cpython350/pull-requests/21/issue-25029-memoryerror-in-test_strptime/diff
msg250276 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2015-09-09 03:43
Does this need a Misc/NEWS entry?
msg250280 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-09-09 04:14
Probably should, since the fix that caused it was in for rc3. There's no section for 3.5.0 final yet though (that's my excuse, anyway :) )
msg250312 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2015-09-09 13:56
New changeset bd7aed300a1b by Steve Dower in branch '3.5':
Issue #25029: MemoryError in test_strptime
https://hg.python.org/cpython/rev/bd7aed300a1b

New changeset 706b9eaba734 by Steve Dower in branch '3.5':
Merge fix for #25029
https://hg.python.org/cpython/rev/706b9eaba734

New changeset cceaccb6ec5a by Steve Dower in branch '3.5':
Adds Mics/NEWS entry for issue #25029.
https://hg.python.org/cpython/rev/cceaccb6ec5a
msg250404 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-09-10 19:01
The test doesn't fail anymore on buildbots. I ran manually test_strptime with a memory limit of 1 GB on Python 3.5 and 3.6: the test pass.

Can we close the issue?
msg250416 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-09-10 20:01
Done.
History
Date User Action Args
2015-09-10 20:01:59steve.dowersetstatus: open -> closed
resolution: fixed
messages: + msg250416

stage: resolved
2015-09-10 19:01:35vstinnersetmessages: + msg250404
2015-09-09 13:56:38python-devsetnosy: + python-dev
messages: + msg250312
2015-09-09 04:14:39steve.dowersetmessages: + msg250280
2015-09-09 03:43:41larrysetmessages: + msg250276
2015-09-09 02:14:49steve.dowersetmessages: + msg250271
2015-09-08 23:10:27steve.dowersetmessages: + msg250266
2015-09-08 15:44:21vstinnersetmessages: + msg250225
2015-09-08 15:35:29steve.dowersetfiles: + 25029_1.patch
keywords: + patch
messages: + msg250219
2015-09-08 15:25:46eryksunsetnosy: + eryksun
messages: + msg250215
2015-09-08 15:15:28steve.dowerlinkissue24917 superseder
2015-09-08 15:14:18steve.dowersetpriority: normal -> release blocker
assignee: steve.dower
messages: + msg250212
2015-09-08 14:13:05vstinnersetmessages: + msg250207
2015-09-08 14:10:51vstinnersetmessages: + msg250206
2015-09-08 14:01:27belopolskysetnosy: + belopolsky
messages: + msg250205
2015-09-08 13:48:53vstinnersetnosy: + steve.dower
messages: + msg250201
2015-09-08 13:40:36vstinnersetmessages: + msg250199
2015-09-08 13:30:56vstinnersetnosy: + vstinner
messages: + msg250197
2015-09-08 12:35:56David.Edelsohnsetmessages: + msg250192
2015-09-08 12:28:35larrysetmessages: + msg250190
2015-09-08 10:30:13serhiy.storchakacreate