Performance regression introduced in 2.0.0

[ypsah]

Hi,

I am (happily) using sh in my simple-git-versioning project, and since version 2.0, I have noticed a significant slowdown in test execution: my 16 tests used to run in 1 second, and they now take 14 seconds.

Using git bisect, I tracked the issue down to e9511de, and more specifically, this part of the change:

@@ -2371,7 +2414,7 @@ class OProc(object):
             # thread, which is attempting to call wait(). by introducing a tiny sleep
             # (ugh), this seems to prevent other threads from equally attempting to
             # acquire the lock. TODO find out if this is a general python bug
-            time.sleep(0.00001)
+            time.sleep(0.1)
             if self.exit_code is not None:
                 return False, self.exit_code
             return True, self.exit_code

Reverting this one line gets the execution speed back down to 1 second for my 16 tests.

[JacobHayes]

I'm seeing this too - I have a job that normally takes 4m but after the upgrade it ran >8h before I cancelled. I reran after downgrading and it ran in 4m again. I tried out #650 and it's been stuck for 30m. I've checked the CPU usage and it stays consistently low (around .03% for python, 0% for the subprocess). Perhaps the .acquire(timeout=0.1) is still slow or perhaps there are other regressions.

This process has _out, _err, and _in function handlers, maybe those compound sleeps?

---

edit: after ensuring #650 was properly installed, I still had to change the timeout back to 0.00001 (sed -i 's/timeout=0.1/timeout=0.00001/' ./venv/lib/python3.10/site-packages/sh.py) in order to run at normal speeds.

[amoffatgmi]

Btw do we have any minimum reproducible example we can try our changes against to see the performance differences?

[JacobHayes]

Looks like any test with a generator _in will do (I didn't test other _in variants):

import sh

sh.cat(_in=("a" for _ in range(100)))

$ pip3 install 'sh<2' 2>/dev/null | grep "Successfully installed"
Successfully installed sh-1.14.3
$ time python3 run.py

________________________________________________________
Executed in   58.41 millis    fish           external

$ pip3 install 'sh>2' 2>/dev/null | grep "Successfully installed"
Successfully installed sh-2.0.1
$ time python3 run.py

________________________________________________________
Executed in   10.35 secs      fish           external

$ pip3 uninstall -y sh && pip3 install 'sh @ git+https://github.com/amoffat/sh@10ee3fab251f787fc3eb6e769eb43e4674c9b65a'  | grep "Successfully installed"
Successfully installed sh-2.0.1
$ time python3 run.py

________________________________________________________
Executed in   10.28 secs      fish           external

$ sed -i 's/timeout=0.1/timeout=0.00001/' .venv/lib/python3.10/site-packages/sh.py
$ time python3 run.py                       0.01s

________________________________________________________
Executed in   74.61 millis    fish           external

Without #651, the runtime seems to be about exactly 100ms per line of input (after the ~fixed startup time):

$ time python3 run.py # 1 line in _in generator

________________________________________________________
Executed in  175.33 millis    fish           external

$ time python3 run.py # 10 line in _in generator (sometimes this runs as fast as 1 line - maybe if we get the lock first?)

________________________________________________________
Executed in  999.35 millis    fish           external

$ time python3 run.py # 100 line _in generator

________________________________________________________
Executed in   10.26 secs      fish           external

[amoffatgmi]

Thanks @JacobHayes that is very helpful

[JacobHayes]

Yup! Looks like @ypsah 👍'd the PR - anything else I can do to help get #651 merged and released? 😃

[amoffatgmi]

Alright 2.0.2 has landed, good work all. Re-open this issue if you still see performance problems

[JacobHayes]

Awesome, thanks so much for the fast turn around @amoffatgmi! 🎉