[issue7739] time.strftime may hung while trying to open /etc/localtime but does not release GIL
Doron Tal
report at bugs.python.org
Tue Jan 19 22:36:55 CET 2010
Doron Tal <doron.tal.list at gmail.com> added the comment:
We didn't prove this point yet, currently it's merely circumstantial.
The application calls strftime few dozen times each second from different
threads. We spot the stall using another two threads, the first takes a time
stamp before calling a python function and reset the time stamp when the
python function is done. The other thread watches the timestamp and if it
gets over a certain limit (2 seconds) it aborts the process, leaving a core
dump behind.
We've build this infrastructure to tackle python stalls caused by
misbehaving C calls which takes long but does not release the GIL.
Here is the traceback (one of the threads):
#0 0x0000003424ac5800 in __open_nocancel () from /lib64/libc.so.6
#1 0x0000003424a6c383 in __GI__IO_file_open () from /lib64/libc.so.6
#2 0x0000003424a6c43c in _IO_new_file_fopen () from /lib64/libc.so.6
#3 0x0000003424a61764 in __fopen_internal () from /lib64/libc.so.6
#4 0x0000003424a8d666 in __tzfile_read () from /lib64/libc.so.6
#5 0x0000003424a8c56f in tzset_internal () from /lib64/libc.so.6
#6 0x0000003424a8d010 in tzset () from /lib64/libc.so.6
#7 0x0000003424a91934 in strftime_l () from /lib64/libc.so.6
#8 0x00002aea01bced34 in ?? () from
/usr/lib64/python2.4/lib-dynload/timemodule.so
#9 0x00000034304360f0 in PyObject_Call () from
/usr/lib64/libpython2.4.so.1.0 #10 0x0000003430436bbc in PyObject_CallMethod
() from /usr/lib64/libpython2.4.so.1.0
#11 0x00002aea01dda64a in ?? () from
/usr/lib64/python2.4/lib-dynload/datetime.so
#12 0x00002aea01dda9c3 in ?? () from
/usr/lib64/python2.4/lib-dynload/datetime.so
#13 0x00000034304950ba in PyEval_EvalFrame () from
/usr/lib64/libpython2.4.so.1.0
#14 0x0000003430494b66 in PyEval_EvalFrame () from
/usr/lib64/libpython2.4.so.1.0
#15 0x0000003430495fe5 in PyEval_EvalCodeEx () from
/usr/lib64/libpython2.4.so.1.0
#16 0x000000343044c45a in ?? () from /usr/lib64/libpython2.4.so.1.0
#17 0x00000034304360f0 in PyObject_Call () from
/usr/lib64/libpython2.4.so.1.0
#18 0x000000343049352c in PyEval_EvalFrame () from
/usr/lib64/libpython2.4.so.1.0
#19 0x0000003430495fe5 in PyEval_EvalCodeEx () from
/usr/lib64/libpython2.4.so.1.0 #20 0x000000343044c45a in ?? () from
/usr/lib64/libpython2.4.so.1.0
#21 0x00000034304360f0 in PyObject_Call () from
/usr/lib64/libpython2.4.so.1.0
#22 0x000000343049352c in PyEval_EvalFrame () from
/usr/lib64/libpython2.4.so.1.0
#23 0x0000003430494b66 in PyEval_EvalFrame () from
/usr/lib64/libpython2.4.so.1.0
#24 0x0000003430495fe5 in PyEval_EvalCodeEx () from
/usr/lib64/libpython2.4.so.1.0
#25 0x000000343044c367 in ?? () from /usr/lib64/libpython2.4.so.1.0
#26 0x00000034304360f0 in PyObject_Call () from
/usr/lib64/libpython2.4.so.1.0
#27 0x000000343043c1ef in ?? () from /usr/lib64/libpython2.4.so.1.0
#28 0x00000034304360f0 in PyObject_Call () from
/usr/lib64/libpython2.4.so.1.0
#29 0x000000343048fc3d in PyEval_CallObjectWithKeywords () from
/usr/lib64/libpython2.4.so.1.0 #30 0x00000034304bbbbd in ?? () from
/usr/lib64/libpython2.4.so.1.0
#31 0x00000034256064a7 in start_thread () from /lib64/libpthread.so.0
#32 0x0000003424ad3c2d in clone () from /lib64/libc.so.6
So, we didn't actually proved that opening /etc/localtime takes so long. I
assumed that it is better to release the GIL prior to opening a file.
In any case, it won't solve our problem, since we use old Python 2.4.3
(CentOS5.4)...
--doron
On Tue, Jan 19, 2010 at 10:27 PM, Martin v. Löwis <report at bugs.python.org>wrote:
>
> Martin v. Löwis <martin at v.loewis.de> added the comment:
>
> I'd also be curious why it takes a second to open /etc/localtime. That
> sounds like a bug in the C library, or a mismanaged system.
>
> ----------
> nosy: +loewis
>
> _______________________________________
> Python tracker <report at bugs.python.org>
> <http://bugs.python.org/issue7739>
> _______________________________________
>
----------
Added file: http://bugs.python.org/file15954/unnamed
_______________________________________
Python tracker <report at bugs.python.org>
<http://bugs.python.org/issue7739>
_______________________________________
-------------- next part --------------
<div dir="ltr">We didn't prove this point yet, currently it's merely circumstantial.<br>The application calls strftime few dozen times each second from different threads. We spot the stall using another two threads, the first takes a time stamp before calling a python function and reset the time stamp when the python function is done. The other thread watches the timestamp and if it gets over a certain limit (2 seconds) it aborts the process, leaving a core dump behind.<br>
<br>We've build this infrastructure to tackle python stalls caused by misbehaving C calls which takes long but does not release the GIL.<br><br>Here is the traceback (one of the threads):<br><meta http-equiv="Content-Type" content="text/html; charset=utf-8"><meta name="ProgId" content="Word.Document"><meta name="Generator" content="Microsoft Word 12"><meta name="Originator" content="Microsoft Word 12"><link rel="File-List" href="file:///C:%5CDOCUME%7E1%5Cdoron.tal%5CLOCALS%7E1%5CTemp%5Cmsohtmlclip1%5C01%5Cclip_filelist.xml"><link rel="themeData" href="file:///C:%5CDOCUME%7E1%5Cdoron.tal%5CLOCALS%7E1%5CTemp%5Cmsohtmlclip1%5C01%5Cclip_themedata.thmx"><link rel="colorSchemeMapping" href="file:///C:%5CDOCUME%7E1%5Cdoron.tal%5CLOCALS%7E1%5CTemp%5Cmsohtmlclip1%5C01%5Cclip_colorschememapping.xml"><style>
<!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;
mso-font-alt:"Calisto MT";
mso-font-charset:0;
mso-generic-font-family:roman;
mso-font-pitch:variable;
mso-font-signature:-1610611985 1107304683 0 0 159 0;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;
mso-font-alt:"Century Gothic";
mso-font-charset:0;
mso-generic-font-family:swiss;
mso-font-pitch:variable;
mso-font-signature:-1610611985 1073750139 0 0 159 0;}
@font-face
{font-family:Consolas;
panose-1:2 11 6 9 2 2 4 3 2 4;
mso-font-charset:0;
mso-generic-font-family:modern;
mso-font-pitch:fixed;
mso-font-signature:-1610611985 1073750091 0 0 159 0;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{mso-style-unhide:no;
mso-style-qformat:yes;
mso-style-parent:"";
margin:0cm;
margin-bottom:.0001pt;
mso-pagination:widow-orphan;
font-size:11.0pt;
font-family:"Calibri","sans-serif";
mso-ascii-font-family:Calibri;
mso-ascii-theme-font:minor-latin;
mso-fareast-font-family:Calibri;
mso-fareast-theme-font:minor-latin;
mso-hansi-font-family:Calibri;
mso-hansi-theme-font:minor-latin;
mso-bidi-font-family:Arial;
mso-bidi-theme-font:minor-bidi;}
p.MsoPlainText, li.MsoPlainText, div.MsoPlainText
{mso-style-noshow:yes;
mso-style-priority:99;
mso-style-link:"Plain Text Char";
margin:0cm;
margin-bottom:.0001pt;
mso-pagination:widow-orphan;
font-size:10.5pt;
font-family:Consolas;
mso-fareast-font-family:Calibri;
mso-fareast-theme-font:minor-latin;
mso-bidi-font-family:Arial;
mso-bidi-theme-font:minor-bidi;}
span.PlainTextChar
{mso-style-name:"Plain Text Char";
mso-style-noshow:yes;
mso-style-priority:99;
mso-style-unhide:no;
mso-style-locked:yes;
mso-style-link:"Plain Text";
mso-ansi-font-size:10.5pt;
mso-bidi-font-size:10.5pt;
font-family:Consolas;
mso-ascii-font-family:Consolas;
mso-hansi-font-family:Consolas;}
.MsoChpDefault
{mso-style-type:export-only;
mso-default-props:yes;
mso-ascii-font-family:Calibri;
mso-ascii-theme-font:minor-latin;
mso-fareast-font-family:Calibri;
mso-fareast-theme-font:minor-latin;
mso-hansi-font-family:Calibri;
mso-hansi-theme-font:minor-latin;
mso-bidi-font-family:Arial;
mso-bidi-theme-font:minor-bidi;}
@page Section1
{size:612.0pt 792.0pt;
margin:72.0pt 90.0pt 72.0pt 90.0pt;
mso-header-margin:36.0pt;
mso-footer-margin:36.0pt;
mso-paper-source:0;}
div.Section1
{page:Section1;}
-->
</style>
<p class="MsoPlainText">#0<span style="">Â
</span>0x0000003424ac5800 in __open_nocancel () from /lib64/libc.so.6</p>
<p class="MsoPlainText">#1<span style="">Â
</span>0x0000003424a6c383 in __GI__IO_file_open () from /lib64/libc.so.6</p>
<p class="MsoPlainText">#2<span style="">Â
</span>0x0000003424a6c43c in _IO_new_file_fopen () from /lib64/libc.so.6</p>
<p class="MsoPlainText">#3<span style="">Â
</span>0x0000003424a61764 in __fopen_internal () from /lib64/libc.so.6</p>
<p class="MsoPlainText">#4<span style="">Â
</span>0x0000003424a8d666 in __tzfile_read () from /lib64/libc.so.6</p>
<p class="MsoPlainText">#5<span style="">Â
</span>0x0000003424a8c56f in tzset_internal () from /lib64/libc.so.6</p>
<p class="MsoPlainText">#6<span style="">Â
</span>0x0000003424a8d010 in tzset () from /lib64/libc.so.6</p>
<p class="MsoPlainText">#7<span style="">Â
</span>0x0000003424a91934 in strftime_l () from /lib64/libc.so.6</p>
<p class="MsoPlainText">#8<span style="">Â </span>0x00002aea01bced34
in ?? () from</p>
<p class="MsoPlainText">/usr/lib64/python2.4/lib-dynload/timemodule.so</p>
<p class="MsoPlainText">#9<span style="">Â
</span>0x00000034304360f0 in PyObject_Call () from
/usr/lib64/libpython2.4.so.1.0 #10 0x0000003430436bbc in PyObject_CallMethod ()
from /usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#11 0x00002aea01dda64a in ?? () from</p>
<p class="MsoPlainText">/usr/lib64/python2.4/lib-dynload/datetime.so</p>
<p class="MsoPlainText">#12 0x00002aea01dda9c3 in ?? () from</p>
<p class="MsoPlainText">/usr/lib64/python2.4/lib-dynload/datetime.so</p>
<p class="MsoPlainText">#13 0x00000034304950ba in PyEval_EvalFrame () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#14 0x0000003430494b66 in PyEval_EvalFrame () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#15 0x0000003430495fe5 in PyEval_EvalCodeEx () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#16 0x000000343044c45a in ?? () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#17 0x00000034304360f0 in PyObject_Call () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#18 0x000000343049352c in PyEval_EvalFrame () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#19 0x0000003430495fe5 in PyEval_EvalCodeEx () from
/usr/lib64/libpython2.4.so.1.0 #20 0x000000343044c45a in ?? () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#21 0x00000034304360f0 in PyObject_Call () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#22 0x000000343049352c in PyEval_EvalFrame () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#23 0x0000003430494b66 in PyEval_EvalFrame () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#24 0x0000003430495fe5 in PyEval_EvalCodeEx () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#25 0x000000343044c367 in ?? () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#26 0x00000034304360f0 in PyObject_Call () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#27 0x000000343043c1ef in ?? () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#28 0x00000034304360f0 in PyObject_Call () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#29 0x000000343048fc3d in PyEval_CallObjectWithKeywords
() from /usr/lib64/libpython2.4.so.1.0 #30 0x00000034304bbbbd in ?? () from
/usr/lib64/libpython2.4.so.1.0</p>
<p class="MsoPlainText">#31 0x00000034256064a7 in start_thread () from
/lib64/libpthread.so.0</p>
<p class="MsoPlainText">#32 0x0000003424ad3c2d in clone () from /lib64/libc.so.6</p>
<p class="MsoPlainText">Â </p>
So, we didn't actually proved that opening /etc/localtime takes so long. I assumed that it is better to release the GIL prior to opening a file.<br><br>In any case, it won't solve our problem, since we use old Python 2.4.3 (CentOS5.4)...<br>
<br>--doron<br><br><div class="gmail_quote">On Tue, Jan 19, 2010 at 10:27 PM, Martin v. Löwis <span dir="ltr"><<a href="mailto:report at bugs.python.org">report at bugs.python.org</a>></span> wrote:<br><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
<br>
Martin v. Löwis <<a href="mailto:martin at v.loewis.de">martin at v.loewis.de</a>> added the comment:<br>
<br>
I'd also be curious why it takes a second to open /etc/localtime. That sounds like a bug in the C library, or a mismanaged system.<br>
<br>
----------<br>
nosy: +loewis<br>
<div><div></div><div class="h5"><br>
_______________________________________<br>
Python tracker <<a href="mailto:report at bugs.python.org">report at bugs.python.org</a>><br>
<<a href="http://bugs.python.org/issue7739" target="_blank">http://bugs.python.org/issue7739</a>><br>
_______________________________________<br>
</div></div></blockquote></div><br></div>
More information about the Python-bugs-list
mailing list