Opened 13 years ago

Closed 13 years ago

#4366 closed defect (fixed)

[with patch, positive review] sys.path is searched ("stat"ed) for *.pyx-files insanely often

Reported by: GeorgSWeber Owned by: GeorgSWeber
Priority: major Milestone: sage-3.2
Component: coercion Keywords:
Cc: robertwb Merged in:
Authors: Reviewers:
Report Upstream: Work issues:
Branch: Commit:
Dependencies: Stopgaps:

Status badges

Description

Hi, Emmanuel Thomé noted that there is a speed/system call activity regression in between Sage 3.0.5 and 3.1.3. If in Sage 3.1.3/3.1.4/3.2.alpha0 one issues something like

sage: time for i in range(10): float(1)/2

and looks at the same at the system call activity of this python "sage.bin" process (in another terminal with something like "strace -p 'pidof sage.bin' -e trace='stat'" under Linux, or using "sudo fs_usage 4711" under Mac OS X, 4711 being the sage.bin pid gotten e.g. via the activity tool), then one sees:

The (sage/python) sys.path is searched by the system call "stat" for "coerce.pyx", "coerce_maps.pyx", "parent.pyx" and "integer.pyx" many times, that whole path, and over and over again.

This does not happen under Sage 3.0.5.

Willem Jan Palenstijn proposed this code fragment, which triggers the behaviour in Sage 3.2.alpha0, too:

sage: cm=sage.structure.element.get_coercion_model()
sage: cm.canonical_coercion(float(1),1)

and noted that

"This seems to be the _record_exception() function in the coercion model."

(See also the recent sage_devel thread started by Emmanuel Thomé about this.)

Attachments (3)

sagetrac-4366-first.patch (6.0 KB) - added by GeorgSWeber 13 years ago.
4366-coercion-traceback.patch (5.3 KB) - added by robertwb 13 years ago.
apply this patch only
4366-coercion-traceback-fixed.patch (5.5 KB) - added by GeorgSWeber 13 years ago.
apply this patch only

Download all attachments as: .zip

Change History (18)

comment:1 Changed 13 years ago by GeorgSWeber

  • Owner changed from somebody to GeorgSWeber

comment:2 Changed 13 years ago by GeorgSWeber

  • Status changed from new to assigned

I know now how to change the code so that when we had before:

sage: time for i in range(10^4): float(1)/2
CPU times: user 17.72 s, sys: 13.44 s, total: 31.16 s
Wall time: 31.20 s

then after the changes we get:

sage: time for i in range(10^4): float(1)/2
CPU times: user 0.37 s, sys: 0.00 s, total: 0.37 s
Wall time: 0.37 s

which is quite impressive, I think (the sys time is used up only by these insanely many calls to "stat")!

Essentially all one has to do is not to call "sys.exc_info()" in "_record_exception" (file: sage/structure/coerce.pyx) unless you really want to do so. But to fix that nicely (e.g. not leaving a broken doctest) will take me another evening or two.

comment:3 Changed 13 years ago by mabshoff

  • Cc robertwb added
  • Milestone changed from sage-3.2.1 to sage-3.2

Very, very nice. Any chance that RobertWB might have some clue here? I would really like to have this fixed in 3.2 :)

Cheers,

Michael

comment:4 Changed 13 years ago by robertwb

Coincidentally, I just responded to this thread on sage-devel. I'll repost here

Thanks for tracking this down. Just out of curiosity, how does one decide if one "really wants to." Ideally one could snapshot the traceback without touching every file involved.

BTW, using RDF rather than float will be 10x faster in this case even after your speedup.

sage: sage: time for i in range(10^4): RDF(1)/2
CPU times: user 0.03 s, sys: 0.00 s, total: 0.03 s
Wall time: 0.03 s

- Robert

The point is that when something goes wrong, one wants to be able to ask "what happened" which is why these tracebacks are stored. Re-running the command may not give you all the information because of the caching involved. Is there a better way to get the traceback information than invoking sys.exc_info?

Changed 13 years ago by GeorgSWeber

comment:5 Changed 13 years ago by GeorgSWeber

  • Summary changed from sys.path is searched ("stat"ed) for *.pyx-files insanely often to [with patch, needs work] sys.path is searched ("stat"ed) for *.pyx-files insanely often

comment:6 Changed 13 years ago by GeorgSWeber

Oops, I had cached this page in my browser so your point about caching completely went past me up to now.

Hmmmmmm.

My first feeling about this that whenever one gets a such failure, it is important to be able to reproduce it. If so, then this means you can "rerun" the code. If not, then you are hunting some "sporadic" phantom. In that case, one should have "enabled the exception stack" all the time.

But for everyday usage of Sage, it might be allowable to have this feature disabled, considering its costs.

Cheers, gsw

comment:7 follow-up: Changed 13 years ago by robertwb

The coercion model caching what the right action is is essential to its speed, so the behavior remains the same but it remembers to not go down (all) the failed code paths the next time around. The only exceptions are float+ZZ and float+QQ. There's a ticket to handle these better.

One should be able to cache the exceptions *without* stating every file in the path, and I think this is what we should do.

comment:8 in reply to: ↑ 7 Changed 13 years ago by mabshoff

Replying to robertwb:

The coercion model caching what the right action is is essential to its speed, so the behavior remains the same but it remembers to not go down (all) the failed code paths the next time around. The only exceptions are float+ZZ and float+QQ. There's a ticket to handle these better.

Which ticket would that be?

One should be able to cache the exceptions *without* stating every file in the path, and I think this is what we should do.

I agree. The patch might solve the problem, but Robert's suggestion to solve the problem should be preferred.

Cheers,

Michael

Changed 13 years ago by robertwb

apply this patch only

comment:9 Changed 13 years ago by robertwb

  • Summary changed from [with patch, needs work] sys.path is searched ("stat"ed) for *.pyx-files insanely often to [with patch, needs review] sys.path is searched ("stat"ed) for *.pyx-files insanely often

As it turns out, it's the formating of the exceptions that's expensive, not the call to sys.exc_info. This is good news for us, as we can defer that to later. See attached patch.

comment:10 Changed 13 years ago by robertwb

The aforementioned tickets would be #3938 and #2898

comment:11 Changed 13 years ago by GeorgSWeber

Excellent! And this is how solutions evolve:

  1. primitive (just comment out the last line of _record_exception)
  2. complicated (my patch)
  3. simple (Robert's patch)

I have to go to work now, but I'll try hard to run and review the patch this evening. (It looks perfect at first sight.)

Cheers, gsw

comment:12 Changed 13 years ago by mabshoff

With RobertWB's patch applied I am seeing one easy to fix doctest failure:

mabshoff@sage:/scratch/mabshoff/release-cycle/sage-3.2.alpha2$ ./sage -t -long devel/sage/sage/structure/coerce.pyx
sage -t -long devel/sage/sage/structure/coerce.pyx          
**********************************************************************
File "/scratch/mabshoff/release-cycle/sage-3.2.alpha2/tmp/coerce.py", line 331:
    sage: cm.exception_stack()
Expected:
    [(<type 'exceptions.TypeError'>,  TypeError("no common canonical parent for objects with parents: 'Rational Field' and 'Finite Field of size 3'",),  <traceback object at ...>)]
Got:
    [(<type 'exceptions.TypeError'>, TypeError("BUG: the base_extend method must be defined for 'Monoid of ideals of Integer Ring' (class '<class 'sage.rings.ideal_monoid.IdealMonoid_c'>')",), <traceback object at 0x2b75e90e8ef0>), (<type 'exceptions.TypeError'>, TypeError("no common canonical parent for objects with parents: 'Rational Field' and 'Finite Field of size 3'",), <traceback object at 0x2b75fd781950>)]
**********************************************************************
1 items had failures:
   1 of  10 in __main__.example_9
***Test Failed*** 1 failures.
For whitespace errors, see the file /scratch/mabshoff/release-cycle/sage-3.2.alpha2/tmp/.doctest_coerce.py
	 [2.9 s]
exit code: 1024

comment:13 Changed 13 years ago by robertwb

Ah, yes. That fix is fine to make (I saw it on my end, but thought it was due to an earlier patch I had in my repo changing some stuff).

Changed 13 years ago by GeorgSWeber

apply this patch only

comment:14 Changed 13 years ago by GeorgSWeber

  • Summary changed from [with patch, needs review] sys.path is searched ("stat"ed) for *.pyx-files insanely often to [with patch, positive review] sys.path is searched ("stat"ed) for *.pyx-files insanely often

Yep, this does the job.

Since I had trouble to get hg / mercurial queues to produce me another patch on top of Robert's original patch (telling me "abort: cannot commit over an applied mq patch" in the course), I just hacked that single line to be fixed in Robert's patch and loaded up the result.

(I'll find out how to do it correctly as soon as I did send this comment ...)

@Robert:

Please take care with this hacked patch and your personal hg repo, the hacked patch still contains your original hg Node ID / parent strings ...

Cheers, gsw

comment:15 Changed 13 years ago by mabshoff

  • Resolution set to fixed
  • Status changed from assigned to closed

Merged 4366-coercion-traceback-fixed.patch in Sage 3.2.alpha2

Note: See TracTickets for help on using tickets.