Opened 5 years ago

Last modified 2 months ago

#10295 new enhancement

Upgrading pexpect

Reported by: SimonKing Owned by: was
Priority: major Milestone: sage-6.7
Component: interfaces Keywords: pexpect upgrade
Cc: drkirkby, leif, Vincent.Neri Merged in:
Authors: Reviewers:
Report Upstream: N/A Work issues:
Branch: u/fbissey/pexpect3.3 (Commits) Commit: 80cd29cee620bb62b53a389cff5f7db4aa65b2d6
Dependencies: Stopgaps:

Description (last modified by fbissey)

We use pexpect version 2.0. Shouldn't we upgrade to the current version 3.3?

This may be related with the performance problem reported at #10294.

See also #502.

New upstream tarball:
https://pypi.python.org/packages/source/p/pexpect/pexpect-3.3.tar.gz

Change History (72)

comment:1 Changed 5 years ago by fbissey

Try version 2.4 even. This has been discussed to death several times on sage-devel.
Version 2.1 and over are slower than what we currently have. Plus from experience
in sage-on-gentoo where at some stage we experimented with pexpect 2.4, some plotting broke down in the notebook.

comment:2 follow-up: Changed 5 years ago by fbissey

When I say version 2.4 you have to go there: http://pypi.python.org/pypi/pexpect
rather than here: http://pypi.python.org/pypi/pexpect

comment:3 in reply to: ↑ 2 Changed 5 years ago by SimonKing

Replying to fbissey:

When I say version 2.4 you have to go there: http://pypi.python.org/pypi/pexpect
rather than here: http://pypi.python.org/pypi/pexpect

Aren't the two links the same?

So, you say that there might be a performance problem with more recent versions of pexpect. That's bad, because the idea was to get rid of a performance problem by upgrading...

comment:4 Changed 5 years ago by fbissey

cut and paste didn't work as expected the second one was meant to be:
http://pexpect.sourceforge.net/

search the mailing list for pexpect, it is a proverbial can of worms.

comment:5 Changed 4 years ago by drkirkby

2.4 is not released yet. Here's a package for 2.3 that I created.

http://boxen.math.washington.edu/home/kirkby/patches/pexpect-2.3.spkg

but on my OpenSolaris machine, this 2.3 package results in one doctest failure, which is:

sage -t  -long -force_lib devel/sage/sage/interfaces/expect.py

The interface must be semi-working, as the interface to R works - or at lease the R doctest does not fail. Here's the error message of the failed doctest.

sage -t  -long -force_lib devel/sage/sage/interfaces/sage0.py
         [14.8 s]
sage -t  -long -force_lib devel/sage/sage/interfaces/expect.py
Exception pexpect.ExceptionPexpect: ExceptionPexpect() in <bound method spawn.__del__ of <pexpect.spawn object at 0xc5988ac>> ignored

<snip out load more similar errors>

<pexpect.spawn object at 0xc386d6c>> ignored
Exception pexpect.ExceptionPexpect: ExceptionPexpect() in <bound method spawn.__del__ of <pexpect.spawn object at 0xc386d6c>> ignored
**********************************************************************
File "/export/home/drkirkby/sage-4.7.alpha3/devel/sage-main/sage/interfaces/expect.py", line 867:
    sage: r._expect.before
Expected:
    'abc;\r\n[1] '
Got:
    'abc <- 10 +15;\r\n__SAGE__R__PROMPT__> abc;\r\n[1] '
**********************************************************************
1 items had failures:
   1 of  11 in __main__.example_16
***Test Failed*** 1 failures.
For whitespace errors, see the file /export/home/drkirkby/.sage//tmp/.doctest_expect.py
         [18.4 s]
sage -t  -long -force_lib devel/sage/sage/interfaces/gap.py
         [20.4 s]

I think in some cases where we call external programs there are probably better ways of doing this. For example

  • R has libraries, I expect we can call R via the libraries, rather than on the command line.
  • Mathematica uses the Mathlink protocol to communicate between the kernel and front end. How to use Mathlink is documented, and has been used by at least open-source program (JMath) to work with Mathematica. But Sage calls Mathematica via the command line.

Dave

comment:6 Changed 4 years ago by drkirkby

Oops, I see this doctest is related to R. But I'm sure there are other doctests which make use of pexpect, which are passing

Dave

comment:7 Changed 4 years ago by fbissey

While 2.4 is not on sourceforge but on pypi.python.org http://pypi.python.org/pypi/pexpect I think we can call it released unless you have other infos (from author/mailing list).
As far as I remember, last time we tried pexpect-2.4 on sage-on-gentoo it broke plotting in the notebook. Can you try to do some plotting in the notebook with this version of pexpect? Digged my email archive, more precisely:

g=sin(x); plot(g,(x,-pi,3*pi/2))

in the notebook. It produced the following for us (at the time, notice the python time stamp):

import os;os.chdir("/tmp/tmpo2KomY");
execfile("_sage_input_1.py")Python 2.6.4 (r264:75706, Mar  4 2010,
21:15:13)
[GCC 4.3.4] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> 
>>> import os;os.chdir("/tmp/tmpo2KomY");
>>> execfile("_sage_input_1.py")
START1

import os;os.chdir("/tmp/tmpY61yjM");
execfile("_sage_input_2.py")

import os;os.chdir("/tmp/tmpXjmsQK");
execfile("_sage_input_3.py")
__SAGE__
__SAGE__import os;os.chdir("/tmp/tmpY61yjM");
__SAGE__execfile("_sage_input_2.py")
START2
__SAGE__
__SAGE__import os;os.chdir("/tmp/tmpXjmsQK");

comment:8 Changed 4 years ago by fbissey

Dave, have you tried plotting in the notebook?

comment:9 Changed 4 years ago by leif

  • Cc leif added

comment:10 Changed 2 years ago by jdemeyer

  • Milestone changed from sage-5.11 to sage-5.12

comment:11 Changed 19 months ago by vbraun_spam

  • Milestone changed from sage-6.1 to sage-6.2

comment:12 Changed 17 months ago by fbissey

Bump this. There is a pexpect 3.1 now at http://pexpect.readthedocs.org/en/latest/ (note: the sourceforge address will redirect you there). For a long time I thought pexpect was done and there wouldn't be anymore release.

I think if the project is alive they may take request from us.

comment:13 Changed 16 months ago by vbraun_spam

  • Milestone changed from sage-6.2 to sage-6.3

comment:14 Changed 13 months ago by vbraun_spam

  • Milestone changed from sage-6.3 to sage-6.4

comment:15 Changed 12 months ago by rws

  • Description modified (diff)

comment:16 Changed 4 months ago by fbissey

  • Branch set to u/fbissey/pexpect3.3
  • Commit set to 9b1e0985e09c7181860d43f41f394cc23103ce1c
  • Description modified (diff)
  • Milestone changed from sage-6.4 to sage-6.7

comment:17 Changed 4 months ago by fbissey

Hum wrong stuff in that branch sorry will update shortly.

comment:18 Changed 4 months ago by git

  • Commit changed from 9b1e0985e09c7181860d43f41f394cc23103ce1c to 679e33af8315444f0080c98a45d7def4566bfbc1

Branch pushed to git repo; I updated commit sha1. New commits:

679e33aUpdate pexpect to 3.3

comment:19 Changed 4 months ago by git

  • Commit changed from 679e33af8315444f0080c98a45d7def4566bfbc1 to a24eab3ce985874ab8445ed5e362bbeead76fd40

Branch pushed to git repo; I updated commit sha1. New commits:

a24eab3Fix broken doctest. _expect.before returns more stuff in pexpect 3.3

comment:20 Changed 4 months ago by fbissey

The bad behavior in the notebook originates in sagenb/notebook/worksheet.py, this is potentially broken but the question is why don't we go there we the old pexpect?

comment:21 Changed 4 months ago by leif

Be aware that #17686 cleans up expect.py.

comment:22 Changed 4 months ago by fbissey

Seems to be orthogonal to the only change I made to that file. It'll just need rebasing. On the other hand there seem to be several load functions defined in sage. And it is not obvious why we should get that one in the notebook.

comment:23 Changed 4 months ago by bpage

https://github.com/billpage/sagenb/commit/811a2e762bb041dd34d32d96b003ab46eaab22e9

Here is a patch to sagenb/interfaces/expect.py that corrects the bad behavior in the notebook following upgrade to pexpect 3.3. The problem is due to a difference between pexpect 2.0 and newer versions of pexpect in what happens following a TIMEOUT of an expect; call. TIMEOUT is the intended result from a call to '_read'. In newer versions '_expect.before' is not modified by TIMEOUT so the output continues to accumulate. There is no need to do this ourselves in 'output_status'.

comment:25 follow-up: Changed 4 months ago by fbissey

Cool, I'll try that tomorrow morning. The next step will be performance measurements. One of the reason we hadn't moved to at least pexpect 2.4 was poor performance (sloooow). I would be willing to trade performance for something properly maintained but we should know what we are getting into on that front. Then again that TIMEOUT thing may have been the cause.

comment:26 in reply to: ↑ 25 Changed 4 months ago by leif

Replying to fbissey:

Then again that TIMEOUT thing may have been the cause.

The mentioned change was made in 2.3, but already 2.1 was said to be slooooooooow.

But we'll (or you'll) see...

comment:27 follow-up: Changed 4 months ago by bpage

I also doubt that this particular case of the use of TIMEOUT has anything to do with version 2.1 being slower. The problem here is how the notebook interacts with Sage in an asynchronous manner. TIMEOUT is the expected behavior when checking on the status of a computation. This allows notebook to display partial results, i.e. the output in 'self._so_far'. The notebook code treats TIMEOUT as a Python exception rather than waiting for it with a 'expect' pattern. In the old version of pexpect this exception did not update the '.before' attribute. On the other hand if the code was changed to explicitly look for 'pexpect.TIMEOUT' then we would have had this problem even with the old version.

What is the recommended way to measure Sage performance?

comment:28 in reply to: ↑ 27 Changed 4 months ago by leif

Replying to bpage:

What is the recommended way to measure Sage performance?

Good question, I can only talk about the command line interface:

Of course there's time ./sage -t --long src/sage/interfaces/ (probably with -p; one can also set SAGE_TEST_ITER and SAGE_TEST_GLOBAL_ITER). Only testing the interfaces that actually use pexpect (and where the external program is really installed) makes more sense.

Tests that make heavy use of (stand-alone) Maxima/ecl, Singular, gap and gp are meaningful as well. I cannot really list them right now, but src/sage/schemes/elliptic_curves/ and especially src/sage/sandpiles/sandpile.py are known to fall into that category IIRC.

Before testing, it IMHO makes sense to remove or rename $DOT_SAGE/timings*.json, otherwise doctests will get reordered with undesirable impact on the resource usage, influencing the measured timings.

comment:29 Changed 4 months ago by bpage

On my system with pexpect 3.x from github I get:

  wspage@suse:~/sage> inxi -SCI
  System:    Host: suse Kernel: 3.0.101-0.46-default x86_64 (64 bit) 
             Desktop Gnome 2.28.2 Distro: SUSE Linux Enterprise Server 11 (x86_64) VERSION = 11 PATCHLEVEL = 3
  CPU:       Quad core Intel Core i5-2500K CPU (-MCP-) cache: 6144 KB flags: (lm nx sse sse2 sse3 sse4_1 sse4_2 ssse3 vmx) 
             Clock Speeds: 1: 1600.00 MHz 2: 1600.00 MHz 3: 3301.00 MHz 4: 1600.00 MHz
  Info:      Processes: 245 Uptime: 67 days  5:09 Memory: 11461.1/15917.0MB Client: Shell inxi: 1.7.24 

 
  wspage@suse:~/sage> time ./sage -t --long src/sage/interfaces/
  ...
  ----------------------------------------------------------------------
  sage -t --long src/sage/interfaces/expect.py  # 1 doctest failed
  ----------------------------------------------------------------------
  Total time for all tests: 123.2 seconds
      cpu time: 14.3 seconds
      cumulative wall time: 120.5 seconds

  real	2m18.358s
  user	0m56.396s
  sys	0m4.856s

comment:30 Changed 4 months ago by was

You should do some things like

    %timeit gp.eval('2+3')
    %timeit gp('2') + gp('3')
    %timeit axiom('2+3')

etc. The doctesting won't testing latency much, and latency is *the* main issue with performance with the pexpect interfaces.
The other is size, e.g.,

    %timeit s=str(gp.eval('2^10000'))

comment:31 Changed 4 months ago by fbissey

I will move to do the latency test shortly but for reference when I do the doctesting of sage/interface on my machine.
pexpect-2.0

Total time for all tests: 118.3 seconds
    cpu time: 20.6 seconds
    cumulative wall time: 115.9 seconds

real    1m59.638s
user    1m21.060s
sys     0m3.290s

pexpect-3.3

Total time for all tests: 128.3 seconds
    cpu time: 21.3 seconds
    cumulative wall time: 125.9 seconds

real    2m9.655s
user    1m27.270s
sys     0m3.200s

So it's a little bit slower already. I don't know if anything skew that a bit. Moving to the latency test which may be a better test anyway.

comment:32 Changed 4 months ago by fbissey

pexpect-2.0

┌────────────────────────────────────────────────────────────────────┐
│ SageMath Version 6.7.beta4, Release Date: 2015-05-05               │
│ Type "notebook()" for the browser-based notebook interface.        │
│ Type "help()" for help.                                            │
└────────────────────────────────────────────────────────────────────┘
┏━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┓
┃ Warning: this is a prerelease version, and it may be unstable.     ┃
┗━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━┛
sage: %timeit gp.eval('2+3')
The slowest run took 269.56 times longer than the fastest. This could mean that an intermediate result is being cached 
10000 loops, best of 3: 94.4 us per loop
sage: %timeit gp('2') + gp('3')
The slowest run took 8.78 times longer than the fastest. This could mean that an intermediate result is being cached 
1000 loops, best of 3: 556 us per loop
sage: %timeit s=str(gp.eval('2^10000'))
1000 loops, best of 3: 250 us per loop

One time only so we don't use the cache

sage: %time gp.eval('2+3')
CPU times: user 0 ns, sys: 0 ns, total: 0 ns
Wall time: 728 us
'5'
sage: %time gp('2') + gp('3')
CPU times: user 0 ns, sys: 0 ns, total: 0 ns
Wall time: 1.51 ms
5
sage: %time s=str(gp.eval('2^10000'))
CPU times: user 0 ns, sys: 0 ns, total: 0 ns
Wall time: 667 us

pexpect-3.3

sage: %timeit gp.eval('2+3')
The slowest run took 80.90 times longer than the fastest. This could mean that an intermediate result is being cached 
1000 loops, best of 3: 309 us per loop
sage: %timeit gp('2') + gp('3')
1000 loops, best of 3: 1.54 ms per loop
sage: %timeit s=str(gp.eval('2^10000'))
The slowest run took 6.02 times longer than the fastest. This could mean that an intermediate result is being cached 
1000 loops, best of 3: 513 us per loop

One time only

sage: %time gp.eval('2+3')
CPU times: user 10 ms, sys: 0 ns, total: 10 ms
Wall time: 30.5 ms
'5'
sage: %time gp('2') + gp('3')
CPU times: user 0 ns, sys: 0 ns, total: 0 ns
Wall time: 4.58 ms
5
sage: %time s=str(gp.eval('2^10000'))
CPU times: user 0 ns, sys: 0 ns, total: 0 ns
Wall time: 644 us

So it is a little bit all over the place, but generally 3 to 4 times slower with pexpect 3.3. I don't know if it is acceptable. Since upstream is now alive and well we could take it as an issue with them?

comment:33 follow-up: Changed 4 months ago by was

So it is a little bit all over the place, but generally 3 to 4 times slower with pexpect 3.3. I don't know if it is acceptable.

No, this is definitely not acceptable. For real work it could easily mean people's programs are 4 times slower due to this upgrade. It's important to understand that the use case of pexpect by Sage is massively different than the use case of pexpect for absolutely everybody else -- for them some latency issues are no big deal, but for us they are.

Incidentally, I think there is no caching going on despite what %timeit says...

comment:34 Changed 4 months ago by fbissey

Right, I am hearing you. This is a definite problem. So is keeping dead software. If we are keeping the pexpect 2.0 branch in for performance issue it becomes the responsibility of sage developers to maintain it and add new features like the one Bill wants.

Effectively we are maintaining a fork and if we are going that way I would like it to be formalized with a different name and possibly integrated in the sage code itself. This is so people don't get upgraded to a different pexpect through pip if they are using it. Also while our core functionality uses this pexpect, we don't want to block other packages that would need a newer pexpect.

That is my opinion on the matter. The other way is to work, possibly with upstream, to solve that latency problem in newer versions.

Last edited 4 months ago by fbissey (previous) (diff)

comment:35 Changed 4 months ago by was

fbissey -- definitely -- I completely agree with you, as long as "we" = not me :-)

comment:36 Changed 4 months ago by fbissey

@bill do you think it would be easy to bake unicode support in pexpect 2.0? Or would it be easier to work out the latency issue? You seem to have a good handle on what's in pexpect.

comment:37 follow-up: Changed 4 months ago by bpage

Apparently the performance problem originates with this old commit:

https://github.com/pexpect/pexpect/commit/600463686284ea102548f5e0bf51582db051dc78#diff-dfb232b43530f0961894e09a0d862aa4R1048

after commenting out

https://github.com/pexpect/pexpect/blob/3.x/pexpect/__init__.py#L1540

                #time.sleep(0.0001)

performance changes from

sage: sage: %timeit gp.eval('2+3')
1000 loops, best of 3: 427 µs per loop
sage: sage: %timeit gp.eval('2+3')
1000 loops, best of 3: 449 µs per loop

to this

sage: %timeit gp.eval('2+3')
The slowest run took 175.25 times longer than the fastest. This could mean that an intermediate result is being cached 
10000 loops, best of 3: 76.3 µs per loop
sage: %timeit gp.eval('2+3')
The slowest run took 7.85 times longer than the fastest. This could mean that an intermediate result is being cached 
10000 loops, best of 3: 76.4 µs per loop

comment:38 Changed 4 months ago by fbissey

Excellent job! Do we have contact upstream to see if this is really needed or could be made optional?

comment:39 follow-up: Changed 4 months ago by jdemeyer

Alternative to patching pexpect, we can just replace pieces of pexpect that we don't like with custom Python or Cython code (I do this in #17686 for exiting programs).

comment:40 in reply to: ↑ 33 Changed 4 months ago by SimonKing

Replying to was:

No, this is definitely not acceptable. For real work it could easily mean people's programs are 4 times slower due to this upgrade.

Indeed. I am even using a patched version of my department's linux distribution, since otherwise the latency (of pseudo-TTY, which slows down pexpect) makes my group cohomology spkg practically unusable.

comment:41 in reply to: ↑ 39 ; follow-up: Changed 4 months ago by fbissey

Replying to jdemeyer:

Alternative to patching pexpect, we can just replace pieces of pexpect that we don't like with custom Python or Cython code (I do this in #17686 for exiting programs).

That's interesting if we can do it in a systematic way. I wouldn't mind getting rid of most pexpect interface with the exception of the notebook (which may be harder).

comment:42 in reply to: ↑ 41 Changed 4 months ago by jdemeyer

Replying to fbissey:

That's interesting if we can do it in a systematic way. I wouldn't mind getting rid of most pexpect interface with the exception of the notebook (which may be harder).

I don't mean to stop using pexpect interfaces. I mean replacing parts of pexpect itself: the main pexpect code is in one Python class spawn and we can monkey-patch that by subclassing that and changing methods as we please.

Since pexpect uses some low-level OS stuff, implementing the critical parts in Cython might also give significant speed gain (I haven't tested this yet, but surely calling os.foo() in Python and playing with strings will be slower than directly calling the foo() system call from Cython).

comment:43 in reply to: ↑ 37 ; follow-up: Changed 4 months ago by leif

Replying to bpage:

Apparently the performance problem originates with this old commit:

https://github.com/pexpect/pexpect/commit/600463686284ea102548f5e0bf51582db051dc78#diff-dfb232b43530f0961894e09a0d862aa4R1048

after commenting out

https://github.com/pexpect/pexpect/blob/3.x/pexpect/__init__.py#L1540

                #time.sleep(0.0001)

Hahaha, I was going to grab 2.1 and investigate the changes compared to 2.0. (Didn't realize the full history was kept.)

Of course continually polling without delay isn't nice either; it will significantly increase the CPU load.

comment:44 in reply to: ↑ 43 ; follow-up: Changed 4 months ago by fbissey

Replying to leif:

Replying to bpage:

Apparently the performance problem originates with this old commit:

https://github.com/pexpect/pexpect/commit/600463686284ea102548f5e0bf51582db051dc78#diff-dfb232b43530f0961894e09a0d862aa4R1048

after commenting out

https://github.com/pexpect/pexpect/blob/3.x/pexpect/__init__.py#L1540

                #time.sleep(0.0001)

Hahaha, I was going to grab 2.1 and investigate the changes compared to 2.0. (Didn't realize the full history was kept.)

Of course continually polling without delay isn't nice either; it will significantly increase the CPU load.

Will it? After all unless there are quite a number of other changes, it is the current situation with 2.0, isn't it? Upgrading without patching would decrease the CPU load if I am not mistaken.

Anyway, I like Jeroen's idea but we will need to upgrade pexpect in any case. I am all in favour of upgrading now with a patch and working on some cythonized elements for pexpect in a follow up ticket. We could remove the patch when we have something satisfactory in place.

comment:45 in reply to: ↑ 44 Changed 4 months ago by leif

Replying to fbissey:

Replying to leif:

Of course continually polling without delay isn't nice either; it will significantly increase the CPU load.

Will it?

http://en.wikipedia.org/wiki/Busy_waiting.

I'll have to look closer at the code. Haven't tested yet, but I guess it'll get worse the longer the net computation in the subprocess takes; the examples above only do short toy computations and don't take the overall CPU time into account. (It may lead to effectively doubling SAGE_NUM_THREADS in ptestlong.)

After all unless there are quite a number of other changes, it is the current situation with 2.0, isn't it? Upgrading without patching would decrease the CPU load if I am not mistaken.

Probably. In fact, for me ptestlong with 3.3 (unpatched) went faster than with 2.0, although only slightly, under the same conditions (constant low load). (But in both cases I had some process apparently still waiting for Singular after all other tests had already finished, so the wall time got messed up a bit.)

But I'm ok with first upgrading here and removing the sleep, then checking what else we could tweak on another ticket.

Anyway, I like Jeroen's idea but we will need to upgrade pexpect in any case. I am all in favour of upgrading now with a patch and working on some cythonized elements for pexpect in a follow up ticket. We could remove the patch when we have something satisfactory in place.

Subclassing, probably with individual changes for different interfaces or dynamically changing parameters is the way to go I think.

While we could perhaps do some parts in Cython, leaving Python of course puts more burden of portablility on us, depending on what exactly we do.

comment:46 Changed 4 months ago by bpage

Perhaps proposing an upstream patch to provide an optional parameter such as

expect(prompt,yield=false)

to optionally avoid the call to sleep would be a good idea? Apparently there are situations such as the way that Sage uses gap where busy waiting is a good thing. Meanwhile in Python 3.x there is asyncio and pexpect 3.x already supports that.

comment:47 follow-up: Changed 4 months ago by bpage

Based on
http://stackoverflow.com/questions/7273474/behavior-of-pythons-time-sleep0-under-linux-does-it-cause-a-context-switch

I tried

                time.sleep(0)

in pexpect/init.py and the result on my linux system remains fast (78.9 µs per loop). In principle the use of sleep(0) should allow scheduling on all systems but it might be a good idea for someone with a MAC to try this on OSX.

The pexpect people might accept a patch to change this to 0.

comment:48 follow-up: Changed 4 months ago by jdemeyer

Why do you think it's busy waiting? It looks like it's reading with a timeout, which is not busy waiting.

comment:49 in reply to: ↑ 47 Changed 4 months ago by leif

Replying to bpage:

The pexpect people might accept a patch to change this to 0.

Well, rather the delay should be configurable.

But the whole expect_loop() and read_nonblocking() look pretty messy. We should perhaps simply overwrite one or both with a version that fits our needs. The whole class certainly isn't written for performance.

Note that the behaviour also depends on the writer (i.e., the subprocess); ECL for example is extremely poor in that it doesn't write strings, but really character by character, such that in the worst case we here would end up with at least len(s) * 0.1 ms (and at least len(s) context switches, not including the system calls themselves, where pexpect doesn't only call select() and probably read(), but also waitpid() because of the isalive() checks).

comment:50 follow-up: Changed 4 months ago by bpage

@jdemeye Yes I see, so I wonder why they need time.sleep at all? I am back to asking them to just remove it. But if they prefer a patch with a configurable sleep time then why not?

@leif Re: rewriting the loop. For sure if you have the time but I think the priority should be to get pexpect updated soonest.

comment:51 in reply to: ↑ 48 ; follow-up: Changed 4 months ago by leif

Replying to jdemeyer:

Why do you think it's busy waiting? It looks like it's reading with a timeout, which is not busy waiting.

Unless the timeout is None, it is busy waiting.

With a larger timeout, it gets less worse, but is still busy waiting.

comment:52 in reply to: ↑ 50 Changed 4 months ago by leif

Replying to bpage:

@leif Re: rewriting the loop. For sure if you have the time but I think the priority should be to get pexpect updated soonest.

Of course on a follow-up, as I said before.

sleep(0) shouldn't be necessary because of the (many!) system calls in the loop.

comment:54 in reply to: ↑ 53 Changed 4 months ago by leif

Replying to bpage:

https://github.com/pexpect/pexpect/issues/215

Thank you for linking back... B)

(Hope the guys don't get my address.)

comment:55 in reply to: ↑ 51 Changed 4 months ago by leif

Replying to leif:

Replying to jdemeyer:

Why do you think it's busy waiting? It looks like it's reading with a timeout, which is not busy waiting.

Unless the timeout is None, it is busy waiting.

With a larger timeout, it gets less worse, but is still busy waiting.

Ok, it's not as bad as I first thought, since the loop is exited upon the first timeout (which is on the total time spent in expect_loop(), but also used in select()). So it depends on what happens in the application upon timeout, and the timeout chosen.

comment:56 follow-up: Changed 4 months ago by fbissey

It would be good if upstream were accepting one of the possible changes.

@Bill I see you have made a pull request can you tell us the results from travis when you have them? If it passes the tests I'll update the branch.

comment:57 follow-up: Changed 4 months ago by fbissey

Hum.... I don't see much improvement by applying that patch at all.

sage: %time gp.eval('2+3')
CPU times: user 0 ns, sys: 0 ns, total: 0 ns
Wall time: 24 ms
'5'

Note that while William says there shouldn't be a cache there is definitely one

sage: %time gp.eval('2+3')
CPU times: user 0 ns, sys: 20 ms, total: 20 ms
Wall time: 23.4 ms
'5'
sage: %time gp.eval('2+3')
CPU times: user 0 ns, sys: 0 ns, total: 0 ns
Wall time: 309 us
'5'

comment:58 in reply to: ↑ 57 Changed 4 months ago by nbruin

Replying to fbissey:

Note that while William says there shouldn't be a cache there is definitely one

sage: %time gp.eval('2+3')
CPU times: user 0 ns, sys: 20 ms, total: 20 ms
Wall time: 23.4 ms
'5'
sage: %time gp.eval('2+3')
CPU times: user 0 ns, sys: 0 ns, total: 0 ns
Wall time: 309 us
'5'

Isn't that just the overhead of starting up the process the first time you run it? If I subsequently send other strings to gp, such as gp.eval('3+4'), I get similar times. That's not consistent with caching.

comment:59 Changed 4 months ago by fbissey

I hadn't thought of that. But then the figure for the first run with pexpect 2.0 is in us while it is ms for 3.3. So there is quite a gap for that. May be I will need to recheck the timing for 2.0.

timeit is definitely in the same ballpark for 2.0 (94.4 us) and 3.3 (99.7 us) so you are probably right.

comment:60 Changed 4 months ago by nthiery

  • Cc Vincent.Neri added

For info: upgrading pexpect might also solve another issue we are having when running Sage's doctests within a docker container. See comment by olliewalsh on:

https://github.com/docker/docker/issues/12277

@Vincent.Neri: using this branch might be the easiest way to try out a recent version of pexpect and experiment with olliewalsh's suggestion

comment:61 in reply to: ↑ 56 Changed 4 months ago by bpage

Replying to fbissey:

It would be good if upstream were accepting one of the possible changes.

@Bill I see you have made a pull request can you tell us the results from travis when you have them? If it passes the tests I'll update the branch.

https://github.com/pexpect/pexpect/pull/216

I am not sure if the "ci/teamcity" result is real. Could someone with more experience with this ci stuff take a look?

comment:62 Changed 4 months ago by fbissey

It looks like a misconfiguration rather than a fault in pexpect but I couldn't affirm it 100%.

comment:63 Changed 4 months ago by git

  • Commit changed from a24eab3ce985874ab8445ed5e362bbeead76fd40 to 80cd29cee620bb62b53a389cff5f7db4aa65b2d6

Branch pushed to git repo; I updated commit sha1. New commits:

80cd29cAdd patch from https://github.com/pexpect/pexpect/pull/216

comment:64 Changed 4 months ago by fbissey

The failing test upstream for python3.3 is a bit annoying but I am pushing the patch anyway as we are only concerned with python2.7 and 3.4.x (or even 3.5) in the future. It looks like we may have to get ready to shift target to pexpect 4.0 if they solve their last issue for a release.

comment:65 Changed 4 months ago by fbissey

We'll also need a new release of sagenb or patch it, getting it done may be fun...

comment:66 Changed 2 months ago by jdemeyer

Note that we can also re-implement the slow/broken parts in the Cython front-end sage/interfaces/sagespawn.pyx. Doing that for expect_loop() and read_nonblocking() might be worth it.

comment:67 follow-up: Changed 2 months ago by bpage

What advantage can we gain from using Cython to re-implement? I think it might be better to propose a different upstream patch, something like:

time.sleep(self.maxSleep)

where maxSleep corresponds to a new optional parameter that defaults to 0.0001 for backward compatibility but which we can set to 0 in expect.py. I have tested time.sleep(0) and it seems to have the same end effect in Sage as commenting it out (and the same failures upstream). Given that they have apparently used similar strategies in the past, by making it optional I think we can expect upstream to agree to the change and that it would be incorporated into future versions of pexpect with no impact on Sage maintenance.

comment:68 in reply to: ↑ 67 Changed 2 months ago by jdemeyer

Replying to bpage:

What advantage can we gain from using Cython to re-implement?

I wasn't specifically talking about the sleep(0.0001) issue, it was just a general comment.

We could

  1. Directly call system calls instead of using os.foo(), leading to better performance and better reliability, especially w.r.t. interrupts.
  2. Use C strings instead of Python strings for performance.
  3. More generally change/add functionality without depending on upstream.

comment:69 follow-ups: Changed 2 months ago by bpage

Is there significant overhead calling os.foo? By "w.r.t. interrupts" are you referring to the so called Python GIL that makes most things like this single-threaded? Would that mean that we would have to be careful to avoid mixing os.foo calls and direct system calls? I understand that this changes significantly in Python 3. pexpect 3.x and 4.x support some new asynchronous modes for i/o processing in Python 3 that might be of interest.

I am sceptical that performance is significantly limited by string matching. I think this might only be the case if it is necessary to locate prompts within very large "before" buffers - something that does not happen frequently in the way that Sage calls external programs and when it does, performance may not be a priority. Do you have any examples where this would be of benefit?

If the goal is to change/add functionality without depending on upstream perhaps the best choice would be to re-write pexpect entirely in cython, e.g. cexpect. But it worries me every time the choice is made to re-invent things in Sage.

comment:70 in reply to: ↑ 69 ; follow-up: Changed 2 months ago by jdemeyer

Replying to bpage:

Is there significant overhead calling os.foo?

No idea, I haven't profiled anything. Most likely there is not a large overhead.

By "w.r.t. interrupts" are you referring to the so called Python GIL that makes most things like this single-threaded?

No, but that could actually be a 4th point on my list above.

Would that mean that we would have to be careful to avoid mixing os.foo calls and direct system calls?

No, there is no such problem.

I understand that this changes significantly in Python 3.

I have no idea what changes in Python 3 for system calls.

I am sceptical that performance is significantly limited by string matching. I think this might only be the case if it is necessary to locate prompts within very large "before" buffers - something that does not happen frequently in the way that Sage calls external programs and when it does, performance may not be a priority. Do you have any examples where this would be of benefit?

It happens a lot in practice: it happens when a pexpect process has a large output (which is then followed by a prompt). See the last example of 30

If the goal is to change/add functionality without depending on upstream perhaps the best choice would be to re-write pexpect entirely in cython, e.g. cexpect.

I don't really want to fork completely pexpect. It might be sufficient to change only expect and read_nonblocking.

comment:71 in reply to: ↑ 69 Changed 2 months ago by jdemeyer

Replying to bpage:

By "w.r.t. interrupts" are you referring to the so called Python GIL that makes most things like this single-threaded?

No, with "interrupts" I am talking about CTRL-C, a.k.a. KeyboardInterrupt in Python. The problem is that Python's os interface really doesn't deal with those well. Here is the problem:

try:
    result = os.read(fd)
except KeyboardInterrupt:
    # ... ?

The problem is that, when an interrupt happens, you simply cannot know whether the read() call actually succeeded and what the result is (the interrupt could happen while assigned the result for example).

I don't know to what extent this is actually a problem in practice, but it is something that worries me about pexpect.

In Cython, interrupt handling has to be done manually, which means that it can be done in a predictable way.

comment:72 in reply to: ↑ 70 Changed 2 months ago by bpage

Replying to jdemeyer:

Replying to bpage:

I am sceptical that performance is significantly limited by string matching. I think this might only be the case if it is necessary to locate prompts within very large "before" buffers - something that does not happen frequently in the way that Sage calls external programs and when it does, performance may not be a priority. Do you have any examples where this would be of benefit?

It happens a lot in practice: it happens when a pexpect process has a large output (which is then followed by a prompt). See the last example of 30

My point was that I would not expect something like %timeit s=str(gp.eval('2^10000')) to be particularly fast. But maybe it is important to note that pexpect already does make an effort to allow faster scanning for prompt if it can be represented as a fixed string rather than a regular expression.

If the goal is to change/add functionality without depending on upstream perhaps the best choice would be to re-write pexpect entirely in cython, e.g. cexpect.

I don't really want to fork completely pexpect. It might be sufficient to change only expect and read_nonblocking.

It seems to me that this is exactly the essential part of pexpect on which Sage depends. Most of the rest of pexpect is just program interface and portability.

Note: See TracTickets for help on using tickets.